Skip to content
This repository has been archived by the owner. It is now read-only.

timers: fix processing of nested same delay timers #25763

Open
wants to merge 1 commit into
base: v0.10
from

Conversation

Projects
None yet
6 participants
@whitlockjc
Copy link

whitlockjc commented Jul 24, 2015

Whenever a timer with a specific timeout value creates a new timer with
the same timeout, the newly added timer might be processed immediately
in the same tick of the event loop instead of during the next tick of
the event loop at the earliest.

Fixes #25607

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Jul 24, 2015

// Whenever a timer creates a new timer in the current list being processed
// you can end up processing the new timer immediately instead of waiting
// the scheduled time. Whenever we encounter this situation stop
// processing this list and reschedule. (Issue 25607)

This comment has been minimized.

Copy link
@Fishrock123

Fishrock123 Jul 24, 2015

Member

Could you put the full issue URL here? Thanks. :)

This comment has been minimized.

Copy link
@whitlockjc

whitlockjc Jul 24, 2015

Author

Of course, consider it done.

@@ -87,13 +87,20 @@ function listOnTimeout() {

var first;
while (first = L.peek(list)) {
// If the previous iteration caused a timer to be added,

This comment has been minimized.

Copy link
@misterdjules

misterdjules Jul 24, 2015

We want to keep these comments because they are still relevant: we still need to update now or use Timer.now() to make sure timing computations are done correctly. However we may want to move these comments to were we use Timer.now() right below.

This comment has been minimized.

Copy link
@whitlockjc

whitlockjc Jul 24, 2015

Author

I am already using Timer.now() to do the computation and since we didn't need to update now, it's not used anywhere else and we quick return, I didn't think the previous comments made sense sticking around since we were no longer updating now. Am I misunderstanding?

This comment has been minimized.

Copy link
@misterdjules

misterdjules Jul 24, 2015

Agreed, it's probably self-explanatory in the current state of this PR. Thank you for questioning my comment :) 👍

// update the value of "now" so that timing computations are
// done correctly. See test/simple/test-timers-blocking-callback.js
// for more information.
// Whenever a timer creates a new timer in the current list being processed

This comment has been minimized.

Copy link
@misterdjules

misterdjules Jul 24, 2015

you can end up processing the new timer immediately instead of waiting the scheduled time.
is a bit too vague. I would suggest rephrasing it as following:

This handles the case of a timer that was created within a timers callback with the same timeout value.
For instance, when processing the timer that would call `bar` in such code :

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

or 

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

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.

At that point, it's not necessary to process any other timer in that list,
because any remaining timer has been added within a callback of a timer
that has already been processed, and thus needs to be processed at the
earliest not in the current tick, but when the rescheduled timer will expire.

Basically we want to be as explicit and precise as possible, so that when we come back to this piece of code
in 6 months, we understand why we made this change.

This comment has been minimized.

Copy link
@whitlockjc

whitlockjc Jul 24, 2015

Author

You got it. Should I update the commit message as well? The code comment would make an excellent description in the Git commit message if you ask me.

This comment has been minimized.

Copy link
@misterdjules

misterdjules Jul 24, 2015

I think your commit message is fine, with the exception that it says that we process timers added within timers' callbacks immediately in all cases when the two timers' timeouts are equal. Actually that happens only if the time to run through all previously scheduled timers with the same timeout value exceeds the timers' timeout.

This is likely to happen with timers with short timeouts, like with setTimeout(function() { setTimeout(function() {}, 0); }, 0);. However it would not happen with longer ones, unless there's blocking code that takes a while to run in the first timer's callback.

So I would rephrase the beginning of your commit message as such:

Whenever a timer with a specific timeout value creates a new timer with the same
timeout, the newly added timer might be processed immediately in the same tick
of the event loop instead of during the next tick of the event loop at the earliest.
if (now < first._monotonicStartTime) {
now = Timer.now();
debug('now: %d', now);
var delay = msecs - (Timer.now() - first._monotonicStartTime);

This comment has been minimized.

Copy link
@misterdjules

misterdjules Jul 24, 2015

I would suggest renaming delay to timeRemaining, as it seems closer to what this value represents, but I'm not a native English speaker, so I may be wrong.

This comment has been minimized.

Copy link
@whitlockjc

whitlockjc Jul 24, 2015

Author

Works for me.

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

/cc @joyent/node-collaborators

@misterdjules misterdjules added this to the 0.10.41 milestone Jul 24, 2015

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

Added the P-1 label because this PR fixes a few flaky tests (test-microtask-queue-run and test-microtask-queue-run-domain.js) in v0.10 and v0.12.

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

@whitlockjc I would actually suggest removing test-microtask-queue-run and test-microtask-queue-run-domain from test/simple/simple.status in the same commit.

EDIT: My bad, test-microtask-queue-run and test-microtask-queue-run-domain don't exist in v0.10. However, I seem to remember you had ran these two tests many times to make sure that this change was fixing their flakiness, am I correct? Were you testing these changes in the v0.12 branch at that time?

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

@whitlockjc Thank you very much for submitting this PR. I left a few comments after a first review. This definitely looks like it's going in the right direction. Please let me know when my comments are addressed, and I'll do another review.

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Jul 24, 2015

@misterdjules I originally wrote this code on master which does have those tests and the test suite ran without error. As for the flaky test reported in #25607, I ran the same 10K recipe in the report and it ran all 10K tests without a single error. Of course, when I ported this work over to v0.10 those tests aren't there so I just relied on the make test passing.

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

@whitlockjc Ok, that sounds good!

@whitlockjc whitlockjc force-pushed the whitlockjc:fix-nested-timers branch from 3964aed to 9bb2b67 Jul 24, 2015

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Jul 24, 2015

@misterdjules I do believe I've addressed your above requests:

  • Changed variable in lib/timers.js from delay to timeRemaining
  • More verbose documentation in lib/timers.js
  • Updated commit message details
@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

In the absence of test-microtask-queue-run.js and test-microtask-queue-run-domain.js in v0.10, we'd need at least one test for this change. Even with these two tests in v0.12, I'm not familiar with the semantics of the microtasks queue, and process.nextTick's behavior compared to setTimeout callbacks is clearly defined, so having specific tests for this change in v0.12 would also be valuable.

I would suggest starting with making sure that with the following code:

setTimeout(function foo() { setTimeout(function bar() {}, 0); process.nextTick(function baz() {}); }, 0);

baz is called before bar.

I would add another variant with nested setTimeout calls with the same timeout but > 0. Ideally the timeout value for that second test would be large enough to exceed the execution time of the outer setTimeout callback, but small enough to not make the overall test too long. 100 miliseconds would seem like a reasonable value.

Then you can go crazy and add even more nesting, anything you can think of basically :)

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 24, 2015

@whitlockjc Another test you can add too is something like the following:

var TIMEOUT = 100;

var barCalled = false;

setTimeout(function foo() {
    setTimeout(function bar() {
        barCalled = true;
    }, TIMEOUT);

    // busy loop for timeout miliseconds so that
    // when listOnTimeout is done calling foo,
    // it processes the inner timer and find that its
    // timer has expired
    common.busyLoop(timeout);

    process.nextTick(function baz() {
        // make sure this nextTick callback
        // is called before the inner setTimeout
        // callback
        assert(barCalled === false);
    });
}, TIMEOUT);

I believe that would fail without the changes in this PR.

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Jul 27, 2015

@tunniclm Continuing the discussion regarding your latest comment here, because this way we can look at the changes that are being discussed.

What I found in my exploration of nested setTimeout() calls is that it is possible to add a timeout in a timeout callback such that it fires on the same iteration of the event loop in which it was added.

Yes, that's the same conclusion @whitlockjc and I arrived at in this PR.

I didn't see a note in the documentation to say whether this should be allowed or not (whereas there is such a note for setImmediate()), but perhaps I missed it?

I don't think you missed anything, unless we both missed it (which is possible :) ).

The above PR assumes that this scenario should not be allowed and if that is correct, then it looks like a good fix for this issue. And in that case I think we should update the doc to describe this contract under https://nodejs.org/api/timers.html#timers_settimeout_callback_delay_arg .

My opinion is there are at least two things to consider:

  1. The previous behavior of Node.js.
  2. Conformance to browsers' behavior/specs.

For 1), the previous behavior of Node.js was definitely to schedule nested timers' callbacks in different ticks of the event loop, which is why test-microtask-queue-run.js and test-microtask-queue-run-domain.js started to fail after d38e865.

As of 2), it seems that all browsers I have access to (Chrome, Firefox, Opera, Safari), with the following code:

setTimeout(function () {
    setTimeout(function() {
        console.log('timer callback called');
    }, 0);

    Promise.resolve().then(function() {
        console.log('promise callback called');
    });
}, 0);

consistently produce the following output:

promise callback called
timer callback called

The HTML spec also indicates that timers are queued in their own tasks queue (see item number 14).

In other words, it seems that:

  1. Regardless of the timeout value, timers should never fire in the same tick of the event loop, and we should document it as you suggested.
  2. This would not be a breaking change, so this can land in v0.10.

@whitlockjc whitlockjc force-pushed the whitlockjc:fix-nested-timers branch from 9bb2b67 to 976936c Jul 27, 2015

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Jul 27, 2015

As requested, I just updated the PR to include a unit test. I wrote this test against v0.10 without my changes to ensure the test would fail consistently. With the logic changes to lib/timers.js made in this PR, this test passes consistently.

Note: This commit also includes a changes to test/common.js#busyLoop so that it uses the monotonic clock just like timers do.

@jasnell

This comment has been minimized.

Copy link
Member

jasnell commented Aug 29, 2015

@misterdjules ... did you have any further thoughts on this one?
@chrisdickinson ... do you happen to have any thoughts on it?

}
debug(msecs + ' list wait because timer was added from another timer');
list.start(timeRemaining, 0);
return;

This comment has been minimized.

Copy link
@Fishrock123

Fishrock123 Aug 29, 2015

Member

Would it be better to just track if we are in a timeout and do the fix in like timer.active()?

In general, touching the actual timeout loop seems pretty hairy.

This comment has been minimized.

Copy link
@whitlockjc

whitlockjc Aug 31, 2015

Author

Let me wrap my head around this. I'm not sure what extra state, etc. would be required for your approach. Do you think the edge case, now <= timer._monotonicStartTime would still be necessary to catch in listOnTimeout. If so, it might not be worth doing thing differently as we'd still have the edge case to deal with.

This comment has been minimized.

Copy link
@misterdjules

misterdjules Sep 30, 2015

@Fishrock123 What did you have in mind more specifically? Some actual code would help.

@rvagg rvagg referenced this pull request Sep 12, 2015

Merged

Release proposal: v0.10.41 #2805

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Sep 21, 2015

I don't want this to drop through the cracks so can we update this with the next steps? Really hoping to either find out that this isn't necessary in the new node repository or be told what the next steps are. If it's still useful/important, I'll gladly port this to the new repository via a PR.

/cc @nodejs/collaborators and @nodejs/tsc

@Fishrock123

This comment has been minimized.

Copy link
Member

Fishrock123 commented Sep 22, 2015

I'm mostly away right now (vacation) so ping me every few weeks until I am able to take a look at it, if no-one else does first.

As a good fist step, could you move this to the nodejs/node repo? thanks!

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Sep 25, 2015

Done. I fixed the merge conflicts but the PR is primarily the same. I did move test/simple/test-timers-nested.js to test/timers/test-timers-nested.js to be consistent with other timers tests. The other changes were trivial.

common.busyLoop(delay);

process.nextTick(function() {
assert.ok(!nestedCalled);

This comment has been minimized.

Copy link
@misterdjules

misterdjules Sep 30, 2015

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.

// Create the nested timer with the same delay as the outer timer so that it
// gets added to the current list of timers being processed by listOnTimeout.
setTimeout(function B() {
nestedCalled = true;

This comment has been minimized.

Copy link
@misterdjules

misterdjules Sep 30, 2015

Also, I would add a process.on('exit') listener that makes sure that the nested callback is actually called before the process exits:

process.on('exit', function onExit() {
  assert.ok(nestedCalled);
});
@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Sep 30, 2015

@whitlockjc This will look good to me once my latest two comments are addressed.

@nodejs/tsc Is it actually a rule now to submit PRs against master before landing changes in v0.12/v0.10?

If so that would be very tedious, since there's a lot of difference between some internal modules between v0.10/v0.12 and nodejs/master, and that would essentially mean forward-porting changes to nodejs/master and then back porting them again.

So unless there's a real benefit in doing that that I missed, I would suggest just landing this PR in v0.10, merging it in v0.12 and then forward-porting it in nodejs/master with a separate PR.

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Oct 1, 2015

@misterdjules no need to add in master first where it doesn't make sense, sometimes things are just not going to belong in master at all and sometimes it's completely different code so separate PRs makes sense. So, no strict rules, don't jump through too many hoops if it's too complex, particularly for 0.10 and 0.12 which are far detached now. Just keep a record in the commit of what happened so when we're cherry-picking things that we know what's going on.

@misterdjules

This comment has been minimized.

Copy link

misterdjules commented Oct 1, 2015

@rvagg Sounds good.

timers: fix processing of nested same delay timers
Whenever a timer with a specific timeout value creates a new timer with
the same timeout, the newly added timer might be processed immediately
in the same tick of the event loop instead of during the next tick of
the event loop at the earliest.

Fixes #25607

@whitlockjc whitlockjc force-pushed the whitlockjc:fix-nested-timers branch from 976936c to 65de5d0 Oct 1, 2015

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Oct 1, 2015

For posterity, I went ahead and updated this PR with the changes @misterdjules requested in nodejs/node#3063

@oleksiyk

This comment has been minimized.

Copy link

oleksiyk commented Mar 5, 2016

Can this still be a problem if the clock in the process is not monotonically updated at some moment? For example when the computer hibernates and then wakes up or the system time being updated by NTP daemon?

This problem petkaantonov/bluebird#1034 with bluebird promise looks to be related.

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Mar 7, 2016

To test, you could build node with this PR applied to see if it still happens: nodejs/node#3063 Long story short, the whole purpose of this PR is to make it so that a timer added within a timer gets fired on the next tick instead of the tick it was added. That being said, I'm not sure why that would cause the issue you're seeing but I'd be willing to look deeper.

@oleksiyk

This comment has been minimized.

Copy link

oleksiyk commented Mar 7, 2016

Thanks, I tried 0.10.41 which as I understand already has this PR applied and the issue with promises call stack still happens. Its hard to reproduce so I'm trying to narrow down the circumstances that can replicate it.

@whitlockjc

This comment has been minimized.

Copy link
Author

whitlockjc commented Mar 7, 2016

I don't think it's been merged to any stream yet. Might tray a custom build. The easiest thing would be to clone my repo, checkout the merge-archive-pr-25763 branch and build it from there. Let me know what you find out.

whitlockjc added a commit to whitlockjc/node that referenced this pull request Jul 15, 2016

timers: fix processing of nested timers
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

whitlockjc added a commit to nodejs/node that referenced this pull request Jul 15, 2016

timers: fix processing of nested timers
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

evanlucas added a commit to nodejs/node that referenced this pull request Jul 19, 2016

timers: fix processing of nested timers
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

evanlucas added a commit to nodejs/node that referenced this pull request Jul 20, 2016

timers: fix processing of nested timers
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
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.