Very slow child_process.spawn stdout stream performance on macOS

[mhart]

The child_process.spawn stdout stream seems to be taking ~4x longer than other "similar" methods of I/O streaming with similarly sized data streams.

Running on Node.js v4.2.1, Mac OS X 10.11, Macbook Air 1.7GHz

As a baseline, the following program, where file is a 472MB gzip file, and stdout is set to ignore takes 6.5 secs with the gzip process using ~100% CPU:

var dataLength = 0
var time = process.hrtime()
var gzip = spawn('gzip', ['-cd', file], {stdio: ['ignore', 'ignore', 'ignore']})

if (gzip.stdout != null) {
  gzip.stdout.on('data', function(data) {
    if (!dataLength) dataLength = data.length
  })
}
gzip.on('close', function(code) {
  var diff = process.hrtime(time)
  console.log('stream took %d seconds', diff[0] + diff[1] / 1e9)
  if (dataLength) console.log('buffer length was %d', dataLength)
})

$ node spawn-bench.js
stream took 6.497701762 seconds

If I set the stdout option from ignore to pipe, it suddenly takes 27 secs, with gzip only using ~35% CPU and node using ~75%:

var dataLength = 0
var time = process.hrtime()
var gzip = spawn('gzip', ['-cd', file], {stdio: ['ignore', 'pipe', 'ignore']})

if (gzip.stdout != null) {
  gzip.stdout.on('data', function(data) {
    if (!dataLength) dataLength = data.length
  })
}
gzip.on('close', function(code) {
  var diff = process.hrtime(time)
  console.log('stream took %d seconds', diff[0] + diff[1] / 1e9)
  if (dataLength) console.log('buffer length was %d', dataLength)
})

$ node spawn-bench.js
stream took 27.406851714 seconds
buffer length was 8192

Fine, so that 4x overhead could just be standard pipe/stream overhead, but if I pipe in from stdin, there's really not much overhead at all and it finishes in 7.2 secs, with gzip using ~95% CPU and node ~30%:

var dataLength = 0
var time = process.hrtime()

process.stdin.on('data', function(data) {
  if (!dataLength) dataLength = data.length
})
process.stdin.on('end', function() {
  var diff = process.hrtime(time)
  console.log('stream took %d seconds', diff[0] + diff[1] / 1e9)
  if (dataLength) console.log('buffer length was %d', dataLength)
})

gzip -cd file.gz | node spawn-bench.js
stream took 7.2209929479999995 seconds
buffer length was 65536

Similarly, if I process the entire gzip file in node using zlib, I get relatively ok performance too, taking 9.8 secs:

var dataLength = 0
var time = process.hrtime()
fs.createReadStream(file, {highWaterMark: 32 * 1024 * 1024})
  .pipe(zlib.createGunzip({chunkSize: 32 * 1024 * 1024}))
  .on('data', function(data) {
    if (!dataLength) dataLength = data.length
  })
  .on('end', function() {
    var diff = process.hrtime(time)
    console.log('stream took %d seconds', diff[0] + diff[1] / 1e9)
    if (dataLength) console.log('buffer length was %d', dataLength)
  })

node spawn-bench.js
stream took 9.836914587 seconds
buffer length was 33554432

So one thing I suspected was the stream buffer size – you can see when spawning it's only 8k, whereas it's 64k when piping from stdin, and I had better performance upping it even further (to 32MB) when reading from the file and gzipping in node.

However, I couldn't see any way to change this with spawn, so I can't really determine if this is the cause.

Is there something else I'm missing? A 4x slowdown seems to be far greater than expected.

[mhart]

I ran with --prof and analyzed... can't really tell what's going on here.

Is this mostly IPC overhead? _openat, _mach_port_extract_member, etc?

Statistical profiling result from isolate-0x101804600-v8.log, (147497 ticks, 602 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
    602    0.4%

 [Shared libraries]:
   ticks  total  nonlib   name
    438    0.3%    0.0%  /usr/lib/system/libsystem_malloc.dylib
    373    0.3%    0.0%  /usr/lib/system/libsystem_pthread.dylib
      1    0.0%    0.0%  /usr/lib/system/libsystem_platform.dylib
      1    0.0%    0.0%  /usr/lib/system/libsystem_c.dylib

 [JavaScript]:
   ticks  total  nonlib   name
    569    0.4%    0.4%  LazyCompile: ~readableAddChunk _stream_readable.js:123:26
    487    0.3%    0.3%  LazyCompile: *emit events.js:117:44
    467    0.3%    0.3%  LazyCompile: *nextTick node.js:475:22
    464    0.3%    0.3%  Stub: LoadICTrampolineStub
    405    0.3%    0.3%  LazyCompile: *onread net.js:501:16
    322    0.2%    0.2%  LazyCompile: *_tickCallback node.js:333:27
...
 [C++]:
   ticks  total  nonlib   name
  56380   38.2%   38.4%  _openat
  44780   30.4%   30.5%  _mach_port_extract_member
  10645    7.2%    7.3%  ___rename_ext
   8456    5.7%    5.8%  _szone_free_definite_size
    907    0.6%    0.6%  __ZN2v88internal4Heap22RegisterNewArrayBufferEbPvm
...
 [GC]:
   ticks  total  nonlib   name
   6978    4.7%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
  56380   38.2%  _openat
  44780   30.4%  _mach_port_extract_member
  10645    7.2%  ___rename_ext
   8456    5.7%  _szone_free_definite_size

 [Top down (heavy) profile]:
  Note: callees occupying less than 0.1% are not shown.

  inclusive      self           name
  ticks   total  ticks   total
  56380   38.2%  56380   38.2%  _openat
  44780   30.4%  44780   30.4%  _mach_port_extract_member
  10645    7.2%  10645    7.2%  ___rename_ext
   8455    5.7%   8455    5.7%  _szone_free_definite_size
   4699    3.2%    405    0.3%  LazyCompile: *onread net.js:501:16
   3879    2.6%    566    0.4%    LazyCompile: ~readableAddChunk _stream_readable.js:123:26
    812    0.6%     92    0.1%      LazyCompile: *maybeReadMore _stream_readable.js:422:23
    582    0.4%    405    0.3%        LazyCompile: *nextTick node.js:475:22
    515    0.3%    436    0.3%      LazyCompile: *emit events.js:117:44
    452    0.3%    452    0.3%      Stub: LoadICTrampolineStub
    186    0.1%    186    0.1%      Stub: InstanceofStub
    152    0.1%     99    0.1%      LazyCompile: *howMuchToRead _stream_readable.js:211:23
    332    0.2%     69    0.0%    LazyCompile: *readableAddChunk _stream_readable.js:123:26
...

[bnoordhuis]

FWIW, I can't reproduce on OS X 10.8. The fact that the process spends nearly 40% of its time in openat() is suspicious.

[mhart]

@bnoordhuis interesting – is there something I can do to narrow this down then?

Perhaps this is an OSX-only issue, even OSX-10.11

I'll test the same setup on a Linux box in a sec

[bnoordhuis]

Maybe you can put a dtrace probe on openat() that prints the filename and the time spent inside the system call? As root:

$ dtrace -q \
-n 'syscall::openat_nocancel:entry /pid == $target/ { self->timestamp = timestamp; self->path = copyinstr(arg1); }' \
-n 'syscall::openat_nocancel:return /pid == $target/ { printf("%d %s\n", timestamp - self->timestamp, self->path) }' \
-c 'node test.js`

I'm just guessing at the name of the openat probe, 10.8 doesn't have that system call. dtrace -l | grep -w syscall prints the available probes.

[mhart]

Well, that appears to be the correct syscall afaict:

$ sudo dtrace -l | grep -w syscall | grep openat
 1076    syscall                                              openat entry
 1077    syscall                                              openat return
 1078    syscall                                     openat_nocancel entry
 1079    syscall                                     openat_nocancel return

But running the command you gave gives me no (extra) output. If I remove the -q I get:

$ sudo dtrace -n 'syscall::openat_nocancel:entry /pid == $target/ { self->timestamp = timestamp; self->path = copyinstr(arg1); }' -n 'syscall::openat_nocancel:return /pid == $target/ { printf("%d %s\n", timestamp - self->timestamp, self->path) }' -c 'node spawn-bench.js'

dtrace: description 'syscall::openat_nocancel:entry ' matched 1 probe
dtrace: description 'syscall::openat_nocancel:return ' matched 1 probe
stream took 25.471454835 seconds
buffer length was 8192
dtrace: pid 56635 has exited

(should I be looking somewhere else for the dtrace output?)

I was using https://github.com/sidorares/node-tick to process the results of --prof – running it using node-tick-processor --mac – just in case there's the possibility that it's resolving the wrong syscalls? There were no errors/warnings though.

[mhart]

Oh, and replacing openat_nocancel with openat in the dtrace command had no effect either.

[bnoordhuis]

Can you use tools/v8-prof/tick-processor.js? The format of the log file is pretty closely tied to the version of V8. If the tick processor and the log file don't match up, you can get bogus results.

@sidorares Don't know if node-tick already does that but newer versions of V8 start the log with a v8-version marker that you can use to print a warning when the tick processor doesn't match. Feel free to steal the logic from here.

[mhart]

@bnoordhuis I kinda remember a similar discussion happening here 😄 sidorares/node-tick#10 (comment)

[mhart]

Same (similar) result with tools/v8-prof/tick-processor.js. I had deleted the old profile, but generating a new one is quite similar, largely made up by _mach_port_extract_member, _openat, ___rename_ext and _free:

$ node tools/v8-prof/tick-processor.js ../isolate-0x102800000-v8.log
Statistical profiling result from ../isolate-0x102800000-v8.log, (19119 ticks, 43 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     79    0.4%          /usr/lib/system/libsystem_malloc.dylib
     50    0.3%          /usr/lib/system/libsystem_pthread.dylib

 [JavaScript]:
   ticks  total  nonlib   name
     82    0.4%    0.4%  Stub: LoadICTrampolineStub
     66    0.3%    0.3%  LazyCompile: *nextTick node.js:475:22
     61    0.3%    0.3%  LazyCompile: *onread net.js:501:16
     55    0.3%    0.3%  LazyCompile: *emit events.js:117:44
     45    0.2%    0.2%  LazyCompile: *Readable.read _stream_readable.js:250:35
     44    0.2%    0.2%  LazyCompile: *_tickCallback node.js:333:27
     27    0.1%    0.1%  Stub: InstanceofStub
...

 [C++]:
   ticks  total  nonlib   name
   6310   33.0%   33.2%  _mach_port_extract_member
   5364   28.1%   28.2%  _openat
   2030   10.6%   10.7%  ___rename_ext
   1308    6.8%    6.9%  _free
    203    1.1%    1.1%  _malloc_zone_valloc
    187    1.0%    1.0%  _malloc_zone_malloc
    146    0.8%    0.8%  v8::internal::Heap::RegisterNewArrayBuffer(bool, void*, unsigned long)
     86    0.4%    0.5%  v8::Context::Enter()
     86    0.4%    0.5%  _uv__io_poll
...

 [Summary]:
   ticks  total  nonlib   name
    800    4.2%    4.2%  JavaScript
  18147   94.9%   95.6%  C++
   1109    5.8%    5.8%  GC
    129    0.7%          Shared libraries
     43    0.2%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
     27   25.0%    0.1%  v8::internal::Builtins::~Builtins()
     18   16.7%    0.1%  v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
     10    9.3%    0.1%  v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*)
      9    8.3%    0.0%  v8::internal::Runtime_Interrupt(int, v8::internal::Object**, v8::internal::Isolate*)
      8    7.4%    0.0%  v8::internal::StoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      8    7.4%    0.0%  v8::internal::LoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      7    6.5%    0.0%  v8::internal::Runtime_CompileOptimized(int, v8::internal::Object**, v8::internal::Isolate*)
      4    3.7%    0.0%  v8::internal::KeyedStoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      3    2.8%    0.0%  v8::Isolate::RunMicrotasks()
      2    1.9%    0.0%  v8::internal::ToBooleanIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      2    1.9%    0.0%  v8::internal::KeyedLoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
...

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
   6310   33.0%  _mach_port_extract_member
   5364   28.1%  _openat
   2030   10.6%  ___rename_ext
   1308    6.8%  _free

[mhart]

@bnoordhuis is there a way you know of to increase the buffer size for spawn stdio streams/pipes?

[evanlucas]

In an attempt to see all of the syscalls made here, I ran dtruss -c -f node <file> and it seems like when stdio is set to ['pipe', 'pipe', 'pipe'], madvise is called significantly more.

With pipe, it was called 24418 times, compared to ignore, 66 times.

[bnoordhuis]

Working hypothesis: the openat and __rename_ext calls (maybe mach_port_extract_member too) are caused by V8 logging to disk.

@mhart Can you try the dtrace command again while passing --prof to node this time?

[mhart]

FWIW, I tested with 0.12.7 and 0.10.40 on the same machine – I do get slightly better results – still at least 2x slower than reading from stdin though. Would love to up the buffer sizes to see if that helps.

nave use 0.12.7 node spawn-bench.js
Already installed: 0.12.7
using 0.12.7
stream took 19.746245263 seconds
buffer length was 8192

$ nave use 0.10.40 node spawn-bench.js
Already installed: 0.10.40
using 0.10.40
stream took 15.013791288 seconds
buffer length was 8192

@bnoordhuis will try that dtrace command now

[mhart]

No difference in the dtrace output using --prof – FWIW there's no difference in execution time either – bizarrely it seems that passing --prof even reduces the time by a few seconds...!? Small sample size I know, but it seems pretty consistent.

$ node spawn-bench.js
stream took 26.928994887 seconds
buffer length was 8192
$ node --prof spawn-bench.js
stream took 22.790958391 seconds
buffer length was 8192
$ node spawn-bench.js
stream took 25.437598346 seconds
buffer length was 8192
$ node --prof spawn-bench.js
stream took 22.1429554 seconds
buffer length was 8192
$ node spawn-bench.js
stream took 25.366320914 seconds
buffer length was 8192
$ node --prof spawn-bench.js
stream took 22.147164474 seconds
buffer length was 8192