nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
105.47k stars 28.6k forks source link

Race conditions between setTimeout() & setImmediate() #48163

Open ckcr4lyf opened 1 year ago

ckcr4lyf commented 1 year ago

Test

test-timers-immediate-queue.js

Platform

Linux x64

Console output

02:49:14 not ok 2722 parallel/test-timers-immediate-queue
02:49:14   ---
02:49:14   duration_ms: 140.40000
02:49:14   severity: fail
02:49:14   exitcode: 1
02:49:14   stack: |-
02:49:14     hit 20
02:49:14     node:assert:125
02:49:14       throw new AssertionError(obj);
02:49:14       ^
02:49:14     
02:49:14     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
02:49:14     
02:49:14     20 !== 10
02:49:14     
02:49:14         at process.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/test/parallel/test-timers-immediate-queue.js:56:10)
02:49:14         at process.emit (node:events:523:35) {
02:49:14       generatedMessage: true,
02:49:14       code: 'ERR_ASSERTION',
02:49:14       actual: 20,
02:49:14       expected: 10,
02:49:14       operator: 'strictEqual'
02:49:14     }
02:49:14     
02:49:14     Node.js v21.0.0-pre

Build links

Additional information

This seems to be some kinda potential race condition between setTimeout() and setImmediate() ?

For the following code, it seems TIMEOUT or IMMEDIATE either could be printed first, since over a few runs the order will flip.

setTimeout(() => {
    console.log('TIMEOUT')
}, 1);
setImmediate(() => {
    console.log('IMMEDIATE');
})

However on my machine, the following code will always result in TIMEOUT being printed first - the while loop strategy is what the test uses

setTimeout(() => {
    console.log('TIMEOUT')
}, 1);
const now = Date.now();
while (Date.now() - now < 2);
setImmediate(() => {
    console.log('IMMEDIATE');
})

I was wondering: is it possible due to some conditions on the host system, for IMMEDIATE to print before TIMEOUT in the second case?

I do not know much about the Event Loop internals, but from some rough reading, setTimeout() will put calbacks in the timers queue, setImmediate() in the I/O queue, and the timers are always checked first (https://nodejs.org/en/docs/guides/event-loop-timers-and-nexttick)

But if in the first case (setTimeout without while waiting loop) it is non-predictable, I wonder if there are other factors at play, which make the test flaky.

ckcr4lyf commented 1 year ago

Caused failure for #48159

bnoordhuis commented 1 year ago

The subject issue says setTimeout() & setInterval() but looks like it's really about setTimeout() & setImmediate()?

ckcr4lyf commented 1 year ago

Correct, my bad. Let me fix it.

ywave620 commented 1 year ago

The timer module only cares about relative time, so node chooses to use gethrtime() as the time source, while the Date.now() is using gettimeofday(). If the clock under the gethrtime() goes enough slower than the one under gettimeofday(), then 'IMMEDIATE' may print first.

setTimeout(() => {
    console.log('TIMEOUT')
}, 1);
const now = Date.now();
while (Date.now() - now < 2);
setImmediate(() => {
    console.log('IMMEDIATE');
})
ckcr4lyf commented 1 year ago

Considering the test is testing timers explicitly, would it be better to change it to use process.hrtime() in the now / while condition instead?