setTimeout Calling Callback Too Early

[fishcharlie]

• Version: v8.15.1
• Platform: Darwin Charlies-MacBook-Pro.local 18.2.0 Darwin Kernel Version 18.2.0: Thu Dec 20 20:46:53 PST 2018; root:xnu-4903.241.1~1/RELEASE_X86_64 x86_64

---

I have the following code in Node.js.

const timeout = (ms) => new Promise((resolve) => setTimeout(resolve, ms));

I'm trying to test this code with the following test:

it("Should wait for given time before resolving", async () => {
    const MS = 100;
    const start = process.hrtime();

    await timeout(MS);

    const diff = process.hrtime(start);
    expect(((diff[0] * NS_PER_SEC) + diff[1]) / 1000000).to.at.least(MS);
});

The problem is sometimes (rarely), this test fails:

Should wait for given time before resolving:

  AssertionError: expected 99.595337 to be at least 100
  + expected - actual

  -99.595337
  +100

Obviously this is some type of timing issue with Node.js or something. If anything I expect await timeout(MS); to take slightly longer than MS. In no case do I expect it to take less time.

What is it about the internals of JavaScript/Node.js that causes this to happen?

This occurred on macOS 10.14.3 running Node.js version 8.15.1.

[devsnek]

@bnoordhuis iirc there was another issue about timeouts firing early but i can't find it

[ZYSzys]

@devsnek I think you were saying #26155 if I'm not wrong.

[Trott]

/ping @nodejs/timers

I'm able to replicate using Node.js 8.15.1, 10.15.3, and 11.11.0. Here's the code I used. Start it and let it run for maybe 20 seconds or so and it will produce the error.

'use strict';
const assert = require('assert');

const timeout = (ms) => new Promise((resolve) => setTimeout(resolve, ms));

const test = async () => {
    const MS = 100;
    const start = process.hrtime();

    await timeout(MS);

    const diff = process.hrtime(start);
    const actual = ((diff[0] * 1e9) + diff[1]) / 1000000;
    assert(actual > MS, `${actual} ${MS}`);
    console.log('cool', actual, MS);
    setImmediate(test);
};

test();

OS info:

$ uname -a
Darwin Fhqwhgads.local 17.7.0 Darwin Kernel Version 17.7.0: Thu Dec 20 21:47:19 PST 2018; root:xnu-4570.71.22~1/RELEASE_X86_64 x86_64
$ 

[lpinca]

Can reproduce with the above test case.

$ uname -a
Darwin imac 18.2.0 Darwin Kernel Version 18.2.0: Thu Dec 20 20:46:53 PST 2018; root:xnu-4903.241.1~1/RELEASE_X86_64 x86_64

[Trott]

I'd be interested to know if non-macOS users are seeing this or not.

[targos]

I can reproduce on Windows:

PS C:\Users\targo\Desktop> node test
cool 103.681201 100
cool 100.133799 100
cool 101.023601 100
cool 100.028599 100
cool 100.9503 100
cool 100.593501 100
cool 100.9425 100
cool 100.4715 100
(node:6896) UnhandledPromiseRejectionWarning: AssertionError [ERR_ASSERTION]: 99.9421 100
    at Immediate.test (C:\Users\targo\Desktop\test.js:14:5)

[Fishrock123]

fwiw:

libuv loop times only run with millisecond precision:

• uv_now http://docs.libuv.org/en/v1.x/loop.html?highlight=uv_now#c.uv_now
• uv_timer_t http://docs.libuv.org/en/v1.x/timer.html

The comes from the fact that libuv only tacks loop times to millisecond precision: https://github.com/libuv/libuv/blob/2d2af382ce84b91d6ee7a185af32fca7f0acd84b/src/unix/internal.h#L289-L293

I do think that should round correctly though?

Measuring this "correctly" shows no issue though:

'use strict'
const assert = require('assert')
const { internalBinding } = require('internal/test/binding')
const { getLibuvNow } = internalBinding('timers')
const timeout = (ms) => new Promise((resolve) => setTimeout(resolve, ms))

const test = async () => {
    const MS = 100
    const start = getLibuvNow()

    await timeout(MS);

    const diff = getLibuvNow() - start
    assert(diff >= MS, `${diff} ${MS}`)
    console.log('cool', diff, MS)
    setImmediate(test)
}

test()

[lpinca]

This is reproducible even with Date.now() so I guess Date.now() and uv_now() work differently.

[Fishrock123]

Correct, uv_now() is, last I recall, more 'stable' than Date.now().

[bnoordhuis]

I'm reasonably sure this is caused by the interaction between setImmediate() and setTimeout() because just setTimeout() doesn't reproduce it. To wit, this fails after some time:

function test() {
  const start = process.hrtime.bigint()
  setTimeout(next, 100)
  function next() {
    const now = process.hrtime.bigint()
    const delta = now - start
    console.log(Number(delta / BigInt(1e6)),
                Number(delta % BigInt(1e6)))
    if (delta < BigInt(100 * 1e6)) throw 'fail'
    setImmediate(test)
  }
}
test()

Whereas this keeps on running:

function test() {
  const start = process.hrtime.bigint()
  setTimeout(next, 100)
  function next() {
    const now = process.hrtime.bigint()
    const delta = now - start
    console.log(Number(delta / BigInt(1e6)),
                Number(delta % BigInt(1e6)))
    if (delta < BigInt(100 * 1e6)) throw 'fail'
    test() // no setImmediate()
  }
}
test()

My guess is that something somewhere does or doesn't call uv_update_time(), causing a slight discrepancy in the time base used for different timers.

[apapirovski]

As @Fishrock123 pointed out, this is kind of expected due to the rounding hence it usually being off by sub 1ms. It also makes sense that it only occurs when there's other process activity.

Think about it like this:

1. You schedule a timer for 50ms at 100.2ms which is equivalent to 100ms.
2. If you don't have any other code running, libuv will let the system poll for 100ms which will be exact.
3. You run the callback roughly at 150.2ms which is exactly 50ms later.

Now imagine you introduce other code in there:

1. You schedule a timer for 50ms at 100.2ms which is equivalent to 100ms.
2. You schedule another timer for 48ms at 101ms.
3. You poll for for 48ms.
4. You come back to your second timer at 149ms and run its callback which, say, takes exactly 1ms.
5. At 150ms, both libuv and node are under the impression that your timer is ready to fire even though it's still technically 0.2ms off.

There's no real solution here other than making timers use more precise units under the hood.