NodeJS Profiling: Build a High-Performance App

This was originally posted by the author on his blog. This version has been edited for clarity and some parts may appear different from the original post.

Introduction to NodeJS Profiling

Understanding NodeJS internals, why NodeJS is so fast,V8 internals and its optimization tricks are cool, but these things are 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, and 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. In this article, however, 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 a log file and that’s it. It means, 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!

NodeJS Profiling

Collecting ticks information into log file

NodeJS has a flag which enables profiler  —  prof. When you’re 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 with 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 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 only have few lines).

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 explain all of these sections another time, but 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 this, we can now optimize it, replace 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

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

This means that 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 profiling for your application. Knowing how to profile your applications and what 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.

Author Bio

Eugene Obrezkov | Developer Advocate
Eugene Obrezkov is a Node.js and D2D developer (and sometimes speaker). He also owns a personal blog where he writes about everything Node.js related. Eugene believes that JavaScript is conquering the world.