http/net: _unrefActive() is extremely expensive

[bnoordhuis]

This probably affects master as well but I'm reporting this for v0.10. With any HTTP-heavy benchmark, exports._unrefActive() from lib/timers.js shows up high on the list of cost centers. Case in point:

1496   10.4%  LazyCompile: *exports._unrefActive timers.js:431
 607   40.6%    LazyCompile: *onread net.js:496
 579   38.7%    LazyCompile: *Socket._write net.js:619
 554   95.7%      LazyCompile: *Writable.write _stream_writable.js:163
 554  100.0%        LazyCompile: *Socket.write net.js:612

NB: That's from an application that puts together a multi-kilobyte SOAP response. That's an expensive operation but _unrefActive() still manages to dominate the list of most expensive functions.

There are two issues here, I think:

1. The efficiency of _unrefActive()'s implementation leaves much to be desired.
2. lib/net.js frequently calls _unrefActive() an ungodly number of times (for just about every I/O operation, something that really hurts with busy connections.)

I'd like to start a discussion on how to best fix that.

For 1, stripping _unrefActive() from unnecessary cruft seems like a first good step, maybe followed by switching to a timer wheel.

For 2, I'm less sure; the easiest solution I can think of (that is still provably correct and performs well) is to replace the timers._unrefActive(this) calls with something like this.nevents += 1. Then, when the timer expires:

1. Check if this.nevents > 0.
2. If true, restart the timer.
3. If false, emit the timeout event.

That should greatly reduce the frequency of the (linear) scan over the timer list.

Thoughts, @indutny and @tjfontaine and anyone else who wants to chime in?

[tjfontaine]

The linear scan of the timer list was my least favorite part of the implementation. This is definitely something I want to get fixed in 0.10 and 0.12 in perhaps something like a timer wheel.

[misterdjules]

@bnoordhuis @tjfontaine I'd like to give it a shot. I agree with your suggestions about how to approach the problem. Here's my plan:

1. Implement @bnoordhuis' suggested solution of not calling _unrefActive for every event, but instead increment a counter that is checked upon timeout. Profile this implementation with a simple test case and present the results.

2. Implement a timer wheel, profile the same test case and present the results. I've never implemented a timer wheel so it could take me some time, but at least we should have some feedback from 1) in the meantime.

3. Depending on the outcome of 1) and 2), refine our plan. Of course, if 1) proves to have a significant positive impact, I guess it could be merged without waiting for 2).

Please let me know what you think.
Please let me know if you're ok with that and I'll keep you posted ASAP.

[bnoordhuis]

@misterdjules Sounds like a good approach to me.

A quick note on the this.nevents += 1 solution that I suggested: timers._unrefActive() moves the timer Timer.now() + timer._idleTimeout milliseconds into the future (put another way, every I/O event postpones expiry by timer._idleTimeout milliseconds) so a simple event counter might not be enough to maintain the current behavior.

What should work, however, is making timers._unrefActive() store the current timestamp on the timer. Then, when the timer expires, you check if Timer.now() - timer._idleTimestamp >= timer._idleTimeout.

If true, it expired but if false, you reschedule it in timer._idleTimeout - (Timer.now() - timer._idleTimestamp) ms from now. You should probably add another field for that so you don't clobber the original timer._idleTimeout.

timer._idleTimestamp is just a suggestion for a name. timer._idleLastActive, for example, is arguably more descriptive.

As a final note, I use Timer.now() indiscriminately above but it's a fairly expensive function. Try to cache its return value as much as is feasible.

[tjfontaine]

I'm not entirely sure if a timer wheel is really necessary, I think for short term implementations you can actually just use a heap

[misterdjules]

@tjfontaine Alright, then for 2), instead of implementing a timer wheel I'll use a heap.

[chirag04]

[Off topic]

@bnoordhuis Can you tell how you came up with that list of cost centers?

[bnoordhuis]

@chirag04 Certainly. That's the output of node --prof app.js, which writes a v8.log file, post-processed with deps/v8/tools/linux-tick-processor.

The tick processor depends on the d8 binary so you need to build V8 first: cd deps/v8 && make native i18nsupport=off. May not work with the V8 from release tarballs, clone the repo in that case.

If you're using master, take note of #8088 (which was fixed only recently.) HTH.

[chirag04]

Awesome! Thanks @bnoordhuis

[misterdjules]

@bnoordhuis @tjfontaine I implemented approach 1) in misterdjules@802b4e3. It would be great if you had some time to look at it and let me know if it's in line with what we discussed.

I added a test in the tests suite that specifically tests _unrefActive, which I think is something currently missing. If and when this code is merged, I'll see if I can make this test more thorough. All tests run by make test pass, including the newly added one.

Below are the results I gathered so far. These results seem to be encouraging, but I have no experience benchmarking changes in Node.js, and I know it's easy to see what you want in benchmarks.

Any comment and suggestion would be very much appreciated, thank you!

Node.js server program used for the benchmarks

var http = require('http');
var server = http.createServer(function (req, res) {
    res.end();
})

server.listen(4242, function() {
    console.log('Server listening on port 4242...');
});

With linear scan in _unrefActive (aka "original version")

wrk results

$ wrk -t12 -c400 -d30s http://127.0.0.1:4242/
Running 30s test @ http://127.0.0.1:4242/
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    20.88ms    5.31ms  45.02ms   85.47%
    Req/Sec     1.02k   631.04     2.64k    49.92%
  360904 requests in 30.00s, 38.89MB read
  Socket errors: connect 155, read 199, write 0, timeout 2170
Requests/sec:  12030.06
Transfer/sec:      1.30MB
$ 

v8 prof's logs

ticks parent  name
  10456   34.4%  LazyCompile: *exports._unrefActive timers.js:517:32
  10275   98.3%    LazyCompile: *onread net.js:492:16

   4283   14.1%  Stub: CompareICStub {1}
   4283  100.0%    LazyCompile: *exports._unrefActive timers.js:517:32
   4215   98.4%      LazyCompile: *onread net.js:492:16

   2020    6.7%  node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
   1326   65.6%    LazyCompile: ~socketOnData _http_server.js:339:24
   1323   99.8%      LazyCompile: *emit events.js:68:44
   1322   99.9%        LazyCompile: *readableAddChunk _stream_readable.js:134:26
   1320   99.8%          LazyCompile: *onread net.js:492:16
    688   34.1%    LazyCompile: socketOnData _http_server.js:339:24
    688  100.0%      LazyCompile: *emit events.js:68:44
    688  100.0%        LazyCompile: *readableAddChunk _stream_readable.js:134:26
    688  100.0%          LazyCompile: *onread net.js:492:16

   1563    5.1%  _getpid

Without linear scan in _unrefActive (aka "optimized version")

wrk results

$ wrk -t12 -c400 -d30s http://127.0.0.1:4242/
Running 30s test @ http://127.0.0.1:4242/
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    18.82ms    2.21ms  44.87ms   79.47%
    Req/Sec     1.18k   650.91     2.25k    50.35%
  380139 requests in 30.01s, 40.97MB read
  Socket errors: connect 155, read 168, write 0, timeout 2203
Requests/sec:  12666.23
Transfer/sec:      1.36MB
$ 

v8 prof's logs

ticks parent  name
   8365   27.6%  node::Parser::Execute(v8::FunctionCallbackInfo<v8::Value> const&)
   4225   50.5%    LazyCompile: ~socketOnData _http_server.js:339:24
   4220   99.9%      LazyCompile: *emit events.js:68:44
   4220  100.0%        LazyCompile: *readableAddChunk _stream_readable.js:134:26
   4220  100.0%          LazyCompile: *onread net.js:492:16
   4095   49.0%    LazyCompile: socketOnData _http_server.js:339:24
   4095  100.0%      LazyCompile: *emit events.js:68:44
   4095  100.0%        LazyCompile: *readableAddChunk _stream_readable.js:134:26
   4095  100.0%          LazyCompile: *onread net.js:492:16

   1798    5.9%  _getpid

   1203    4.0%  LazyCompile: *emit events.js:68:44
    867   72.1%    LazyCompile: *readableAddChunk _stream_readable.js:134:26
    867  100.0%      LazyCompile: *onread net.js:492:16
    214   17.8%    LazyCompile: *resume_ _stream_readable.js:717:17
    214  100.0%      LazyCompile: ~<anonymous> _stream_readable.js:711:30
    214  100.0%        LazyCompile: _tickCallback node.js:332:27
     43    3.6%    LazyCompile: *emitReadable_ _stream_readable.js:417:23
     43  100.0%      LazyCompile: ~<anonymous> _stream_readable.js:409:32
     43  100.0%        LazyCompile: _tickCallback node.js:332:27
     30    2.5%    LazyCompile: ~finish _http_outgoing.js:504:18
     30  100.0%      LazyCompile: *afterWrite _stream_writable.js:321:20
     30  100.0%        LazyCompile: ~<anonymous> _stream_writable.js:312:32
     30  100.0%          LazyCompile: _tickCallback node.js:332:27

    801    2.6%  LazyCompile: *exports._unrefActive timers.js:555:32
    778   97.1%    LazyCompile: *onread net.js:492:16

    692    2.3%  LazyCompile: socketOnData _http_server.js:339:24
    692  100.0%    LazyCompile: *emit events.js:68:44
    692  100.0%      LazyCompile: *readableAddChunk _stream_readable.js:134:26
    692  100.0%        LazyCompile: *onread net.js:492:16

[misterdjules]

I just realized @bnoordhuis benchmark was based on v0.10. I will rebase my changes on it and post benchmarks based on v0.10 so that we can compare apples to apples.

[misterdjules]

@bnoordhuis @tjfontaine It seems mac-tick-processor and more generally d8 on branch v0.10 fails to build on MacOS X. I tried to build it on Linux and it also fails with similar build issues. I was able to fix them on Linux but when running linux-tick-processor, it segfaults and dumps core.

I was able to build and run the mac-tick-processor on v0.12. Is d8 known to build and run on the v0.10 branch?

[misterdjules]

Also, just for your information, I backported the change from v0.12 to v0.10 here: misterdjules@7d78abd.