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

[Fishrock123]

In #7386 @zhangzifa has suggested to use this patch as a fix:

diff --git a/lib/timers.js b/lib/timers.js
index dc2506e..fa3b3b7 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -169,7 +169,7 @@ function listOnTimeout() {
     // Check if this loop iteration is too early for the next timer.
     // This happens if there are more timers scheduled for later in the list.
     if (diff < msecs) {
-      this.start(msecs - diff, 0);
+      this.start(msecs, 0);
       debug('%d list wait because diff is %d', msecs, diff);
       return;
     }

But I'm not sure that is correct, consider the following:

var timer_a = {
  _idleStart: 40000, // Time when `a` was scheduled from
  _idleTimeout: 2000 // Duration (`msecs`)
}

var timer_b = {
  _idleStart: 41000, // Time when `b` was scheduled from
  _idleTimeout: 2000 // Duration (`msecs`)
}

Both timers will go into the same underlying list (backed by a timer_wrap handle) because they have the same ._idleTimeout (duration), and thus hit the aforementioned logic.

With that "fix", timer_a will fire at ~42000, but timer_b will fire at ~4400, rather than at ~4300, when it is supposed to. This is because we would now be rescheduling the full timer duration (msecs) from the first called timer rather than checking if it should fire before that full duration...

---

I'm still quite puzzled by this problem. Investigating more.

[zhangzifa]

@Fishrock123 @STRML @misterdjules

With the following fix, based on LTS, which is the same logic as 5.x 6.x, the timer works as it should, in my opinion.

• If all the callbacks can be executed within repeat, the diff between two timeouts of the same timer should be as the repeat value.
• If all the callbacks executed more than repeat, the dff between two timeouts of the same timers should be the real execute time (given other event almost takes no time to execute).
• The above logic should work for timers with different repeat.

Could you help check if this fix reasonable, then i can raise a PR for this? Thanks

This is the fix:

diff --git a/lib/timers.js b/lib/timers.js
index 3cd830a..0bfea18 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -28,11 +28,15 @@ var lists = {};
 // it will reset its timeout.
 // the main function - creates lists on demand and the watchers associated
 // with them.
-exports.active = function(item) {
+exports.active = function(item, start) {
   const msecs = item._idleTimeout;
   if (msecs < 0 || msecs === undefined) return;

-  item._idleStart = Timer.now();
+  if (start) {
+    item._idleStart = start;
+  } else {
+    item._idleStart = Timer.now();
+  }

   var list;

@@ -61,11 +65,28 @@ function listOnTimeout() {
   debug('timeout callback %d', msecs);

   var now = Timer.now();
+  var isFirstCalled = false;
   debug('now: %s', now);

   var diff, first, threw;
   while (first = L.peek(list)) {
+    now = Timer.now();
     diff = now - first._idleStart;
+
+    if (!isFirstCalled) {
+      isFirstCalled = true;
+      first._firstCalled = true;
+    } else {
+      if (first._firstCalled) {
+        first._firstCalled = false;
+        // it needs more than msecs
+        // when the callbacks of all the timers called
+        debug('%d list execute time is larger than %d', msecs, msecs);
+        list.start(0, 0);
+        return;
+      }
+    }
+
     if (diff < msecs) {
       list.start(msecs - diff, 0);
       debug('%d list wait because diff is %d', msecs, diff);
@@ -379,6 +400,7 @@ exports.setInterval = function(callback, repeat) {
   return timer;

   function wrapper() {
+    var now = Timer.now();
     timer._repeat();

     // Timer might be closed - no point in restarting it
@@ -390,7 +412,7 @@ exports.setInterval = function(callback, repeat) {
       this._handle.start(repeat, 0);
     } else {
       timer._idleTimeout = repeat;
-      exports.active(timer);
+      exports.active(timer, now);
     }
   }
 };
@@ -411,6 +433,7 @@ const Timeout = function(after) {
   this._idleNext = this;
   this._idleStart = null;
   this._onTimeout = null;
+  this._firstCalled = false;
   this._repeat = null;
 };

This is the test code:

var sleepMs = function (ms) {
  var startTime = new Date().getTime();
  while (new Date().getTime() < startTime + ms);
};

var printDiffFromStart = function(pre) {
  var now = (new Date().getTime() - start) % 100000; // 99888, 99.888s
  console.log(pre + ' ' + (now / 1000));
};

var setupTimer = function (interval, name, callback_delay) {
  printDiffFromStart('setup timer: ' + name + ' ' + interval + ' ' + callback_delay);
  return setInterval(function(){
    printDiffFromStart(name + ' ' + interval + ' ' + callback_delay);
    if (callback_delay > 0) {
      sleepMs(callback_delay);
    }
  }, interval);
};


var t3, t4, t5, t6, t7;

var test = function() {
  t3 = setupTimer(2000, 't3', 1200);
  sleepMs(1000);
  t4 = setupTimer(2000, 't4', 500);
  sleepMs(500);
  t5 = setupTimer(2000, 't5', 0);
  sleepMs(490);
  t6 = setupTimer(2000, 't6', 600);
  sleepMs(100);
  t7 = setupTimer(1000, 't7', 100);
};

var start = new Date();
test();

var count = 0;
var monitor = setInterval(function(){
  count++;
  if (count >= 6) {
    clearInterval(t3);
    console.log('-------t3 cleared----------');
    clearInterval(monitor);
  }
}, 1000);

This is the output:

setup timer: t3 2000 1200 0.001
setup timer: t4 2000 500 1.017
setup timer: t5 2000 0 1.518
setup timer: t6 2000 600 2.008
setup timer: t7 1000 100 2.108
t3 2000 1200 2.109
t4 2000 500 3.309
t5 2000 0 3.809
t7 1000 100 3.809
t6 2000 600 4.008
t3 2000 1200 4.608
t4 2000 500 5.808
t5 2000 0 6.308
t7 1000 100 6.308
t6 2000 600 6.408
t3 2000 1200 7.008-----------previous 4.608  diff is 2.4s
t4 2000 500 8.208------------previous 5.808  diff is 2.4s
t5 2000 0 8.708-----------previous 6.308  diff is 2.4s
t7 1000 100 8.708---------previous 6.308 diff is 2.4s
t6 2000 600 8.808
t3 2000 1200 9.408
t4 2000 500 10.608
t5 2000 0 11.108
t7 1000 100 11.108
t6 2000 600 11.208
t3 2000 1200 11.808
t4 2000 500 13.008
t5 2000 0 13.508
t7 1000 100 13.508
t6 2000 600 13.608
t3 2000 1200 14.208
t4 2000 500 15.408
t5 2000 0 15.908
t7 1000 100 15.908
-------t3 cleared----------
t6 2000 600 16.008
t7 1000 100 16.908
t4 2000 500 17.408
t5 2000 0 17.908
t7 1000 100 17.909
t6 2000 600 18.009
t7 1000 100 18.909
t4 2000 500 19.409
t5 2000 0 19.909
t7 1000 100 19.91
t6 2000 600 20.01----------previous is 18.009  diff is 2.0s
t7 1000 100 20.91----------previous is 19.91 diff is 1.0s
t4 2000 500 21.41----------previous is 19.409 diff is 2.0s
t5 2000 0 21.91----------previous is 19.909 diff is 2.0s
t7 1000 100 21.91
t6 2000 600 22.01
t7 1000 100 22.91
t4 2000 500 23.411
t5 2000 0 23.911
t7 1000 100 23.911
t6 2000 600 24.011
t7 1000 100 24.911
t4 2000 500 25.412
t5 2000 0 25.912
t7 1000 100 25.912
...

Before t3 is cleared, the execute time is larger than repeat, so the diff is the real execute time.

After t3 is cleared, the execute time is less than repeat, then the diff is the repeat.

[misterdjules]

In #7386 @zhangzifa has suggested to use this patch as a fix:

diff --git a/lib/timers.js b/lib/timers.js
index dc2506e..fa3b3b7 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -169,7 +169,7 @@ function listOnTimeout() {
// Check if this loop iteration is too early for the next timer.
// This happens if there are more timers scheduled for later in the list.
if (diff < msecs) {

•  this.start(msecs - diff, 0);
  

•  this.start(msecs, 0);
  

  debug('%d list wait because diff is %d', msecs, diff);
  return;
  }

But I'm not sure that is correct

That patch is not correct exactly for the reasons @Fishrock123 outlined later in that comment:

we would now be rescheduling the full timer duration (msecs) from the first called timer rather than checking if it should fire before that full duration...

As mentioned before, this issue is fixed by #3063, which needs to be updated like described in #3063 in order for it to land.

The problem is well understood, and has been fixed for over a year in v0.10.x and v0.12.x versions. The only reason why this issue is still open is that the fix for these versions need to be ported (with #3063), it is not because it's a problem that needs to be solved.

[whitlockjc]

#3063 should be ready to be merged. If we could get a few new "LGTM" I'll land it.

[misterdjules]

@whitlockjc Before landing #3063, #3063 (comment) will need to be addressed. But please keep the conversation about #3063 in #3063. Thank you!

[misterdjules]

@zhangzifa It seems that, with your latest comment, you are referring to a different problem than this issue describes.

I believe you are referring to the same problem as #7346. Would you mind checking if it's indeed the case, and if so commenting in that issue?

Thank you!