Executing npm by node's spawn on windows is really slow, it takes minutes

[AndyOGo]

I'm opening this issue because:

• npm is crashing.
• npm is producing an incorrect install.
• npm is doing something I don't understand.
• npm is producing incorrect or undesirable behavior.
• Other (see below for feature requests):

What's going wrong?

Utilising child_process.execFile at windows takes minutes to finish.
To demonstrate the bug I created a timed script, running npm whoami first and git status afterwards. I compared those measured results between MacOS and Windows. Following are my results and all the details:

Test run with native child_process.execFile

Run	MacOS	Windows	Slower by
1 npm whoami	1256.060359 ms = 1.256 sec	189733.792206 ms = 189.7338 sec = 3.162 min	151.0547 times
2 git status	16.693848 ms (x75.24091264039304 times faster)	161.197277 ms (x1177.02851894948573 times faster)	9.6561 times

test script:

const { execFile } = require('child_process');
const precise = require('precise');
const timer = precise();

// Node does not support PATHEXT on Windows
const npmCmd = process.platform === 'win32' ? 'npm.cmd' : 'npm';

timer.start();

execFile(npmCmd, ['whoami'], (error, stdout, stderr) => {
  timer.stop();
  console.log('Message received in', timer.diff() / 1000000, 'ms');
  if (error) {
    console.error(error);
  } else {
    console.log(stdout);
  }

  const timer2 = precise();
  timer2.start();

  execFile('git', ['status'], (error, stdout, stderr) => {
    timer2.stop();
    console.log('Message received in', timer2.diff() / 1000000, 'ms');
    if (error) {
      console.error(error);
    } else {
      console.log(stdout);
    }
  });
});

Windows 10:

C:\eplatform\git-repos\patterns-library>npm run test-child-spawn-nodejs

> @axa-ch/patterns-library@2.0.1-beta.160 test-child-spawn-nodejs C:\eplatform\git-repos\patterns-library
> node ./stack/tasks/test-child-spawn-nodejs.js

Message received in 189733.792206 ms
user-name

Message received in 161.197277 ms
On branch bugfix/windows-spawn-hangs
Your branch is up-to-date with 'origin/bugfix/windows-spawn-hangs'.

Untracked files:
  (use "git add <file>..." to include in what will be committed)

        .idea/
        patterns-library.iml

nothing added to commit but untracked files present (use "git add" to track)

Mac OSX El Capitan Version 10.11.6:

npm run test-child-spawn-nodejs

> @axa-ch/patterns-library@2.0.1-beta.160 test-child-spawn-nodejs /Users/axawinterthur/dev/axa-ch_style-html-guide
> node ./stack/tasks/test-child-spawn-nodejs.js

Message received in 1256.060359 ms
andyogo

Message received in 16.693848 ms
On branch bugfix/windows-spawn-hangs
Your branch is up-to-date with 'github/bugfix/windows-spawn-hangs'.
nothing to commit, working tree clean

Original issue at node:
nodejs/node#21632

How can the CLI team reproduce the problem?

supporting information:

• npm -v prints:
• node -v prints: v10.5.0
• npm config get registry prints:
• Windows, OS X/macOS, or Linux?: Windows
• Network issues:
  • Geographic location where npm was run:
  • I use a proxy to connect to the npm registry.
  • I use a proxy to connect to the web.
  • I use a proxy when downloading Git repos.
  • I access the npm registry via a VPN
  • I don't use a proxy, but have limited or unreliable internet access.
• Container:
  • I develop using Vagrant on Windows.
  • I develop using Vagrant on OS X or Linux.
  • I develop / deploy using Docker.
  • I deploy to a PaaS (Triton, Heroku).

[AndyOGo]

Okay, we performed some other tests and it seems that this tremendous slowdown does only happen if we execute npm.cmd on windows, other commands like dir and git complete quickly.

Furthermore we use NPM behind a corporate proxy and have enabled NPM's proxy and https-proxy and utilise the HTTP_PROXY and HTTPS_PROXY environment variables.

So we created another NPM-only test script und sniffed all traffic with Fiddler, here are the results:

Run	Windows	Fiddler/Network delay	Slower by
1 npm whoami	189448.449313 ms	1707 ms	x110.9833 times
2 npm owner ls	189201.805259 ms	945 ms	x200.2136 times

So the network isn't the problem, but maybe the usage of a proxy creates a wrong state in npm, which causes this tremendous delay.

The new npm-only test-script

const { execFile } = require('child_process');
const precise = require('precise');
const timer = precise();

// Node does not support PATHEXT on Windows
const npmCmd = process.platform === 'win32' ? 'npm.cmd' : 'npm';

timer.start();

execFile(npmCmd, ['whoami'], (error, stdout, stderr) => {
  timer.stop();
  console.log('Message received in', timer.diff() / 1000000, 'ms');
  if (error) {
    console.error(error);
  } else {
    console.log(stdout);
  }

  const timer2 = precise();
  timer2.start();

  execFile(npmCmd, ['owner', 'ls'], (error, stdout, stderr) => {
    timer2.stop();
    console.log('Message received in', timer2.diff() / 1000000, 'ms');
    if (error) {
      console.error(error);
    } else {
      console.log(stdout);
    }
  });
});

The CLI output (on Windows 10):

C:\eplatform\git-repos\patterns-library>npm run test-child-spawn-nodejs

> @axa-ch/patterns-library@2.0.1-beta.160 test-child-spawn-nodejs C:\eplatform\git-repos\patterns-library
> node ./stack/tasks/test-child-spawn-nodejs.js

Message received in 189448.449313 ms
user-name

Message received in 189201.805259 ms
andyogo <andy.782542@gmail.com>
axa-ch-user <aem@axa.ch>
lucamele <lucamele1@hotmail.com>
thedadi <difada1@hotmail.com>

Fiddler Log of npm whoami:

This is a Tunnel. Status: CLOSED, Raw Bytes Out: 722; In: 6'596

The selected session is a HTTP CONNECT Tunnel. This tunnel enables a client to send raw traffic (e.g. HTTPS-encrypted streams or WebSocket messages) through a HTTP Proxy Server (like Fiddler).


To enable Fiddler's HTTPS-decryption feature and view decrypted traffic, click Tools > Fiddler Options > HTTPS.


Request Count:   1
Bytes Sent:      204        (headers:204; body:0)
Bytes Received:  115        (headers:115; body:0)
Tunnel Sent:     722
Tunnel Received: 6'596

ACTUAL PERFORMANCE
--------------
ClientConnected:    12:49:57.827
ClientBeginRequest:    12:49:57.830
GotRequestHeaders:    12:49:57.830
ClientDoneRequest:    12:49:57.830
Determine Gateway:    0ms
DNS Lookup:         0ms
TCP/IP Connect:    1ms
HTTPS Handshake:    0ms
ServerConnected:    12:49:57.833
FiddlerBeginRequest:    12:49:57.833
ServerGotRequest:    12:49:57.833
ServerBeginResponse:    12:49:57.840
GotResponseHeaders:    12:49:57.840
ServerDoneResponse:    12:49:58.775
ClientBeginResponse:    12:49:58.775
ClientDoneResponse:    12:49:58.775

    Overall Elapsed:    0:00:00.945

RESPONSE BYTES (by Content-Type)
--------------
~headers~: 115


ESTIMATED WORLDWIDE PERFORMANCE
--------------
The following are VERY rough estimates of download times when hitting servers based in Seattle.

US West Coast (Modem - 6KB/sec)
    RTT:        0.10s
    Elapsed:    0.10s

Japan / Northern Europe (Modem)
    RTT:        0.15s
    Elapsed:    0.15s

China (Modem)
    RTT:        0.45s
    Elapsed:    0.45s

US West Coast (DSL - 30KB/sec)
    RTT:        0.10s
    Elapsed:    0.10s

Japan / Northern Europe (DSL)
    RTT:        0.15s
    Elapsed:    0.15s

China (DSL)
    RTT:        0.45s
    Elapsed:    0.45s

Fiddler Log of npm owner ls:

The selected session is a HTTP CONNECT Tunnel. This tunnel enables a client to send raw traffic (e.g. HTTPS-encrypted streams or WebSocket messages) through a HTTP Proxy Server (like Fiddler).


To enable Fiddler's HTTPS-decryption feature and view decrypted traffic, click Tools > Fiddler Options > HTTPS.


Request Count:   1
Bytes Sent:      206        (headers:206; body:0)
Bytes Received:  116        (headers:116; body:0)
Tunnel Sent:     742
Tunnel Received: 83'019

ACTUAL PERFORMANCE
--------------
ClientConnected:    12:53:05.895
ClientBeginRequest:    12:53:05.899
GotRequestHeaders:    12:53:05.899
ClientDoneRequest:    12:53:05.899
Determine Gateway:    0ms
DNS Lookup:         0ms
TCP/IP Connect:    1ms
HTTPS Handshake:    0ms
ServerConnected:    12:53:05.902
FiddlerBeginRequest:    12:53:05.902
ServerGotRequest:    12:53:05.902
ServerBeginResponse:    12:53:05.907
GotResponseHeaders:    12:53:05.907
ServerDoneResponse:    12:53:07.607
ClientBeginResponse:    12:53:07.607
ClientDoneResponse:    12:53:07.607

    Overall Elapsed:    0:00:01.707

RESPONSE BYTES (by Content-Type)
--------------
~headers~: 116


ESTIMATED WORLDWIDE PERFORMANCE
--------------
The following are VERY rough estimates of download times when hitting servers based in Seattle.

US West Coast (Modem - 6KB/sec)
    RTT:        0.10s
    Elapsed:    0.10s

Japan / Northern Europe (Modem)
    RTT:        0.15s
    Elapsed:    0.15s

China (Modem)
    RTT:        0.45s
    Elapsed:    0.45s

US West Coast (DSL - 30KB/sec)
    RTT:        0.10s
    Elapsed:    0.10s

Japan / Northern Europe (DSL)
    RTT:        0.15s
    Elapsed:    0.15s

China (DSL)
    RTT:        0.45s
    Elapsed:    0.45s

[vitalybibikov]

Hello,

Had the same issue with node's 10.4.0 version,
removal and update to 10.6.0 had helped to solve it.

Installation of npm (Copying new files of npm step) takes 5-10 minutes for some reason.

[AndyOGo]

Interesting, will have to test this...

[AndyOGo]

Updating to node 10.6.0 does not fix this issue 😞

[DanielRuf]

Please try disabling Windows Defender realtime protection to see if this affects it (and all other realtime Av scanners).

[AndyOGo]

@DanielRuf
Thanks for your feedback.

Though please consider, that running npm directly within cmd.exe is as fast as expected (it takes just hundreds of milliseconds).
IMHO this is one of several npm's major bugs on windows.