Debugging and Profiling

Tests say expected behavior is preserved. When the process slows down, memory grows, or it gets stuck somewhere unexpected, tests stay silent: these are not correctness problems, they’re behavior problems.

This lesson takes up the tools that make those problems visible, all of them inside the runtime — no extra component needed.

The Inspector Interface

The runtime can open an interface a debugger attaches to. It listens on a port, and commands for breakpoints, stepping, inspecting variables, and taking profiles pass through it.

node --inspect=127.0.0.1:9229 -e "setTimeout(()=>{},200)"

Debugger listening on ws://127.0.0.1:9229/0dd16a67-741b-482d-86db-82b41709dc92
For help, see: https://nodejs.org/learn/getting-started/debugging

The id at the end of the address changes every run; it identifies the session and makes a random connection harder. The port number can change too.

The 127.0.0.1 part must never be skipped. This interface gives full access to the process’s memory and can run arbitrary code; listening on an address open to the network means giving up control of the process to the outside. When diagnostics are needed on a server, the interface opens on the local address, and the connection tunnels through the secure shell from the Introduction to Linux course.

The --inspect-brk flag stops before running the first line — the way to examine startup problems. A running process can also be attached to later: one that receives SIGUSR1 opens the inspector interface.

Reading Memory Usage

The process.memoryUsage() call returns several separate numbers, and which one you look at matters:

node -e "console.log(process.memoryUsage())"

{
  rss: 43483136,
  heapTotal: 5783552,
  heapUsed: 3767112,
  external: 1582649,
  arrayBuffers: 137503
}

The numbers are in bytes and change every run; their order of magnitude is what matters.

• rss is the total space the process holds in physical memory, including the runtime’s own code and the stack.
• heapTotal is the heap space allocated for JavaScript objects.
• heapUsed is the portion actually in use — the number to watch for a leak.
• external and arrayBuffers count binary data kept outside the heap; buffers live here.

The difference shows with a deliberately growing array:

// leak.mjs
import { mkdirSync } from 'node:fs';
import v8 from 'node:v8';

mkdirSync('profile', { recursive: true });

const history = [];

function addMeasurement(record) {
  history.push(record);            // never cleared
}

function heapMB() {
  return (process.memoryUsage().heapUsed / 1024 / 1024).toFixed(0);
}

console.log('heap used at start (MB)     :', heapMB());
for (let i = 0; i < 500000; i += 1) {
  addMeasurement({ node: `edge-${i % 3}`, metric: 'temperature', value: i % 40 });
}
console.log('after 500,000 records (MB)  :', heapMB());

const path = v8.writeHeapSnapshot('profile/measurements.heapsnapshot');
console.log('snapshot                    :', path.split('/').pop());

node leak.mjs

heap used at start (MB)     : 4
after 500,000 records (MB)  : 48
snapshot                    : measurements.heapsnapshot

The megabyte values shift a few units depending on runtime version and the garbage collector’s state; what matters is the size of the increase.

This is a real risk for the measurement collector: appending every incoming record to an array grows memory in direct proportion to input volume. This is why the summarizer’s bucket map stores no records, only a count and a total — memory is bounded by the number of distinct keys.

Heap Snapshot

writeHeapSnapshot writes every object at that moment and the references between them to a file. The file is a graph: every node is an object, every edge a reference — a direct application of the graph representations from the Data Structures course.

A single snapshot says little on its own. The method is comparing two snapshots: one before the load, one after, checking which object type’s count grew in between. A type that keeps growing and never shrinks leads to the source of the leak.

Taking a snapshot stops the process and produces a large file; in the example above, tens of megabytes. Taken in production, it is done accepting that requests will be delayed, with disk space checked beforehand.

The same signal mechanism works here too: the process can be written to take a snapshot on a predetermined signal, so one is taken the moment a problem shows up, without restarting the process.

CPU Profile

A CPU profile measures which function the process spends its time in by sampling: the call stack’s snapshot is taken at fixed intervals, and if a function shows up in most samples, it is spending most of the time there.

Profiling turns on with a flag and writes to a file when the process ends. The expensive computation from the Cluster and Worker Threads lesson is profiled below:

node --cpu-prof --cpu-prof-dir=cpu-profile no-worker.mjs

The produced file is in JSON format and can be read directly:

// read-profile.mjs
import { readdirSync, readFileSync } from 'node:fs';
import path from 'node:path';

const dir = process.argv[2] ?? 'cpu-profile';
const file = readdirSync(dir).find((f) => f.endsWith('.cpuprofile'));
const profile = JSON.parse(readFileSync(path.join(dir, file), 'utf8'));

const frames = new Map(profile.nodes.map((d) => [d.id, d.callFrame]));
const counts = new Map();
for (const id of profile.samples) counts.set(id, (counts.get(id) ?? 0) + 1);

const total = profile.samples.length;
console.log(`file: ${file.replace(/\d{8}\.\d{6}\.\d+/, 'DATE.TIME.PID')}`);
console.log(`sample count: ${total}`);
for (const [id, count] of [...counts].sort((a, b) => b[1] - a[1]).slice(0, 3)) {
  const c = frames.get(id);
  const name = c.functionName || '(anonymous)';
  const location = c.url ? `${path.basename(c.url)}:${c.lineNumber + 1}` : '(internal)';
  console.log(`${((count / total) * 100).toFixed(0).padStart(3)}%  ${name.padEnd(14)} ${location}`);
}

node read-profile.mjs cpu-profile

file: CPU.DATE.TIME.PID.0.001.cpuprofile
sample count: 1787
100%  heavySum       no-worker.mjs:3
  0%  (program)      (internal)
  0%  compileForInternalLoader realm:383

The file name carries the date, time, and process id, masked here for readability. The sample count changes run to run, and the lines below the first that round to zero can also differ depending on the runtime’s internal work at that moment. Fixed is the result: nearly all the time was spent in one function.

Reading a profile has two rules. First, many lines with a low percentage each means the bottleneck is not in one place, and a single optimization will not change the result. Second, sampling only sees the running CPU: time spent waiting for input/output never shows up. If a request’s slowness comes from waiting, the CPU profile comes back empty, and duration has to be measured some other way.

In-Code Duration Measurement

For a measurement that also covers waiting, node:perf_hooks is used: marks are set, intervals are measured, and an observer gathers the measurements.

// measure-duration.mjs
import { performance, PerformanceObserver } from 'node:perf_hooks';
import { readFile } from 'node:fs/promises';
import { Summarizer, recordFromLine } from './summarizer.mjs';

const observer = new PerformanceObserver((list) => {
  for (const entry of list.getEntries()) {
    console.log(`${entry.name.padEnd(12)} ${entry.duration.toFixed(2)} ms`);
  }
});
observer.observe({ entryTypes: ['measure'] });

performance.mark('read-start');
const text = await readFile('measurements.ndjson', 'utf8');
performance.mark('read-end');

const summarizer = new Summarizer();
for (const line of text.split('\n')) {
  if (line.trim() === '') continue;
  summarizer.add(recordFromLine(line));
}
performance.mark('summary-end');

performance.measure('read', 'read-start', 'read-end');
performance.measure('summarize', 'read-end', 'summary-end');

node measure-duration.mjs

read         0.39 ms
summarize    0.07 ms

Durations change every run; a measurement is not taken once and decided on, it is repeated and its distribution examined. What matters is the ratio between the two stages: in this small file, most of the time goes to reading, summarizing is nearly free.

Measurement results can be added as a field to the log record from the Logging lesson. Once records carrying a duration field pile up, which stage a slowdown comes from shows without taking a profile — why writing a duration field to request logs is a common habit.

Summary

• The inspector interface gives full access to the process’s memory; it opens on the local address, and remote access is done through tunneling.
• Memory fields carry separate meanings; the used-heap field is watched when looking for a leak, the outside-heap fields for binary data.
• A heap snapshot writes objects and references as a graph; diagnosis is done by comparing two snapshots.
• A CPU profile works by sampling and sees only the running CPU; waiting time does not show up in it.
• Marks and measures cover waiting too; writing a duration field to the log shows the source of a slowdown without taking a profile.

Next Step

So far, the process has always started by hand and stopped by closing the terminal. In production, a supervisor starts the process, reopens it when it crashes, and sends a signal when it needs to shut down. The next lesson builds the process side of that contract: catching signals, finishing running requests without taking new connections, and reporting the service’s state to the supervisor.