timers distribution predictability

[vsemozhetbyt]

• Version: 8.4.0
• Platform: Windows 7 x64
• Subsystem: libuv, promises

Revisiting this article, I've found out that an example which illustrates some known bug (?) in microtask queue execution behaves differently because of times of script call.

'use strict';

console.log('script start')

const interval = setInterval(() => { 
 console.log('setInterval')
}, 0)

setTimeout(() => { 
 console.log('setTimeout 1')
 Promise.resolve().then(() => {
 console.log('promise 3')
 }).then(() => {
 console.log('promise 4')
 }).then(() => {
 setTimeout(() => {
 console.log('setTimeout 2') //< place of random microtask queue intrusion
 Promise.resolve().then(() => {
 console.log('promise 5')
 }).then(() => {
 console.log('promise 6')
 }).then(() => {
 clearInterval(interval)
 })
 }, 0)
 })
}, 0)

Promise.resolve().then(() => { 
 console.log('promise 1')
}).then(() => {
 console.log('promise 2')
})

Every first call in a new cmd.exe terminal produces the mentioned error. Every next call has proper execution order:

>node test.js
script start
promise 1
promise 2
setInterval
setTimeout 1
promise 3
promise 4
setInterval
setTimeout 2
setInterval //< intruder
promise 5
promise 6

>node test.js
script start
promise 1
promise 2
setInterval
setTimeout 1
promise 3
promise 4
setInterval
setTimeout 2
promise 5
promise 6

Compare the next step after the setTimeout 2 output.

[vsemozhetbyt]

The same is valid for v6.11.2, the last nightly and V8 canary.

[bzoz]

On my box it is random, with each run the output will either have or have not this extra setInterval.

The docs for setTimeout and setInterval say When delay is larger than 2147483647 or less than 1, the delay will be set to 1, so I guess that this is some kind of a race?

[vsemozhetbyt]

@bzoz I've checked some more times: the first time is always with extra setInterval, in the next ones — ~1 of 10 has extra setInterval.

[vsemozhetbyt]

Strangely, in git bash for Windows, the first time is also random, in the next ones statistics is reverted: ~1 of 10 has not extra setInterval.

[bzoz]

On my box it is totally random, no matter if on cmd, bash or anything.

[mcollina]

This is not a problem, but it depends on when setTimeout(func, 0) places func. This is explained in https://nodejs.org/en/docs/guides/event-loop-timers-and-nexttick.

[bzoz]

The article says:
According to the WHATVG specification, exactly one (macro)task should get processed from the macrotask queue in one cycle of the event loop
while Nodes setImmediate documentation says:
The entire callback queue is processed every event loop iteration.
So I guess Node does not follow WHATVG exactly. More details are here.

I think that the thing here is that in the article uses setTimeout(..., 0). Node makes this into setTimeout(..., 1). This 1 is a minimum delay, so it probably gets scheduled slightly differently each time.

[vsemozhetbyt]

This variant has the same behavior:

'use strict';

console.log('script start')

const interval = setInterval(() => {
 console.log('setInterval')
}, 0)

setTimeout(() => {
 console.log('setTimeout 1')
 Promise.resolve().then(() => {
 console.log('promise 3')
 }).then(() => {
 console.log('promise 4')
 }).then(() => {
 setTimeout(() => {
 console.log('setTimeout 2') //< place of random microtask queue intrusion
 process.nextTick(() => { console.log('nextTick 1'); })
 process.nextTick(() => { console.log('nextTick 2'); })
 process.nextTick(() => { clearInterval(interval); })
 }, 0)
 })
}, 0)

Promise.resolve().then(() => {
 console.log('promise 1')
}).then(() => {
 console.log('promise 2')
})

>node test.js
script start
promise 1
promise 2
setInterval
setTimeout 1
promise 3
promise 4
setInterval
setTimeout 2
setInterval //< intruder
nextTick 1
nextTick 2

>node test.js
script start
promise 1
promise 2
setInterval
setTimeout 1
promise 3
promise 4
setInterval
setTimeout 2
nextTick 1
nextTick 2

[benjamingr]

Very nice find!

Just pointing out that the whole micro/macrotask semantics aren't really specified anywhere - and we're free to schedule promises (as a platform as we choose).

We currently schedule them with microtask semantics (again, this is not required by the specification but is more correct since it does not defer things by I/O).

I'd like to point out that the order of callbacks will likely change in the future as a part of nodejs/promises#31 since we currently needlessly defer a lot of actions to the nextTick where we don't have to which I hope V8 will fix.

Have you tested what happens when you replace all the Promise.resolve().then(() => ... calls with nextTick calls?

[vsemozhetbyt]

@benjamingr If I get this right, this is the equivalent:

'use strict';

console.log('script start');

const interval = setInterval(() => { console.log('setInterval'); }, 0);

setTimeout(() => {
 console.log('setTimeout 1');
 process.nextTick(() => { console.log('nextTick 3'); });
 process.nextTick(() => { console.log('nextTick 4'); });
 process.nextTick(() => {
 setTimeout(() => {
 console.log('setTimeout 2'); //< place of random microtask queue intrusion
 process.nextTick(() => { console.log('nextTick 5'); });
 process.nextTick(() => { console.log('nextTick 6'); });
 process.nextTick(() => { clearInterval(interval); });
 }, 0);
 });
}, 0);

process.nextTick(() => { console.log('nextTick 1'); });
process.nextTick(() => { console.log('nextTick 2'); });

It is more random for me (even the first run in the new terminal has random output), but the extra setInterval emerges inside microtask queue more seldom:

> node test.js
script start
nextTick 1
nextTick 2
setInterval
setTimeout 1
nextTick 3
nextTick 4
setInterval
setTimeout 2
setInterval //< intruder
nextTick 5
nextTick 6

> node test.js
script start
nextTick 1
nextTick 2
setInterval
setTimeout 1
nextTick 3
nextTick 4
setInterval
setTimeout 2
nextTick 5
nextTick 6

[benjamingr]

@vsemozhetbyt good, that looks a lot more manageable than if the problem was in the promise glue code but not in the nextTick queue.

Removing the libuv and promises labels and adding the timers label. Also pinging @mscdex about timers :)