spawn() is not asynchronous, blocks event loop for 2-3 seconds

[jorangreef]

• Version: v8.2.1
• Platform: Linux ronomon.com 3.13.0-106-generic [stream] - callback based API additions #153-Ubuntu SMP Tue Dec 6 15:44:32 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: child_process

spawn() is not asynchronous while launching a child process.

I think this is a known issue but it took a few months to track down.

Our event loop was blocking frequently:

2017-08-18T12:18:03.935Z INFO Event loop blocked for 258ms.
2017-08-18T12:18:17.200Z INFO Event loop blocked for 223ms.
2017-08-18T12:18:45.417Z INFO Event loop blocked for 288ms.
2017-08-18T12:19:11.981Z INFO Event loop blocked for 296ms.
2017-08-18T12:19:39.142Z INFO Event loop blocked for 282ms.
2017-08-18T12:19:43.750Z INFO Event loop blocked for 329ms.
2017-08-18T12:19:48.655Z INFO Event loop blocked for 247ms.
2017-08-18T12:19:55.191Z INFO Event loop blocked for 266ms.
2017-08-18T12:20:52.000Z INFO Event loop blocked for 269ms.
2017-08-18T12:21:18.157Z INFO Event loop blocked for 294ms.
2017-08-18T12:21:20.388Z INFO Event loop blocked for 272ms.
2017-08-18T12:21:31.557Z INFO Event loop blocked for 276ms.
2017-08-18T12:21:32.529Z INFO Event loop blocked for 320ms.
2017-08-18T12:21:36.400Z INFO Event loop blocked for 307ms.

The system has many components and the RSS is around 14 GB. We had had issues with GC pause times so we moved everything off-heap and reduced the number of pointers. We may still have issues with GC pause times, but I thought it might also be something else.

In addition, over time, the majority of components were rewritten to run in the threadpool.

I thought it was finally down to deduplication chunking and hashing, but when this was recently moved to the threadpool, I took another look at a spawn routine which was calling out to clamdscan (moving to a socket protocol was the long term plan but spawning clamdscan was the first draft):

var stdout = '';
var stderr = '';
var child = Node.child.spawn('clamdscan', ['-']);
child.stdin.on('error', function(error) {}); // Fix ECONNRESET bug with Node.
child.stdin.write(buffer);
child.stdin.end();
child.stdout.on('data', function(data) { stdout += data; });
child.stderr.on('data', function(data) { stderr += data; });
child.on('error',
  function(error) {
    end(undefined, false, '', '');
  }
);
child.on('exit',
  function(code) {
    end(undefined, code === 1, stdout, stderr);
  }
);

I came across nodejs/node-v0.x-archive#9250 today and https://github.com/davepacheco/node-spawn-async seems to explain it in terms of the large heap or RSS size:

While workloads that make excessive use of fork(2) are hardly high-performance to begin with, the behavior of blocking the main thread for hundreds of milliseconds each time is unnecessarily pathological for otherwise reasonable workloads.

Wrapping the spawn code above in a simple timer shows:

2017-08-18T12:18:03.935Z INFO MDA: Blocking: scan: 271ms
2017-08-18T12:18:17.196Z INFO MDA: Blocking: scan: 263ms
2017-08-18T12:18:45.417Z INFO MDA: Blocking: scan: 296ms
2017-08-18T12:19:11.980Z INFO MDA: Blocking: scan: 293ms
2017-08-18T12:19:39.142Z INFO MDA: Blocking: scan: 306ms
2017-08-18T12:19:43.750Z INFO MDA: Blocking: scan: 293ms
2017-08-18T12:19:48.655Z INFO MDA: Blocking: scan: 276ms
2017-08-18T12:19:55.191Z INFO MDA: Blocking: scan: 299ms
2017-08-18T12:20:52.000Z INFO MDA: Blocking: scan: 277ms
2017-08-18T12:21:18.156Z INFO MDA: Blocking: scan: 294ms
2017-08-18T12:21:20.388Z INFO MDA: Blocking: scan: 292ms
2017-08-18T12:21:31.557Z INFO MDA: Blocking: scan: 290ms
2017-08-18T12:21:32.529Z INFO MDA: Blocking: scan: 318ms
2017-08-18T12:21:36.400Z INFO MDA: Blocking: scan: 315ms

All correlated with the event loop blocks reported above.

I understand that spawn is not meant to be called every few seconds, but I never expected average latency of 300ms?

Is there any way to improve spawn along the lines of what Dave Pacheco has done?

Or at least to document that spawn() will block the event loop for around 300ms depending on heap size?

[bnoordhuis]

Some sleuthing with perf(1) should tell you where the time is spent. I have a few hunches but why guess when you can know for sure, right?

[jorangreef]

Some sleuthing with perf(1) should tell you where the time is spent. I have a few hunches but why guess when you can know for sure, right?

Thanks Ben.

Here's a script to reproduce. Would you try your perf magic on it to see what you see?

It grows the heap every 2 seconds by 256 mb and then spawns echo hello. You should see pause times increasing as RSS increases beyond a few GB.

node --max-old-space-size=32768 spawn.js

var child = require('child_process');
var rss = [];

function alloc() {
  var buffer = Buffer.alloc(256 * 1024 * 1024);
  var index = 0;
  var length = buffer.length;
  while (index < length) {
    buffer[index] = index & 255;
    index += 4096;
  }
  rss.push(buffer);
  process.stdout.write('RSS=' + process.memoryUsage().rss + ': ');
}

function spawn() {
  var now = Date.now();
  var stdout = '';
  var stderr = '';
  var instance = child.spawn('echo', ['hello']);
  instance.stdin.on('error', function(error) {});
  instance.stdin.end();
  instance.stdout.on('data', function(data) { stdout += data; });
  instance.stderr.on('data', function(data) { stderr += data; });
  instance.on('error', function(error) { console.error(error); });
  instance.on('exit', function() {});
  process.stdout.write(
    'spawn() blocked event loop for ' + (Date.now() - now) + 'ms\n'
  );
}

setInterval(
  function() {
    alloc();
    spawn();
  },
  2000
);

I get the following:

RSS=284983296: spawn() blocked event loop for 25ms
RSS=553795584: spawn() blocked event loop for 14ms
RSS=822267904: spawn() blocked event loop for 19ms
RSS=1091592192: spawn() blocked event loop for 22ms
RSS=1359175680: spawn() blocked event loop for 25ms
RSS=1626419200: spawn() blocked event loop for 32ms
RSS=1895088128: spawn() blocked event loop for 35ms
RSS=2163490816: spawn() blocked event loop for 36ms
RSS=2432102400: spawn() blocked event loop for 36ms
RSS=2700414976: spawn() blocked event loop for 42ms
RSS=2968948736: spawn() blocked event loop for 47ms
RSS=3237343232: spawn() blocked event loop for 48ms
RSS=3505799168: spawn() blocked event loop for 49ms
RSS=3774234624: spawn() blocked event loop for 58ms
RSS=4042723328: spawn() blocked event loop for 60ms
RSS=4311146496: spawn() blocked event loop for 59ms
RSS=4579643392: spawn() blocked event loop for 67ms
RSS=4848050176: spawn() blocked event loop for 70ms
RSS=5116522496: spawn() blocked event loop for 71ms
RSS=5385150464: spawn() blocked event loop for 75ms
RSS=5653585920: spawn() blocked event loop for 80ms
RSS=5922144256: spawn() blocked event loop for 79ms
RSS=6190612480: spawn() blocked event loop for 82ms
RSS=6459039744: spawn() blocked event loop for 90ms
RSS=6727450624: spawn() blocked event loop for 92ms
RSS=6995865600: spawn() blocked event loop for 96ms
RSS=7264325632: spawn() blocked event loop for 97ms
RSS=7532867584: spawn() blocked event loop for 102ms
RSS=7801253888: spawn() blocked event loop for 108ms
RSS=8069656576: spawn() blocked event loop for 110ms
RSS=8338120704: spawn() blocked event loop for 108ms
RSS=8606556160: spawn() blocked event loop for 116ms
RSS=8874950656: spawn() blocked event loop for 118ms
RSS=9143349248: spawn() blocked event loop for 120ms
RSS=9411850240: spawn() blocked event loop for 123ms
RSS=9680269312: spawn() blocked event loop for 124ms
RSS=9948717056: spawn() blocked event loop for 130ms
RSS=10217205760: spawn() blocked event loop for 131ms
RSS=10485600256: spawn() blocked event loop for 139ms
RSS=10754035712: spawn() blocked event loop for 143ms
RSS=11022508032: spawn() blocked event loop for 145ms
RSS=11290894336: spawn() blocked event loop for 147ms
RSS=11559350272: spawn() blocked event loop for 150ms
RSS=11827826688: spawn() blocked event loop for 155ms
RSS=12096196608: spawn() blocked event loop for 161ms
RSS=12364754944: spawn() blocked event loop for 158ms
RSS=12633448448: spawn() blocked event loop for 165ms
RSS=12901801984: spawn() blocked event loop for 169ms
RSS=13170253824: spawn() blocked event loop for 172ms
RSS=13438726144: spawn() blocked event loop for 172ms
RSS=13707096064: spawn() blocked event loop for 175ms
RSS=13975621632: spawn() blocked event loop for 178ms
RSS=14243762176: spawn() blocked event loop for 188ms
RSS=14512508928: spawn() blocked event loop for 188ms
RSS=14780751872: spawn() blocked event loop for 193ms
RSS=15049326592: spawn() blocked event loop for 193ms
RSS=15317659648: spawn() blocked event loop for 197ms
RSS=15586279424: spawn() blocked event loop for 199ms
RSS=15854604288: spawn() blocked event loop for 202ms
RSS=16121454592: spawn() blocked event loop for 2501ms
RSS=16034512896: spawn() blocked event loop for 3156ms
RSS=16088698880: spawn() blocked event loop for 684ms
RSS=16056156160: spawn() blocked event loop for 1745ms
RSS=16123555840: spawn() blocked event loop for 494ms
RSS=16005734400: spawn() blocked event loop for 547ms
RSS=16055742464: spawn() blocked event loop for 1253ms
RSS=16117850112: spawn() blocked event loop for 632ms
RSS=16047591424: spawn() blocked event loop for 1752ms
RSS=16092176384: spawn() blocked event loop for 2044ms
RSS=16003870720: spawn() blocked event loop for 422ms
RSS=16033472512: spawn() blocked event loop for 365ms
RSS=15988920320: spawn() blocked event loop for 716ms
RSS=15989665792: spawn() blocked event loop for 463ms
RSS=16040112128: spawn() blocked event loop for 657ms
RSS=16017305600: spawn() blocked event loop for 1441ms
RSS=15969497088: spawn() blocked event loop for 519ms
RSS=15969656832: spawn() blocked event loop for 828ms
RSS=16012042240: spawn() blocked event loop for 281ms

I think this is the explanation but perhaps there's a better:

forking a Node server with a large heap just to exec some other program causes a significant amount of additional swap to be used

[jorangreef]

We removed the offending spawn() call, replacing it with a unix domain socket write last week.

The problem is down to http://docs.libuv.org/en/v1.x/process.html#c.uv_spawn being run in the main event loop thread, and not in the thread pool. Forking a new process causes the RSS of the parent process to be copied. As RSS increases, spawn time increases.

Anyone familiar with uv_spawn() interested in fixing this?

In the meantime, I'm willing to open a PR to add a warning to the child_process docs:

spawn() is not truly asynchronous and will block the event loop while launching a child process. The larger the RSS of the parent process, the longer spawn() will block. For resident set sizes of 200 MB, spawn() will block for +/-20ms. For resident set sizes of 20 GB, spawn() will block for between 200ms and 2 seconds. See #14917 for more information.

[bnoordhuis]

The problem is down to http://docs.libuv.org/en/v1.x/process.html#c.uv_spawn being run in the main event loop thread, and not in the thread pool. Forking a new process causes the RSS of the parent process to be copied. As RSS increases, spawn time increases.

That depends. Linux preforks the working set (to reduce page faults afterwards) but platforms that do simple copy-on-write profit from synchronicity because they only copy a few pages of stack.

In fact, such platforms would be penalized when thread A forks just when thread B is collecting garbage and touching all pages.

[jorangreef]

Blocking the event loop for upwards of 2-3 seconds whenever spawn() is called for RSS of 16 GB is something I think needs to be addressed. Node should not be calling uv_spawn() from the main event loop thread in the first place. It's not a breaking change for Node, since it does not affect the interface in any way. It might be a pain to fix but it should be fixed properly.

There must be plenty of people affected by this issue who are yet to realize where all their throughput is disappearing to.

Linux preforks the working set (to reduce page faults afterwards) but platforms that do simple copy-on-write profit from synchronicity because they only copy a few pages of stack.

It's good to know the problem is limited to Linux but Linux is a major platform for Node. If anyone is running Node servers with large RSS they are probably doing that on Linux. Surely calling uv_spawn from another thread will solve the problem for Linux?

In fact, such platforms would be penalized when thread A forks just when thread B is collecting garbage and touching all pages.

I'm not sure about that. GC is free to touch all pages in any event, regardless of whether fork is called from the main event loop thread or from a background thread.

[bnoordhuis]

Blocking the event loop for upwards of 2-3 seconds whenever spawn() is called for RSS of 16 GB is something I think needs to be addressed.

You are the first to bring it up, to my knowledge, so it can't be that prevalent. What's more, I don't think your particular use case would benefit from threading so much as it would from marking everything but a few pages madvise(MADV_DONTFORK). That's something you can test by tweaking libuv.

That said, have you verified with perf that the fork() or clone() system call is the actual cost center?

GC is free to touch all pages in any event, regardless of whether fork is called from the main event loop thread or from a background thread.

I think you misunderstand. The fact that uv_spawn() does not return until the fork calls execve() means there is never a concurrent compacting GC (except concurrent marking, but that's limited in scope and frequency.)

No GC is good because otherwise the parent incurs a page fault for every page it mutates until the execve() call. That's easily tens or even hundreds of thousands of page faults.

It's not a hypothetical. uv_spawn() initially didn't wait for the fork to complete. When I changed that, it had the pleasant side effect of improving a number of benchmarks, sometimes dramatically so.

[jorangreef]

You are the first to bring it up, to my knowledge, so it can't be that prevalent.

It took a few months to track down. My point was actually that most people wouldn't think that Node's async spawn() would block the event loop for 2-3 seconds every call. It's not productive to argue that 16 GB RSS is "not normal" - if it's not "normal" it will be.

I'm not in fact the first to bring it up. @davepacheco ran into this issue at Joyent in production (https://github.com/davepacheco/node-spawn-async). Notwithstanding, whether it's prevalent is irrelevant. It should be fixed without regard to whether people happen to know it's broken or not.

What's more, I don't think your particular use case would benefit from threading so much as it would from marking everything but a few pages madvise(MADV_DONTFORK)

Sure, that would also work, but we just stopped using Node's spawn() altogether now.

That said, have you verified with perf that the fork() or clone() system call is the actual cost center?

See the script to reproduce here #14917 (comment). You are welcome to verify with perf yourself. You might spot something I've missed.

I think you misunderstand. The fact that uv_spawn() does not return until the fork calls execve() means there is never a concurrent compacting GC (except concurrent marking, but that's limited in scope and frequency.)

It's not a hypothetical. uv_spawn() initially didn't wait for the fork to complete. When I changed that, it had the pleasant side effect of improving a number of benchmarks, sometimes dramatically so.

Thanks for expanding. The current design is very tightly coupled to the GC.

At present, if I understand correctly, the story is that uv_spawn() was moved into the event loop to block the event loop intentionally and thereby keep the compacting GC from running while a fork is in progress?

Why not just keep the event loop running, run the fork in another thread and use another method to keep the compacting GC from running while a fork is in progress? Just pause the compacting GC?

[bnoordhuis]

It's not productive to argue that 16 GB RSS is "not normal" - if it's not "normal" it will be.

My point is that the number of bug reports is proportional to the number of affected users. We haven't received many bug reports so there likely aren't many affected users.

Notwithstanding, whether it's prevalent is irrelevant. It should be fixed without regard to whether people happen to know it's broken or not.

Issues are prioritized based on their impact. This is not a clear "always wrong" bug, it's suboptimal behavior under specific conditions.

In fact, it's not even clear if there is a way of addressing this without regressing the common case.

See the script to reproduce here #14917 (comment). You are welcome to verify with perf yourself.

The reason I ask you to is that there may be something particular to your setup (kernel, configuration, something else.) perf should be able to capture that.

At present, if I understand correctly, the story is that uv_spawn() was moved into the event loop to block the event loop intentionally and thereby keep the compacting GC from running while a fork is in progress?

No, hence "side effect" (although one I half expected when I made the change.)

Why not just keep the event loop running, run the fork in another thread and use another method to keep the compacting GC from running while a fork is in progress? Just pause the compacting GC?

You can't. It's like saying "why don't you stop breathing while you're under water?"

[bnoordhuis]

@jorangreef I'm still interested to see the output of perf report --stdio.

[nathansobo]

I don't understand the details of process spawning as well as I'd like, but I thought it might be helpful to report that the synchronous nature of child_process.spawn has been a problem for us in Atom. We were making pretty heavy use of spawn to run Git commands in the background, and eventually tracked it down as the source of intermittent pauses that were harming the responsiveness of the application.

As a solution, we moved all Git spawning to a separate Electron process. Since that eats way more memory than we'd like, I'm tinkering with a native spawn server that will serve a similar role to the server in node-spawn-async, but with a lighter memory footprint.

Before proceeding though, I thought I'd check my understanding.

No GC is good because otherwise the parent incurs a page fault for every page it mutates until the execve() call. That's easily tens or even hundreds of thousands of page faults.

It's not a hypothetical. uv_spawn() initially didn't wait for the fork to complete. When I changed that, it had the pleasant side effect of improving a number of benchmarks, sometimes dramatically so.

This makes sense to me, but I'm not clear on the consequences of excessive page faults. If we built a native module that performed the spawn off the main thread would we be just treading into the same issues you fixed by moving it there to begin with? Would this still lead to poor responsiveness? Basically, is direct spawning from a Node process always a bad idea? That's my intuition based on this thread, but I wanted to check. How do other garbage-collected languages deal with spawning? Do they all suffer from this same pitfall? Are there platform-specific tools for spawning that could avoid forking?

Apologies if these are somewhat naive questions. The answer may be that I just need to go spend more time researching, but I thought other people might have similar questions.

[bnoordhuis]

@nathansobo No problem, happy to answer. The thread and later the fork still share memory with the parent until execve so yes, you'd have the same issue.

A Linux-only solution might be to call clone(2) with the right set of flags to create a thread or fork with unshared memory that spawns the new process, although it's probably not exactly trivial to combine with the other setup that uv_spawn() does.

If you have time to test something: see this comment in libuv's sources; I'd be interested to know if disabling the pipe impacts Electron positively or negatively.

[tim-kos]

My point is that the number of bug reports is proportional to the number of affected users. We haven't received many bug reports so there likely aren't many affected users.

Disagreed here. We have had unexplainable event loop blocks for years. The reason why we didn't file a bug report was that:

a) The problem was not big enough for us to worry about (RSS sizes not high enough).
b) With blocked event loops one first analyzes his own code in an out before assuming it might be an issue in node itself.

Point is: For most other problems I'd agree with your thesis. But this one is different.

I was really happy to find this issue. 👍