Skip to content

The execution order of asynchronous processes differs from other runtimes #965

@nabetti1720

Description

@nabetti1720

While I was implementing async_hooks, I was also studying asynchronous processing and came across a strange phenomenon while verifying the execution order.

// blockingTimer.js
function pause(milliseconds, order) {
  const dt = new Date();
  while ((new Date()) - dt <= milliseconds) {
    // Noop
  }
  console.log(`🦖 ${order} MAINLINE: Sync process: timer exit after ${milliseconds}`);
}

console.log("🦖 [1] MAINLINE: Sync process: start");

setTimeout(() => {
  console.log("⏰ [8] TIMER: setTimeout[1000ms] finished");
}, 1000);

setTimeout(() => {
  console.log("⏰ [7] TIMER: setTimeout[500ms] finished");
}, 500);

setTimeout(() => {
  console.log("⏰ [6] TIMER: setTimeout[0ms] finished");
}, 0);

setImmediate(() => {
  console.log("👨 [5] MACRO: setImmediate");
});

queueMicrotask(() => {
  console.log("👶 [4] MICRO: queueMicrotask");
});

pause(2000, "[2]"); // Blocking the event loop

console.log("🦖 [3] MAINLINE: Sync process: end");

Node.js :

% node blockingTimer.js 
🦖 [1] MAINLINE: Sync process: start
🦖 [2] MAINLINE: Sync process: timer exit after 2000
🦖 [3] MAINLINE: Sync process: end
👶 [4] MICRO: queueMicrotask
👨 [5] MACRO: setImmediate
⏰ [6] TIMER: setTimeout[0ms] finished
⏰ [7] TIMER: setTimeout[500ms] finished
⏰ [8] TIMER: setTimeout[1000ms] finished

Bun :

% bun blockingTimer.js
🦖 [1] MAINLINE: Sync process: start
🦖 [2] MAINLINE: Sync process: timer exit after 2000
🦖 [3] MAINLINE: Sync process: end
👶 [4] MICRO: queueMicrotask
👨 [5] MACRO: setImmediate
⏰ [6] TIMER: setTimeout[0ms] finished
⏰ [7] TIMER: setTimeout[500ms] finished
⏰ [8] TIMER: setTimeout[1000ms] finished

Deno (setImmediate() is not supported so I commented it out and ran it.) :

% deno run blockingTimer.js 
🦖 [1] MAINLINE: Sync process: start
🦖 [2] MAINLINE: Sync process: timer exit after 2000
🦖 [3] MAINLINE: Sync process: end
👶 [4] MICRO: queueMicrotask
⏰ [6] TIMER: setTimeout[0ms] finished
⏰ [7] TIMER: setTimeout[500ms] finished
⏰ [8] TIMER: setTimeout[1000ms] finished

The numbers are in the expected output order, but LLRT gives different results.

LLRT :

% llrt blockingTimer.js
🦖 [1] MAINLINE: Sync process: start
🦖 [2] MAINLINE: Sync process: timer exit after 2000
🦖 [3] MAINLINE: Sync process: end
👨 [5] MACRO: setImmediate
👶 [4] MICRO: queueMicrotask
⏰ [8] TIMER: setTimeout[1000ms] finished
⏰ [7] TIMER: setTimeout[500ms] finished
⏰ [6] TIMER: setTimeout[0ms] finished

As for No. 4 and 5, the implementation calls the same JS_EnqueueJob(), so it appears that the behavior follows the registration order. Since JS_EnqueueJob() is also used inside Promises, we can assume that it is a queue of microtasks, so setImmediate tasks should not be put into the same queue.

Regarding 6, 7 and 8, are these issues related to the implementation of the LLRT timer processing? It may have something to do with all the timeout conditions having been met by the time the 2 second pause is lifted. Strictly speaking, when registering a new timer, it seems necessary to sort them by remaining time (or by order of registration if the remaining time is the same). If that's too much hassle, I think you could achieve the same effect if you could control the callback order of the timers that fire at the time the firing decision is made. To do this, you need to store the scheduled firing time when you register the timer.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions