child_process IPC is very slow, about 100-10000x slower than I expected (scales with msg size)

[avoidwork]

Hi,

I'm not sure if my expectations of using IPC are unreasonable, and if so please tell me / close this issue. I planned to use a forked child_process to do some background ops for a nwjs app, and intended to send roughly 40MB of JSON data to the forked ps, and I'd get back a pojo describing that data; I measured the timing at roughly 250-300 seconds on a maxed out 2015 macbook pro (sad face); a Worker in chromium is doing the same job in 1-2 milliseconds.

I then decided to measure the example in the documentation on my personal maxed macbook air (less ram, slower cpu, fast ssd):

// index.js
var cp = require('child_process'),
 n = cp.fork(__dirname + '/sub.js'),
 precise = require('precise'),
 timer = precise();

n.on('message', function(m) {
 timer.stop();
 console.log('PARENT got message:', m);
 console.log('Message received in', timer.diff() / 1000000, 'ms');
});

timer.start();
n.send({ hello: 'world' });

// sub.js
process.on('message', function(m) {
 console.log('CHILD got message:', m);
});

process.send({ foo: 'bar' });

// Console output:
// PARENT got message:{foo: 'bar' }
// CHILD got message:{hello: 'world' }
// Message received in 94.963261 ms

In both hardware scenarios, a simple small text message takes 90-100ms. Not writing to console saves roughly 5-10ms in the provided example.

[bnoordhuis]

The biggest reason Chromium is faster is that worker and main thread run in the same process, whereas node.js sends the message over a socket to the worker. Using shared memory has been discussed in the past but it's fraught with platform-specific perils.

The other reason is that it employs a fairly efficient binary-ish serializer/deserializer (blink::SerializedScriptValueFactory), whereas node.js uses plain JSON. We can make some strides there, although we probably end up with a ton of dependencies if we lift it from Blink wholesale. I'll look into that when I have time.

[avoidwork]

Thanks, I appreciate that! 👍

[Rush]

@bnoordhuis even with all the IPC .. do you think 100ms is reasonable? I think it shows something is terribly wrong, either with the test or with node. To be honest i have used child_process messaging a lot in some projects and I didn't notice such huge delays.

[avoidwork]

The latency manifests in multiple versions of node; I tested 0.12.x & 4.1.0 when I filed this bug. I also ran the code first in nwjs 0.11.6 which uses one of the iojs 1.5.x versions I believe.

It's consistent across machines & versions of node/io; have you timed your messages? You can take the sample test above to validate the issue, precise is just putting process.hrtime into an object to hold state.

[Rush]

Obviously your test is wrong, on several merits:

• You are including child_process start time in your test
• You are sending message from the child_process not in the message event handler but in the global scope
• By running code repeatedly, V8 optimizes it so results are getting better and better

// index.js
var cp = require('child_process');
var n = cp.fork(__dirname + '/sub.js');
var precise = require('precise');
var assert = require('assert');

function runTest() {
 var timer = precise();

 var expectingId = Math.floor(Math.random() * 1000);
 console.log('Sending', {id: expectingId});
 timer.start();
 n.send({ id: expectingId });

 n.once('message', function(m) {
 timer.stop();
 console.log('Message received in', timer.diff() / 1000000, 'ms');
 console.log('PARENT got message back:', m);
 assert(m.id == expectingId);
 setTimeout(runTest, 500);
 });
}
runTest();

// sub.js
process.on('message', function(m) {
 process.send({ id: m.id });
});

My results:

~/node-test ❯ node index.js
Sending{id: 838 }
Message received in 52.125594 ms
PARENT got message back:{id: 838 }
Sending{id: 729 }
Message received in 0.509135 ms
PARENT got message back:{id: 729 }
Sending{id: 524 }
Message received in 0.122227 ms
PARENT got message back:{id: 524 }
Sending{id: 15 }
Message received in 0.141159 ms
PARENT got message back:{id: 15 }
Sending{id: 85 }
Message received in 0.122186 ms
PARENT got message back:{id: 85 }
Sending{id: 880 }
Message received in 0.145977 ms
PARENT got message back:{id: 880 }
Sending{id: 367 }
Message received in 0.143486 ms
PARENT got message back:{id: 367 }

Sub-millisecond performance is pretty good and in my opinion this issue can be closed. I used child_process for caching stuff in a cluster environment and I know it works well.

[Rush]

Also, if you want to use it in a web-worker fashion, keep your child process alive, or have some child process pool to avoid paying for the start up time.

[avoidwork]

As I stated earlier, that is the example from the documentation. Putting process.hrtime() in front of the send is valid, I'm testing the entire thing.

You're assuming multiple messages, and that's wrong. In the browser I can / do hold a warmed up blob ready to go, that's impossible in this case 👍

mba results:

jason@avoidwork:~/Projects$ node test
Sending{id: 793 }
Message received in 85.733802 ms
PARENT got message back:{id: 793 }
Sending{id: 91 }
Message received in 0.904732 ms
PARENT got message back:{id: 91 }
Sending{id: 538 }
Message received in 0.268293 ms
PARENT got message back:{id: 538 }
Sending{id: 692 }
Message received in 0.228595 ms
PARENT got message back:{id: 692 }

[Rush]

What is wrong is your statement "child_process IPC is very slow". Also, I am not assuming anything. I have merely provided you with an example that shows that IPC performs very well, proving your statement wrong. Should you wish to start a new process every single message, it's your choice but you need to know that the cost is very high.

[avoidwork]

lol, geez buddy... seriously.

The initial message size directly impacts the start up time. that's the bug. you're nitpicking on phrasing that only seems to bother you.

[avoidwork]

For context, if the startup always took 80-100ms, I wouldn't have filed this bug, because that's consistent and I can work with it.

[Rush]

Even sending several-MBs long messages I get sub millisecond performance. IPC is super good. The start up time is something that you cannot optimize, simply because node is a big program. Don't be mad at reality. Keep a process in the background that is ready to serve your messages. Just re-work your code and you don't need to sacrifice anything but RAM.

[avoidwork]

Your last comment confirms the bug, so I don't understand any point you're trying to make. Yes the JIT has to warm up, yes there is a cold start time; I'm not arguing any of that.

• I cannot have a ps sitting around for a single message eating up 24MB of ram (heap)
• I want a fast first message but I'm willing to deal with it taking more time than a chromium worker due to the different methodology

None of this changes the ticket, or the fact that it's consistent. I fail to see how you think it's acceptable for > the latency to travel across north america, when the message isn't leaving the physical location.

What you consider 'super good' is only 'super good' in your conditions, and there's a whole world out there where your conditions are irrelevant, much like how you're dismissing my use case as irrelevant, because it's not an issue you're running into.

Simple fact: IPC takes 100x longer than a worker (we both confirmed this), and that initial response does scale linearly in time with the initial message body (the bug).