Repository navigation
setInterval interval includes duration of callback #7346
Description
Activity
/cc @Fishrock123
I think this is a duplicate of #5426
Do note that the underlying implementation for
setInterval()andsetTimeout()is virtually the same and both return aTimeoutobject.- added a commit that references this issue
on Jun 24, 2016 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; };
@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 withsetInterval. 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
setIntervalcallbacks are called with a delay that is equal to the interval delay + the execution time of the callback. Fixing #5426 will not change that.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)endInterval2Note 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.
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.388ZWhat 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.953ZThis 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...
Reacted by Nikos Oikonomou, Timofei Trainenkov, Ioannis Varvarelis, zifa.zhang, Tyler Hartley, dt-rush, Chad Johnson and Charith Dissanayake- added a commit that references this issue
on Dec 15, 2017 - added a commit that references this issue
on Jan 12, 2018
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.jsfor node's behaviour andopen index.htmlfor browser behaviour.I have been using nodenv to switch between different node versions.