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

Published on: 7th Dec 2024

Updated on: 21th Jul 2025

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

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,

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

Author

Lau Hon Wan, software developer.