Debugging Performance Bottlenecks in a Node.js Application

Background

A recent update to one of our high volume production apps had the undesired consequence of increasing the time-to-first-byte by a staggering 500%. Although we had done rigorous testing, this bug did not clearly manifest itself until it was in production. To make matters worse, the application is isomorphic and we had just updated from React v0.13 to v0.14 refactoring components along the way so there was not one single change we could easily pinpoint as being the most probable cause. Tasked with identifying the problematic code, I began CPU profiling the JavaScript node application using the readily available tool – node-inspector.

This guide aims to demonstrate how to diagnose bottlenecks in your node application using node-inspector and Google Chrome.

Sample project

I’ve put together a very basic express app that calls off to a fake service which adds a delay of ~1 second (depending on your machine) to the response from the server. The code can be cloned from github:-

Quick start

To start the server, execute the following from the application root:-

The server should then output the following response:-

Node performance debug site server listening console output
Server ready and listening

Identifying the problem

Next, open up Chrome and with debugging tools enabled and focused on the network tab, navigate to http://localhost:3000/

Network trace for the node performance debug site showing a 1 second delay for time-to-first-byte
Network trace of our sample node application showing a delay of over a 1 second for time-to-first-byte.

We can clearly see that something is not right; over 1 second to get a response is too slow. So how can we diagnose what’s causing the delay?

CPU profilling Node.js

Node inspector Can help us to identify bottlenecks in the execution of the node application by profiling the code execution.

First install node-inspector globally (you may need to run as sudo),

then execute the node application using node-debug instead of node.

This will launch your application in node-inspector and open a Chrome debugger window.

Application console.log running under node-inspector
Application console.log running under node-inspector

If your browser does not automatically load, then open up a new browser instance and navigate to the debug url displayed in the console e.g. http://127.0.0.1:8080/?ws=127.0.0.1:8080&port=5858

node-inspector Chrome debug window
node-inspector Chrome debugger attached to the process and paused at the first line of code

By default, node inspector will pause execution of the application at the very first line of code.

Allow code execution to continue by pressing F8 or clicking the resume execution button.

Recording the CPU Profile

To record the JavaScript CPU profile, we need to instruct the node inspector debugging tools to record the CPU profiles, then in another browser window visit our site to generate a request that will appear in the CPU profile.

Step 1. Profiles tab

Start CPU profiling in node inspector
Start CPU profiling in node inspector

Step 2. Make sure the “Collect JavaScript CPU Profile” option has been selected.

Step 3. Click start.

Step 4. In a separate browser, navigate to http://localhost:3000/ and wait for the request to complete.

Step 5. Back in node inspector, click “Stop”.

Stop recording of the CPU profile in node inspector
Stop CPU profile recording in node inspector

6. The profile will automatically load.

Analysing the CPU profile graph

The CPU profile chart helps to easily identify where our application is spending its time whilst processing the request.

1. Make sure the chart view is selected.

Annotated node inspector CPU profile trace
The node inspector CPU profile trace – Note that the duration of the call time has increased from 1 second to almost 1 minute. Running with a debugger attached slows down the application significantly.

2. The graph shows the activity over time. We’re interested in this big block.

3. The call stack starting from top to bottom.

Looking at the call stack, we can quickly identify where our application is spending most of its time processing the request.

Using the mouse to hover over each method call, we can see that it looks like the culprit lies in slowService.js, around line 14. Armed with the knowledge let’s go to the code and see what’s going on.

So the method that’s taking a lot of time to execute is appropriately named cpuIntensiveProcess.

Clicking on the block with the name “service” will directly take you through to the source code whilst inside node inspector.

Node inspector source view of slowService.js
Viewing the problematic file in node inspector

In our sample application we can now refactor the cpuIntensiveProcess method out to be more performant, or in this example just delete it entirely because it’s not doing anything useful.

Conclusion

It is relatively pain free to troubleshoot performance problems in our application. Node-inspector is just one of a suite of tools available to help us monitor, report and diagnose performance problems.

In our production environment, we use newrelic to alert if there is ever a significant degradation in time-to-first-byte performance, as well as capturing server and client side errors giving better insights into how our applications behave in the real world.