setTimeout() introduces artificial delay between ticks when doing synchronous work

[STRML]

Affected Versions: 0.11+

The issue came up during testing of node-toobusy. I found that in newer Node versions, there seemed to be an artificial delay introduced between setTimeout() calls if there is a significant amount of synchronous work in them. The delay seems to always equal the amount of work done, as if Node is measuring the time taken by the function and delaying it by that amount of time to keep the loop free.

Reproduction script:

function tightWork(duration) {
  var start = Date.now();
  while ((Date.now() - start) < duration) {
    for (var i = 0; i < 1e5;) i++;
  }
}

var count = 0;
var last = Date.now();

function load() {
  if (count++ > 10) return;
  // This measures the amount of time between setTimeout() being called,
  // and it actually firing.
  console.log('tick delta:', (Date.now() - last));
  tightWork(100);
  last = Date.now();
  setTimeout(load, 0);
}

load();

Output (similar on 0.11.x and above):

$ node -v
v5.6.0
$ node index
tick delta: 13
tick delta: 1
tick delta: 105
tick delta: 104
tick delta: 105
tick delta: 105
tick delta: 105
tick delta: 104
tick delta: 105
tick delta: 105
tick delta: 105

Yet this doesn't happen on 0.10:

$ node -v
v0.10.41
$ node index
tick delta: 8
tick delta: 2
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1
tick delta: 1

[Fishrock123]

Hmmm, interesting. here is the result if you use setImmediate():

tick delta: 13
tick delta: 1
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0
tick delta: 0

[Fishrock123]

@STRML I think you are running into some overhead or issue from Date.now() in newer versions of V8.

Here is an example using process.hrtime():

function tightWork(duration) {
  var start = process.hrtime()[1];
  while ((process.hrtime()[1] - start) < duration) {
    for (var i = 0; i < 1e5;) i++;
  }
}

var count = 0;
var last = process.hrtime()[1];

function load() {
  if (count++ > 10) return;
  // This measures the amount of time between setTimeout() being called,
  // and it actually firing.
  console.log('tick delta (ns):', 0.000001 * (process.hrtime()[1] - last));
  tightWork(100);
  last = process.hrtime()[1];
  setTimeout(load, 0);
}

load();

Output:

tick delta: 13.153296
tick delta: 2.8150939999999998
tick delta: 2.7386399999999997
tick delta: 1.390803
tick delta: 1.105172
tick delta: 2.57055
tick delta: 1.378833
tick delta: 1.256799
tick delta: 1.335664
tick delta: 1.1811589999999998
tick delta: 1.3384239999999998

[misterdjules]

@STRML Excellent analysis and report, thank you very much for doing this!

I believe this bug was actually fixed in node v0.10.39 and up and v0.12.5 and up. Would you mind checking that these versions fix your problem?

It is still present in node v4.x and up though. There's an open PR to fix it in these versions at #3063.

This issue is also duplicate of nodejs/node-v0.x-archive#15447 and nodejs/node-v0.x-archive#9333, so I'll close it for now, but feel free to let me know if I missed something.

@Fishrock123 It seems that the sample code you mentioned uses the part of process.hrtime's return value that is in nanoseconds, and so it busy-waits for 1e5 nanoseconds, which is not enough time to make this issue noticeable.

[STRML]

Great. Thanks for the context @misterdjules. I'm going to link #3063 here for reference since GitHub doesn't seem to have picked that one up.

I can confirm 0.10.40-41 and 0.12.9 do not exhibit this issue.

[misterdjules]

Reopening to have one issue open about this problem in nodejs/node and not just in joyent/node-v0.x-archive as suggested by @onlucky.

[MylesBorins]

/cc @Fishrock123