setInterval interval includes duration of callback #7346

Activity

1. mscdex

   added

   timersIssues and PRs related to timers, setImmediate(), setInterval(), and setTimeout().Issues and PRs related to timers, setImmediate(), setInterval(), and setTimeout().

   on Jun 21, 2016
2. mscdex commented on Jun 21, 2016

   

   mscdex

   on Jun 21, 2016

   Contributor

   More actions

   /cc @Fishrock123
3. Fishrock123 commented on Jun 23, 2016

   

   Fishrock123

   on Jun 23, 2016

   Contributor

   More actions

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

   added a commit that references this issue on Jun 24, 2016

   test: add tests for ensuring proper timer delays

   ...

   e0ef4ea
5. zhangzifa commented on Jul 6, 2016

   

   zhangzifa

   on Jul 6, 2016

   Contributor

   More actions

   @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;
    };
6. misterdjules commented on Jul 6, 2016

   

   misterdjules

   on Jul 6, 2016

   More actions

   @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.
7. renewooller commented on Mar 16, 2017

   

   renewooller

   on Mar 16, 2017

   Last edited by gibfahn

   More actions

   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.
8. mitsos1os commented on May 10, 2017

   

   mitsos1os

   on May 10, 2017

   Contributor

   More actions

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

   👍React with 👍8Reacted by Nikos Oikonomou, Timofei Trainenkov, Ioannis Varvarelis, zifa.zhang, Tyler Hartley, dt-rush, Chad Johnson and Charith Dissanayake
9. Trott

   added a commit that references this issue on Dec 15, 2017

   timers: setInterval interval includes cb duration

   ...

   3e47c6c
10. BridgeAR

    added a commit that references this issue on Jan 12, 2018

    timers: setInterval interval includes cb duration

    ...

    1385e1b
11. BridgeAR

    closed this as completedin 1385e1bon Jan 12, 2018