timers: fix processing of nested same delay timers

[whitlockjc]

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]

/cc @misterdjules

[Fishrock123]

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

[whitlockjc]

Of course, consider it done.

[misterdjules]

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.

[whitlockjc]

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?

[misterdjules]

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

[misterdjules]

/cc @joyent/node-collaborators

[misterdjules]

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]

@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]

@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]

@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]

@whitlockjc Ok, that sounds good!

[whitlockjc]

@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]

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]

@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]

@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]

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]

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

[Fishrock123]

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.

[whitlockjc]

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.

[misterdjules]

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

[whitlockjc]

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]

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]

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.

[misterdjules]

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]

@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]

@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]

@rvagg Sounds good.

[whitlockjc]

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

[oleksiyk]

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]

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]

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]

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.