Profile slow code in Node.js

Let’s set the scene. An alert comes in, and it looks like CPU usage is high for one of your Node.js applications. The support team just received a call from one of your clients who are affected. You restart the application to get your clients back up and running, but sure enough, the CPU is climbing again. Looks like someone or something stumbled into a hot path, a highly trafficked path, in the code. What do you do? Why is it slow?

Take a deep breath, you can do this. Node has some built-in tools at your disposal.

Avoiding heavy CPU usage is important for servers due to Node’s single-threaded nature. Time spent on the CPU takes time away from servicing other requests. If your application is slow to respond and the CPU runs consistently higher for the process, profiling your application will help find bottlenecks. Result? Your program is back to a speedy state.

In this article, we’ll focus on debugging applications in a remote environment (such as a staging or production server). However, these concepts also work in a local environment.

Profile using the –inspect flag

First, start the application with the --inspect flag:

node --inspect myapp.js

This enables remote debugging by opening up a debugging port bound to 127.0.0.1:9229 on the remote server. If you need another address, you can use --inspect=[host:port]. Do not use 0.0.0.0 as a host though, as it could expose your debugger to the Internet.

Then, on your local machine, tunnel to the debugger using SSH:

ssh -N -L 9229:localhost:9229 name-or-ip-of-remote-server

We use an SSH tunnel because we bound our debugger to 127.0.0.1 (localhost) on the remote server. This security measure limits the scope of who can access the debugging port to those with access to the remote server itself.

Now, we are ready to start inspecting. Launch Google Chrome and head to chrome://inspect/#devices and click on Open dedicated DevTools for Node. You should see a screen like this:

https://developer.ibm.com/developer/articles/profiling-slow-code-in-nodejs/images/profiling-1.png

Ensure you have localhost:9229 listed; if not, click Add connection to add it. Then, head to the Profiler tab.

https://developer.ibm.com/developer/articles/profiling-slow-code-in-nodejs/images/profiling-2.png

Here, select your application under Select JavaScript VM instance and click Start to begin profiling. While profiling, your application may take a slight performance hit, so keep that in mind. After some time, click Stop to finish profiling and look at the output.

Now, analyze the output using the Chrome Developer Tools, inspect the code and even test changes without starting the server.

Profile using inspector module

Using the --inspect flag requires you to restart your application to enable or run your applications with the flag already enabled, awaiting an issue. But there is another way you can approach the problem: Use the built-in inspector package.

Let’s look at a module to include in your application that runs a profiler for the provided seconds when triggered. This technique won’t expose a debugging port; instead it uses the DevTools Protocol directly:

// runProfiler.js
const inspector = require('inspector')
const util = require('util')
module.exports = runProfiler
let session = new inspector.Session()
session.connect()
let post = util.promisify(session.post.bind(session))
let delay = ms => new Promise(res => setTimeout(res, ms))
let profilerRunning = false
async function runProfiler(seconds) {
  if (profilerRunning) {
    throw new Error('Profiler already running, try again later')
  }
  profilerRunning = true
  let profile
  try {
    await post('Profiler.enable')
    await post('Profiler.start')
    await delay(seconds * 1000)
    profile = (await post('Profiler.stop')).profile
  } catch (er) {
    console.error('Profiler error:', er)
  } finally {
    await post('Profiler.disable')
    profilerRunning = false
  }
  return profile
}

Since this is a programmatic API, you can trigger it however and whenever you’d like. Let’s look at a couple examples. The first is sending the process a signal.

To send a signal, use the SIGUSR2 signal to profile 30 seconds of data and write the profile to the current working directory of the application.

const runProfiler = require('./runProfiler')
const fs = require('fs')
const util = require('util')
let writeFile = util.promisify(fs.writeFile)
process.on('SIGUSR2', async () => {
  try {
    let profile = await runProfiler(30)
    let fn = `./profile_${Date.now()}.cpuprofile`
    await writeFile(fn, JSON.stringify(profile))
    console.error('Profile written to', fn)
  } catch (er) {
    console.error('Profiler error:', er)
  }
})

If you are running a web server (like Express), you can expose a private endpoint to take a profile as well. This will download a 30-second profile when accessing the endpoint.

const runProfiler = require('./runProfiler')
// Express route. Make sure to lock this down from public access!
app.get('/_profile', async (req, res) => {
  try {
    let profile = await runProfiler(30)
    res.attachment(`profile_${Date.now()}.cpuprofile`)
    res.send(profile)
  } catch (er) {
    res.status(500).send(er.message)
  }
})

Once you have your .cpuprofile file, load that into the Chrome Developer Tools for Node by clicking the Load button on the Profiler tab (see Figure B above).

Inspecting with the inspector module

The inspector package allows you to programmatically start and shut down a debugging port. Here is a module that essentially toggles on and off --inspect flag when sent a SIGUSR2 signal:

const inspector = require('inspector')
let inspectorRunning = false
async function toggleInspector() {
  if (inspectorRunning) {
    inspector.close()
    console.log('Inspector closed')
    return
  }
  inspector.open()
  inspectorRunning = true
  console.log('Inspector running on 127.0.0.1:9229')
}
process.on('SIGUSR2', toggleInspector)

Let’s set a new scene: the alert comes in, but now you have a plan to diagnose the unexpected CPU load. By using valuable profile information, you are already on your way to understanding the problem better to make a fix.

Next steps

This article showed you how to use two built-in methods for profiling applications in Node: the --inspect flag and the inspector module. There are some other alternatives you may interested in:

Marc Harter