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?

Solution

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

setTimeout calling the function prematurely

Update: using git-bisect here is the culprit:

Update: using `git-bisect` here is the culprit: