setInterval/setTimeout interval should not include duration of callback

[zhangzifa]

• Version: Multiple
• Platform: Linux u 3.19.0-15-generic domain: add arguments for the function in domain.run() #15-Ubuntu SMP Thu Apr 16 23:32:37 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: timer

@Fishrock123 @misterdjules @whitlockjc @bnoordhuis

This is an issue about if callback duration should be included in setInterval/setTimeout interval or not.

In my opinion, callback duration should NOT be included in interval.

Yes, we know JavaScript timer is not 100% accurate. However, it should be logically accurate, which is important and necessary, especially for the IoT applications.

setInterval/setTimeout is defined in ../lib/timer.js as:

exports.setTimeout = function(callback, after) {
...
exports.setInterval = function(callback, repeat) {
...

Timer should follow these rules(repeat stands for both repeat and after):

• If all the callbacks in a timer list can be executed within repeat, the real interval should be repeat.
• If all the callbacks in a timer list executed longer than repeat, the real interval should be the real execute time (given other event almost takes little time to execute).
• The above logic should work for timers with different repeat.

When using setInterval, the real interval is not as expected.

• Node.js 4.x, 5.x and 6.x:
  • Real interval includes double duration of callback.
• Node.js 0.10.x and 0.12.x
  • Real interval includes the duration of callback.

If you want to know the detailed test and result, please move to #7346, provided by @distributedlife .

From the discussion of #5426 #3063, it's an known issue.

And has been fixed for over a year in v0.10.x and v0.12.x versions.

I raised another #7386. However, that fix is not mature.

How should setInterval behaves? [#3063] provides an port from 0.10.x and 0.12.x.

I think there is a better solution to make the real interval not include callback duraiton.

This fix works for #5426, too. I list the output at the end of this issue.

The following works as the above (code based on LTS 4.x):

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
...

validation for #5426

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();

$ node iii.js    // without fix
tick delta: 8
tick delta: 2
tick delta: 102
tick delta: 100
tick delta: 101
tick delta: 101
tick delta: 101
tick delta: 101
tick delta: 101
tick delta: 101
tick delta: 101

$ ./node iii.js    // with fix
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]

This is.. yet another? Duplicate of #5426 ... I'll try to get it fixed for the release after v6.3.0

[misterdjules]

This issue conflates two separate issues into one:

1. setTimeout() introduces artificial delay between ticks when doing synchronous work #5426, which is only about a problem where the delay of a nested timer is incorrectly offset when scheduled with setTimeout, and offset by a larger delay than it should when scheduled with setInterval. This issue is being fixed in timers: fix processing of nested same delay timers #3063.

2. As described in the original comment, whether:

   callback duration should be included in setInterval/setTimeout interval or not.

   which is also described in setInterval interval includes duration of callback #7346 and setInterval doesn't comply with DOM-version node-v0.x-archive#8066.

I believe it would help if we kept these two issues separate, so please comment in the respective separate issues/PRs instead of creating new ones that conflate distinct problems.