CODEWITHSUNDEEP
javascriptnode.jstimerevent-loop
kal
kal

Reputation: 13

Confused about timers and microtasks in Nodejs event loop

I'm confused about the output of the code below. (Taken from IBM developer Nodejs course).

'use strict'

const logger = require('../common/logger');

const { MAINLINE, START, END } = require('../common/constants');

(function mainline() {
    logger.info(START, MAINLINE);
    
    process.nextTick(() => {
        logger.info('mainline:process.nextTick() says: hello!', 'MICROTASK')
    });

    let iteration = 0;
    let intervalTimeout = setInterval(() => {
        if (iteration < 3) {
            setTimeout((iteration) => {
                logger.info('setInterval(' + iteration + '):setTimeout() says: Timer expired!', 'TIMERS');
                process.nextTick((iteration) => {
                    logger.info('setInterval():setTimeout(' + iteration + '):process.nextTick() says: Delimit TIMERS phase!', 'MICROTASK');
                }, iteration);
            }, 0, iteration);
        } else {
            logger.info('setInterval(' + iteration + ') says: Goodbye!', 'TIMERS');
            clearInterval(intervalTimeout);
        }
        iteration++;
    });

    logger.info(END, MAINLINE)
})();

The output is as follows:

1593574413204:INFO: MAINLINE: START
1593574413206:INFO: MAINLINE: END
1593574413207:INFO: MICROTASK: mainline:process.nextTick() says: hello!
1593574413210:INFO: TIMERS: setInterval(0):setTimeout() says: Timer expired!
1593574413210:INFO: MICROTASK: setInterval():setTimeout(0):process.nextTick() says: Delimit TIMERS phase!
1593574413211:INFO: TIMERS: setInterval(1):setTimeout() says: Timer expired!
1593574413211:INFO: MICROTASK: setInterval():setTimeout(1):process.nextTick() says: Delimit TIMERS phase!
1593574413213:INFO: TIMERS: setInterval(2):setTimeout() says: Timer expired!
1593574413213:INFO: TIMERS: setInterval(3) says: Goodbye!
1593574413213:INFO: MICROTASK: setInterval():setTimeout(2):process.nextTick() says: Delimit TIMERS phase!

Why does the logger log "Goodbye" before the final timer microtask?

Upvotes: 1

Views: 199

Answers (1)

Kaiido
Kaiido

Reputation: 136588

Maybe if you rewrite this code using a recursive setTimeout instead of setInterval that would make it clearer what happens.

That would give something like

(function mainline() {

  let iteration = 0;
  function intervalJob() {
    if (iteration < 3) {
      setTimeout(timeoutJob, 0, interation);
      // reproduce what setInterval does using recursive setTimeout
      setTimeout(intervalJob, 0);
    }
    else {
      logger.info('setInterval(' + iteration + ') says: Goodbye!', 'TIMERS');
    }
    iteration++;
  }
  function timeoutJob(iteration) {
    logger.info('setInterval(' + iteration + '):setTimeout() says: Timer expired!', 'TIMERS');
    process.nextTick(microtaskJobFromTimeout, iteration);
  }
  function microtaskJobFromTimeout(iteration) {
    logger.info('setInterval():setTimeout(' + iteration + '):process.nextTick() says: Delimit TIMERS phase!', 'MICROTASK');
  }

  logger.info("START", "MAINLINE");
  
  process.nextTick(() => {
    console.log('mainline:process.nextTick() says: hello!', 'MICROTASK')
  });
  
  setTimeout(intervalJob,0);
  
  logger.info("END", "MAINLINE")

})();

Basically, before iteration reaches 3, each intervalJob call will schedule two new jobs to get executed at the next event loop iteration: timeoutJob, which itself will internally schedule a microtask, and the recursive intervalJob.

Because node's event loop does first executes all timeouts jobs, then only all microtasks, the last intervalJob will actually be in the pool of timeouts during the same event loop iteration than the last timeoutJob.

So timeoutJob is normally executed before, since it was scheduled first, then intervalJob because it was in the pool of timers too, and finally the microtask, before the loop reiterates.

You can verify this by logging unconditionally from the setInterval callback, the output would be:

MAINLINE: START
MAINLINE: END
MICROTASK: mainline:process.nextTick() says: hello!
INTERVALJOB: unconditional intervalJob logging
TIMERS: setInterval(0):setTimeout() says: Timer expired!
INTERVALJOB: unconditional intervalJob logging
MICROTASK: setInterval():setTimeout(0):process.nextTick() says: Delimit TIMERS phase!
TIMERS: setInterval(1):setTimeout() says: Timer expired!
INTERVALJOB: unconditional intervalJob logging
MICROTASK: setInterval():setTimeout(1):process.nextTick() says: Delimit TIMERS phase!
TIMERS: setInterval(2):setTimeout() says: Timer expired!
TIMERS: setInterval(3) says: Goodbye!
INTERVALJOB: unconditional intervalJob logging
MICROTASK: setInterval():setTimeout(2):process.nextTick() says: Delimit TIMERS phase!

Note that this is node specific behavior, in browsers each task will have its own microtasks checkpoint and two timers scheduled to fire at the same time will actually get executed on two different event loop iterations.

Upvotes: 1

Related Questions