Node.js logging part 2 - log down the runtime performance

Overview

After writing many lines of code, writing many test cases, testing it and you think the system is ready to go live confidently. In real life, this is not the end of the story.

More questions come into our mind after the system has gone live. We want to find out what is the runtime performance when the number of concurrent users grows? Is it slower? By what percentage it has slowed down? And which function is slow.

Tracks the function performance

In this simplify example, it will log down the duration for this function to run.

const path = require('path');
const { threadId } = require('worker_threads');

// declare the file name without the path.
const FILE_ID = path.basename(__filename) + ':';

function handle_req(data) {
    const PROC_NAME = `${FILE_ID}handle_req:`;
    const hrstart = process.hrtime();
    const log = `${PROC_NAME}tid=${threadId},rid=${data.rid}`;

    // run some processes here.
    // load some data from the Postgres database at server 1.
    // download some JSON data from server 2 through HTTP API.
    // save the data in Postgres database at server 1.
    // notify server 2 through HTTP API on the status.

    // log down the duration.
    const hrend = process.hrtime(hrstart);
    const ts = `${hrend[0]}s ${hrend[1] / 1000000}ms`;
    console.log((new Date).toISOString() + '|i|' + log + ',req-done,~' + ts);
}

Here's the output:

2024-12-07T11:12:40.604Z|i|app-summ.js:handle_req:tid=2,rid=182,req-done,~4.915ms
2024-12-07T11:12:42.221Z|i|app-summ.js:handle_req:tid=2,rid=183,req-done,~3.262ms

Explanations

• The first part (2024-12-07T11:12:42.217Z) is the time stamp.
• The second part (i) is the log type. 'i' represents information while 'e' represents error.
• The third part (app-summ.js) is the script file name.
• The fourth part (handle_req) is the function name.
• The fifth part (tid) is the worker thread ID (threadId).
• The sixth part (rid) is the request ID assigned and maintained by our program. We will recycle it at 99,999 so that it will not occupy too much storage space.
• The seventh part (req-done) to indicate which part of the function was running.
• The last part (~5.0942ms) is the total duration in milliseconds that is required to run this function.

Conclusion

Tracking the function performance in this way is different from the profiling process that you can find in v8 where profiling is targeting on the hot function (i.e., the function that has been called many times).

With these real performance data, we will be able to find out which components is slow. For example,

• Was it caused by other services such as database performance issues or networking issues?
• Is your function is too complex?
• A function that is running inside a loop and it is blocking or slowing down other functions?
• Is Node.js event loop congestion?

We find these performance data is helpful in troubleshooting and upgrading.

Related posts

1. Logging part 1 - log down the process ID and thread ID.
2. Logging part 2 - log down the runtime performance.
3. Logging part 3 - log destination

Back to #NODEJS blog

Back to #blog listing