Logging part 2 - runtime performance

Published on: 7th Dec 2024

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 because what we have done is completing the development stage. The problem starts when you miss out on the most important information - what is the runtime speed when the number of concurrent users grows? What is the high peak and low peak?

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 that you can find in v8. With these performance data, you will be able to tell which part is slow:

Node.js event loop congestion?
Your function is too complex?
Some other functions running a loop that are affecting other functions?
Was it caused by other services such as database performance issues or networking issues?

We find these performance data is helpful in troubleshooting the performance issue.

Logging part 1 - down the process ID (pid) and thread ID (threadId).
Logging part 2 - runtime performance.

Jump to #NODEJS blog

Author

Lau Hon Wan, software developer.