setInterval interval includes duration of callback

[distributedlife]

• Version: Multiple
• Platform: Darwin 15.5.0 Darwin Kernel Version 15.5.0: Tue Apr 19 18:36:36 PDT 2016; root:xnu-3248.50.21~8/RELEASE_X86_64 x86_64

When using setInterval in node, I find that node waits until the callback is complete before scheduling the next interval. This appears to be different behaviour to setInterval on Chrome, Safari, Opera and Firefox. My expectation was that setInterval would try to schedule on the interval. At present I find the behaviour equivalent to setTimeout with automatic rescheduling.

I've read #5426 and #3063 and while the seem to relate, they refer to setTimeout and not to setInterval.

I've have test scenarios and results in this repository.

My test is to execute setInterval with a 100ms interval. The callback spends about 5-7ms calculating fibonacci. At the start of the callback I record the current time. I let the setInterval run for 10 seconds. Afterwards I calculate the delta between setInterval calls.

The aforementioned browsers have an average delta between 100-103ms. I don't expect the delta to be exactly 100ms.

When running on node 0.x, I get results of 106-107ms for the average delta. This is the interval plus the approximate duration of the callback. When running on node 4, 5 or 6, I get 112-114ms. About double the callback duration.

If I increase the workload of the fibonacci function from 2,000,000 to 20,000,000 cycles the browsers stay at ~100ms, while node 0.x jumps to ~130-140ms and node 4+ to ~180-190ms. With this we're executing 2 callbacks in node to every 3-4 in the browser.

If you want to run the tests you can clone set-interval-behaviour and run node index.js for node's behaviour and open index.html for browser behaviour.

I have been using nodenv to switch between different node versions.

Implementation	Average Delta
node 6.2.1	113.79
node 5.11.1	114.58
node 4.4.5	112.83
node 0.12.14	107.28
node 0.10.45	106.51
Chrome 51.0.2704.84	100.02
Firefox 47.0	101.87
Firefox 45.0.2	103.36
Firefox 43.0.4	99.97
Opera 38.0.2220.31	100.03
Opera 37.0.2178.32	100.02
Safari 9.1.1	103.06

[mscdex]

/cc @Fishrock123

[Fishrock123]

I think this is a duplicate of #5426

Do note that the underlying implementation for setInterval() and setTimeout() is virtually the same and both return a Timeout object.

[zhangzifa]

@distributedlife

I think this is what you want if you want an accurate timer set by setInterval. this is based on LTS 4.x.

iff --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;
 };

[misterdjules]

@Fishrock123 This issue is not a duplicate of #5426. #5426 is 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 mentions the problem in #5426 when it says:

When running on node 0.x, I get results of 106-107ms for the average delta. [..] When running on node 4, 5 or 6, I get 112-114ms.

However this is not the core of what this issue is about. This issue is about what nodejs/node-v0.x-archive#8066 describes too, that is setInterval callbacks are called with a delay that is equal to the interval delay + the execution time of the callback. Fixing #5426 will not change that.

[renewooller]

I've found a similar issue in node v5.12.0.

For what it's worth, here's the simple test, and the results, which really highlight the problem.

'use strict'

let delay = function(s) {
    console.log((new Date())+'start delay')
    var startTime = Date.now()
    while(Date.now() < startTime + s*1000) {}
    console.log((new Date())+'finish delay');
}

let count = 1;

let interval = setInterval(function() {
    console.log((new Date()) + 'startInterval' + count);
    delay(5); // 5 second delay
    console.log((new Date())+ 'endInterval' + count);
    count++;
}, 500)

node timerTest.js 
Thu Mar 16 2017 15:21:03 GMT+1000 (AEST)startInterval1
Thu Mar 16 2017 15:21:03 GMT+1000 (AEST)start delay
Thu Mar 16 2017 15:21:08 GMT+1000 (AEST)finish delay
Thu Mar 16 2017 15:21:08 GMT+1000 (AEST)endInterval1
Thu Mar 16 2017 15:21:14 GMT+1000 (AEST)startInterval2
Thu Mar 16 2017 15:21:14 GMT+1000 (AEST)start delay
Thu Mar 16 2017 15:21:19 GMT+1000 (AEST)finish delay
Thu Mar 16 2017 15:21:19 GMT+1000 (AEST)endInterval2

Note that even if the second evaluation of the callback couldn't complete because the first one was already running, when it is fired, it should have happened 500ms after, not a whole 6 seconds after.

[mitsos1os]

I totally agree with the mentioned problem. It is also happening on latest Node v7.10.0
This shouldn't be the expected behavior!!!
It is acceptable to have a delay when the event loop is busy processing the stack before triggering the setInterval callback, but when will this be triggered should not depend on the time spent inside the callback.

I cannot understand how can this not happen in Chrome which is using the same V8 Engine.

This could be really easy bypassed by setting the new timeout as the first command in the interval and not after its completion. This could be done, by sending the callback execution at the end of event loop (maybe using a promise, or process.nextTick). Example:

The delay function makes a silly computation just to keep the cpu busy

'use strict';

const x = 1245;
const times = 1000000000;

function delay() {
	for (let i = 0; i < times; i++) {
		x*x;
	}
}

setInterval(() => {
	console.log(new Date().toISOString());
	delay(); // delay 2 seconds
}, 3000);

This outputs the time drifted for 2 seconds, like the interval was actually 5:

2017-05-10T09:45:24.680Z
2017-05-10T09:45:29.858Z
2017-05-10T09:45:35.007Z
2017-05-10T09:45:40.158Z
2017-05-10T09:45:45.388Z

What SHOULD happen is demonstrated with this code:

'use strict';

const x = 1245;
const times = 1000000000;

function delay() {
	for (let i = 0; i < times; i++) {
		x*x;
	}
}

setInterval(() => {
	console.log(new Date().toISOString());
	process.nextTick(() => delay()); // delay 2 seconds send to end of eventloop
        // Promise.resolve().then(() => delay()); // This could also be valid
}, 3000);

Output:

2017-05-10T09:43:54.943Z
2017-05-10T09:43:57.949Z
2017-05-10T09:44:00.953Z
2017-05-10T09:44:03.953Z

This has to be fixed immediately. I found this on our server logs, where a recurring process acquired steadily a drift over time. This is also nowhere mentioned in the docs. This is really bad for the trust on NodeJS ecosystem in general, when there are such basic inconsistencies...

Please give it the proper attention. I find it unacceptable for this and similar issues to be abandoned for months...