non-deterministic order of execution of setTimeout vs setImmediate

[marzelin]

The flow of execution in the event loop is strictly specified:

• timers
• pending callbacks
• idle handles
• prepare handles
• poll for i/0
• check handles
• close callbacks

Hence, when we have main script:

// main_script.js
setTimeout(function timeout () {
  console.log('timeout');
},0);

setImmediate(function immediate () {
  console.log('immediate');
});

with setTimeout() callback with the 0 delay time (which makes it due initially) should be called before setImmediate() 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 to 0 is internally converted to 1 (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?

[addaleax]

Is that because setTimeout() delay when set to 0 is internally converted to 1 (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);.

[blacksun1]

As per the documentation, setImmediate is supposed to be triggered BEFORE any other timers such as created with setTimeout.

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 setImmediate but sometimes (until the bug is fixed) setTimeout might win as well.

[marzelin]

@blacksun1

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 setImmediate callbacks or event callbacks.

nodejs/node#7145 is not a bug.
In your test code you have setTimeout() and setImmediate() run in the setTimeout() 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 setTimeout callback 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 before setImmediate(), 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()

[blacksun1]

Hi @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 -

• uncaughtException
• beforeExit

uncaughtException is 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 setImmediate and one setTimeout(() => {}, 1. As per the spec...

Schedules the "immediate" execution of the callback after I/O events' callbacks and before timers created using setTimeout() and setInterval() are triggered.

So, all 3 events are queued in the same tick so if keeping to the spec the 2 setImmediate events should always be fired before the setTimeout. This is not the case - as you can see from the results.

BTW, in your example, you have specified that // this will never be logged but it is.

Regards,

[marzelin]

@blacksun1

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 phase

As you can see, due setTimeout() callbacks are run before setImmediate() callbacks

[marzelin]

@blacksun1

When 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 before setTimeout() callbacks. In other cases expired timers take precedence.

For example, when calling setImmediate() in an i/o event handler, it is guaranteed that setImmediate() 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');
  });
}

[ankur-anand]

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 Code

int 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 function uv__hrtime

UV_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__hrtime is 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 is setTimeout when set to 0 is internally converted to 1.
Also as the hr_time return time in Nanoseconds, this behaviour as shown by the timeout_vs_immediate.js becomes more explanatory now.

If the preparation before the first loop took more than 1ms then the Timer Phase calls the callback associated with it. If it's is less than 1ms Event-loop continues to next phase and runs the setImmediate callback in check phase of the loop and setTimeout in the
next tick of the loop.

Hopefully this clarifies the way around the non-deterministic behaviour of setTimeout and setImmediate when both are called from within the main module.

[marzelin]

Great answer. Thanks @ankur-anand

[ackvf]

@marzelin The example did not work as expected and immediate fired was all over my console, how come? Also in node 9, 10, 12

[marzelin]

@ackvf timers were broken before https://github.com/nodejs/node/pull/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 https://github.com/nodejs/node/pull/15072 landed, you can't block the event loop with setTimeout or setInterval.

[vysh1986]

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?

[Samjin]

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.