timers: fix timeout when added in timer's callback #17203

misterdjules · 2015-04-21T02:01:32Z

When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes #9333 and #15447.

misterdjules · 2015-04-21T02:03:40Z

/cc @ilc-opensource, @obastemur, @hankduan, @joyent/node-coreteam.

indutny · 2015-04-21T07:41:07Z

lib/timers.js

  var first;
  while (first = L.peek(list)) {
+    var now = Timer.now();


Maybe we should do it only if the list was changed? I believe this will come with a performance loss for a many-timer case.

Good point, I added a _addedTimer property on timers lists to determine when a timer has been added to the list. There are other ways to do that, but this one seemed to be the more lightweight and less intrusive.

misterdjules · 2015-04-21T21:06:35Z

@indutny @trevnorris I updated the PR with your review comments. I also took the opportunity to slightly refactor the included test:

busyLoop is now in test/common.js.
More importantly, the test make sure that it covers both cases of the timers list being empty and non-empty when the timer is added after a long-running timer callback.

Please let me know what you think. Thank you!

indutny · 2015-04-21T21:58:13Z

LGTM! Thank you!

obastemur · 2015-04-22T14:04:33Z

@misterdjules I don't think this is a better way in terms of performance. This implementation calls timer.now twice instead of one.

trevnorris · 2015-04-22T15:07:44Z

@obastemur I believe this is a bug fix. If it's comparable in performance then that's fine.

indutny · 2015-04-22T15:11:12Z

@obastemur I think it calls it only once...

obastemur · 2015-04-22T15:15:20Z

@trevnorris I was comparing this to original suggested fix. This is a different implementation since it tries to call timer.now less. IMHO timer.now doesn't cost anything serious. I had made run a perf. test on a range of devices. The most scary one takes 0.001 ms on a mips32r2 board which is still nothing. Yet, this implementation calls at least +1. If there is only one timeout. It calls twice.

@indutny it calls twice. First calls before the loop and second a timeout needs to be active to be there right?

indutny · 2015-04-22T15:16:19Z

@obastemur it should not invoke now() unless new timer is added to the same bucket.

obastemur · 2015-04-22T15:23:43Z

@indutny I don't think it's very hard to test and see a basic setTimeout case.

indutny · 2015-04-22T15:25:54Z

@obastemur could you please share a test case with us?

obastemur · 2015-04-22T15:26:40Z

setTimeout(function(){ console.log("Hello!");}, 1);

indutny · 2015-04-22T15:31:09Z

@obastemur

NODE_DEBUG=timer ./node 1
timeout callback 1
now: %d
54512505
Hello!
1 list empty

As you can see debug('now %d') is invoked only once.

obastemur · 2015-04-22T16:01:01Z

@indutny My bad. After you insisting it won't. I've checked it again. Seems like the result was coming from the original fix. Somehow https://github.com/misterdjules/node/tree/8b00d748aee6c1cc3f06faea51339b74b4763d8c didn't build on the test machine and results mixed.

This one calls at least 25% less (if system wasn't busy)

Sorry for the confusion.

indutny · 2015-04-22T16:02:53Z

No problem at all, @obastemur . I have seen this too, before @misterdjules fixed the PR.

obastemur · 2015-04-22T16:44:52Z

a minor detail. I've applied this patch to JXcore to run the tests on our test environment. After this fix, test/simple/test-timers-ordering is no longer a reliable test case. It can be very hard to reproduce on a single run but I'm running the test cases on multiple devices at once and it fails as expected. (bsd, osx, debian on mips..) This doesn't mean the fix is wrong though. As expected, if the system is busy, multiple timeouts may end-up inside the same cycle which this test case fails to measure.

@misterdjules

Credit goes to @misterdjules nodejs/node-v0.x-archive#17203

misterdjules · 2015-04-22T18:37:32Z

Thank you @indutny @obastemur and @trevnorris for your feedback!

Ran the tests suite and found no regression on Windows and on UNIX.

misterdjules · 2015-04-22T18:42:58Z

@joyent/node-coreteam Added to the 0.10.39 milestone as we may want to release that with the next release.

misterdjules · 2015-04-30T01:06:44Z

@obastemur @trevnorris @indutny As I was reviewing this change one last time before landing it, I thought that its implementation could and should be simpler. This resulted in misterdjules@52c35bd that builds on top of the previous commit in the same PR.

If that looks better to you too, I'll squash both commits and land the resulting new commit.

Thank you!

misterdjules · 2015-05-07T00:30:52Z

@indutny ping, did you have some time to read my latest comment?

misterdjules · 2015-05-07T23:46:23Z

/cc @joyent/node-coreteam

saquibkhan · 2015-05-08T06:17:59Z

lib/timers.js

@@ -83,10 +83,19 @@ function listOnTimeout() {
  debug('timeout callback ' + msecs);

  var now = Timer.now();
-  debug('now: ' + now);
+  debug('now: %d', now);


debug('now: %d', now); Is using %d appropriate? or should we use %s, now can also have double value right?

@saquibkhan now is a non negative 64 bits integer number that is stored as a double if its value is larger than a V8 SMI. Plus the %d format supports non-integer numbers since it uses the function Number to convert the parameter corresponding to this format to a number.

indutny · 2015-05-08T07:16:09Z

LGTM

bootstraponline · 2015-06-04T13:14:59Z

👍

misterdjules · 2015-06-11T22:14:49Z

Still no regression on UNIX or Windows, landing.

When a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect. The reason is that the value that represents the current time is not updated between the time the original callback is called and the time the added timer is processed by timers.listOnTimeout. That leads the logic in timers.listOnTimeout to do an incorrect computation that makes the added timer fire with a timeout of scheduledTimeout + timeSpentInCallback. This change fixes that and make timers scheduled within other timers' callbacks fire as expected. Fixes nodejs#9333 and nodejs#15447.

misterdjules · 2015-06-17T18:26:13Z

@joyent/node-collaborators Squashed, finally landing in v0.10.

When a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect. The reason is that the value that represents the current time is not updated between the time the original callback is called and the time the added timer is processed by timers.listOnTimeout. That leads the logic in timers.listOnTimeout to do an incorrect computation that makes the added timer fire with a timeout of scheduledTimeout + timeSpentInCallback. This change fixes that and make timers scheduled within other timers' callbacks fire as expected. Fixes nodejs#9333 and nodejs#15447. PR: nodejs#17203 PR-URL: nodejs#17203 Reviewed-By: Fedor Indutny <[email protected]>

misterdjules · 2015-06-17T18:38:59Z

@joyent/node-collaborators Landed in d38e865, thank you @obastemur, @indutny and @trevnorris!

When a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect. The reason is that the value that represents the current time is not updated between the time the original callback is called and the time the added timer is processed by timers.listOnTimeout. That leads the logic in timers.listOnTimeout to do an incorrect computation that makes the added timer fire with a timeout of scheduledTimeout + timeSpentInCallback. This change fixes that and make timers scheduled within other timers' callbacks fire as expected. Fixes: nodejs/node-v0.x-archive#9333 Fixes: nodejs/node-v0.x-archive#15447 PR: nodejs/node-v0.x-archive#17203 PR-URL: nodejs/node-v0.x-archive#17203 Reviewed-By: Fedor Indutny <[email protected]> Conflicts: lib/timers.js test/common.js

Whenever a timer is scheduled within another timer, there are a few known issues that we are fixing: * Whenever the timer being scheduled has the same timeout value as the outer timer, the newly created timer can fire on the same tick of the event loop instead of during the next tick of the event loop * Whenever a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect This commit consists of nodejs/node-v0.x-archive#17203 and nodejs/node-v0.x-archive#25763. Fixes: nodejs/node-v0.x-archive#9333 Fixes: nodejs/node-v0.x-archive#15447 Fixes: nodejs/node-v0.x-archive#25607 Fixes: nodejs#5426 PR-URL: nodejs#3063

Whenever a timer is scheduled within another timer, there are a few known issues that we are fixing: * Whenever the timer being scheduled has the same timeout value as the outer timer, the newly created timer can fire on the same tick of the event loop instead of during the next tick of the event loop * Whenever a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect This commit consists of nodejs/node-v0.x-archive#17203 and nodejs/node-v0.x-archive#25763. Fixes: nodejs/node-v0.x-archive#9333 Fixes: nodejs/node-v0.x-archive#15447 Fixes: nodejs/node-v0.x-archive#25607 Fixes: #5426 PR-URL: #3063

When a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect. The reason is that the value that represents the current time is not updated between the time the original callback is called and the time the added timer is processed by timers.listOnTimeout. That leads the logic in timers.listOnTimeout to do an incorrect computation that makes the added timer fire with a timeout of scheduledTimeout + timeSpentInCallback. This change fixes that and make timers scheduled within other timers' callbacks fire as expected. Fixes nodejs#9333 and nodejs#15447. PR: nodejs#17203 PR-URL: nodejs#17203 Reviewed-By: Fedor Indutny <[email protected]>

misterdjules added timer in progress labels Apr 21, 2015

Nodejs-Jenkins added pr v0.10 labels Apr 21, 2015

This was referenced Apr 21, 2015

Debugger does not respect timer #9333

Closed

setTimeout can’t work well after the process is blocked #15447

Closed

misterdjules mentioned this pull request Apr 21, 2015

Debugger is incredibly slow to start up #9125

Closed

indutny reviewed Apr 21, 2015
View reviewed changes

misterdjules force-pushed the fix-issue-15447 branch from 4d34651 to 8b00d74 Compare April 21, 2015 21:01

obastemur added a commit to jxcore/jxcore that referenced this pull request Apr 22, 2015

Fixes #308

21aabda

Credit goes to @misterdjules nodejs/node-v0.x-archive#17203

misterdjules added this to the 0.10.39 milestone Apr 22, 2015

saquibkhan reviewed May 8, 2015
View reviewed changes

misterdjules force-pushed the fix-issue-15447 branch from 52c35bd to 127f653 Compare May 9, 2015 00:21

misterdjules added the P-2 label May 13, 2015

misterdjules force-pushed the fix-issue-15447 branch from 127f653 to fe78c98 Compare June 17, 2015 18:25

misterdjules closed this Jun 17, 2015

misterdjules removed the in progress label Jun 17, 2015

misterdjules mentioned this pull request Oct 1, 2015

Port from joyent/node: timers: fix timeout when added in timer's callback nodejs/node#2232

Closed

misterdjules mentioned this pull request Feb 25, 2016

setTimeout() introduces artificial delay between ticks when doing synchronous work nodejs/node#5426

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

timers: fix timeout when added in timer's callback #17203

timers: fix timeout when added in timer's callback #17203

misterdjules commented Apr 21, 2015

misterdjules commented Apr 21, 2015

indutny Apr 21, 2015

misterdjules Apr 21, 2015

misterdjules commented Apr 21, 2015

indutny commented Apr 21, 2015

obastemur commented Apr 22, 2015

trevnorris commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

misterdjules commented Apr 22, 2015

misterdjules commented Apr 22, 2015

misterdjules commented Apr 30, 2015

misterdjules commented May 7, 2015

misterdjules commented May 7, 2015

saquibkhan May 8, 2015

misterdjules May 9, 2015

indutny commented May 8, 2015

bootstraponline commented Jun 4, 2015

misterdjules commented Jun 11, 2015

misterdjules commented Jun 17, 2015

misterdjules commented Jun 17, 2015

timers: fix timeout when added in timer's callback #17203

timers: fix timeout when added in timer's callback #17203

Conversation

misterdjules commented Apr 21, 2015

misterdjules commented Apr 21, 2015

indutny Apr 21, 2015

Choose a reason for hiding this comment

misterdjules Apr 21, 2015

Choose a reason for hiding this comment

misterdjules commented Apr 21, 2015

indutny commented Apr 21, 2015

obastemur commented Apr 22, 2015

trevnorris commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

indutny commented Apr 22, 2015

obastemur commented Apr 22, 2015

misterdjules commented Apr 22, 2015

misterdjules commented Apr 22, 2015

misterdjules commented Apr 30, 2015

misterdjules commented May 7, 2015

misterdjules commented May 7, 2015

saquibkhan May 8, 2015

Choose a reason for hiding this comment

misterdjules May 9, 2015

Choose a reason for hiding this comment

indutny commented May 8, 2015

bootstraponline commented Jun 4, 2015

misterdjules commented Jun 11, 2015

misterdjules commented Jun 17, 2015

misterdjules commented Jun 17, 2015