Profiling

A CPU profile samples the call stack and shows where the time actually went, instead of guessing from log timestamps.

Syntaxnode --cpu-prof --cpu-prof-dir=./profiles --cpu-prof-interval=500 server.js

A CPU profile is a record of what your code was doing. V8 interrupts the process on a timer, writes down the current call stack, and counts. Functions that sit on top of many samples are where the time went. This replaces guessing, which is usually wrong, because the slow line is rarely the one that looks expensive.

Two numbers matter. Self time counts samples where the function itself was on top. Total time counts samples where it was anywhere on the stack. High total with near-zero self time means the function is only a caller; look at its children.

The quick way

node --cpu-prof app.js (added in v12.0.0) starts the profiler at startup and writes a .cpuprofile file before the process exits, into the working directory or into --cpu-prof-dir. The sampling interval defaults to 1000 microseconds and is changed with --cpu-prof-interval. Open the file in Chrome DevTools or VS Code.

Shorthand and longhand

That flag is shorthand for driving the profiler yourself through node:inspector: session.post('Profiler.enable'), then 'Profiler.start', then 'Profiler.stop', which hands back the same profile object to write to disk. The long form lets you profile one route or one job instead of the whole process. node:inspector/promises (added in v19.0.0) is the same API with Promises in place of callbacks.

What trips people up

Profile under load. An idle server's profile is mostly waiting and tells you nothing. Sampling also cannot see a function that never runs longer than one interval; a thousand tiny calls show up only inside their caller.

Example

Try it yourself
Loading editor…
Press Run to execute the code.

When to use it

  • Find which function owns the 800 ms in a request whose logs only say the whole handler was slow.
  • Prove whether a slow endpoint is burning CPU or waiting on a database before you optimise the wrong half.
  • Compare profiles before and after a change to show the hot function actually got cheaper.
  • Capture sixty seconds of a production process without restarting it.

More examples

Profiling one endpoint on demand

The longhand, used for what the flag cannot do: start profiling on a live process, capture sixty seconds of real traffic, stop, and download the file. Reach for this when the problem only appears in production and restarting with a flag is not an option. Keep the routes behind authentication; a profile contains your function names and file paths.

Example · javascript
// profile.js - mounted on an admin-only route
const { Session } = require('node:inspector/promises');  // added in v19.0.0
const { writeFile } = require('node:fs/promises');

let session = null;

async function start() {
  session = new Session();
  session.connect();
  await session.post('Profiler.enable');
  await session.post('Profiler.start');
}

async function stop(path) {
  // The same object --cpu-prof would have written for the whole process.
  const { profile } = await session.post('Profiler.stop');
  await writeFile(path, JSON.stringify(profile));
  session.disconnect();
  session = null;
  return path;
}

module.exports = { start, stop };

Capturing a profile from a running service

Two ways in, as scripts so nobody has to remember the flags. The flag form suits a reproducible load test: start, run the load, stop the process, open the file. The --inspect form suits a service you cannot restart cheaply. Note that 9229 is bound to 127.0.0.1 on purpose, since anything that attaches to the inspector can run code in your process.

Example · javascript
// package.json
{
  "scripts": {
    "start": "node server.js",
    "start:prof": "node --cpu-prof --cpu-prof-dir=./profiles server.js",
    "debug": "node --inspect=127.0.0.1:9229 server.js"
  }
}

// --inspect opens the inspector on 127.0.0.1:9229 (the default).
// Chrome at chrome://inspect then attaches and can record a profile
// live, with no code change and no restart needed to stop it.
//
// --cpu-prof-interval is in microseconds. The 1000 default is fine for
// a slow route; drop it to 100 when the whole request takes 5 ms, and
// accept the larger file and the extra overhead.

Knowing when to profile at all

Event loop delay is how long a ready callback waited before it got to run. A p99 of 2 ms means your slow endpoint is waiting on something external, and a CPU profile will show mostly idle. A p99 of 300 ms means a function is hogging the thread, and a profile will name it. Log this continuously so you know which of the two you have before you start.

Example · javascript
const { monitorEventLoopDelay } = require('node:perf_hooks');

// resolution is the gap between samples, in milliseconds (default 10).
const loop = monitorEventLoopDelay({ resolution: 20 });
loop.enable();

const timer = setInterval(() => {
  // Every value this histogram reports is in nanoseconds.
  const p99ms = loop.percentile(99) / 1e6;
  const meanMs = loop.mean / 1e6;
  console.log(`loop delay mean ${meanMs.toFixed(1)}ms p99 ${p99ms.toFixed(1)}ms`);
}, 10_000);

// unref() stops this timer from keeping the process alive on its own.
timer.unref();

Discussion

  • Be the first to comment on this lesson.