Optimize child_process IPC for large data

[ypresto]

jsonBuffer.indexOf('\n', start) in channel.onread (internal/child_process.js) dramatically slows down when jsonBuffer is very large.
jsonBuffer does not contains linebreak before jsonBuffer += decoder.write(pool) call, so checking linebreaks in return value of decoder.write(pool) is enough to parse chunks.

This increases total bytes received in 5 secs by 2-4x in benchmark...!

I found this when developing vscode plugin which returns very large result (around 10MB):
rubyide/vscode-ruby#107
Also vscode core has workaround for this bottleneck:
microsoft/vscode#6026 (comment)

Also fixed benchmark script which only shows zero.

Checklist

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• commit message follows commit guidelines

Affected core subsystem(s)

child_process

Benchmark result

Mac OS X 10.12.2
MacBook Pro (Retina, 15-inch, Mid 2014)
2.2 GHz Intel Core i7

Before:
child_process/child-process-read-ipc.js dur=5 len=64: 7,583,464
child_process/child-process-read-ipc.js dur=5 len=256: 10,687,553
child_process/child-process-read-ipc.js dur=5 len=1024: 6,279,313
child_process/child-process-read-ipc.js dur=5 len=4096: 6,319,896
child_process/child-process-read-ipc.js dur=5 len=16384: 6,482,388
child_process/child-process-read-ipc.js dur=5 len=65536: 8,580,203
child_process/child-process-read-ipc.js dur=5 len=1048576: 13,398,807
child_process/child-process-read-ipc.js dur=5 len=16777216: 0

After:
child_process/child-process-read-ipc.js dur=5 len=64: 9,131,734
child_process/child-process-read-ipc.js dur=5 len=256: 10,502,876
child_process/child-process-read-ipc.js dur=5 len=1024: 6,272,325
child_process/child-process-read-ipc.js dur=5 len=4096: 6,195,482
child_process/child-process-read-ipc.js dur=5 len=16384: 6,505,698
child_process/child-process-read-ipc.js dur=5 len=65536: 8,513,730
child_process/child-process-read-ipc.js dur=5 len=1048576: 40,615,305
child_process/child-process-read-ipc.js dur=5 len=16777216: 30,183,113

---

When setTimeout() in benchmark is 0:
(I have no idea why this produces quite different result.)

Before:
child_process/child-process-read-ipc.js dur=5 len=64: 11,924,365
child_process/child-process-read-ipc.js dur=5 len=256: 34,004,413
child_process/child-process-read-ipc.js dur=5 len=1024: 51,082,451
child_process/child-process-read-ipc.js dur=5 len=4096: 61,968,471
child_process/child-process-read-ipc.js dur=5 len=16384: 59,297,771
child_process/child-process-read-ipc.js dur=5 len=65536: 59,533,374
child_process/child-process-read-ipc.js dur=5 len=1048576: 6,704,920
child_process/child-process-read-ipc.js dur=5 len=16777216: 0

After:
child_process/child-process-read-ipc.js dur=5 len=64: 12,209,873
child_process/child-process-read-ipc.js dur=5 len=256: 36,964,340
child_process/child-process-read-ipc.js dur=5 len=1024: 50,775,987
child_process/child-process-read-ipc.js dur=5 len=4096: 79,817,420
child_process/child-process-read-ipc.js dur=5 len=16384: 92,115,253
child_process/child-process-read-ipc.js dur=5 len=65536: 105,704,985
child_process/child-process-read-ipc.js dur=5 len=1048576: 23,256,095
child_process/child-process-read-ipc.js dur=5 len=16777216: 0

[mscdex]

forEach() is slower than a normal for loop.

[ypresto]

forEach() removed!
New performance test result:

setTimeout() is 20:
child_process/child-process-read-ipc.js dur=5 len=64: 13,380,196
child_process/child-process-read-ipc.js dur=5 len=256: 10,571,078
child_process/child-process-read-ipc.js dur=5 len=1024: 5,688,590
child_process/child-process-read-ipc.js dur=5 len=4096: 5,898,209
child_process/child-process-read-ipc.js dur=5 len=16384: 6,037,993
child_process/child-process-read-ipc.js dur=5 len=65536: 8,054,859
child_process/child-process-read-ipc.js dur=5 len=1048576: 36,042,245
child_process/child-process-read-ipc.js dur=5 len=16777216: 43,590,387

setTimeout() is 0:
child_process/child-process-read-ipc.js dur=5 len=64: 13,237,553
child_process/child-process-read-ipc.js dur=5 len=256: 38,048,327
child_process/child-process-read-ipc.js dur=5 len=1024: 54,938,211
child_process/child-process-read-ipc.js dur=5 len=4096: 83,703,421
child_process/child-process-read-ipc.js dur=5 len=16384: 89,017,635
child_process/child-process-read-ipc.js dur=5 len=65536: 101,471,791
child_process/child-process-read-ipc.js dur=5 len=1048576: 28,087,643
child_process/child-process-read-ipc.js dur=5 len=16777216: 0

[YurySolovyov]

I wonder how it performs with setImmediate or possibly other ways of queueing up callbacks

[mscdex]

I don't think the setTimeout() is a good change to the benchmark. As @YurySolovyov suggested, perhaps setImmediate() is a more suitable replacement?

[ypresto]

58f6cc0 fixes '"${msg}"' is used so actually above benchmarks uses len + 2 size message.

New benchmark result with setImmediate():

child_process/child-process-read-ipc.js dur=5 len=64: 9,758,913
child_process/child-process-read-ipc.js dur=5 len=256: 34,099,862
child_process/child-process-read-ipc.js dur=5 len=1024: 101,673,385
child_process/child-process-read-ipc.js dur=5 len=4096: 143,175,819
child_process/child-process-read-ipc.js dur=5 len=16384: 82,422,291
child_process/child-process-read-ipc.js dur=5 len=65536: 34,661,893
child_process/child-process-read-ipc.js dur=5 len=1048576: 2,096,105
child_process/child-process-read-ipc.js dur=5 len=16777216: 0

[addaleax]

Does this work? for (var … in …) iterates over the indices of the array, so it does not do the same thing as for (var i = 0; i < args.length; ++i)

[ypresto]

for (var … in …) iterates over the indices of the array

Oops... test was failing. Fixed in de82d97..!

[addaleax]

The changes in lib LGTM, can’t really speak up for the benchmark part

CI: https://ci.nodejs.org/job/node-test-commit/7051/

[MylesBorins]

Is this something we will want to backport? Should it bake a bit longer first?

[MylesBorins]

ping

[addaleax]

@MylesBorins This should be fine to backport to v6.x… I’ve cherry-picked the changes here to v6.x-staging