node worker_threads console.log comes after postMessage

Question

node v10.16.3

I was running an worker_threads example from node official doc. I made some changes as want to test share variables. Here is an example

work-thread.js

const {
  Worker,
  isMainThread,
  parentPort,
  workerData
} = require("worker_threads");

let a = 10;

if (isMainThread) {
  module.exports = async function parseJSAsync(num) {
    return new Promise((resolve, reject) => {
      const worker = new Worker(__filename, {
        workerData: num
      });
      worker.on("message", resolve);
      worker.on("error", reject);
      worker.on("exit", code => {
        if (code !== 0)
          reject(new Error(`Worker stopped with exit code ${code}`));
      });

      for (let i = 0; i < num; i++) {
        console.log("master: ", a);
        a++;
      }
    });
  };
} else {
  const num = workerData;
  let result = 1;
  for (let i = 1; i < num; i++) {
    console.log("worker: ", a);
    a--;
    result = result * i;
  }
  parentPort.postMessage(result);
}

And there is a script for testing this example:

const calculateFactorial = require("./work-thread");

calculateFactorial(10).then(res => console.log("res", res));

There is an a can be accessed by both main thread and worker thread. When I run this code, the output is

master:  10
master:  11
master:  12
master:  13
master:  14
master:  15
master:  16
master:  17
master:  18
master:  19
worker:  10
res 362880
worker:  9
worker:  8
worker:  7
worker:  6
worker:  5
worker:  4
worker:  3
worker:  2

I wonder why worker's postMessage is earlier than worker's console.log

Answer 1

It looks like logging is dependent on the main thread, which is blocked by the for loop until it completes. The logs from the worker seem to be buffered at the time console.log is called in the worker, but not actually written out until the main thread is unblocked. So the work is being done in parallel, but not the logging. I have not found a reference for this yet, but it can be verified by running a time dependent example:

const {
  Worker,
  isMainThread
} = require('worker_threads');

if (isMainThread) {
  console.log(`start time: ${Date.now()}`);
  const worker = new Worker(__filename);

  worker.on('exit', (code) => {
    console.log(`exited with code [${code}]`);
  });

  worker.on('error', (err) => {
    console.log(err);
  });

  // Block main thread for 10 seconds
  const start = new Date();
  while (true) {
    const now = new Date();
    if (now.getTime() - start.getTime() > 10000) {
      console.log('broke loop');
      break;
    }
  }

  // Stop worker after another 10 seconds
  setTimeout(() => worker.terminate(), 10000);
} else {
  setInterval(() => console.log(Date.now()), 1000);
}

Output below (annotated with some comments about the timing)

start time: 1600900685482 // written to console immediately
broke loop // written to console 10s later
1600900686512 // these 10 lines are written all at one as soon as the loop is broken. Note that even though they are written at once, the times are all 1 second apart.
1600900687515
1600900688517
1600900689518
1600900690519
1600900691520
1600900692524
1600900693525
1600900694526
1600900695527
1600900696533 // after dumping the backlog of log lines from while the main thread was blocked, new lines are now written every 1 second
1600900697536
1600900698539
1600900699540
1600900700544
1600900701550
1600900702550
1600900703556
1600900704558
exited with code [1]