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

[Fishrock123]

Ah yes, I was missing the initial scheduling rounding.

While this may technically be unintended, I don’t see any practical issue arising from this.

[fishcharlie]

Is there plans to maybe make timers use more precise units under the hood then? Or is this too minor to be addressed?

[Fishrock123]

Is there a reasonable use case for more precision on timers?

Keep in mind, timeout time is not guaranteed at all to begin with - it is only guaranteed to be after the set amount of time (rounded).

[fishcharlie]

@Fishrock123 I don't have a major use case right now. Maybe I would in the future. But my only reason for wanting to be more precise is so I don't have to write rounding code in that test. Super minor tho. Adding one extra line of code or so isn't a big deal at all.

To me, it just seems like it should be more precise. Maybe I just missed it, but I struggled to find documentation about this. I think it's a reasonable expectation that the callback will be fired after the time, not before. So since that is not the case I would have expected to find some type of documentation about that.

Maybe it's such a minor thing that it's not worth it tho.

[apapirovski]

@fishcharlie if you want to open a PR to add a note to the documentation, that would be appreciated! Realistically I don’t see us switching to hrtime.

[Fishrock123]

I am not opposed to the idea of ensuring the checks are rounded in such a way to ensure that the time is always at least the specified duration.

I do not know how feasible that would be, though.

[devsnek]

We could use Math.round instead of Math.trunc

[Fishrock123]

@devsnek If that was the issue then the code posted in https://github.com/nodejs/node/issues/26578#issuecomment-471694685 shouldn't work.

[devsnek]

@Fishrock123 do you mean that putting a number like 10.3 could fire before 10.3 ms was up? Right now we use Math.trunc on the idle time, which would turn 10.3 and 10.7 into 10. Math.round was sort of my compromise between Math.ceil and Math.trunc. I think using Math.ceil would also be totally reasonable though.

[Fishrock123]

@devsnek This is not about the input number. Please re-read this issue, especially Rich's example and Anatoli's comment.

[fishcharlie]

So just to confirm, this can be up to 1 ms off? So in my test just doing Math.round will not fix this issue. Using something like Math.ceil in my test should fix this issue tho, correct?

[Fishrock123]

Maybe we should still try to round up everywhere for this? That could mean a 1ms timeout ends up taking 2ms though. I'm not sure whether or not that _actually_ matters.