child_process spawn, execFile, etc. is tremendously slower at Windows and takes minutes

[AndyOGo]

• Version: v10.5.0
• Platform: Windows 10 (64-Bit)
• Subsystem: not sure, we use a corporate proxy though

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

Related Bugs (but all closed, why?):

#3145
#3429
#7652

Btw PATHEXT is still not supported on windows, why is the related bugs closed then?
nodejs/node-v0.x-archive#2318

Unable to reproduce the issue. Here is my output on Windows 10 x64 using your script:

C:\21632>npm run test-child-spawn-nodejs

> @ test-child-spawn-nodejs C:\21632
> node main.js

Message received in 1766.736999 ms
trvsapjiac

Message received in 15.665841 ms
On branch master

No commits yet

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

        main.js
        package.json

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

It takes ~1.7 sec in total.

[AndyOGo]

@trvsapjiac
Thank you for your quick answer.
Wau, I didn't expect that 😲
Why do I measure this huge difference, there must be some unknown side-effect, either from the OS or something weird in node 🤔

Which node version are you using?

I will try to perform some more tests and gather some more data about the environment.

Which node version are you using?

v10.5.0

[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

[Trott]

@nodejs/platform-windows

[bzoz]

This looks a lot like an issue with NPM, not Node. @AndyOGo , I think you should report this issue in the npm issue tracker

[AndyOGo]

@bzoz
I thought that too, but there is one weird thing.
If I use any npm command in the CLI, they are fast as hell 😲
As soon as I start to script them by child_process.execFile, only then they get really really slow?
I wonder how that is possible 🤔

Please take the time to investigate this issue deeply.
I took the time to measure proper timings and sniff the network requests.

Issue at npm:
npm/npm#21148

[bzoz]

Yeah, if it runs ok from CLI then there could be something going on.

Some ideas:

• I see you run the test by calling npm run test-child-spawn-nodejs. Maybe npm run is the problem, could you try running the test directly?
• Can you try running exec, or adding {shell: true} to execFile options? npm is a shell script, running it with execFile is not really supported, but Windows make it run anyway
• Can you try using spawn? Also with {stdio: 'inherit'} option?

[AndyOGo]

Thanks for your answer, really good points, will try it asap and share my results here, though probably not until next week.

[AndyOGo]

@bzoz
A colleague helped us out, here are the results for:
node .\stack\tasks\test-child-spawn-nodejs.js - which runs npm whoami first and git status afterwards - still very slow.

So either the bugs is in npm.cmd or node's API.

C:\eplatform\git-repos\patterns-library (bugfix/windows-spawn-hangs -> origin) (@axa-ch/patterns-library@2.0.1-beta.160)
λ node .\stack\tasks\test-child-spawn-nodejs.js
Message received in 189201.678317 ms
user-name

Message received in 164.329462 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)