CODEWITHSUNDEEP
javascriptnode.jssettimeout
BlackGlory
BlackGlory

Reputation: 4031

setTimeout calling the function prematurely

My library has test cases based on real time, and I noticed that tests will randomly fail with 1 millisecond error:

expect(received).toBeGreaterThanOrEqual(expected)

    Expected: >= 1000
    Received:    999

This seems to be due to setTimeout calling the function prematurely.

So I wrote a separate test script:

let last = Date.now()

setTimeout(next, 1000)

function next() {
  if (Date.now() - last < 1000) process.exit(1)
  last = Date.now()
  setTimeout(next, 1000)
}

On Node.js v12.19.0, v14.15.3, v15.4.0, it will fail randomly: sometimes the script can continue to run, sometimes the script will exit soon. This is not only happening on my local computer, but also on Github's CI server.

My questions: Is this a bug? Or some kind of expected behavior of setTimeout? Or Date.now() - time always needs to add 1 millisecond?

UPDATE: See also https://github.com/nodejs/node/issues/26578

Upvotes: 5

Views: 457

Answers (2)

Trott
Trott

Reputation: 70075

Timers (as of this writing) run with millisecond precision under the hood and always have in Node.js, so it has always been possible that a 1000ms timer might run after only (for example) 999.95ms. Since Date.now() is also millisecond precision, it's possible that the same duration of time might show up as only 999ms.

For example, hypothetically, a timer might start at 0.55ms after the epoch and run at 1000.45ms after the epoch. That's 999.9ms duration, which the millisecond precision rounds to 1000ms, which is why the timer runs. But Date.now() measures from the epoch. So as far as Date.now() is concerned, the timer was set at 1ms after the epoch (rounding from 0.55ms) and run at 1000ms after the epoch (rounding down from 1000.45ms), a duration of 999ms.

Whether this is a bug or merely a quirk is debatable. (I consider it a bug, but understand people who don't.)

I'm guessing this is just about getting a test to pass and not something that is actually likely to ever affect users. If so, you can safely change the expectation to >= 999. Another option that is more work is to use process.hrtime() or process.hrtime.bigint() to get a higher-precision timestamp and round accordingly.

Upvotes: 0

niry
niry

Reputation: 3308

Update: using git-bisect here is the culprit:

2c409a285359faae58227da283a4c7e5cd9a2f0c is the first bad commit
commit 2c409a285359faae58227da283a4c7e5cd9a2f0c
Date:   Tue Aug 25 13:36:37 2020 -0600

    perf_hooks: add idleTime and event loop util
    
    Use uv_metrics_idle_time() to return a high resolution millisecond timer
    of the amount of time the event loop has been idle since it was
    initialized.
    
    Include performance.eventLoopUtilization() API to handle the math of
    calculating the idle and active times. This has been added to prevent
    accidental miscalculations of the event loop utilization. Such as not
    taking into consideration offsetting nodeTiming.loopStart or timing
    differences when being called from a Worker thread.
    
    PR-URL: https://github.com/nodejs/node/pull/34938

This seems like a bug, not an expected behavior. I would vote against always adding 1ms since the behavior is inconsistent. (However, will it ever be earlier more than 1 ms? I didn't observe more than 1ms) You may workaround the problem with the following:

const origSetTimeout = setTimeout;
setTimeout = (f, ms, ...args) => {
  let o;
  const when = Date.now() + ms,
    check = ()=> {
      let t = when - Date.now();
      if (t > 0) Object.assign(o, origSetTimeout(check, t));
      else f(...args);
    };
  return o = origSetTimeout(check, ms);
};

It will allow to clearTimeout() even while working around the problem.

Here is a browser code that simulates the problem and alternates the workaround every 3 seconds:

// Simulate the problem
const realOrigSetTimeout = setTimeout;
setTimeout = (func, ms, ...args) => realOrigSetTimeout(func, ms - Math.random(), ...args);

const ms = 200;
let when = Date.now() + ms;
setTimeout(next, ms);

function next() {
  let now = Date.now();
  setTimeout(next, ms);
  console.log(now < when ? 'premature' : 'ok');
  when = now + ms;
}

function workAround() {
  console.log('Applying workaround');

  const origSetTimeout = setTimeout;
  setTimeout = (f, ms, ...args) => {
    let o;
    const when = Date.now() + ms,
      check = ()=> {
        let t = when - Date.now();
        if (t > 0) Object.assign(o, origSetTimeout(check, t));
        else f(...args);
      };
    return o = origSetTimeout(check, ms);
  };

  setTimeout(_=>{
    console.log('Removing workaround');
    setTimeout = origSetTimeout;
    setTimeout(workAround, 3000);
  }, 3000);
}
setTimeout(workAround, 3000);

Below is a nodejs code that will clearly show the problem ('p' among dots) and will apply the workaround after pressing enter.

'use strict';

const ms = 1;
let when = Date.now() + ms;
setTimeout(next, ms);

function next() {
  let now = Date.now();
  setTimeout(next, ms);
  process.stdout.write(now < when ? 'p' : '.');
  when = now + ms;
}

process.stdin.on('readable', _=> {
  console.log('enabling workaround');
  const origSetTimeout = setTimeout;
  setTimeout = (f, ms, ...args) => {
    let o;
    const when = Date.now() + ms,
      check = ()=> {
        let t = when - Date.now();
        if (t > 0) Object.assign(o, origSetTimeout(check, t));
        else f(...args);
      };
    return o = origSetTimeout(check, ms);
  };
});

Upvotes: 3

Related Questions