Repository navigation
spawn() is not asynchronous, blocks event loop for 2-3 seconds #14917
Description
Activity
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?
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.jsvar 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 281msI 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
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_processdocs: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 longerspawn()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.Reacted by Benjamin GruenbaumThe 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.
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 callinguv_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_spawnfrom 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.
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.
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
perfyourself. 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?
Reacted by Marvin Hagemeister, Landon Abney, Oskar Risberg, Mark Armendariz, Alexander Sorokin, AntoBrajkovic, Roberto and Oleguer LlopartIt'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?"
@jorangreef I'm still interested to see the output of
perf report --stdio.- changed the title
[-]spawn() is not asynchronous[/-][+]spawn() is not asynchronous, blocks event loop for 2-3 seconds[/+]on Nov 4, 2017 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.spawnhas been a problem for us in Atom. We were making pretty heavy use ofspawnto 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.
Reacted by Jonas Gebhardt, Abraham Williams, Sindre Sorhus, AntoBrajkovic, João Moreno, Tim Pulver, Ethan Resnick and Oleguer Llopart@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.
Reacted by YuryMy 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. 👍
Reacted by Marco Scannadinari, Ivy Reese, Guangcong Luo, bruce-one, Mark Armendariz, LunNova, Eric M. Dantas, Lauri, AntoBrajkovic, Che Fisher and 11 more40 remaining items
- added 2 commits that reference this issue
on Oct 9, 2023 - added 2 commits that reference this issue
on Nov 26, 2023 FWIW the issue you linked, while I still see as invalid, would be a duplicate of this one in any case.
Yeah, that attitude is really going to take you far. @redyetidev asked you to post a reproducer without 3rd-party deps. Do that first, then we'll talk.
Reacted by Aviv Keller8 years later, I'm having the exact same issue. Why is it closed if not fixed?
Reacted by Oleguer Llopart and xavier
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:
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 spawningclamdscanwas the first draft):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:
Wrapping the spawn code above in a simple timer shows:
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?