CPU-bound tasks can grind your Node.js applications to a standstill, frustrating users and driving them away. You must master the art of profiling your application to pinpoint bottlenecks, and implement effective strategies to resolve any issues.
In this guide, we'll explore various techniques to help you identify and fix the root causes of your Node.js performance issues.
Let's get started!
Prerequisites
Before proceeding with the article, ensure that you have the most recent LTS of
Node.js and npm installed on your computer.
We'll use autocannon to run load tests on various server endpoints, so install it globally on your machine:
npm install -g autocannon
To follow along with the code samples, clone this repository and install the dependencies accordingly:
git clone https://github.com/damilolaolatunji/nodejs-profiling && cd nodejs-profiling npm install
Node.js Architecture: A Quick Overview
Node.js operates on an event-driven architecture, handling multiple client requests concurrently without creating separate threads for each connection. It achieves this by being non-blocking, allowing I/O operations like file operations and database queries to be processed asynchronously. When events occur, registered callbacks are executed, ensuring efficient handling of various tasks.
However, Node.js isn't suitable for CPU-bound tasks like heavy calculations or image processing. These tasks rely on the speed of a computer's CPU, and Node.js, with its single-threaded event loop, can only execute one JavaScript code at a time. As a result, CPU-bound tasks can block the main thread, causing significant performance problems, as we'll explore further in the next section.
Demonstrating a CPU-bound Task in Node.js
To illustrate a CPU-bound task, let's use the classic example of calculating a Fibonacci number from a specific position in the Fibonacci sequence.
This sequence starts with 0 and 1, where each subsequent number is the sum of
the two preceding ones, following the relation F(n) = F(n−1) + F(n−2) with
seed values F(0) = 0, F(1) = 1. Here are the first 20 Fibonacci numbers:
0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181
Calculating the nth Fibonacci number using a recursive algorithm is straightforward:
// src/fibonacci.js function calcFiboRecursive(n) { if (n <= 1) return n; return calcFiboRecursive(n - 1) + calcFiboRecursive(n - 2); }
However, this algorithm's time complexity is O(2^n), indicating exponential
growth for the input size (n) (meaning that as n increases, the
algorithm becomes significantly slower).
Bear in mind that there are much more efficient algorithms for calculating the Fibonacci number. This example only serves to illustrate the problem with CPU-bound tasks in Node.js.
Testing the CPU-bound Task
In the src/server.js file, there's a /fibonacci-recursive/:n route for
calculating the Fibonacci number at position n:
// src/server.js . . . fastify.get('/fibonacci-recursive/:n', (request, reply) => { const n = parseInt(request.params.n, 10); const result = calcFiboRecursive(n); reply.send({ result }); }); . . .
You can test it by starting the server on port 3000:
npm start
Once the server has started, send a request to find the 30th Fibonacci number.
You can prepend the time command to find out approximately how long the
request takes:
time curl http://localhost:3000/fibonacci-recursive/30
You should observe the result fairly quickly (on my laptop, it took 10 milliseconds):
{"result":832040} Executed in 10.34 millis fish external usr time 1.22 millis 235.00 micros 0.99 millis sys time 2.03 millis 52.00 micros 1.98 millis
When the number starts to increase, even only slightly, the response time grows by many orders of magnitude. On my machine, finding the 40th and 45th Fibonacci numbers took 810ms and 9s, respectively.
Impact on the Event Loop
Aside from the fact that the results take a progressively long time to compute, each request also completely blocks the event loop, preventing any other task from executing until its completion.
To establish baseline behavior, use autocannon to send some load to the /
route. Ensure that the server isn't processing any other requests before
running the command below:
autocannon --renderStatusCodes http://localhost:3000
On my machine, I observed a throughput of almost 49k requests per second:
Running 10s test @ http://localhost:3000 10 connections ┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐ │ Stat │ 2.5% │ 50% │ 97.5% │ 99% │ Avg │ Stdev │ Max │ ├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤ │ Latency │ 0 ms │ 0 ms │ 0 ms │ 0 ms │ 0.01 ms │ 0.06 ms │ 11 ms │ └─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘ ┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐ │ Stat │ 1% │ 2.5% │ 50% │ 97.5% │ Avg │ Stdev │ Min │ ├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤ │ Req/Sec │ 41951 │ 41951 │ 49151 │ 50207 │ 48594.91 │ 2182.35 │ 41931 │ ├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤ │ Bytes/Sec │ 8.09 MB │ 8.09 MB │ 9.49 MB │ 9.69 MB │ 9.38 MB │ 422 kB │ 8.09 MB │ └───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘ ┌──────┬────────┐ │ Code │ Count │ ├──────┼────────┤ │ 200 │ 534515 │ └──────┴────────┘ Req/Bytes counts sampled once per second. # of samples: 10 535k requests in 10.01s, 103 MB read
Now, block the event loop by calculating the 50th Fibonacci number as follows. This request will take a long time to complete (about 123 seconds on my machine):
curl http://localhost:3000/fibonacci-recursive/50
While the result is computing (and the event loop is blocked), in a different
terminal, use autocannon to send load to the / once again:
autocannon --renderStatusCodes http://localhost:3000
You will observe that the throughput drops dramatically to zero requests per second due to the ongoing Fibonacci computation. This clearly demonstrates how devastating blocking the event loop can be to Node.js performance.
. . . ┌──────┬───────┐ │ Code │ Count │ └──────┴───────┘ Req/Bytes counts sampled once per second. # of samples: 10 20 requests in 10.02s, 0 B read 10 errors (10 timeouts)
Profiling your Node.js Application for Bottlenecks
When your application's performance starts to lag, pinpointing the exact cause of slowdowns can be a challenge. To effectively troubleshoot such issues, the first step is to profile your code and identify bottlenecks.
In this section, we'll explore three main approaches for profiling Node.js applications:
- Using the built-in Node.js profiler
- Using Chrome DevTools
- Using the Inspector module for on-demand profiling in production
1. Using the Built-in Node.js Profiler
The first approach we'll consider requires no external tools or libraries. It
involves using the built-in sample-based profiler built into Node.js, which is
enabled through the --prof command-line option. Once the profiler is turned
on, it records stacks of both JavaScript and C/C++ code into a file in the
current working directory.
First, enable the profiler using the --prof command-line option when starting
your Node.js server:
node --prof src/server.js
Once the server is running, simulate traffic to the /fibonacci-recursive/:n
route through autocannon as shown below:
autocannon --renderStatusCodes http://localhost:3000/fibonacci-recursive/30
On my machine, the server processed an average of 138.7 requests per second:
. . . ┌──────┬───────┐ │ Code │ Count │ ├──────┼───────┤ │ 200 │ 1387 │ └──────┴───────┘ Req/Bytes counts sampled once per second. # of samples: 10 1k requests in 10.01s, 261 kB read
The profiler records data into a file in your project directory. You will notice
a new tick log file named isolate-0x<number>-v8.log. This file is not meant to
be consumed by humans, but must be processed further to generate
human-readable data.
To process this log data, use the built-in Node.js tick processor:
node --prof-process isolate-0x<number>-v8.log > processed.txt
This creates a new processed.txt file with human-readable profiling data in
your project root. You can view its content by opening it up in your text
editor. The file is broken up into several sections, each with its own table.
Let's delve into the processed data to identify bottlenecks, starting with the
[Summary] section:
// processed.txt [Summary]: ticks total nonlib name 8603 84.0% 84.0% JavaScript 191 1.9% 1.9% C++ 28 0.3% 0.3% GC 7 0.1% Shared libraries 1442 14.1% Unaccounted
This summary indicates that approximately 84% of the samples occurred in JavaScript code, directing your attention to the JavaScript functions for investigation.
With this in mind, navigate to the [Javascript] section of the file to see
which JavaScript functions are taking up the most time:
// processed.txt [JavaScript]: ticks total nonlib name 8542 83.4% 83.5% JS: *calcFiboRecursive file:///home/ayo/dev/demo/nodejs-profiling/src/fibonacci.js:1:27 9 0.1% 0.1% JS: *resolve node:path:1095:10 4 0.0% 0.0% JS: *readPackageScope node:internal/modules/cjs/loader:377:26 3 0.0% 0.0% JS: *clearIncoming node:_http_server:948:23 2 0.0% 0.0% JS: ^defaultGenReqId /home/ayo/dev/demo/nodejs-profiling/node_modules/fastify/lib/reqIdGenFactory.js:23:28 . . .
In a real-world application, you might do a lot of processing in several functions
to handle user requests. But here, the calcFiboRecursive() function is
(predictably) where most time is spent, making it the clear target for
optimization.
2. Using Chrome DevTools
A second approach to profiling your Node.js applications is to use Chrome
DevTools to collect performance data. You need to start your server using the
--inspect flag to get started:
node --inspect src/server.js
Once the server is running, open Google Chrome or any other Chromium-based browser,
and type chrome://inspect in the address bar.
Find the inspect link for your Node.js script and click on it to bring up a new DevTools window for debugging your Node.js app. Head over to the Performance tab and click on the record button to start profiling your code.
Head back to your terminal, and run autocannon against the
/fibonacci-recursive/:n route once more:
autocannon --renderStatusCodes http://localhost:3000/fibonacci-recursive/30
Once the command finishes, return to your DevTools window and click the Stop button to finish the profiling. You will immediately observe a detailed performance profile of your program:
The Main section displays a flame chart representing main thread activity in your program. The horizontal axis represents time, while the vertical axis represents the call stack. You can zoom in to get a more detailed view:
In this view, the events on top cause the events below them, and the width of each event
indicates its duration (the wider it is, the longer the event runs). The frames under
parserOnHeadersComplete encompass routing logic, parameter processing, and,
finally, lead to the request handler ((anonymous)). This handler calls the
calcFiboRecursive() function multiple times due to its recursive nature,
clearly visible in the graph.
Clicking the (anonymous) frame and switching to the Bottom-Up tab below
lists the various resulting function calls and orders them according to their
duration:
3. Using the Inspector Module for On-Demand Profiling in Production
The two profiling approaches above are useful ways to profile your code in a development environment. However, since performance issues are often first observed in production, it's crucial to set up on-demand profiling in a way that won't affect runtime performance.
The approach we'll discuss here combines the strengths of both methods, using built-in Node.js APIs to capture profiling data and then analyzing the data using Chrome DevTools.
The Inspector API provides the ability to interact with the V8 inspector programmatically. You can use it to collect profiling data from your application like this:
// src/inspector.js import * as inspector from "node:inspector/promises"; import fs from "node:fs"; const session = new inspector.Session(); async function startCPUProfile() { try { session.connect(); await session.post("Profiler.enable"); await session.post("Profiler.start"); } catch (err) { console.error(err); } } async function stopCPUProfile() { try { const { profile } = await session.post("Profiler.stop"); fs.writeFileSync("./profile.cpuprofile", JSON.stringify(profile)); session.disconnect(); } catch (err) { console.error(err); } } process.on("SIGUSR1", startCPUProfile); process.on("SIGUSR2", stopCPUProfile);
This file sets up an on-demand CPU profiling mechanism for the Node.js application through the following two functions:
startCPUProfile()connects to the inspector session and enables the CPU profiler by sending appropriate commands using the inspector protocol.stopCPUProfile()stops the CPU profiler, retrieves the profiling data, and writes it to a file namedprofile.cpuprofile.
The program is also set up to listen for the SIGUSR1 and SIGUSR2 signals.
The former triggers the collection of the CPU profile, while the latter stops
CPU profiling and saves the profiling data to a file for analysis.
You can restart your server with npm start, then trigger CPU profiling by
sending the SIGUSR1 signal to the process through the kill command. Ensure
you replace <process_id> with the pid value found in the server startup log:
kill -SIGUSR1 <process_id>
If the above command exits successfully, it indicates that profiling has
started. You can now use autocannon to send some load to the
/fibonacci-recursive/:n route as before. Once that's done, send the SIGUSR2
signal to stop the profiling and write the data to a file:
kill -SIGUSR2 <process_id>
You should see a new profile.cpuprofile file in your project directory
which contains the collected profiling information. To analyze the data, open
Chrome DevTools and click the Load profile button in the Performance tab:
Once the file is loaded, you will see the flame graph as before. Analyze it to identify performance bottlenecks, just as described in the previous section.
With this approach, you can trigger CPU profiling on demand, in real-time, without interrupting server operations. In a production environment, consider setting up a different mechanism (e.g., an HTTP endpoint) to trigger profiling and automatically upload the profile data to a secure location for convenient retrieval and analysis.
Wrapping Up
In this article, we explored the challenges associated with managing CPU-bound tasks in Node.js and their substantial influence on runtime efficiency. You also learned several methods to profile your code and identify performance bottlenecks.
In the upcoming and concluding second part, our focus will shift to specific techniques you can employ to enhance the performance of CPU-bound tasks in Node.js.
Until next time, thanks for reading!
P.S. If you liked this post, subscribe to our JavaScript Sorcery list for a monthly deep dive into more magical JavaScript tips and tricks.
P.P.S. If you need an APM for your Node.js app, go and check out the AppSignal APM for Node.js.
