why does performance.now() does not work in a sync call back function in nodejs

Question

i am trying to run a async read write in nodejs and trying to measure execution time by using perfomance.now . But inside the call back function, performance.now gives me undefined.

const { performance } = require("perf_hooks");

var st1 = performance.now();
console.log("start");
var st2, st3, st4, st5;
const { readFile, writeFile } = require("fs");
console.log("middle");
readFile("./content/first.txt", "utf-8", (err, result) => {
  if (err) {
    console.log(err);
    return;
  }
  const first = result;
  st2 = performance.now();

  readFile("./content/second.txt", "utf-8", (err, result) => {
    if (err) {
      console.log(err);
      return;
    }
    const second = result;
    st3 = performance.now();

    writeFile(
      "./content/result-async.text",
      `Here is the result : ${first}: ${second}`,
      (err, result) => {
        if (err) {
          console.log(err);
          return;
        }
        console.log(result);
        console.log("after result");
        st4 = performance.now();
      }
    );
  });
});
console.log("end");
console.log("after end");
st5 = performance.now();
console.log(`st1=${st1},st2=${st2},st3=${st3},st4=${st4},st5=${st5}`);

below was the result for the above

start
middle
end
after end
st1=50.264651000499725,st2=undefined,st3=undefined,st4=undefined,st5=56.36346299946308
undefined
after result

i cannot understand the reason for st2,st3 and st4 being undefined???

i tried searching for reasons on mdn docs for the same, but there is no mention for use case in async environment. want to knoe what could be the reason for this.

Because your callbacks are NOT sync. They are executed once the file is read. But in the meantime you already executed the last few `console.log`s .as you can clearly see in the order of your outputs. Ie `end` and `after end` are logged *before* `after result`. And if you add additional `console.log`s as first statement in the callbacks of `readFile` and `writeFile`, you will notice, they will also be logged *after* the log of `after end` ... — derpirscher, Jun 17 '23 at 07:41

jfriend00 · Answer 1 · 2023-06-17T07:05:59.597

You callbacks are NOT synchronous. They are asynchronous. readFile() and writefile() (assuming these come from the fs module) are asynchronous. So, you're trying to use st1, st2, st3 and st4 in your final statement BEFORE those variables have been assigned in the asynchronous callbacks. It's a matter of timing.

To time and sequence asynchronous operations, you have to write proper asynchronous code that outputs results only when those operations are actually complete.

Because you nested your asynchronous operations, you can move this code:

console.log("end");
console.log("after end");
st5 = performance.now();
console.log(`st1=${st1},st2=${st2},st3=${st3},st4=${st4},st5=${st5}`);

Into the last writeFile() callback like this:

const { performance } = require("perf_hooks");

var st1 = performance.now();
console.log("start");
var st2, st3, st4, st5;
const { readFile, writeFile } = require("fs");
console.log("middle");
readFile("./content/first.txt", "utf-8", (err, result) => {
    if (err) {
        console.log(err);
        return;
    }
    const first = result;
    st2 = performance.now();

    readFile("./content/second.txt", "utf-8", (err, result) => {
        if (err) {
            console.log(err);
            return;
        }
        const second = result;
        st3 = performance.now();

        writeFile(
            "./content/result-async.text",
            `Here is the result : ${first}: ${second}`,
            (err) => {
                if (err) {
                    console.log(err);
                    return;
                }
                st4 = performance.now();
                console.log("end");
                console.log("after end");
                st5 = performance.now();
                console.log(`st1=${st1},st2=${st2},st3=${st3},st4=${st4},st5=${st5}`);
            }
        );
    });
});

A couple suggestions on this code:

Using the promise version of these functions fs.promises with await will make sequence asynchronous operations a lot simpler.
fs.writeFile() does not pass a result to its callback as there is no result, just an error argument.

i am going through a course on nodejs, and out of curiosity, tried to time the execution. first tried it on synchronous and then this one - asynchronous. thanks for pointing the error, i intended to see the below result---start middle end after end st5=55.955283999443054 undefined after result st1=49.84751899540424,st2=57.762265995144844,st3=58.1380579918623,st4=60.31069000065327............ basically timing the asynchronous nature , which i was able to by your suggested correction. yup, will be going for promise,async-await further. — blueflyer, Jun 17 '23 at 07:53

why does performance.now() does not work in a sync call back function in nodejs

1 Answers1