Profiling Technique - Finding and Removing Performance Bottlenecks in Node.js

The first one or two years after starting work are often the most energetic period in a programmer's career. I could imagine many ways to solve a problem, and even think about which approach would be the most "elegant". The reasoning was simple: if an approach was recommended and used by many people, it must be the best one. A piece of logic that initially looked simple could become as thick as a burger after passing through several layers of thought, because a function had to pass through several wrappers to be ready to "cover" many future cases.

Writing code can be an enjoyable job. Solving a problem can lift my mood for the whole day, give me stories to talk about with colleagues, and let us analyze and dissect problems that seemed unknown to everyone else. Yet most conversations eventually come back to one question: "What about performance?" Getting the code to run is one thing, but have you ever asked how to know whether your code is good enough? Many people think that simply following Best Practices will automatically make it run as fast as possible. That is true, but not enough. If everyone were certain that their code was good, perfect systems would be everywhere. Whether code runs quickly depends on many factors, not just how it is written. People do not usually rely on intuition to judge whether a piece of logic is fast or slow. To prove it, they need data, or at least need to know which part of the code is taking time to process. Only after everything is laid out in front of them can they find a way to optimize it.

Profiling is a widely used method for measuring where an application actually spends its CPU, memory, or time, replacing intuition-based optimization with data. Most programming languages come with tools to support this work. In Node.js, we have the profiler inside V8, built into V8, which is the "central processor" of Node.

A heavy synchronous task can block the event loop, increase latency, and reduce concurrency even when the application's source code looks fine at first glance. Performance optimization is not usually about simply removing components considered unimportant. That approach is driven by intuition and can even cause errors once the program is running in production. To know whether something is actually slow, we need a way to measure it.

A Simple Profiling Example

Node.js has a very easy-to-understand article about profiling with its own built-in tools: Profiling Node.js Applications. You can refer to it; in this post, I will only summarize the main ideas.

The example presents an API server with a /newUser endpoint. Inside that endpoint, it calls crypto.pbkdf2Sync(). At first glance, nothing seems particularly complicated: pbkdf2Sync is needed to encrypt a password into a string before storing it in the database. Suppose the server starts reporting overload continuously one day, and you suspect that /newUser may be the problem. What should you do? Send a few requests to it and see how long the actual responses take? That is one way! However, there is a better way: diagnose the problem with profiling.

It is not easy to run a debugger in production, so a simpler approach is to run the application locally and use ApacheBench to simulate requests to the endpoint. For example:

$ ab -k -c 20 -n 250 http://localhost:3000/newUser`.

The command above is equivalent to running 20 concurrent threads that send requests, stopping after a total of 250 calls.

Before running the ab command, start node with the --prof flag to enable profiling by running node --prof app.js. Then run the ab command as shown above. The result is written to a file with a name such as <isolate-v8.log>, but we cannot read it yet. We need to process the log by running node --prof-process <isolate-v8.log>, focusing on [Summary], [C++], and [Bottom up (heavy) profile]. The result shows that most of the CPU is spent in the node::crypto::PBKDF2 function.

 [Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
      7    0.0%    0.0%  GC
    767    2.0%          Shared libraries
    215    0.6%          Unaccounted

 [C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

Fix It and Measure Again

We can see that 97.2% of the processing time is spent in C++, with 51.8% belonging to a function named node::crypto::PBKDF2. Mapping this back to the code, it is the pbkdf2Sync function. At this point, we realize that the Sync suffix usually indicates a synchronous function. Running it in the main thread can block the event loop. So this is likely where the problem lies!

Replace pbkdf2Sync() with pbkdf2(), a similar function that runs asynchronously so it does not block the event loop while the calculation is in progress. Then run the program again and measure its performance. Comparing the numbers, throughput increases from about 5.3 to 19.5 req/s, while average latency drops from about 3.75 to 1.03 seconds.

This clearly shows that we identified the problem correctly by relying on data. Although it may seem obvious at first glance, the example needs to remain simple; in practice, the process is similar. At this point, there is a question for you: why can Node handle more requests at the same time when changing from crypto.pbkdf2Sync() to pbkdf2()? Do not all hash calculations still have to be performed?

Measuring in Production

The profiler built into V8 is only suitable for debugging: forming a suspicion, measuring, and identifying the exact cause. It cannot be used to monitor production directly. Therefore, it usually needs to be combined with tracing, metrics, and logs to form a toolkit that helps identify performance problems early.

In production, people often combine an APM with a continuous profiler to observe the application continuously and associate data with endpoints, traces, versions, and errors. Imagine it as a display filled with dense application metrics. One typical example is OpenTelemetry combined with platforms such as Datadog, New Relic, Elastic, or Grafana/Pyroscope. OpenTelemetry acts as the telemetry standardization layer between the application and observability systems, while Datadog, Grafana, New Relic, and others provide a platform for monitoring.

However, the profiler inside V8 is not useless for that reason. It is still a foundational tool for measuring cases that other tools cannot handle.

References