timers distribution predictability #15081

vsemozhetbyt · 2017-08-30T00:04:39Z

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.

The text was updated successfully, but these errors were encountered:

vsemozhetbyt · 2017-08-30T00:13:32Z

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

bzoz · 2017-08-30T07:14:43Z

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 · 2017-08-30T08:56:06Z

@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 · 2017-08-30T09:01:22Z

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 · 2017-08-30T09:02:06Z

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

mcollina · 2017-08-30T09:19:35Z

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 · 2017-08-30T09:20:02Z

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 · 2017-08-30T09:42:12Z

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 · 2017-08-30T10:17:42Z

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 · 2017-08-30T10:37:24Z

@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 · 2017-08-30T11:25:45Z

@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 · 2017-08-30T11:26:43Z

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

addaleax · 2017-08-30T14:52:21Z

Can somebody do a quick check whether this would be fixed or otherwise affected by #15072?

Fishrock123 · 2017-08-30T14:56:53Z

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

benjamingr · 2017-08-30T14:59:47Z

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 · 2017-08-30T15:00:03Z

Output is identical before/after #15072

mcollina · 2017-08-30T15:03:43Z

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 · 2017-08-30T15:06:23Z

@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 · 2017-08-30T15:10:36Z

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

TimothyGu · 2017-08-30T15:26:29Z

@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 · 2017-08-30T15:29:38Z

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

vsemozhetbyt · 2017-08-30T15:43:54Z

@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 · 2017-08-30T15:46:41Z

@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 · 2017-08-30T15:47:33Z

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 · 2017-08-30T16:25:37Z

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

benjamingr · 2017-08-30T16:27:59Z

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

vkurchatkin · 2017-08-30T16:30:36Z

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

benjamingr · 2017-08-30T16:42:52Z

@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 · 2017-08-30T16:51:46Z

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

In both cases, this output fragment still seems strange:

setInterval
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 · 2017-08-30T18:02:08Z

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

vsemozhetbyt · 2017-08-31T11:30:35Z

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

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.

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

vkurchatkin · 2017-08-31T14:18:03Z

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

benjamingr · 2017-08-31T14:45:25Z

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 · 2017-08-31T17:39:16Z

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 · 2017-08-31T19:00:53Z

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

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

vsemozhetbyt · 2017-09-04T21:36:24Z

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.

vsemozhetbyt changed the title ~~strange dependence between event loop and script times of script call~~ strange dependence between event loop and times of script call Aug 30, 2017

vsemozhetbyt added libuv Issues and PRs related to the libuv dependency or the uv binding. promises Issues and PRs related to ECMAScript promises. labels Aug 30, 2017

vsemozhetbyt mentioned this issue Aug 30, 2017

Promise Performance Meeting nodejs/promises#31

Open

benjamingr added timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. and removed libuv Issues and PRs related to the libuv dependency or the uv binding. promises Issues and PRs related to ECMAScript promises. labels Aug 30, 2017

vsemozhetbyt changed the title ~~strange dependence between event loop and times of script call~~ setInterval randomly intrudes in microtask queue Aug 30, 2017

addaleax added the promises Issues and PRs related to ECMAScript promises. label Aug 30, 2017

Fishrock123 self-assigned this Aug 30, 2017

benjamingr mentioned this issue Sep 4, 2017

Promise usage mikeal/r2#10

Closed

vsemozhetbyt closed this as completed Sep 4, 2017

vsemozhetbyt changed the title ~~setInterval randomly intrudes in microtask queue~~ timers distribution predictability Sep 4, 2017

vsemozhetbyt mentioned this issue Nov 21, 2017

The order of Task & MicroTask execution is inconsistent with browser #17181

Closed

jpsfs mentioned this issue Aug 10, 2018

MacroTask and MicroTask execution order #22257

Closed

adamlaska mentioned this issue May 13, 2022

[Snyk] Fix for 1 vulnerabilities adamlaska/node#67

Open

snyk-bot mentioned this issue Apr 27, 2023

[Snyk] Fix for 20 vulnerabilities aliscco/alisco-node#253

Open

This was referenced Apr 28, 2023

[Snyk] Fix for 16 vulnerabilities aliscco/alisco-node#304

Open

[Snyk] Fix for 18 vulnerabilities aliscco/alisco-node#310

Open

snyk-bot mentioned this issue Apr 28, 2023

[Snyk] Fix for 20 vulnerabilities aliscco/alisco-node#314

Open

This was referenced Apr 28, 2023

[Snyk] Fix for 9 vulnerabilities aliscco/alisco-node#330

Open

[Snyk] Fix for 19 vulnerabilities aliscco/alisco-node#334

Open

snyk-bot mentioned this issue Apr 28, 2023

[Snyk] Fix for 114 vulnerabilities aliscco/alisco-node#338

Open

aliscco mentioned this issue Apr 28, 2023

[Snyk] Fix for 8 vulnerabilities aliscco/alisco-node#342

Open

timers distribution predictability #15081

timers distribution predictability #15081

Comments

vsemozhetbyt commented Aug 30, 2017 • edited Loading

vsemozhetbyt commented Aug 30, 2017 • edited Loading

bzoz commented Aug 30, 2017

vsemozhetbyt commented Aug 30, 2017 • edited Loading

vsemozhetbyt commented Aug 30, 2017 • edited Loading

bzoz commented Aug 30, 2017

mcollina commented Aug 30, 2017

bzoz commented Aug 30, 2017

vsemozhetbyt commented Aug 30, 2017 • edited Loading

benjamingr commented Aug 30, 2017

vsemozhetbyt commented Aug 30, 2017 • edited Loading

benjamingr commented Aug 30, 2017

benjamingr commented Aug 30, 2017

addaleax commented Aug 30, 2017

Fishrock123 commented Aug 30, 2017

benjamingr commented Aug 30, 2017

benjamingr commented Aug 30, 2017

mcollina commented Aug 30, 2017

benjamingr commented Aug 30, 2017

vkurchatkin commented Aug 30, 2017

TimothyGu commented Aug 30, 2017

vkurchatkin commented Aug 30, 2017

vsemozhetbyt commented Aug 30, 2017

benjamingr commented Aug 30, 2017

benjamingr commented Aug 30, 2017

vkurchatkin commented Aug 30, 2017

benjamingr commented Aug 30, 2017

vkurchatkin commented Aug 30, 2017

benjamingr commented Aug 30, 2017

vsemozhetbyt commented Aug 30, 2017 • edited Loading

benjamingr commented Aug 30, 2017

vsemozhetbyt commented Aug 31, 2017 • edited Loading

vkurchatkin commented Aug 31, 2017

benjamingr commented Aug 31, 2017

vsemozhetbyt commented Aug 31, 2017 • edited Loading

vkurchatkin commented Aug 31, 2017

vsemozhetbyt commented Sep 4, 2017 • edited Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 30, 2017 •

edited

Loading

vsemozhetbyt commented Aug 31, 2017 •

edited

Loading

vsemozhetbyt commented Aug 31, 2017 •

edited

Loading

vsemozhetbyt commented Sep 4, 2017 •

edited

Loading