Spawning a child process on Windows is really slow, takes minutes to complete #142

AndyOGo · 2018-07-03T07:32:22Z

I experience a really weird massive delay on windows by running npm or git as a child process.
Compared to my running it on MacOS, windows takes ages to complete 🤔

These are my test scripts:

const execa = require('execa');

execa('npm', ['whoami']).then(({stdout}) => {
  console.log(stdout);
}).catch(reason => {
  console.error(reason);
})

const execa = require('execa');

execa('git', ['status']).then(({stdout}) => {
  console.log(stdout);
}).catch(reason => {
  console.error(reason);
})

Timing those calls:

The first call is significantly slower than the second call (that's maybe due to JIT).
But the difference between MacOS and Windows is tremendous:

Run	MacOS	Windows
1 `npm whoami`	`1289.505351 ms` = `1.2895 sec`	`189807.887698 ms` = `189.8079 sec` = `3.1635 min`
2 `git status`	`15.803947 ms` (x`81.59387974409178` times faster)	`201.531065 ms` (x`941.82942812315312` times faster)

test script:

const execa = require('execa');

const precise = require('precise');
const timer = precise();

timer.start();
execa('npm', ['whoami']).then(({stdout}) => {
  timer.stop();
  console.log('Message received in', timer.diff() / 1000000, 'ms');
  console.log(stdout);
}).catch(reason => {
  timer.stop();
  console.log('Message received in', timer.diff() / 1000000, 'ms');
  console.error(reason);
}).then(() => {
  const timer2 = precise();
  timer2.start();
  execa('git', ['status']).then(({stdout}) => {
    timer2.stop();
    console.log('Message received in', timer2.diff() / 1000000, 'ms');
    console.log(stdout);
  }).catch(reason => {
    timer2.stop();
    console.log('Message received in', timer2.diff() / 1000000, 'ms');
    console.error(reason);
  })
})

Windows 10:

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

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

Message received in 189807.887698 ms
user-name
Message received in 201.531065 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:   package.json

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")

Mac OSX El Capitan Version 10.11.6:

npm run test-child-spawn

> @axa-ch/[email protected] test-child-spawn /Users/axawinterthur/dev/axa-ch_style-html-guide
> node ./stack/tasks/test-child-spawn.js

Message received in 1289.505351 ms
andyogo
Message received in 15.803947 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

The text was updated successfully, but these errors were encountered:

SamVerschueren · 2018-07-03T08:02:53Z

Can your try running it with Node.js child_process instead of execa? It might have nothing to do with execa itself.

AndyOGo · 2018-07-03T08:08:10Z

@SamVerschueren
Thanks for your quick answer.
Sure, IMHO I think it will be a bug in node, though we just started to setup basic tests and run them on windows and Mac, to see the measured difference. Will post the results asap.

AndyOGo · 2018-07-03T08:20:24Z

@SamVerschueren
I shared our test results with using execa.
Next we will write a plain child_process test, will keep you updated.

AndyOGo · 2018-07-03T09:18:41Z

Test run with native `child_process.execFile`

Run	MacOS	Windows
1 `npm whoami`	`1256.060359 ms` = `1.256 sec`	`189733.792206 ms` = `189.7338 sec` = `3.162 min`
2 `git status`	`16.693848 ms` (x`75.24091264039304` times faster)	`161.197277 ms` (x`1177.02851894948573` times faster)

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

AndyOGo · 2018-07-03T09:26:11Z

@SamVerschueren
Okay, this is a critical bug in node on Windows

AndyOGo · 2018-07-03T09:35:47Z

I just created an issue at node's repo:
nodejs/node#21632

AndyOGo · 2018-07-04T15:54:55Z

Issue at npm:
npm/npm#21148

AndyOGo · 2018-08-27T08:23:06Z

@SamVerschueren
Alright, luckily we finally found the culprit.
It's update-notifier being part of [email protected] which can't handle enterprise proxies and timeouts after 3 minutes 😱

Using NO_UPDATE_NOTIFIER: true did work for me 😄

Original workaround found in:
npm/npm#20979

New issue at NPM's new issue tracker:
https://npm.community/t/npm-version-takes-3-minutes-to-complete-when-run-in-child-process-and-behind-corporate-proxy/1658

AndyOGo · 2018-08-27T08:24:20Z

@sindresorhus This issues of not handling proxy environments dates back to got if I understand it correctly 🤔

sindresorhus · 2018-08-27T08:30:58Z

Got docs on proxy here: https://github.com/sindresorhus/got#proxies

npm should probably use https://github.com/np-maintain/global-tunnel so all the tools they depend on also use the set proxy info.

AndyOGo · 2018-08-27T08:36:09Z

@sindresorhus
Thanks for your quick response.

Unfortunately those links do not provide reasonable solutions if a user just wants to use npm commands from his CLI or have a script which runs several in order...

Maybe node should have proxy support by environment variables backed in, though current status is definitly not ideal...

Actually I'm also convinced that's a bug in npm to use a package like update-notifier, which is out of it's control...

sindresorhus · 2018-08-27T08:48:46Z

Unfortunately those links do not provide reasonable solutions if a user just wants to use npm commands from his CLI or have a script which runs several in order...

Yes, it does, global-tunnel fixes proxy for all request libs used in the dependency tree. Please take a closer look at it. If npm used that, it would be fixed.

Maybe node should have proxy support by environment variables backed in, though current status is definitly not ideal...

It should, but the core team doesn't seem interested in solving the problem: nodejs/node#8381

AndyOGo · 2018-08-27T08:51:35Z

Thanks a lot, seems you faced this issue several times already...
I will look into it.

This was referenced Jul 3, 2018

start trying enabling windooof axa-ch-webhub-cloud/pattern-library#504

Closed

Windows child process spawn, exec, execFile hangs axa-ch-webhub-cloud/pattern-library#503

Closed

Gudahtt mentioned this issue Aug 3, 2018

Disables a tarball fetching test on windows yarnpkg/yarn#6211

Merged

sindresorhus closed this as completed Aug 27, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Spawning a child process on Windows is really slow, takes minutes to complete #142

Spawning a child process on Windows is really slow, takes minutes to complete #142

AndyOGo commented Jul 3, 2018 •

edited

Loading

SamVerschueren commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018 •

edited

Loading

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 4, 2018

AndyOGo commented Aug 27, 2018 •

edited

Loading

AndyOGo commented Aug 27, 2018 •

edited

Loading

sindresorhus commented Aug 27, 2018

AndyOGo commented Aug 27, 2018 •

edited

Loading

sindresorhus commented Aug 27, 2018 •

edited

Loading

AndyOGo commented Aug 27, 2018

Spawning a child process on Windows is really slow, takes minutes to complete #142

Spawning a child process on Windows is really slow, takes minutes to complete #142

Comments

AndyOGo commented Jul 3, 2018 • edited Loading

Timing those calls:

SamVerschueren commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018 • edited Loading

Test run with native child_process.execFile

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 3, 2018

AndyOGo commented Jul 4, 2018

AndyOGo commented Aug 27, 2018 • edited Loading

AndyOGo commented Aug 27, 2018 • edited Loading

sindresorhus commented Aug 27, 2018

AndyOGo commented Aug 27, 2018 • edited Loading

sindresorhus commented Aug 27, 2018 • edited Loading

AndyOGo commented Aug 27, 2018

AndyOGo commented Jul 3, 2018 •

edited

Loading

AndyOGo commented Jul 3, 2018 •

edited

Loading

Test run with native `child_process.execFile`

AndyOGo commented Aug 27, 2018 •

edited

Loading

AndyOGo commented Aug 27, 2018 •

edited

Loading

AndyOGo commented Aug 27, 2018 •

edited

Loading

sindresorhus commented Aug 27, 2018 •

edited

Loading