Node: 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/[email protected] 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/[email protected] 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?):

https://github.com/nodejs/node/issues/3145
https://github.com/nodejs/node/issues/3429
https://github.com/nodejs/node/issues/7652

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

[ghost]

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.

[ghost]

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/[email protected] 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 <[email protected]>
axa-ch-user <[email protected]>
lucamele <[email protected]>
thedadi <[email protected]>

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:
https://github.com/npm/npm/issues/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/[email protected])
λ 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)

[richardlau]

Does the slowness occur if spawn/execFile is called with the absolute/relative path to npm.cmd? On Windows libuv has to manually walk the PATH to find the command to execute: https://github.com/nodejs/node/blob/8476053c132fd9613aab547aba165190f8064254/deps/uv/src/win/process.c#L298-L447

[AndyOGo]

@richardlau
Yeah exactly, node does not support PATHEXT on windows, hence node does not find npm.cmd on windows, but we check the platform to mitigate this bug:

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

[mjenny]

@richardlau @bzoz
We tested it with the latest version of nodejs (10.6.0) and npm (6.1.0) but still are experiencing the same result even when setting shell-option to true.

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'], { 'shell': true },(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);
    }
  });

Shell-output:

npm run test-child-spawn-nodejs --verbose
npm info it worked if it ends with ok
npm verb cli [ 'C:\\eplatform\\tools\\node\\node.exe',
npm verb cli   'C:\\eplatform\\tools\\node\\node_modules\\npm\\bin\\npm-cli.js',
npm verb cli   'run',
npm verb cli   'test-child-spawn-nodejs',
npm verb cli   '--verbose' ]
npm info using [email protected]
npm info using [email protected]
npm verb run-script [ 'pretest-child-spawn-nodejs',
npm verb run-script   'test-child-spawn-nodejs',
npm verb run-script   'posttest-child-spawn-nodejs' ]
npm info lifecycle @axa-ch/[email protected]~pretest-child-spawn-nodejs: @axa-ch/[email protected]
npm info lifecycle @axa-ch/[email protected]~test-child-spawn-nodejs: @axa-ch/[email protected]

> @axa-ch/[email protected] test-child-spawn-nodejs C:\eplatform\git-repos\patterns-library
> node ./stack/tasks/test-child-spawn-nodejs.js

Message received in 189270.100785 ms
user-name

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

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git checkout -- <file>..." to discard changes in working directory)

        modified:   stack/tasks/test-child-spawn-nodejs.js

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

        .idea/
        patterns-library.iml

no changes added to commit (use "git add" and/or "git commit -a")

npm verb lifecycle @axa-ch/[email protected]~test-child-spawn-nodejs: unsafe-perm in lifecycle true
npm verb lifecycle @axa-ch/[email protected]~test-child-spawn-nodejs: PATH: C:\eplatform\tools\node\node_modules\npm\node_modules\npm-lifecycle\node-gyp-bin;C:\eplatform\git-repos\patterns-library\node_modules\.bin;C:\eplatform\tools\cmder_mini\bin;C:\eplatform\tools\cmder_mini\vendor\conemu-maximus5\ConEmu\Scripts;C:\eplatform\tools\cmder_mini\vendor\conemu-maximus5;C:\eplatform\tools\cmder_mini\vendor\conemu-maximus5\ConEmu;C:\Program Files (x86)\Common Files\Oracle\Java\javapath;C:\Program Files\oracle\instantclient\12.2.0.1;C:\Program Files (x86)\oracle\instantclient\12.2.0.1;C:\Program Files (x86)\IBM\Trace Facility\;C:\Program Files (x86)\IBM\Personal Communications\;C:\ProgramData\Oracle\Java\javapath;C:\Program Files (x86)\Intel\iCLS Client\;C:\Program Files\Intel\iCLS Client\;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;c:\Sysdat\Tools;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files (x86)\PTKT;C:\WINDOWS\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files (x86)\ibm\gsk8\lib;C:\Program Files\ibm\gsk8\lib64;C:\PROGRA~1\IBMDSC\SQLLIB\BIN;C:\PROGRA~1\IBMDSC\SQLLIB\FUNCTION;C:\PROGRA~1\IBMDSC\SQLLIB\SAMPLES\REPL;C:\Program Files\IBM\WebSphere MQ\bin64;C:\Program Files\IBM\WebSphere MQ\bin;C:\Users\C193577\AppData\Local\Microsoft\WindowsApps;C:\Program Files\IDM Computer Solutions\UltraEdit\;C:\eplatform\tools\Git\bin;C:\eplatform\tools\maven\3\bin;C:\eplatform\tools\node;C:\eplatform\tools\oc-3.9;;C:\eplatform\tools\Git\usr\bin;C:\eplatform\tools\Git\usr\share\vim\vim74;C:\eplatform\tools\cmder_mini\
npm verb lifecycle @axa-ch/[email protected]~test-child-spawn-nodejs: CWD: C:\eplatform\git-repos\patterns-library
npm info lifecycle @axa-ch/[email protected]~posttest-child-spawn-nodejs: @axa-ch/[email protected]
npm verb exit [ 0, true ]
npm timing npm Completed in 190002ms
npm info ok

[richardlau]

@richardlau
Yeah exactly, node does not support PATHEXT on windows, hence node does not find npm.cmd on windows, but we check the platform to mitigate this bug:

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

My comment was more about the path to npm.cmd, i.e. does the slowness still occur if the path to npm.cmd is specified?

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

If there is no difference in behaviour (i.e. the slowness still occurs) this would rule out the manual path walking code on Windows in libuv (even though you specify npm.cmd libuv still has to walk through PATH to find npm.cmd).

[AndyOGo]

@richardlau
Thanks for your clarification. Now I understood your point.
But I really don't believe that this can be an issue that it delays execution for minutes 😲
Also we sniffed the network and the API calls go over the wire in expected timing, just the process exit is tremendously delayed long after the network requests have already succeeded. Which also means that the path resolution process can't be the bottleneck IMHO.

Further more running git like git status is as fast as expected and it's executable also needs to be resolved.

[bzoz]

Could you attach debugger to the node child process and provide the call stack? You can get VS Community from here, from it Ctrl-Alt-P brings "Attach to process" menu.

[piotrpeszt]

I have the same issue. I'm using Windows 7 in our company environment with proxy set up.
With it I run the following code:

'use strict' let precise = require('precise') let timer = precise() let task = 'npm --version' console.log('Test started') timer.start() console.log(require('child_process').execSync(task).toString()) timer.stop() console.log('Test finished in: ', timer.diff() / 1000000 / 1000, 'sec')
And the results are:

$ node build/dev-check-ver.js
Test started
5.6.0
Test finished in: 189.055587446 sec

But if I run plain

time npm --version

Then the timing is instant:

5.6.0
real 0m1.188s
user 0m0.060s
sys 0m0.214s

What's interesting is that every time I run it the timings are more or less around 189 sec. I see that others in this topic have also similar timings. Looks like a 3 minutes (180 sec) timeout after which the process is starting up.

[mjenny]

@piotrpeszt
Can you try and disable your anti virus as suggested in https://github.com/npm/npm/issues/21148#issuecomment-404475074 ?
Apparently this solved it for me at least on my private pc.

npm run test-child-spawn

> @axa-ch/[email protected] test-child-spawn E:\IdeaProjects\aletheia
> node ./build/scripts/test-child-spawn.js

Message received in 1629.977086 ms
manuel-jenny

Message received in 1605.18016 ms
andyogo <[email protected]>
axa-ch-user <[email protected]>
davidknezic <[email protected]>
linasalih <[email protected]>
lucamele <[email protected]>
manuel-jenny <[email protected]>
sventschui <[email protected]>
thedadi <[email protected]>

Still having issues on my working machine though since I cannot disable the realtime protection...

[piotrpeszt]

I tried, but it didn't help.

[SirNiggo]

Does anyone have a fix for that? We do also use NPM behind a company proxy and child processes are extremely slow.

[SirNiggo]

@AndyOGo the workaround that is mentioned in issue https://github.com/npm/npm/issues/20979 did the trick for me. You could try that out, too. Looks like npm's version check takes a lot of time if it is used in a child process.

[AndyOGo]

@NicoEnking
Awesome feedback, thank you very very much.
We will try that ASAP:)

Very interesting data, like:

The update check feature that was introduces with [email protected]. The update check feature that was introduces with [email protected] does not support proxies and thus prevents the child process from closing until it times out after 3 minutes. does not support proxies and thus prevents the child process from closing until it times out after 3 minutes.

The update check feature uses the update-notifier package that uses the latest-version package which in turn uses package-json. package-json currently does not support proxies and the author seems not to be willing to implement proxy support.

Workarounds

See https://github.com/yeoman/update-notifier#user-settings

• Set environment variable NO_UPDATE_NOTIFIER=1
• Use --no-update-notifier flag
• Set "optOut": true in ~/.config/configstore/update-notifier-[your-module-name].json

This whole proxy support story dates back a few years 😱

• https://github.com/nodejs/node/issues/8381
• https://github.com/sindresorhus/got/issues/79
• https://github.com/sindresorhus/package-json/issues/22#issuecomment-185158091

[AndyOGo]

Since npm moved to another issue tracker, I just recreated the issue here:
https://npm.community/t/npm-version-takes-3-minutes-to-complete-when-run-in-child-process-and-behind-corporate-proxy/1658

Please add your thoughs, issues over there.

[SirNiggo]

@AndyOGo no problem. A Nativescript dev helped me figure this out :-)
We are in a same environment like you are, running scripts that run child processes behind a proxy and this workaround fixed it for us. Everything runs smooth now!

[AndyOGo]

@NicoEnking
Using the --no-update-notifier flag did not work for us, but specifying the environment variable NO_UPDATE_NOTIFIER: true did work 🎉

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';
const env = {
  ...process.env,
  // only this works for us
  NO_UPDATE_NOTIFIER: true,
}

timer.start();

execFile(npmCmd, ['whoami', '--no-update-notifier' /* does not work */], { env }, (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);
    }
  });
});

[CaptainN]

I think I ran into this bug through meteor-now - I noticed that if I watch the output in PowerShell, I can spot when it stalls (the little \, /, - spinner animation stops, and the text doesn't vibrate) - if I press ctrl+c I can get it to resume, speeding up the overall build process tremendously. I hope this observation helps shed some light in some way.

[bnoordhuis]

This issue has been open for over a year without a conclusion and without even a clear indication it's a Node.js bug (as opposed to, say, an npm issue or an overzealous virus scanner.)

I'm closing it out. Let me know if there is reason to reopen.