timers: fix processing of nested same delay timers #3063

whitlockjc · 2015-09-25T17:01:14Z

This is a port of https://github.com/nodejs/nodejs/node-v0.x-archive/pull/17203 and nodejs/node-v0.x-archive#25763 which fixes nodejs/node-v0.x-archive#9333, nodejs/node-v0.x-archive#15447, nodejs/node-v0.x-archive#25607 and #5426.

/cc @Fishrock123, @misterdjules, @nodejs/collaborators and @nodejs/tsc

mscdex · 2015-09-25T18:14:05Z

test/common.js

@@ -445,3 +446,11 @@ exports.fileExists = function(pathname) {
    return false;
  }
 };
+
+exports.busyLoop = function busyLoop(time) {


Why add this for just one test?

Good question. :) I'm glad to remove it until others need something similar. My only worry is removing it means people will probably write their own stuff not knowing that we have a common need for a busy loop. Your call.

Yes, if you could move it to a function in the bottom of the test file that would be better for now.

Edit, maybe don't pending #2232

Just let me know.

yeah this should go into the test itself imo

If this PR is still up for consideration, I'll update this. I'm not sure where it stands so I defer to your judgement.

Seems like there is an actual bug here, so yeas, please update it. :)

Will do. Thanks for your help.

mscdex · 2015-09-25T18:15:15Z

/cc @bnoordhuis @trevnorris ?

Fishrock123 · 2015-09-26T00:59:34Z

Does #2232 need to land first, or does this incorporate that?

Can we just port the test maybe? We should probably preserve julien's commit though.

whitlockjc · 2015-09-28T15:15:57Z

@misterdjules should comment. Last I talked to Julien I was asked to port this over but if there is already work to port things and this is superfluous, no big deal to me. Just let me know how I can help.

misterdjules · 2015-09-30T23:22:13Z

test/timers/test-timers-nested.js

+    common.busyLoop(delay);
+
+    process.nextTick(function() {
+      assert.ok(!nestedCalled);


I'd suggest adding a comment that this assert is done within a nextTick callback so that it runs after A completed, but before the next turn of libuv's event loop. Otherwise it's not clear for anyone but who wrote the code why it's done this way.

misterdjules · 2015-10-01T00:02:59Z

This PR fixes one issue with #2232 by basically refactoring it, so most of the changes in #2232 are superseded by this PR. However, we need test/parallel/test-timers-blocking-callback.js and another one line change from #2232.

whitlockjc · 2015-10-01T16:17:40Z

I have made the changes @misterdjules requested and the PR is updated with those changes. Let me know if there is more to be done and thanks for your help.

misterdjules · 2015-11-27T18:37:00Z

@whitlockjc

However, we need test/parallel/test-timers-blocking-callback.js and another one line change from #2232.

I don't see these changes in this PR, do you have some time to update this PR with these changes? Then we'll close github.com//pull/2232 in favor of this one.

whitlockjc · 2015-11-27T22:35:21Z

Sure thing. I am mobile right now but when I get back to the laptop, I will update this PR with those changes and resolve conflicts.

whitlockjc · 2015-11-30T17:19:34Z

I'll take care of this today. I didn't manage to get laptop time over the holiday.

Fishrock123 · 2015-11-30T17:25:10Z

lib/timers.js

+    //
+    // We want to make sure that newly added timer fires in the next turn of the
+    // event loop at the earliest. So even if it's already expired now,
+    // reschedule it to fire later.


I'm not sure this is actually a bug. Shouldn't the timer be scheduled in setImmediate() if you want to guarantee this?

Also, how does this not only apply to 0ms timeout timers?

setTimeout(function foo() { setTimeout(function bar() {}, 500) }, 500);

In this example, the 2nd timeout should be caught by https://github.com/nodejs/node/blob/master/lib/timers.js#L68

I'm not sure this is actually a bug.

It is indeed a grey area. However, this is how node v4.x and later behaves now. It is also how node v0.10.x and v0.12.x used to behave before nodejs/node-v0.x-archive@d38e865, which is a regression that is fixed by nodejs/node-v0.x-archive#25763.

Shouldn't the timer be scheduled in setImmediate() if you want to guarantee this?

Scheduling the timer with setImmediate would basically make it not a timer anymore, as immediates are scheduled and ran in a completely different way.

Also, how does this not only apply to 0ms timeout timers?

setTimeout(function foo() { setTimeout(function bar() {}, 500) }, 500);

The comment in this PR should be clearer and mention that it happens with non-0 delay timers if the callback of the outer timer blocks the JS thread for a duration that is greater or equal to the timer delay. So the snippet should be:

setTimeout(function foo() { setTimeout(function bar() {}, 500); codeThatBlocksFor500ms(); }, 500);

In this example, the 2nd timeout should be caught by https://github.com/nodejs/node/blob/master/lib/timers.js#L68

Except that then we'd hit the bug fixed by nodejs/node-v0.x-archive@d38e865.

That bug does not have a big impact for timers with short delays, but it can be a problem for timers with large delays that are scheduled before code that blocks for a long time, as it can make the timer fire with a delay of originalDelay + timeSpentBlockingInOutterTimer.

Fishrock123 · 2015-11-30T17:28:51Z

Sorry, after figuring out how timers work fully for #4007 I'm not convinced this is the correct behavior, or necessary?

whitlockjc · 2015-11-30T17:35:40Z

Have we ran test-timers-blocking-callback.js and test-timers-nested.js as added/changed by this PR and #2232 to see if these tests run successfully and non-flaky? As for deciding whether this is necessary or not, I defer to @misterdjules as these issues were originally reported by him and initial fixes were by him as well. I know that when the work was done, there was definitely an issue with timers and this PR reproduced the issue with its tests and fixed the issue with its changes. In the meantime, I'll go look at #4007 to get acquainted with the new approach.

Fishrock123 · 2015-11-30T17:37:02Z

I think the included test isn't actually valid, so it doesn't really matter if it is flaky or not. :s

whitlockjc · 2015-11-30T17:37:47Z

It seemed to work with the original sources. ;) I guess that doesn't matter now.

Fishrock123 · 2015-11-30T17:39:26Z

@whitlockjc I think you may be misunderstanding. It may work but that doesn't mean it is correct. :/

Fishrock123 · 2015-11-30T17:43:35Z

Is this PR just trying to make sure the callback is always Async per-se?

whitlockjc · 2015-11-30T17:44:29Z

Seeing as I'm not always right and I love to learn, I'd love to hear more about why it's not correct. At the time the issue was reported, the test was capable of reproducing the reported issue and when the code to fix the issue was in place, the test passed showing the issue had been addressed. Instead of just saying it's not right, why not provide a little context? Worst case someone learns something.

Fishrock123 · 2015-11-30T17:47:51Z

Seeing as I'm not always right and I love to learn, I'd love to hear more about why it's not correct.

Sorry, I put some reasoning into #3063 (comment) -- basically I'm not sure we guarantee a callback will actually be called at least next tick, and timers by nature timeout as soon as possible.

Fishrock123 · 2015-11-30T21:24:45Z

I suppose users may expect it to be async. Would it also be possible to do this by always calling insert() within a setimmediate() in active()? That may be cleaner if it works?

misterdjules · 2015-12-01T20:40:07Z

I suppose users may expect it to be async

It is at least how it behaves now. Having nested timers that expire when their outer timer's callback is done fire asynchronously has the nice side effect of not starving the event loop too.

Would it also be possible to do this by always calling insert() within a setimmediate() in active()? That may be cleaner if it works?

I don't think we should use setImmediate for rescheduling timers for the reason I mentioned in #3063 (comment):

Scheduling the timer with setImmediate would basically make it not a timer anymore, as immediates are scheduled and ran in a completely different way.

Using active with a different timer delay (the remaining time before the timer fires) would create a new underlying timer, and it seems doing that in a general fashion would make the number of underlying timers grow to a large number, for no added benefit except readability. Instead, the code might be made clearer by just factoring it out into separate functions.

Fishrock123 · 2015-12-18T21:20:47Z

lib/timers.js

+    // expire.
+    //
+    // See: https://github.com/joyent/node/issues/25607
+    if (now <= first._idleStart) {


I don't really understand how this won't be hit when there are just timers scheduled for a later date?

first._idleStart is the time at which a timer was scheduled. Since now is updated to be the time at the start of listOnTimeout execution, now is always > first._idleStart, unless first was scheduled from within the call to listOnTimeout.

Oh duh, this is _idleStart not _idleTimeout, I'm sorry.

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

bnoordhuis · 2016-07-26T16:43:58Z

For the record: #7866 is caused by this PR although it it may not be a regression in a strict sense.

whitlockjc · 2016-07-26T16:47:09Z

I'll take a peek.

misterdjules · 2016-07-26T17:40:40Z

@bnoordhuis Thanks for the heads up, I responded in #7866.

MylesBorins · 2016-08-30T14:08:20Z

Not 100% if this should land in v4.x. Thoughts @misterdjules / @whitlockjc / @bnoordhuis

It seems like there is a non zero chance this could break production code, even if the production code itself is wrong.

As v6 is nearing LTS and this exists in there I would opt to simply pass on this for v4 unless one of you says otherwise.

Adding dont-land, please feel free to change

Fishrock123 · 2016-08-30T14:14:00Z

@thealphanerd This should be backported along with any fixes.

I'm not sure how it could break, but the new behavior is definitely the expected one. (And inferred by docs too)

Fishrock123 · 2016-08-31T14:32:00Z

Here's another issue about this problem: #8354 (comment)

@thealphanerd lmk if you need any help backporting

MylesBorins · 2016-08-31T15:04:40Z

@nodejs/lts how does everyone feel about backporting this given the above information

@Fishrock123 is this commit dependent on your other timers changes?

Fishrock123 · 2016-08-31T15:08:43Z

I don't think so?

MylesBorins · 2016-10-11T00:42:12Z

@Fishrock123 will need help with the backport if you can

mscdex added the timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. label Sep 25, 2015

mscdex reviewed Sep 25, 2015
View reviewed changes

misterdjules reviewed Sep 30, 2015
View reviewed changes

whitlockjc force-pushed the merge-archive-pr-25763 branch from d7d5236 to d848924 Compare October 1, 2015 16:17

whitlockjc mentioned this pull request Oct 1, 2015

timers: fix processing of nested same delay timers nodejs/node-v0.x-archive#25763

Closed

Fishrock123 reviewed Nov 30, 2015
View reviewed changes

Fishrock123 reviewed Dec 18, 2015
View reviewed changes

Trott force-pushed the master branch from 1e896a6 to 082cc8d Compare December 27, 2015 02:00

Fishrock123 mentioned this pull request Jan 11, 2016

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

Closed

STRML mentioned this pull request Feb 25, 2016

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

Closed

evanlucas mentioned this pull request Jul 19, 2016

v6.3.1 Release Proposal #7782

Merged

MylesBorins added dont-land-on-v4.x and removed lts-watch-v4.x labels Aug 30, 2016

MylesBorins added lts-watch-v4.x and removed dont-land-on-v4.x labels Aug 30, 2016

Fishrock123 mentioned this pull request Aug 31, 2016

setTimeout bug. There is example #8354

Closed

marzelin mentioned this pull request Nov 15, 2019

non-deterministic order of execution of setTimeout vs setImmediate nodejs/help#392

Closed

aliscco mentioned this pull request Jun 22, 2023

[Snyk] Security upgrade karma from 1.3.0 to 3.0.0 aliscco/alisco-node#496

Open

timers: fix processing of nested same delay timers #3063

timers: fix processing of nested same delay timers #3063

Conversation

whitlockjc commented Sep 25, 2015 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mscdex commented Sep 25, 2015

Fishrock123 commented Sep 26, 2015

whitlockjc commented Sep 28, 2015

Choose a reason for hiding this comment

misterdjules commented Oct 1, 2015

whitlockjc commented Oct 1, 2015

misterdjules commented Nov 27, 2015

whitlockjc commented Nov 27, 2015

whitlockjc commented Nov 30, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Fishrock123 commented Nov 30, 2015

whitlockjc commented Nov 30, 2015

Fishrock123 commented Nov 30, 2015

whitlockjc commented Nov 30, 2015

Fishrock123 commented Nov 30, 2015

Fishrock123 commented Nov 30, 2015

whitlockjc commented Nov 30, 2015

Fishrock123 commented Nov 30, 2015

Fishrock123 commented Nov 30, 2015

misterdjules commented Dec 1, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bnoordhuis commented Jul 26, 2016

whitlockjc commented Jul 26, 2016

misterdjules commented Jul 26, 2016

MylesBorins commented Aug 30, 2016

Fishrock123 commented Aug 30, 2016

Fishrock123 commented Aug 31, 2016

MylesBorins commented Aug 31, 2016

Fishrock123 commented Aug 31, 2016

MylesBorins commented Oct 11, 2016

whitlockjc commented Sep 25, 2015 •

edited

Loading