The Problem of Measuring your Node.js app Runtime

Photo by Chris Gonzalez from Burst Copied

Measuring the runtime of a Node.js application is a critical aspect of performance optimization. By measuring how long different parts of your application take to execute, you can identify bottlenecks and optimize your code to improve performance.

How can we measure the time execution of a function?

There are many ways to measure time in node.js, the most high-resolution way to do it is using process.hrtime() or Perf_hooks, both of them are better than using Date class because they do not lean on your system clock, but still, there are few differences between them:

process.hrtime() provides nanosecond-level resolution, while perf_hooks provides microsecond-level resolution. This means that process.hrtime() is generally more precise but also more expensive to call.

Now let’s have an example of measuring the runtime of the following logic. We have an asynchronous logic (we can assume this is some HTTP call) that resolves after 1000 ms. We will use perf_hooks to measure how long it takes to fulfill this promise.

const {performance} = require('perf_hooks');
const SOME_BIG_NUMBER = 4000000000;

async function asyncLogic(ms) {
    return new Promise(resolve => setTimeout(resolve, ms));
}

const start = performance.now();
asyncLogic(1000).then(() => {
    const time = performance.now() - start;
    console.log(`Time taken: ${time}ms`);
});

let x = 0;
for (let i = 0; i < SOME_BIG_NUMBER; i++) {
    x += Math.sqrt(SOME_BIG_NUMBER);
}

Result:

Time taken: 3948ms

We can see that the result is around 4000ms even though the promise should take only 1000ms to resolve, this happens because we have some slow loop that affects our measurement, let’s understand why.

The Event Loop and Event queue

The JavaScript runtime model is based on the event loop, this is the part which is responsible for executing our code and allows us to use asynchronous logic.

When we execute JavaScript code the following happens:

1. JavaScript executes all synchronous code in the order it appears in the program.
2. If there is any asynchronous code (such as our asyncLogic function), JavaScript will add it to the event queue instead of executing it immediately.
3. The event loop constantly checks the event queue to see if there are any events waiting to be executed.
4. When an event is ready to be executed, the event loop moves it from the event queue to the call stack, where it can be executed.
5. Once the event is executed, any additional synchronous code is executed before the event loop goes back to check the event queue for more events.

In short, the event loop allows JavaScript to run asynchronous code without blocking the main thread, which could cause the program to become unresponsive. Instead, JavaScript adds asynchronous code to the event queue, and the event loop checks the queue for new events to execute as soon as possible.

That’s why in our example, the time measurement was 4000ms,

1. We execute the asyncLogic function, which was added to the event queue.
2. Then we execute our synchronous logic, which takes us around 4000ms to run.
3. The event loop moves our asyncLogic() call back from the event queue to the call stack
4. We then execute the callback function and calculate the end time

When we try to measure asynchronous logic we might get it wrong because of the way the event loop works.

Event Loop Lag

Therefore, when monitoring our application performance, there is an important metric we should pay attention to, the lag of the event loop, the time taken to the event loop between adding a new callback to the event queue till the execution of this callback.

We can easily create a loop that will let us measure our event loop lag with the following code:

function measureEventLoopLag() {
    let lastLoopTime = performance.now();
    setTimeout(() => {
        const delay = performance.now() - lastLoopTime - 1000;
        lastLoopTime = performance.now();
        console.log(`Event Loop lag is: ${delay} ms`)
        measureEventLoopLag();
    }, 1000)
}

Higher event loop lag is terrible for your performance. It leads to higher memory usage and increases our application latency. As a rule of thumb, you should have less than ~30ms delay, a higher threshold than that should make you worry.

Runtime improvement

Let’s assume that our code has an HTTP call that takes us 4000ms, and we also have a slow loop that also takes us around 4000ms to run. As we saw in our previous example, when we measure this runtime, we will find out it took us 4000ms to run the whole code.

After refactoring our code we reduce the slow loop runtime by 50%. When we rerun the code the overall runtime according to our measurement didn’t really change, we still waited for around 4000ms to complete the overall flow because we waited for our asynchronous flow to be done. Seems like our refactor didn’t really help.

Not really, if we take a look in terms of CPU we made a huge difference. Our HTTP calls do not consume a lot of CPU, we mostly just wait for the response. So most of the time, our CPU used to execute our slow loop, when we refactored the code and reduced it by 50% it didn’t change the overall time but it had a significant effect on our CPU.

Conclusion

In our example, we had very small logic to monitor, things get really complicated when you have a complex system with a lot of logic to run, in that case you should try to measure small parts of your logic to monitor decline in performance better.

There are two important things to note when monitoring your application run time:

• Measuring asynchronous function time can be affected by synchronous code (event loop lag)
• Measuring functions that have both asynchronous and synchronous logic can hide runtime improvement (or decline).
• Event loop lag higher than ~30ms is really bad for your application.