How Logging Affect Performance in Nodejs

We already know that logging is affecting performance, especially when we use console.log because its a syncronous process. In nodejs, we have to use asyncronous process to get the best performance. In this article, we will be comparing the performance difference between no logging, console logging, the most popular logging library winston and the fastest logging library pino.

Test Scenario

All the application needed for the test is installed on my notebook. This is my notebook & App spec:

1. CPU: Intel Core i3-6006U, 2 cores, 4 threads.
2. RAM: 16 GB
3. OS: Ubuntu 18.04 WSL
4. Node Version: 14.17.2
5. Express Version: 4.17.2
6. Fastify Version: 3.25.3
7. ApacheBench Version: 2.3
8. Pino Version: 7.6.4
9. Winston Version: 3.4.0

The application we used to test is ab (ApacheBench). the ab will hit the nodejs server 10k times with 1000 concurrency with this is the command:

ab -n 10000 -c 1000 -H "Authorization: Bearer {token}" http://localhost:3000/getproducts

The webserver will first verify the bearer token from the request, if the token verified it will return the list of products (20 rows) which it gets from database query. We use MySQL database in this test. You can see the test topology below:

  ab ------> NodeJS ------> MySQL
  

In this test, We will compare:

1. NodeJS using fastify framework with no logging.
2. NodeJS using fastify framework with pino sync logging.
3. NodeJS using fastify framework with pino async logging.
4. NodeJS using fastify framework with winston logging.
5. Nodejs using fastify framework with console logging.

And we will compare 1 and 2 times logging in 1 request for each setup above:

1. For 1 times logging, we will write log right after the token verified.
2. For 2 times logging, we will write log right after the token verified and after database query.

Fastify with No Logging Code

This is the app.js using no logging implementation:

const fastify = require("fastify");
const app = fastify();

app.register(require("fastify-mysql"), {
  connectionLimit: 100,
  host: process.env.DB_HOST,
  user: process.env.DB_USER,
  password: process.env.DB_PASS,
  database: process.env.DB_NAME,
  promise: true,
});

app.register(require("fastify-jwt"), {
  secret: process.env.JWT_SECRET,
});

app.get("/getproduct", async (req, res) => {
  const decoded = await req.jwtVerify();
  if (!decoded) {
    res.status(403).send({ message: "token not valid" });
    return;
  }
  const [results] = await app.mysql.query("SELECT * FROM product");
  res.send({ results });
});

app.listen(3000);

As you can see this is plain source code without logging

Fastify with Pino (Sync Mode) Logging Code

This is the app.js using pino logging implementation with sync mode:

const fastify = require("fastify");
const pino = require("pino");
const app = fastify();
const logger = pino();

app.register(require("fastify-mysql"), {
  connectionLimit: 100,
  host: process.env.DB_HOST,
  user: process.env.DB_USER,
  password: process.env.DB_PASS,
  database: process.env.DB_NAME,
  promise: true,
});

app.register(require("fastify-jwt"), {
  secret: process.env.JWT_SECRET,
});

app.get("/getproduct", async (req, res) => {
  const decoded = await req.jwtVerify();
  if (!decoded) {
    res.status(403).send({ message: "token not valid" });
    return;
  }
  logger.info(decoded);
  const [results] = await app.mysql.query("SELECT * FROM product");
  logger.info(results); // Commented when testing 1 time logging
  res.send({ results });
});

app.listen(3000);

In this source code, we are using pino logging with default option, without activating async mode.

Fastify with Pino (Async Mode) Logging Code

This is the app.js using pino logging implementation with async mode:

const fastify = require("fastify");
const pino = require("pino");
const app = fastify();
const logger = pino(pino.destination({ sync: false }));

app.register(require("fastify-mysql"), {
  connectionLimit: 100,
  host: process.env.DB_HOST,
  user: process.env.DB_USER,
  password: process.env.DB_PASS,
  database: process.env.DB_NAME,
  promise: true,
});

app.register(require("fastify-jwt"), {
  secret: process.env.JWT_SECRET,
});

app.get("/getproduct", async (req, res) => {
  const decoded = await req.jwtVerify();
  if (!decoded) {
    res.status(403).send({ message: "token not valid" });
    return;
  }
  logger.info(decoded);
  const [results] = await app.mysql.query("SELECT * FROM product");
  logger.info(results); // Commented when testing 1 time logging
  res.send({ results });
});

app.listen(3000);

This time, we are using pino logging with async mpde by declaring sync: false.

Fastify with Winston Logging Code

This is the app.js using winston logging implementation:

const fastify = require("fastify");
const { createLogger, transports } = require("winston");
const app = fastify();
const logger = createLogger({
  transports: [new transports.Console()],
});

app.register(require("fastify-mysql"), {
  connectionLimit: 100,
  host: process.env.DB_HOST,
  user: process.env.DB_USER,
  password: process.env.DB_PASS,
  database: process.env.DB_NAME,
  promise: true,
});

app.register(require("fastify-jwt"), {
  secret: process.env.JWT_SECRET,
});

app.get("/getproduct", async (req, res) => {
  const decoded = await req.jwtVerify();
  if (!decoded) {
    res.status(403).send({ message: "token not valid" });
    return;
  }
  logger.info(decoded);
  const [results] = await app.mysql.query("SELECT * FROM product");
  logger.info(results); // Commented when testing 1 time logging
  res.send({ results });
});

app.listen(3000);

In this code, we are using winston package with default option with console transport.

Fastify with Console Logging Code

This is the app.js using console logging implementation:

const fastify = require("fastify");
const app = fastify();


app.register(require("fastify-mysql"), {
  connectionLimit: 100,
  host: process.env.DB_HOST,
  user: process.env.DB_USER,
  password: process.env.DB_PASS,
  database: process.env.DB_NAME,
  promise: true,
});

app.register(require("fastify-jwt"), {
  secret: process.env.JWT_SECRET,
});

app.get("/getproduct", async (req, res) => {
  console.log("incoming requset")
  const decoded = await req.jwtVerify();
  if (!decoded) {
    res.status(403).send({ message: "token not valid" });
    return;
  }
  console.log(decoded);
  const [results] = await app.mysql.query("SELECT * FROM product");
  console.log(results); // Commented when testing 1 time logging
  res.send({ results });
});

app.listen(3000);

Last, we are not using any external package for logging. Just plain console.log logging.

The Test Result

In this segment we will show you the result of the test (10k request, 1k concurrent). The test scenario is done 10 times each, we only display the average results here so you are not overwhelmed by the information:

Time Taken For Tests

Requests Per Second

Conclusion

There are some key point when I was doing this experiment:

1. When using pino async, the performance reduced around 20% when logging once, and 53% when logging twice.
2. When using pino, the performance reduced around 45% when logging once, and 78% when logging twice.
3. When using winston, the performance reduced around 46% when logging once, and 79% when logging twice.
4. When using console, the performance reduced around 51% when logging once, and 88% when logging twice.
5. We can see from the result above that the performance is reduced a lot even when we try to log only once. So be careful when you want to log something. Only log when you really need to especially in production environment.
6. Do not use standard console.log to log in production environment. It is worst in term of performance when you compare it with other library such as pino or winston.
7. If you really care about performance, then choose pino in async mode for logging, it is much better than winston in term of performance as you can see from the test results. This is why fastify use pino for its logging.

That’s it! Now you know how logging really affect performance, even when you are using the fastest one. So, use them wisely.