timers: assorted cleanup + improvements #18486

apapirovski · 2018-01-31T18:49:40Z

There a few changes in this PR, all to timers, and it's best to review each commit independently. It will make way more sense that way.

Instead of using nextTick to process failed lists, just attempt to process them again from C++ if the process is still alive. This also allows the removal of domain specific code in timers. (The current behaviour is not quite ideal as it means that all lists after the failed one will process on an arbitrary nextTick, even if they're — say — not due to fire for another 2 days...)
Pass in Timer.now() as an argument of kOnTimeout instead of always re-entering C++ to get it. Also don't constantly call Timer.now() from ontimeout, even when it isn't needed. Improves performance on our pooled benchmark by roughly 40%.
Switch to use const where appropriate.
Instead of calling stop + start from the refresh method of Timeout, instead just call start as libuv already calls stop if necessary.
When an interval takes exactly as long to run as its timeout setting, it can sometimes block the event loop if exactly 1ms elapses before start() is called. This commit fixes that.

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)

timers

apapirovski · 2018-01-31T19:00:27Z

CI: https://ci.nodejs.org/job/node-test-pull-request/12855/
CitGM: https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/1248/
Benchmark CI: https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/112/

BridgeAR

Nice!

Fishrock123

Some smaller things. I noticed that the commit descriptions are less informative than what's in your PR here, think you could update them?

Speaking of that, it's pretty nuts that removing Timer.now() has that kind of perf impact, however your PR says 40% but you commit says 80%.. which is it? :P

Oh and, could you explain 5. a bit more? I think I have a hint of what's going on there but I suspect it'd be pretty difficult to understand in any detail.

Fishrock123 · 2018-02-02T17:36:57Z

test/parallel/test-timers-unref-throw-then-ref.js

+  message: 'Timeout Error'
+}));
+
+let called = false;


common.mustCall() doesn't work here? It checks for one and only one call by default.

It can potentially cause an infinite loop since it only checks at exit and this tests the fact that calling ref on unref'd handle doesn't cause the C++ loop to continue forever.

This is related to the owner check in C++. Someone could, in the future, think to optimize that by checking whether the handle is ref or unref, instead of checking for presence of an owner, but that would actually be incorrect and would cause an infinite loop on this test.

Fishrock123 · 2018-02-02T17:41:19Z

test/sequential/test-timers-set-interval-excludes-callback-duration.js

@@ -9,9 +9,16 @@ const t = setInterval(() => {
  cntr++;
  if (cntr === 1) {
    common.busyLoop(100);
+    // ensure that the event loop passes before the second interval
+    setImmediate(() => assert.strictEqual(cntr, 1));


Should these new callbacks also have common.mustCall()?

I opted not to include since setImmediate is guaranteed to run and if it doesn't, others tests will fail.

Mmm yes but I'm not sure that's guaranteed to be true for all APIs so we do need to be careful about that path of doing things,

apapirovski · 2018-02-02T18:05:43Z

Some smaller things. I noticed that the commit descriptions are less informative than what's in your PR here, think you could update them?

Yep, no worries. Will update later today.

Speaking of that, it's pretty nuts that removing Timer.now() has that kind of perf impact, however your PR says 40% but you commit says 80%.. which is it? :P

Not sure. I got 80% on my local machine but I'm getting 40% on benchmark CI but also 10% on a couple of other tests which I didn't see locally. From doing other benchmark runs in the past, I suspect that some of our performance gains can be platform specific (for example, frequency of GC would be one consideration).

In terms of why the big jump, the function itself does very little so constantly re-entering C++ accounts for a huge part of it.

Oh and, could you explain 5. a bit more? I think I have a hint of what's going on there but I suspect it'd be pretty difficult to understand in any detail.

There was a PR recently (e647c5d#diff-0a5d4868b2b9b17cf9e2c11f1bd1311e) that fixed the case where an interval executing longer than its timeout value would block the event loop. It solved that issue for most cases except where the trip from rearm to the code here: https://github.com/apapirovski/node/blob/4746614757b8881523211c40dc200fcc2f459084/lib/timers.js#L237-L245 takes exactly 1ms to complete. Then the timeRemaining = 0 and the interval would execute on the same cycle of the event loop.

Fishrock123 · 2018-02-02T19:16:19Z

Not sure. I got 80% on my local machine but I'm getting 40% on benchmark CI but also 10% on a couple of other tests which I didn't see locally. From doing other benchmark runs in the past, I suspect that some of our performance gains can be platform specific (for example, frequency of GC would be one consideration).

Imo put down something like up to 80% improvement or 40%-80% improvement, or 40%+ improvement.

(...)

Ah yes, thanks.

Instead of using nextTick to process failed lists, just attempt to process them again from C++ if the process is still alive. This also allows the removal of domain specific code in timers. The current behaviour is not quite ideal as it means that all lists after the failed one will process on an arbitrary nextTick, even if they're — say — not due to fire for another 2 days...

Pass in Timer.now() as an argument of kOnTimeout instead of always re-entering C++ to get it. Also don't constantly call Timer.now() from ontimeout, even when it isn't needed. Improves performance on our pooled benchmark by upwards of 40%.

Instead of calling stop + start from the refresh method of Timeout, instead just call start as libuv already calls stop if necessary.

When an interval takes as long or longer to run as its timeout setting and the roundtrip from rearm() to its deferal takes exactly 1ms, that interval can then block the event loop. This is an edge case of another recently fixed bug (which in itself was an edge case). Refs: nodejs#15072

apapirovski · 2018-02-02T21:48:18Z

I've updated the commit messages with a bit more info.

apapirovski · 2018-02-04T16:05:10Z

Landed in 9b8e1c2, a986158, 71c0d03, d7894f3, and 47a984a

Instead of using nextTick to process failed lists, just attempt to process them again from C++ if the process is still alive. This also allows the removal of domain specific code in timers. The current behaviour is not quite ideal as it means that all lists after the failed one will process on an arbitrary nextTick, even if they're — say — not due to fire for another 2 days... PR-URL: #18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

Pass in Timer.now() as an argument of kOnTimeout instead of always re-entering C++ to get it. Also don't constantly call Timer.now() from ontimeout, even when it isn't needed. Improves performance on our pooled benchmark by upwards of 40%. PR-URL: #18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

PR-URL: #18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

Instead of calling stop + start from the refresh method of Timeout, instead just call start as libuv already calls stop if necessary. PR-URL: #18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

When an interval takes as long or longer to run as its timeout setting and the roundtrip from rearm() to its deferal takes exactly 1ms, that interval can then block the event loop. This is an edge case of another recently fixed bug (which in itself was an edge case). PR-URL: #18486 Refs: #15072 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

dyatlov · 2018-04-08T16:24:47Z

When it's going to be included in Node release?

Instead of using nextTick to process failed lists, just attempt to process them again from C++ if the process is still alive. This also allows the removal of domain specific code in timers. The current behaviour is not quite ideal as it means that all lists after the failed one will process on an arbitrary nextTick, even if they're — say — not due to fire for another 2 days... PR-URL: nodejs#18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

Pass in Timer.now() as an argument of kOnTimeout instead of always re-entering C++ to get it. Also don't constantly call Timer.now() from ontimeout, even when it isn't needed. Improves performance on our pooled benchmark by upwards of 40%. PR-URL: nodejs#18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

PR-URL: nodejs#18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

Instead of calling stop + start from the refresh method of Timeout, instead just call start as libuv already calls stop if necessary. PR-URL: nodejs#18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

When an interval takes as long or longer to run as its timeout setting and the roundtrip from rearm() to its deferal takes exactly 1ms, that interval can then block the event loop. This is an edge case of another recently fixed bug (which in itself was an edge case). PR-URL: nodejs#18486 Refs: nodejs#15072 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Jan 31, 2018

jasnell approved these changes Jan 31, 2018

View reviewed changes

BridgeAR approved these changes Feb 1, 2018

View reviewed changes

Fishrock123 self-requested a review February 1, 2018 18:14

Fishrock123 suggested changes Feb 2, 2018

View reviewed changes

Fishrock123 approved these changes Feb 2, 2018

View reviewed changes

apapirovski added 5 commits February 2, 2018 16:42

timers: re-enter C++ less frequently

cdf6da5

Pass in Timer.now() as an argument of kOnTimeout instead of always re-entering C++ to get it. Also don't constantly call Timer.now() from ontimeout, even when it isn't needed. Improves performance on our pooled benchmark by upwards of 40%.

timers: use const as appropriate

8c6953d

timers: use start instead of stop + start

987d96e

Instead of calling stop + start from the refresh method of Timeout, instead just call start as libuv already calls stop if necessary.

apapirovski force-pushed the patch-timers-improvements branch from 4746614 to 4dacb85 Compare February 2, 2018 21:47

apapirovski closed this Feb 4, 2018

apapirovski deleted the patch-timers-improvements branch February 4, 2018 16:05

apapirovski added a commit that referenced this pull request Feb 4, 2018

timers: use const as appropriate

71c0d03

PR-URL: #18486 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

apapirovski mentioned this pull request Apr 12, 2018

Unreferenced timer started in uncaughtException handler fires immediately if exception was thrown from inside a timer #19970

Closed

ChALkeR mentioned this pull request Aug 9, 2018

src: fix integer overflow in GetNow #22214

Closed

3 tasks

jhuckaby mentioned this pull request Aug 31, 2018

Cronicle scheduler stops working after 2^31 milliseconds (~25 days) of continuous running jhuckaby/Cronicle#108

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

timers: assorted cleanup + improvements #18486

timers: assorted cleanup + improvements #18486

apapirovski commented Jan 31, 2018 •

edited

Loading

apapirovski commented Jan 31, 2018

BridgeAR left a comment

Fishrock123 left a comment

Fishrock123 Feb 2, 2018

apapirovski Feb 2, 2018

Fishrock123 Feb 2, 2018

apapirovski Feb 2, 2018

Fishrock123 Feb 2, 2018

apapirovski commented Feb 2, 2018

Fishrock123 commented Feb 2, 2018

apapirovski commented Feb 2, 2018

apapirovski commented Feb 4, 2018

dyatlov commented Apr 8, 2018

timers: assorted cleanup + improvements #18486

timers: assorted cleanup + improvements #18486

Conversation

apapirovski commented Jan 31, 2018 • edited Loading

Checklist

Affected core subsystem(s)

apapirovski commented Jan 31, 2018

BridgeAR left a comment

Choose a reason for hiding this comment

Fishrock123 left a comment

Choose a reason for hiding this comment

Fishrock123 Feb 2, 2018

Choose a reason for hiding this comment

apapirovski Feb 2, 2018

Choose a reason for hiding this comment

Fishrock123 Feb 2, 2018

Choose a reason for hiding this comment

apapirovski Feb 2, 2018

Choose a reason for hiding this comment

Fishrock123 Feb 2, 2018

Choose a reason for hiding this comment

apapirovski commented Feb 2, 2018

Fishrock123 commented Feb 2, 2018

apapirovski commented Feb 2, 2018

apapirovski commented Feb 4, 2018

dyatlov commented Apr 8, 2018

apapirovski commented Jan 31, 2018 •

edited

Loading