Profiling NodeJS applications

In previous articles, I talked about NodeJS internals, why NodeJS is so fast, V8 internals and its optimization tricks. That’s cool, but… Understanding these things is not enough to write high-performance NodeJS applications. You still need to know, how to profile your NodeJS application, find the bottleneck and optimize it, knowing how NodeJS and V8 optimizes it.

Profiler

The main goal of a profiler is to measure all the CPU ticks spent on executing functions in your application. There are also memory profilers, which can be used to find memory leaks, but in this article I’ll be talking about performance issues only.

For instance, Google Chrome (or any other modern browser) has a built-in profiler in DevTools, recording all the information about functions and how long it takes to execute them into a log file. Afterwards, Google Chrome analyzes this log file, providing you with human-readable information of what’s happening (Flamechart, stack, whatever), so you can understand it and find the bottleneck.

NodeJS has a built-in profiler as well, but with one difference. It doesn’t analyze log files as Google Chrome does. Instead, it just collects all the information into log file and that’s it. It means, that you need to have some separate tool that can understand this log file and provide you with human-readable information.

Let’s skip the theory for now and start with a simple example. I recommend you do everything I do step by step, so you can see what’s going on on your local machine as well (my NodeJS version is 5.10.1 and npm 3.8.7, I can’t guarantee this example to work for you if you have a different version of Node).

Project with a bottleneck

Let’s imagine, that the following example is some big project with performance issues. I have chosen crypto module and sync version of pbkdf2 specifically, because they decrease performance a lot and that’s what we want in this example.

"use strict";
const crypto = require('crypto');
function hash(password) {
  const salt = crypto.randomBytes(128).toString('base64');
  const hash = crypto.pbkdf2Sync(password, salt, 10000, 512);
  return hash;
}
// Imagine that loop below is real requests to some route
for (let i = 0; i < 50; i++) {
  hash('random_password');
}

Running this snippet gives me the following:

~: time node server.js
9.24 real    9.21 user    0.02 sys

We definitely have an issue with performance here — 9.24 seconds.

Let’s profile it!

Collecting ticks information into log file

NodeJS has a flag which enables profiler — prof. When you running your application with this flag, it actually collects the CPU ticks into log file in the same folder, where your script is.

Run NodeJS with profiler and wait for it to finish:

~: node --prof server.js

Now, you have the log file with ticks information. This log file gets a name something like isolate-*.log. If you try to see the content of the log file with a tool like cat, you will see a lot of un-readable information. That’s why we need a tool for analyze it.

Analyzing log file

Until NodeJS 4.x you must to use separate packages like node-tick-processor. Since we have NodeJS 5.10.1, we can use a built-in tool.

Run NodeJS with flag prof-process and provide path\filename to log file, generated before. Filename will be different, so replace it with yours.

~: node --prof-process isolate-0x101804a00-v8.log

After some time, you will get all information about your application, including amount of processor ticks spent for each function (since we have a small example, we have few lines only).

Example of statistical profiling result in NodeJS application

As you see, prof-process analyzed ticks log file and now we have readable information about what’s happening in our script. It has six sections: Shared libraries, JavaScript, C++, Summary, C++ entry points, Bottom up (heavy) profile.

I’ll explaing all of these sections another time, for now, lets look at Bottom (up) heavy profile. That’s the place where you get information about more heavy functions.

As we can see, 99.9% of CPU ticks are spent in pbkdf2Sync function in crypto.js module which is called from our hash function. This is our bottleneck. Knowing that, we can optimize it, replacing sync function with async and provide a callback that will do some stuff after hashing.

"use strict";
const crypto = require('crypto');
function hash(password, cb) {
  const salt = crypto.randomBytes(128).toString('base64');
  const hash = crypto.pbkdf2(password, salt, 10000, 512, cb);
}
// Imagine that loop below is real requests to some route
for (let i = 0; i < 50; i++) {
  hash('random_password', (error, hash) => console.log(hash));
}

Run our modified snippet via time:

~: time node server.js
2.64 real    9.91 user    0.07 sys

9.24 seconds versus 2.64 seconds. It runs 3.5 times faster. Now, let’s profile it again and compare profiling results with un-optimized version before:

~: node --prof server.js
~: node --prof-process isolate-0x101804a00-v8.log

Statistical profiling results of optimized version

We can see now, that in Bottom up (heavy) profile not a lot of CPU ticks, comparing to 7431 at previous time. Also, there is no hash function that calls pbkdf2.

It means, we have an optimized version of our server and there are no heavy functions.

Summary

This was just a simple example to show you the basics of NodeJS application profiling. Knowing how to profile your applications and tools you can use to do it helps you make right decisions about what you need to optimize.

Thanks for reading! I hope it helped you understand how to profile NodeJS applications a little bit better. Tweet me on Twitter if you have any questions or suggestions about my articles.

Eugene Obrezkov aka ghaiklor, Developer Advocate at Onix-Systems, Kirovohrad, Ukraine.