Node: 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 https://github.com/nodejs/promises/issues/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 :)

[benjamingr]

I also recall this issue was discussed at one point - but I'm not sure what the conclusion was.

[addaleax]

Can somebody do a quick check whether this would be fixed or otherwise affected by https://github.com/nodejs/node/pull/15072?

[Fishrock123]

I'll try to take a look at this later today.

[benjamingr]

Output of:

'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'); });

with #15072 :

~/Documents/OpenSource/node [master] $ ./out/Release/node ~/Documents/test/index.js 
script start
nextTick 1
nextTick 2
setInterval
setTimeout 1
nextTick 3
nextTick 4
setInterval
setTimeout 2
nextTick 5
nextTick 6

[benjamingr]

Output is identical before/after #15072

[mcollina]

IMHO this is not a bug on Node side related to the event loop. I have little time to explain now, but it looks ok from here.

The big question is if this breaks the Promise spec.

[benjamingr]

@mcollina it 100% does not break the ECMAScript spec (or the A+ old one). It doesn't really relate to promises too - it's about how the nextTick queue and timers interact in certain scenarios.

[vkurchatkin]

Honestly, I don't see a problem here. Timers don't really follow any specs

[TimothyGu]

@vkurchatkin It's not about any specs, but about predictable behavior. FWIW, timers are defined de jure by HTML and de facto by browsers. Would be interesting to see what browsers do.

[vkurchatkin]

@TimothyGu order of events always was and will be something that you are not supposed to rely on

[vsemozhetbyt]

@TimothyGu In the Chrome 62.0.3199.0 canary, this seems to be consistently:

18:37:58.081 Script snippet #1:3 script start
18:37:58.082 Script snippet #1:30 promise 1
18:37:58.083 Script snippet #1:32 promise 2
18:37:58.087 Script snippet #1:6 setInterval
18:37:58.087 Script snippet #1:10 setTimeout 1
18:37:58.087 Script snippet #1:12 promise 3
18:37:58.088 Script snippet #1:14 promise 4
18:37:58.088 Script snippet #1:6 setInterval
18:37:58.092 Script snippet #1:6 setInterval
18:37:58.093 Script snippet #1:17 setTimeout 2
18:37:58.093 Script snippet #1:19 promise 5
18:37:58.093 Script snippet #1:21 promise 6

[benjamingr]

@vsemozhetbyt the DOM Specification actually does define timers and their relation to promises in the platform explicitly.

What we do in Node.js in terms of timers isn't bound to the timer spec - and nextTick doesn't really have an equivalent in browsers.

I look at nextTick as "I need this to happen later, hopefully before events are handled" and setTimeout as "I need this to happen after X milliseconds" (with setImmediate being "I need this to happen after I/O, hopefully").

[benjamingr]

For example, Bluebird an Q which are the two most popular promise libraries schedule promises with macrotask semantics (with setImmediate) and that has never been a problem although we considered changing it many times. The issue just never rose.

[vkurchatkin]

@benjamingr the equivalent of nextTick is microtask queue (job queue).

[benjamingr]

@vkurchatkin right, but Bluebird schedules with setImmediate and macrotask semantics explicitly. (It runs all scheduled tasks together though, rather than schedule them individually)

[vkurchatkin]

@benjamingr well, that's one reason to avoid Bluebird.

[benjamingr]

@vkurchatkin I don't think it is, but if you have a compelling argument on why nextTick semantics is inherently better I'm all ears. Node that bluebird typically doesn't schedule at all - only when the promise itself resolved synchronously.

There are plenty of reasons to not pick bluebird and hopefully we will reach performance parity with native promises but scheduling on macrotick semantics worked so well (well _enough_) that the two most popular libraries with over 25M monthly downloads on NPM do it and (almost) nobody noticed.

[vsemozhetbyt]

Is this answer, referenced in some place, applicable for Node.js?

In both cases, this output fragment still seems strange:

setTimeout 2
setInterval 
promise 5
promise 6

How can we parse it if the answer is true?

--------------------event loop go-around 1
setInterval
--------------------event loop go-around 2
setTimeout 2
--------------------event loop go-around 3
setInterval 
promise 5
promise 6

This seems not OK: in the event loop go-around 3 we have microtask queue from the event loop go-around 2.
If the answer is not true, what would be the separation?

--------------------event loop go-around 1
setInterval
setTimeout 2
--------------------event loop go-around 2
setInterval 
promise 5
promise 6

We still have microtask queue from the previous loop go-around.

--------------------event loop go-around 1
setInterval
--------------------event loop go-around 2
setTimeout 2
setInterval 
promise 5
promise 6

We have one missing macrotask in the event loop go-around 1 (and reverted order of handler execution in event loop go-around 2? — or setTimeout/setInterval order in the next setInterval runs is random by design? ).

--------------------event loop go-around 1
setInterval
setTimeout 2
setInterval 
promise 5
promise 6

We have two identical macrotasks in one event loop go-around

[benjamingr]

We should probably document that the ordering of asynchronous actions is not guaranteed by Node.js.

[vsemozhetbyt]

I am trying to visually separate event loop go-around with setImmediate() calls (I am not sure if this is a right approach though). So this is a simplified version of the above-used cases:

'use strict';

const outputs = [];

outputs.push('script start');

const interval = setInterval(() => {
  outputs.push('setInterval');
  setImmediate(() => { outputs.push('-------------------- setImmediate'); });
}, 0);

setTimeout(() => {
  outputs.push('setTimeout 1');
  setTimeout(() => {
    outputs.push('setTimeout 2');
    clearInterval(interval);
    setImmediate(() => { console.log(outputs.join('\n')); });
  }, 0);
}, 0);

outputs.push('-------------------- Script ends');

It randomly outputs these 2 variants:

script start
-------------------- Script ends
setInterval
setTimeout 1
-------------------- setImmediate
setInterval
setTimeout 2
-------------------- setImmediate

script start
-------------------- Script ends
setInterval
setTimeout 1
setInterval
-------------------- setImmediate
-------------------- setImmediate
setTimeout 2

1. The first one seems valid if we admit that these statements are not applicable to Node.js:

One go-around of the event loop will have exactly one task being processed from the macrotask queue (this queue is simply called the task queue in the WHATWG specification).

According to the WHATVG specification, exactly one (macro)task should get processed from the macrotask queue in one cycle of the event loop.

but this is applicable:

when the event loop enters a given phase, it will perform any operations specific to that phase, then execute callbacks in that phase's queue until the queue has been exhausted or the maximum number of callbacks has executed.

1. I still cannot understand how the second variant can be parsed and substantiated.

[vkurchatkin]

@vsemozhetbyt well, node doesn't have macrotasks, so it's definitely not applicable.

[benjamingr]

We should probably document that the ordering of asynchronous actions is not guaranteed by Node.js.

Is this something you agree with in general - or do you think the current way is fine?

(I'm +0, I think Node.js has traditionally been doing a good job in communicating that this is unspecified)

[vsemozhetbyt]

Well, I've read some articles (and watched some videos) about event loop with all these schemes of event loop phases and careful statements about execution in order of queueing — and still did not know that we had so unpredictable distribution of queued tasks between event loop go-arounds(

[vkurchatkin]

did not know that we had so unpredictable distribution of queued tasks

Well, timers are uninvolved, so it shouldn't be surprising.

[vsemozhetbyt]

Closure.

With asynk_hooks, I can see that there is no guarantee of timers distribution between loop runs.

With this code:

const async_hooks = require('async_hooks');
const { writeSync } = require('fs');

const types = {};
let indent = 0;
function syncLog(msg) { writeSync(1, `${msg}\n`); }

const hooks = {
  init(asyncId, type) {
    types[asyncId] = type;
    syncLog(`${' '.repeat(indent * 2)}${asyncId} ^ (${type})`);
  },
  before(asyncId) {
    syncLog(`${' '.repeat(indent * 2)}${asyncId} > (${types[asyncId]})`);
    indent++;
  },
  after(asyncId) {
    indent--;
    syncLog(`${' '.repeat(indent * 2)}${asyncId} < (${types[asyncId]})`);
  },
  destroy(asyncId) {
    syncLog(`${' '.repeat(indent * 2)}${asyncId} x (${types[asyncId]})`);
  },
};

async_hooks.createHook(hooks).enable();

const interval = setInterval(() => {
  setImmediate(() => {});
}, 0);

setTimeout(() => {
  setTimeout(() => {
    clearInterval(interval);
  }, 0);
}, 0);

I get at least these variants (brackets mean TIMERWRAP group, semicolons separate loop phases):

1 (setInterval) + (setTimeout); setImmediate; (setInterval + setTimeout); setImmediate

Output:

2 ^ (Timeout)
3 ^ (TIMERWRAP)
4 ^ (Timeout)
3 > (TIMERWRAP)
  2 > (Timeout)
    5 ^ (Immediate)
  2 < (Timeout)
3 < (TIMERWRAP)
3 > (TIMERWRAP)
  4 > (Timeout)
    6 ^ (Timeout)
  4 < (Timeout)
3 < (TIMERWRAP)
4 x (Timeout)
5 > (Immediate)
5 < (Immediate)
5 x (Immediate)
3 > (TIMERWRAP)
  2 > (Timeout)
    7 ^ (Immediate)
  2 < (Timeout)
  6 > (Timeout)
  6 < (Timeout)
3 < (TIMERWRAP)
2 x (Timeout)
6 x (Timeout)
7 > (Immediate)
7 < (Immediate)
7 x (Immediate)
3 x (TIMERWRAP)

2.1 (setInterval + setTimeout) + (setInterval + setTimeout); setImmediate + setImmediate

Output:

2 ^ (Timeout)
3 ^ (TIMERWRAP)
4 ^ (Timeout)
3 > (TIMERWRAP)
  2 > (Timeout)
    5 ^ (Immediate)
  2 < (Timeout)
  4 > (Timeout)
    6 ^ (Timeout)
  4 < (Timeout)
3 < (TIMERWRAP)
4 x (Timeout)
3 > (TIMERWRAP)
  2 > (Timeout)
    7 ^ (Immediate)
  2 < (Timeout)
  6 > (Timeout)
  6 < (Timeout)
3 < (TIMERWRAP)
2 x (Timeout)
6 x (Timeout)
5 > (Immediate)
5 < (Immediate)
7 > (Immediate)
7 < (Immediate)
5 x (Immediate)
7 x (Immediate)
3 x (TIMERWRAP)

2.2 (setInterval) + (setTimeout + setInterval) + (setTimeout); setImmediate + setImmediate

Output:

2 ^ (Timeout)
3 ^ (TIMERWRAP)
4 ^ (Timeout)
3 > (TIMERWRAP)
  2 > (Timeout)
    5 ^ (Immediate)
  2 < (Timeout)
3 < (TIMERWRAP)
3 > (TIMERWRAP)
  4 > (Timeout)
    6 ^ (Timeout)
  4 < (Timeout)
  2 > (Timeout)
    7 ^ (Immediate)
  2 < (Timeout)
3 < (TIMERWRAP)
4 x (Timeout)
3 > (TIMERWRAP)
  6 > (Timeout)
  6 < (Timeout)
3 < (TIMERWRAP)
2 x (Timeout)
6 x (Timeout)
5 > (Immediate)
5 < (Immediate)
7 > (Immediate)
7 < (Immediate)
5 x (Immediate)
7 x (Immediate)
3 x (TIMERWRAP)

If this is true, it seems there is no unexpectedness in the original article example output or next outputs in this issue. So I can close this issue for now. Feel free to reopen if needed or to add any useful information.