Repository navigation
non-deterministic order of execution of setTimeout vs setImmediate #392
Description
Activity
Is that because
setTimeout()delay when set to0is internally converted to1(which may or may not be due when checked in the timers phase)I think that’s exactly it. You can check that this makes sense by increasing the timeout to, say, 50, and you can see a clear difference in behaviour when adding
const a = Date.now(); while(Date.now() - a < 100);.As per the documentation,
setImmediateis supposed to be triggered BEFORE any other timers such as created withsetTimeout.There is a bug in nodejs/node#7145 though that means that this doesn't always work.
The upshot though is that you should always expect
setImmediatebut sometimes (until the bug is fixed)setTimeoutmight win as well.From documentation:
setImmediate()Schedules the "immediate" execution of the callback after I/O events' callbacks and before timers created using setTimeout() and setInterval() are triggered.It says that immediates are executed after events and before timers, it describes the order of execution in the event loop, and since it is a loop, another way of describing it:
timers are called before events, and events are called before immediates
is also true. It depends from which point we look at the event loop.
how
setImmediate()documentation presents the order of execution:- events
- immediates
- timers
order in the source code:
- timers
- events
- immediates
Important thing here is that timers phase comes directly after main code has been executed. It is the first phase of the event loop. If there are expired timers at this point, they will be executed before any
setImmediatecallbacks or event callbacks.nodejs/node#7145 is not a bug.
In your test code you havesetTimeout()andsetImmediate()run in thesetTimeout()callback.
Simplifying source code of the timers phase, it work like this:while there are any expired callbacks then run the callbacks; otherwise proceed to the next phase.
Since you're adding another timer inside of a
setTimeoutcallback with the 1ms delay, it can happen that the callback execution time is over 1ms, which causes just set timer to expire, and therefore it is executed immediately after the code that set it and beforesetImmediate(), which makes your code throw an error.Timers phase will only end if there are no more expired timers. If new timers are being added in the timer callbacks, it is possible that timer phase will never end.
Example:
const timer = () => { setTimeout(timer, 1) setImmediate(() => console.log('immediate fired')) // this will never be logged const date = new Date() while (new Date() - date < 2) {} } timer()
Reacted by Qwerty (Vítězslav Ackermann Ferko) and FonteynHi @marzelin,
Thanks for your long explanation. The code that I put up is what you should be looking at.
Let me take you through it. So, there is two events which are being handled -
uncaughtExceptionbeforeExit
uncaughtExceptionis just to output a custom message when we get an error.The important bit though is
beforeExit. This will fire once there is no events ready to be fired so we are starting at the beginning of each call with a clean slate of the queues.Then it fires off 2
setImmediateand onesetTimeout(() => {}, 1. As per the spec...Schedules the "immediate" execution of the callback after I/O events' callbacks and before timers created using
setTimeout()andsetInterval()are triggered.So, all 3 events are queued in the same tick so if keeping to the spec the 2
setImmediateevents should always be fired before thesetTimeout. This is not the case - as you can see from the results.BTW, in your example, you have specified that
// this will never be loggedbut it is.Regards,
The following diagram illustrates all stages of an event loop iteration:
Your
beforeExit()function is run in the close callbacks stage
setTimeout()callbacks are run in the due timers phase
setImmediate()callbacks are run in the check handles phaseAs you can see, due
setTimeout()callbacks are run beforesetImmediate()callbacksWhen
setImmediate()is run in the phases after due timers phase and before check phase, that is following phases:- pending callbacks
- idle handles
- prepare handles
- poll for i/o
it is guaranteed that
setImmediate()callbacks will run beforesetTimeout()callbacks. In other cases expired timers take precedence.For example, when calling
setImmediate()in an i/o event handler, it is guaranteed thatsetImmediate()callback will run before any timers:const readdir = require('fs').readdir let immediateFired; let numberOfIterations = 0; // Handle any errors or rejections process.on('uncaughtException', (err) => { console.error(`uncaughtException handled on iteration ${numberOfIterations}`) console.error(`immediateFired: ${immediateFired}`) process.exit(1); }); console.log(`Running test at ${new Date().toISOString()} on`, process.release, process.arch); process.on('beforeExit', function() { immediateFired = 0; numberOfIterations++; //////////////////////////////////////////////////////////////////////////////// // main() // main function is called from 'close callbacks' phase (expired timers are executed before immediates) // setTimeout(main, 1) // main function is called from 'due timers' phase (expired timers are executed before immediates) // setImmediate(main) // main function is called from 'check handles' phase (expired timers are executed before immediates) readdir(__dirname, main); // main function is called from 'Poll for I/O' phase (immediates are executed before expired timers) /////////////////////////////////////////////////////////////////////////////// }); function main() { setImmediate(() => { immediateFired++; // console.log('setImmediate 1 fired'); }); setTimeout(() => { if (immediateFired < 2) { throw new Error('setTimeout was fired before set immediate'); } // console.log('setTimeout 1'); }, 1); setImmediate(() => { immediateFired++; // console.log('setImmediate 2 fired'); }); }
is there more factors that contribute to this non-deterministic behavior?
As Node.js doc says:
setimmediate-vs-settimeout
The order in which the timers are executed will vary depending on the context in which they are called. If both are called from within the main module, then timing will be bound by the performance of the process (which can be impacted by other applications running on the machine).
For example, if we run the following script which is not within an I/O cycle (i.e. the main module), the order in which the two timers are executed is non-deterministic, as it is bound by the performance of the process:Why ?.
Every event in node.js is driven by
uv_run()function of libuv. Partial Codeint uv_run(uv_loop_t* loop, uv_run_mode mode) { int timeout; int r; int ran_pending; r = uv__loop_alive(loop); if (!r) uv__update_time(loop); while (r != 0 && loop->stop_flag == 0) { uv__update_time(loop); uv__run_timers(loop); ran_pending = uv__run_pending(loop); uv__run_idle(loop); uv__run_prepare(loop); ...... uv__io_poll(loop, timeout); uv__run_check(loop); uv__run_closing_handles(loop); ............So As explained by the node.js Doc, we can match each Phase of the event loop in the code.
Timer Phase
uv__run_timers(loop);I/O Callback
ran_pending = uv__run_pending(loop);idle/ prepare
uv__run_idle(loop); uv__run_prepare(loop);poll
uv__io_poll(loop, timeout);check
uv__run_check(loop);close callbacks
uv__run_closing_handles(loop);More than phase
But if we see the code closely before the loop goes to timer phase, it calls
uv__update_time(loop);to initialize the loop time.void uv_update_time(uv_loop_t* loop) { uv__update_time(loop); }What happens is
uv__update_time(loop)calls an functionuv__hrtimeUV_UNUSED(static void uv__update_time(uv_loop_t* loop)) { /* Use a fast time source if available. We only need millisecond precision. */ loop->time = uv__hrtime(UV_CLOCK_FAST) / 1000000; }This call to
uv__hrtimeis platform dependent and is cpu-time-consuming work as it makes system
call to clock_gettime. It's is impacted by other application running on the machine.#define NANOSEC ((uint64_t) 1e9) uint64_t uv__hrtime(uv_clocktype_t type) { struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); return (((uint64_t) ts.tv_sec) * NANOSEC + ts.tv_nsec); }Once this is returned Timer phase is called in the event loop.
void uv__run_timers(uv_loop_t* loop) { ... for (;;) { .... handle = container_of(heap_node, uv_timer_t, heap_node); if (handle->timeout > loop->time) break; .... uv_timer_again(handle); handle->timer_cb(handle); } }The callback in the Timer phase is run if the current time of loop is greater than the timeout.
One more important things to note issetTimeoutwhen set to0is internally converted to1.
Also as thehr_timereturn time in Nanoseconds, this behaviour as shown by thetimeout_vs_immediate.jsbecomes more explanatory now.If the preparation before the first loop took more than
1msthen theTimerPhase calls the callback associated with it. If it's is less than1msEvent-loop continues to next phase and runs thesetImmediatecallback in check phase of the loop andsetTimeoutin the
next tick of the loop.Hopefully this clarifies the way around the non-deterministic behaviour of
setTimeoutandsetImmediatewhen both are called from within the main module.Reacted by Mohammad Aziz, Uladzimir Aleshka, Harleen Mann, Serhii Drahunov, Qwerty (Vítězslav Ackermann Ferko), vdmchpg, Fonteyn, SAU1999, wind4gis, Bruce Liu and 14 moreReacted by Harleen Mann, vdmchpg, Fonteyn, wind4gis, Bruce Liu, Mihail, Calina Cristian, Destroyer, Pramithas Dhakal, nimapdevyash and 1 moreReacted by nimapdevyashGreat answer. Thanks @ankur-anand
@ackvf timers were broken before nodejs/node#3063 landed in v6.3.1
Since then, the behavior of timers was as I presented here. And the example code still works on node versions that were shipped from roughly the second half of 2016 to the end of 2017 i.e. 6.3.1 - 6.12.0 or 8.0.0 - 8.7.0 (you can check it easily with
npx -p node@8.7.0 -- node testfile.js)Although this behavior doesn't violate any specification, having timers that can starve the loop is not particularly useful, to say the least.
So, since nodejs/node#15072 landed, you can't block the event loop with
setTimeoutorsetInterval.Referring to @marzelin 's comment here - If new (immediately expiring) timers are being added while executing the current setTimeout, how can it be added and executed in the same iteration. From what i understood it will not be picked up until the next iteration of the event loop, - the reason being this below, from libuv design
Did i understand it right?But why when setImmediate() is scheduled under Poll phase, its callback is always executed before setTimeout? Does 2nd tick bypass Timer phase? or is setImmediate callback executed directly in 1st tick?
fs.readFile('xx', () => { setTimeout(() => { console.log('timeout'); }, 0); setImmediate(() => { console.log('Immediate'); }); })
I have read the node blog and everywhere else, still don't find the exact reason.
The flow of execution in the event loop is strictly specified:
Hence, when we have main script:
with
setTimeout()callback with the0delay time (which makes it due initially) should be called beforesetImmediate()callbacks that are executed in check phase that takes place after timers phase.But it is not so. The order is pretty random.
Is that because
setTimeout()delay when set to0is internally converted to1(which may or may not be due when checked in the timers phase), or is there more factors that contribute to this non-deterministic behavior?