child_process.spawm is slow?

[ronag]

Don't have any real numbers but ran some profiling on one of our services that makes heavy use of spawning cli tools to perform tasks and the spawn method is taking up significant time.

[santigimeno]

This might be of interest: libuv/libuv#2133

[H4ad]

To add more numbers to this issue, I did some exploration on execSync:

execSync calls spawnSync, which has a similar performance to spawn itself.

Benchmark

exec x 272 ops/sec ±5.89% (59 runs sampled)
execSync x 176 ops/sec ±4.25% (68 runs sampled)
Fastest is exec

benchmark.js

var Benchmark = require('benchmark');
var childProcess = require('child_process');

var suite = new Benchmark.Suite();
var command = 'echo "123"';

suite.add(`exec`, async function () {
  const r = await new Promise(resolve => {
    childProcess.exec(command, (err, out) => {
      resolve(out);
    });
  });
});

suite.add(`execSync`, function () {
  const r = childProcess.execSync(command, { encoding: 'utf8' });
});

suite
  // add listeners
  .on('cycle', function (event) {
    console.log(String(event.target));
  })
  .on('complete', function () {
    console.log('Fastest is ' + this.filter('fastest').map('name'));
  })
  .run({
    async: true,
  });

Adding some logs

Below, is the amount of time each part of the code takes when we call execSync:

First Execution

execSync normalizeExecArgs: 0.058121003210544586
execSync spawnSync > normalizeSpawnArguments: 0.6293980032205582
execSync spawnSync > validation: 0.06221800297498703
execSync spawnSync > sanitizeKillSignal: 0.03522700071334839
execSync spawnSync > stdio & input: 0.24450600147247314
execSync spawnSync > child_process.spawnSync: 2.081940993666649
execSync spawnSync: 3.4516379982233047
execSync inheritStderr: 0.002504996955394745
execSync checkExecSyncError: 0.08398999273777008
Total: 6.673679001629353ms

There is some lag in the first execution that I don't know what is causing, module compilation?

Second Execution

execSync normalizeExecArgs: 0.0116720050573349
execSync spawnSync > normalizeSpawnArguments: 0.2574800029397011
execSync spawnSync > validation: 0.004238002002239227
execSync spawnSync > sanitizeKillSignal: 0.001993998885154724
execSync spawnSync > stdio & input: 0.015389002859592438
execSync spawnSync > child_process.spawnSync: 1.9157060012221336
execSync spawnSync: 2.572445996105671
execSync inheritStderr: 0.0013229995965957642
execSync checkExecSyncError: 0.0015130043029785156
Total: 2.7211980000138283ms

Execute single-child-sync.js with the node compiled from h4ad-forks/node@856245f

single-child-sync.js

var command = 'echo "123"';
var childProcess = require('child_process');

var now = performance.now();
childProcess.execSync(command, { encoding: 'utf8' });
console.log(`Total: ${performance.now() - now}ms`);

now = performance.now();
childProcess.execSync(command, { encoding: 'utf8' });
console.log(`Total: ${performance.now() - now}ms`);

---

With these numbers, we could probably optimize the JS side a little bit to reach 5~10%, but I don't think we can extract much from the JS side, most likely the work will be on the C++ side.

[H4ad]

nodejs/node#48523 was merged and it improved by 53% and ~9% of spawn and spawnSync, should we close this issue?