setInterval where callback "work" time is more then interval, will sleep for work time, not zero

[onnlucky]

• Version: v5.9.0 (but any version of lib/timers.js) I have seen so far
• Platform:Darwin imac15.local 15.3.0 Darwin Kernel Version 15.3.0
• Subsystem: timer

When setting setInterval with a relatively short interval, and a callback that (sometimes) takes longer on cpu then that short interval, will delay the next callback by time it was on cpu, not 0 or interval.

Below is a testcase from what could be a gameloop that tries to do work every 100 millis exactly. When the simulated work is more then 1 millis, it will run into the problem above.

The scope of the bug is slightly more broad: any setInterval or setTimer with a certain timeout T, if we are currently processing timers of that T, and total processing of all timers of time T takes more time then T, the system will go into this state, where it will postpone for exactly CPU time. Resulting in a system that when under load uses exactly 50% cpu. Moreover, newly scheduled timers might get processed in the same loop, which violates the (perhaps implicit) contract that newly scheduled timers are only processed in the next io loop.

Related, this way of handling repeated timers means the actual interval is T + average cpu time of all timers of T.

var MILLIS = 100

var list = []
var last = +new Date
var sleepStart = +new Date

function work() {
    var start = +new Date
    if (start - last < MILLIS) return
    last = start - ((start - last) - MILLIS)

    list.length = 0
    for (var i = 0; i < 800000; i++) {
        list.push(String(i))
    }
    var end = +new Date
    var sleeptime = start - sleepStart
    var worktime = end - start
    var total = sleeptime + worktime
    console.log("worked for:", worktime, "millis", "slept for:", sleeptime, "total:", total, (total > MILLIS && sleeptime > MILLIS - worktime + 5? "oeps":""))
    sleepStart = end
}

setInterval(work, 1)

a preliminary fix, but still a problem, the this.start(0, 0), or this.start(msec - diff, 0) have no relation with the actual current time, and TimerWrap.now() returns loop time, not wallclock time.

diff --git a/lib/timers.js b/lib/timers.js
index 478a054..3b28aab 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -166,6 +166,13 @@ function listOnTimeout() {
   while (timer = L.peek(list)) {
     diff = now - timer._idleStart;

+    // Check if any new timers are sheduled after we started processing this list
+    if (diff <= 0) {
+      this.start(0, 0);
+      debug('%d list break because next timer is from the future %d', msecs, diff);
+      return;
+    }
+
     // 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) {

[benjamingr]

The current behavior is also what browsers do, right?

Also ping @Fishrock123 for timers.

[onnlucky]

The current behavior is also what browsers do, right?

No, most browsers schedule the repeat before handling the callback, like libuv does for instance: https://github.com/libuv/libuv/blob/v1.x/src/unix/timer.c#L165 that also prevents the interval from becoming effectively timeout + cputime.

Wheras due to this bug, if all timers of timeout T have a total cpu time > T, and that is all you do, you get exactly 50% cpu usage, because nodejs is going to sleep for exactly total cpu time.

[misterdjules]

@onnlucky Thanks for the detailed bug report!

I believe this is a duplicate of #5426 and is fixed by #3063, which hopefully will land soon. Closing, but feel free to let me know if it should be reopened.

Thanks again!

[onnlucky]

Excellent! Indeed that is the same issue.

I had used search, but the issues referenced are all already set to closed. Perhaps it is better to keep issues open until the pull request has landed? Or perhaps I should have search the pull requests as well?

[misterdjules]

@onnlucky

I had used search, but the issues referenced are all already set to closed. Perhaps it is better to keep issues open until the pull request has landed? Or perhaps I should have search the pull requests as well?

Good suggestion. I reopened #5426 to have one issue in nodejs/node that describes this problem. I still think we can close duplicate issues like this one as duplicate, as long as we mention what is the reference issue in their comments and we label them properly.

Let me know if that works for you!

[onnlucky]

@misterdjules Agree, keep one open, close duplicates. Thanks