Performance all 4 written
What blocking the event loop actually costs, threads for work that computes, and measuring speed and memory instead of guessing.
43 Blocking the event loop, measured
Node runs all of your JavaScript on one thread, one callback at a time (lesson 25). That is why it can juggle thousands of connections without locks or threads — and it means that while one callback is busy, nothing else happens. No other request is answered, no timer fires, no data is read. This lesson measures what that costs, finds the common ways it happens by accident, and fixes them.
One slow route makes every route slow
server.mjs
import { createServer } from "node:http";
// About half a second of pure computation.
function buildReport() {
let total = 0;
for (let i = 0; i < 300_000_000; i++) total += i % 7;
return total;
}
const server = createServer((req, res) => {
if (req.url === "/report") return res.end(`report total: ${buildReport()}`);
res.end("ok");
});
server.listen(0, "127.0.0.1", () => {
console.log(`http://127.0.0.1:${server.address().port}`);
});
example.mjs
import { spawn } from "node:child_process";
import { createInterface } from "node:readline";
import { once } from "node:events";
import { setTimeout as sleep } from "node:timers/promises";
// The server runs as its own process, so this one stays free to measure.
const server = spawn(process.execPath, ["server.mjs"], { stdio: ["ignore", "pipe", "inherit"] });
const [base] = await once(createInterface({ input: server.stdout }), "line");
async function timed(path) {
const started = performance.now();
await (await fetch(base + path)).text();
return performance.now() - started;
}
await timed("/health"); // warm up the connection
const alone = await timed("/health");
const report = timed("/report"); // start the slow one...
await sleep(50);
const during = await timed("/health"); // ...and ask for health 50 ms in
const reportMs = await report;
console.log(`/health on its own: ${alone.toFixed(1)} ms`);
console.log(`/report: ${reportMs.toFixed(0)} ms`);
console.log(`/health while /report runs: ${during.toFixed(0)} ms`);
server.kill();
check("health is quick on its own", alone < 50, true);
check("but waited for the report to finish", during > 200, true);
What node printed, when the build ran it
node example.mjs
/health on its own: 3.9 ms /report: 506 ms /health while /report runs: 456 ms ok health is quick on its own ok but waited for the report to finish
/health does nothing, and on its own it answers in a millisecond or two. Asked while
/report was computing, it took hundreds of milliseconds, because the server could not
even read the request until the loop in buildReport finished. Every user of the server
waits behind every slow request. With a hundred users asking for reports, the hundredth waits fifty
seconds — and so does anyone who only wanted the home page.
This is also why the panel starts the server as a separate process, as lesson 36 did. A client in the same process as the server would have been frozen too, and measured nothing.
The sync versions of async functions
example.mjs
import { scrypt, scryptSync } from "node:crypto";
import { promisify } from "node:util";
const scryptAsync = promisify(scrypt);
const cost = { N: 2 ** 15, r: 8, p: 1, maxmem: 64 * 1024 * 1024 }; // about 90 ms per hash
// A ticker standing in for "everything else the server should be doing".
let ticks = 0;
const ticker = setInterval(() => ticks++, 5);
let started = performance.now();
ticks = 0;
for (let i = 0; i < 4; i++) scryptSync(`password ${i}`, "salt", 64, cost);
const syncMs = performance.now() - started;
const syncTicks = ticks;
await new Promise((resolve) => setTimeout(resolve, 20));
started = performance.now();
ticks = 0;
await Promise.all([0, 1, 2, 3].map((i) => scryptAsync(`password ${i}`, "salt", 64, cost)));
const asyncMs = performance.now() - started;
const asyncTicks = ticks;
console.log(`4 × scryptSync: ${syncMs.toFixed(0)} ms, and the ticker ran ${syncTicks} times`);
console.log(`4 × scrypt: ${asyncMs.toFixed(0)} ms, and the ticker ran ${asyncTicks} times`);
// Eight at once: when does each one finish?
started = performance.now();
const finished = await Promise.all(Array.from({ length: 8 }, (_, i) =>
scryptAsync(`password ${i}`, "salt", 64, cost).then(() => Math.round(performance.now() - started))));
clearInterval(ticker);
finished.sort((a, b) => a - b);
console.log("8 × scrypt, finish times in ms:", finished.join(", "));
const gaps = finished.slice(1).map((t, i) => t - finished[i]);
check("the sync calls froze everything else", syncTicks, 0);
check("the async ones ran in parallel while the ticker kept going", [asyncMs < syncMs, asyncTicks > 5], [true, true]);
check("eight hashes finished as two groups of four", gaps.indexOf(Math.max(...gaps)), 3);
What node printed, when the build ran it
node example.mjs
4 × scryptSync: 365 ms, and the ticker ran 0 times 4 × scrypt: 116 ms, and the ticker ran 22 times 8 × scrypt, finish times in ms: 97, 97, 97, 97, 194, 194, 194, 195 ok the sync calls froze everything else ok the async ones ran in parallel while the ticker kept going ok eight hashes finished as two groups of four
Four synchronous hashes took their full time one after another, and the ticker did not run once:
the process was frozen for the whole of it. The asynchronous version hands each hash to one of
Node's background threads — the libuv thread pool — and the main thread carries on, so the
ticker kept ticking and the four ran side by side. The eight-hash run shows the pool's size: four
finished together, and the next four could only start as those freed their threads, so the largest
gap in the finish times comes after the fourth. The pool has four threads unless the
UV_THREADPOOL_SIZE environment variable says otherwise, and it is shared by file system
calls, DNS lookups, compression and crypto.
The rule that follows: in anything that serves requests, never call readFileSync,
scryptSync, execSync or any other ...Sync function on the
request path. They are fine in a script, or at start-up before the server listens.
A regular expression that never finishes
example.mjs
// A pattern for "one or more groups of a's". It looks harmless.
const pattern = /^(a+)+$/;
pattern.test("aaaa!"); // one short run first: V8 compiles a pattern after its first use
const timings = {};
for (const length of [18, 20, 22, 24, 26]) {
const input = "a".repeat(length) + "!"; // almost matches, then does not
const started = performance.now();
pattern.test(input);
timings[length] = performance.now() - started;
console.log(`${length} characters: ${timings[length].toFixed(1)} ms`);
}
const simpler = /^a+$/; // means exactly the same thing
const started = performance.now();
simpler.test("a".repeat(26) + "!");
const simplerMs = performance.now() - started;
console.log(`the simpler pattern, 26 characters: ${simplerMs.toFixed(2)} ms`);
check("four more characters took several times as long", timings[26] > 4 * timings[22], true);
check("the simpler pattern answered at once", simplerMs < 5, true);
What node printed, when the build ran it
node example.mjs
18 characters: 2.2 ms 20 characters: 8.9 ms 22 characters: 34.4 ms 24 characters: 121.0 ms 26 characters: 502.5 ms the simpler pattern, 26 characters: 0.03 ms ok four more characters took several times as long ok the simpler pattern answered at once
When (a+)+ fails to match, the regex engine tries every way of splitting the a's
between the inner and outer + before giving up, and the number of ways doubles with each
extra character. Two more characters, four times as long: at 26 characters it takes about half a
second; at 40, doubling fourteen more times, it would take over two hours. (The short run before the
loop is there because V8 interprets a pattern the first time it is used and compiles it to machine
code after that; without it, the first timing is misleadingly slow.) The engine runs on the main thread, so while it tries, the server
is frozen. Anyone who can type into a field your regex checks can do that on purpose — the attack is
called ReDoS, regular expression denial of service.
The defences: avoid a repeated group that itself contains a repeat ((a+)+,
(\w+\s?)*), write the simpler pattern it usually means, and limit the length of input
before you test it — a 10,000-character "email address" should be refused before any regex sees
it.
Breaking up long work
example.mjs
import { setImmediate as yieldToLoop } from "node:timers/promises";
// The longest time the loop went without running a 10 ms timer.
let last = performance.now();
let worstGap = 0;
const ticker = setInterval(() => {
const now = performance.now();
worstGap = Math.max(worstGap, now - last);
last = now;
}, 10);
function score(i) { // a little work per item
let x = 0;
for (let j = 0; j < 400; j++) x += Math.sqrt(i * j);
return x;
}
const ITEMS = 1_000_000;
async function measure(label, job) {
await new Promise((resolve) => setTimeout(resolve, 30));
worstGap = 0;
last = performance.now();
const started = performance.now();
await job();
const took = performance.now() - started;
await new Promise((resolve) => setTimeout(resolve, 30));
console.log(`${label}: took ${took.toFixed(0)} ms; longest gap between ticks ${worstGap.toFixed(0)} ms`);
return { took, worstGap };
}
const inOneGo = await measure("in one go ", async () => {
let total = 0;
for (let i = 0; i < ITEMS; i++) total += score(i);
});
const inChunks = await measure("in 10,000s ", async () => {
let total = 0;
for (let i = 0; i < ITEMS; i++) {
total += score(i);
if (i % 10_000 === 0) await yieldToLoop(); // let everything else have a turn
}
});
clearInterval(ticker);
check("in one go, nothing else ran for hundreds of milliseconds", inOneGo.worstGap > 200, true);
check("in chunks, the ticker was never held up for long", inChunks.worstGap < 100, true);
What node printed, when the build ran it
node example.mjs
in one go : took 589 ms; longest gap between ticks 589 ms in 10,000s : took 648 ms; longest gap between ticks 17 ms ok in one go, nothing else ran for hundreds of milliseconds ok in chunks, the ticker was never held up for long
The work is the same, and took about the same time. What changed is that every 10,000 items the
chunked version awaits setImmediate, which lets every waiting callback —
timers, incoming requests, finished file reads — run before it continues. Nothing waits longer than
one chunk. The cost is a little overhead per yield, so the chunk size is a trade: small enough to keep
others waiting briefly, big enough that the yields do not dominate.
Chunking keeps the server responsive, but the work still happens on the one thread, so it is still as slow as before and still competes with every request. For work that is genuinely heavy, the real answer is another thread, which is the next lesson.
Watching it in production. monitorEventLoopDelay() from
node:perf_hooks keeps a histogram of how late the loop is running. A server that
reports its 99th-percentile delay alongside its response times will show a blocking bug as a spike
long before users complain about it.
- While one callback runs, nothing else in the process can: no requests, no timers.
- A slow request delays every other request, including trivial ones.
- Never use
...Syncfunctions on a request path. The async versions run on the libuv thread pool, four threads by default. - Nested repeats like
(a+)+can take exponential time. Limit input length first. - Split long loops with
await setImmediate(), or move the work to a worker thread.
44 worker_threads and using every core
Your machine almost certainly has several CPU cores, and a Node program uses
one of them for its JavaScript. node:worker_threads starts more threads, each with its
own event loop and its own copy of the JavaScript engine, in the same process. Work that computes —
resizing images, parsing a huge file, hashing, a simulation — can run there, so the main thread stays
free to answer requests, and several can run at once, one per core.
Moving work off the main thread
fib.mjs
import { parentPort, workerData } from "node:worker_threads";
function fib(n) {
return n < 2 ? n : fib(n - 1) + fib(n - 2);
}
// workerData is the value the parent passed in; postMessage sends the answer back.
parentPort.postMessage(fib(workerData));
example.mjs
import { Worker } from "node:worker_threads";
function fib(n) {
return n < 2 ? n : fib(n - 1) + fib(n - 2);
}
let ticks = 0;
const ticker = setInterval(() => ticks++, 10);
const pause = () => new Promise((resolve) => setTimeout(resolve, 30));
// 1. On the main thread.
await pause();
ticks = 0;
let started = performance.now();
const here = fib(38);
const hereMs = performance.now() - started;
const hereTicks = ticks;
// 2. In a worker.
await pause();
ticks = 0;
started = performance.now();
const there = await new Promise((resolve, reject) => {
const worker = new Worker(new URL("./fib.mjs", import.meta.url), { workerData: 38 });
worker.once("message", resolve);
worker.once("error", reject);
});
const thereMs = performance.now() - started;
const thereTicks = ticks;
clearInterval(ticker);
console.log(`main thread: fib(38) = ${here} in ${hereMs.toFixed(0)} ms; the ticker ran ${hereTicks} times`);
console.log(`worker: fib(38) = ${there} in ${thereMs.toFixed(0)} ms; the ticker ran ${thereTicks} times`);
check("the same answer either way", there, here);
check("on the main thread, nothing else ran", hereTicks, 0);
check("with a worker, the main thread stayed free", thereTicks > 10, true);
What node printed, when the build ran it
node example.mjs
main thread: fib(38) = 39088169 in 427 ms; the ticker ran 0 times worker: fib(38) = 39088169 in 470 ms; the ticker ran 44 times ok the same answer either way ok on the main thread, nothing else ran ok with a worker, the main thread stayed free
A worker is started from a file. workerData passes it a value to start with,
parentPort.postMessage sends a result back, and it arrives as a "message"
event. The computation took the same time either way — a worker does not make code faster — but on the
main thread the ticker was frozen for all of it, and in the worker it ticked throughout, which in a
server means every other request carried on being answered.
new URL("./fib.mjs", import.meta.url) finds the worker file relative to this module
rather than to whatever directory the program was started from, which is the reliable way to write
it (lesson 30).
Using every core
fib.mjs
import { parentPort, workerData } from "node:worker_threads";
function fib(n) {
return n < 2 ? n : fib(n - 1) + fib(n - 2);
}
// workerData is the value the parent passed in; postMessage sends the answer back.
parentPort.postMessage(fib(workerData));
example.mjs
import { Worker } from "node:worker_threads";
import { availableParallelism } from "node:os";
function fib(n) {
return n < 2 ? n : fib(n - 1) + fib(n - 2);
}
const jobs = Array.from({ length: 8 }, () => 35);
const cores = availableParallelism();
let started = performance.now();
const oneByOne = jobs.map((n) => fib(n));
const oneByOneMs = performance.now() - started;
started = performance.now();
const inParallel = await Promise.all(jobs.map((n) => new Promise((resolve, reject) => {
const worker = new Worker(new URL("./fib.mjs", import.meta.url), { workerData: n });
worker.once("message", resolve);
worker.once("error", reject);
})));
const parallelMs = performance.now() - started;
const speedup = oneByOneMs / parallelMs;
console.log(`this machine has ${cores} cores`);
console.log(`8 jobs, one after another: ${oneByOneMs.toFixed(0)} ms`);
console.log(`8 jobs, 8 workers: ${parallelMs.toFixed(0)} ms (${speedup.toFixed(1)} times as fast)`);
check("the same answers", inParallel, oneByOne);
check("several times faster, in proportion to the cores available", speedup > Math.min(cores, 8) / 3, true);
What node printed, when the build ran it
node example.mjs
this machine has 16 cores 8 jobs, one after another: 868 ms 8 jobs, 8 workers: 183 ms (4.7 times as fast) ok the same answers ok several times faster, in proportion to the cores available
Each worker ran on its own core, so the eight jobs overlapped. The speed-up is not the full eight
times: every worker costs time to start, the machine is doing other things, and on a laptop the cores
slow down when they all get busy at once. On a machine with fewer cores the jobs would queue for them,
and more workers than cores only adds overhead. availableParallelism() tells you how
many are worth starting.
Starting a worker is not free: a pool
fib-service.mjs
import { parentPort } from "node:worker_threads";
function fib(n) {
return n < 2 ? n : fib(n - 1) + fib(n - 2);
}
// Stays alive, answering one message after another.
parentPort.on("message", (n) => parentPort.postMessage(fib(n)));
pool.mjs
import { Worker } from "node:worker_threads";
// A fixed set of workers, and a queue of jobs waiting for a free one.
export class WorkerPool {
#idle = [];
#queue = [];
constructor(file, size) {
for (let i = 0; i < size; i++) this.#idle.push(new Worker(file));
}
run(data) {
return new Promise((resolve, reject) => {
this.#queue.push({ data, resolve, reject });
this.#next();
});
}
#next() {
if (this.#idle.length === 0 || this.#queue.length === 0) return;
const worker = this.#idle.pop();
const { data, resolve, reject } = this.#queue.shift();
const done = (result, error) => {
worker.off("message", onMessage);
worker.off("error", onError);
if (error) return reject(error); // a crashed worker is not put back
this.#idle.push(worker);
resolve(result);
this.#next();
};
const onMessage = (result) => done(result);
const onError = (error) => done(undefined, error);
worker.on("message", onMessage);
worker.on("error", onError);
worker.postMessage(data);
}
close() {
return Promise.all(this.#idle.map((worker) => worker.terminate()));
}
}
example.mjs
import { Worker } from "node:worker_threads";
import { WorkerPool } from "./pool.mjs";
const file = new URL("./fib-service.mjs", import.meta.url);
const tasks = Array.from({ length: 40 }, () => 27); // forty small jobs, a few ms each
// A fresh worker for every task.
let started = performance.now();
const fresh = await Promise.all(tasks.map((n) => new Promise((resolve, reject) => {
const worker = new Worker(file);
worker.once("message", (result) => { resolve(result); worker.terminate(); });
worker.once("error", reject);
worker.postMessage(n);
})));
const freshMs = performance.now() - started;
// Four workers, started once and reused.
started = performance.now();
const pool = new WorkerPool(file, 4);
const pooled = await Promise.all(tasks.map((n) => pool.run(n)));
const pooledMs = performance.now() - started;
await pool.close();
console.log(`40 tasks, a new worker each: ${freshMs.toFixed(0)} ms`);
console.log(`40 tasks, a pool of 4: ${pooledMs.toFixed(0)} ms`);
check("the same answers", pooled, fresh);
check("the pool was faster, with a tenth of the workers", pooledMs < freshMs, true);
What node printed, when the build ran it
node example.mjs
40 tasks, a new worker each: 477 ms 40 tasks, a pool of 4: 66 ms ok the same answers ok the pool was faster, with a tenth of the workers
A worker is a whole new JavaScript engine: starting one takes tens of milliseconds and several
megabytes of memory. For big jobs that is noise; for small ones it is most of the cost. A
pool starts a few workers once, keeps them alive, and feeds them jobs from a queue as they
become free. pool.mjs is a complete one in about forty lines; in a real project a
maintained package such as piscina adds timeouts, cancellation and resizing, but works
the same way.
Messages are copied
example.mjs
import { Worker } from "node:worker_threads";
import { once } from "node:events";
// A worker that reports the size of whatever it receives.
const worker = new Worker(`
const { parentPort } = require("node:worker_threads");
parentPort.on("message", (buffer) => parentPort.postMessage(buffer.byteLength));
`, { eval: true });
await once(worker, "online");
const data = new ArrayBuffer(200 * 1024 * 1024); // 200 MB
let started = performance.now();
worker.postMessage(data); // copied
const [copiedSize] = await once(worker, "message");
const copyMs = performance.now() - started;
console.log(`copied: ${copyMs.toFixed(0)} ms; the worker got ${copiedSize / 1024 / 1024} MB; ours is still ${data.byteLength / 1024 / 1024} MB`);
started = performance.now();
worker.postMessage(data, [data]); // transferred
const [movedSize] = await once(worker, "message");
const transferMs = performance.now() - started;
console.log(`transferred: ${transferMs.toFixed(1)} ms; the worker got ${movedSize / 1024 / 1024} MB; ours is now ${data.byteLength} bytes`);
await worker.terminate();
check("transferring was more than ten times faster", copyMs > 10 * transferMs, true);
check("and left the sender with nothing", data.byteLength, 0);
What node printed, when the build ran it
node example.mjs
copied: 579 ms; the worker got 200 MB; ours is still 200 MB transferred: 1.5 ms; the worker got 200 MB; ours is now 0 bytes ok transferring was more than ten times faster ok and left the sender with nothing
Workers do not share ordinary objects. Everything sent with postMessage is copied with
the structured clone algorithm, the same one as structuredClone, so a large message costs
time and doubles the memory. An ArrayBuffer can instead be transferred by listing
it in the second argument: the memory itself changes hands, which is almost instant, and the sender's
copy becomes empty so the two threads can never touch it at once.
Sharing memory, and a race
example.mjs
import { Worker } from "node:worker_threads";
import { once } from "node:events";
// Each worker adds 1 to the same counter, a million times.
const code = `
const { workerData } = require("node:worker_threads");
const counter = new Int32Array(workerData.shared);
for (let i = 0; i < 1_000_000; i++) {
if (workerData.atomic) Atomics.add(counter, 0, 1);
else counter[0]++;
}
`;
async function count(atomic) {
const shared = new SharedArrayBuffer(4); // one 32-bit integer, seen by every thread
const workers = Array.from({ length: 4 }, () =>
new Worker(code, { eval: true, workerData: { shared, atomic } }));
await Promise.all(workers.map((worker) => once(worker, "exit")));
return new Int32Array(shared)[0];
}
const plain = await count(false);
const atomic = await count(true);
console.log(`4 workers × 1,000,000 with counter[0]++: ${plain.toLocaleString("en")}`);
console.log(`4 workers × 1,000,000 with Atomics.add: ${atomic.toLocaleString("en")}`);
check("plain ++ lost updates", plain < 4_000_000, true);
check("Atomics.add lost none", atomic, 4_000_000);
What node printed, when the build ran it
node example.mjs
4 workers × 1,000,000 with counter[0]++: 1,467,566 4 workers × 1,000,000 with Atomics.add: 4,000,000 ok plain ++ lost updates ok Atomics.add lost none
A SharedArrayBuffer is the one thing threads really share. counter[0]++
is three steps — read the value, add one, write it back — and when two threads read the same value at
the same moment, both write back the same result and one increment disappears. Millions did. This is
a race condition, the classic bug of threaded programs, and it is why the main thread in Node
never shares anything by default. Atomics.add does all three steps as one indivisible
operation. If you find yourself needing shared memory, keep it to numbers and use
Atomics for every access; most programs only ever need messages.
When a worker fails
example.mjs
import { Worker } from "node:worker_threads";
const worker = new Worker(`throw new TypeError("the worker's own bug");`, { eval: true });
const seen = [];
worker.on("error", (err) => {
seen.push(err.name);
console.log("the parent got an error event:", err.name + ":", err.message);
});
worker.on("exit", (code) => {
seen.push(code);
console.log("the worker exited with code", code);
console.log("and the parent is still running");
check("an exception in a worker arrives as an error event, then exit 1", seen, ["TypeError", 1]);
});
What node printed, when the build ran it
node example.mjs
the parent got an error event: TypeError: the worker's own bug the worker exited with code 1 and the parent is still running ok an exception in a worker arrives as an error event, then exit 1
An exception a worker does not catch ends that worker only, and reaches the parent as an
"error" event followed by "exit" with code 1. The parent carries on — as long
as it listens for "error", because like any EventEmitter (lesson 33) an unhandled
"error" would crash it. One trap: await once(worker, "exit") rejects
if an "error" arrives first, so waiting that way for a worker that may fail needs a
try. A pool should also replace a worker that died rather than put it back, which is
what the if (error) in pool.mjs is for.
- A worker runs JavaScript on another thread with its own event loop. Start one with
new Worker(url, { workerData }). - It does not make code faster; it keeps the main thread free and lets jobs run on several cores.
- Starting a worker is expensive. Reuse them with a pool.
- Messages are copied. Transfer large
ArrayBuffers instead. - Shared memory needs
Atomics, or updates are lost. - Listen for
"error"on every worker.
45 Measuring speed instead of guessing at it
Programmers are famously bad at guessing where their programs spend time. The loop you suspect is usually fine, and the slow part is a line you never looked at twice. This lesson is about finding out instead: timing code in a way that means something, profiling a whole program to see where its time really goes, and reporting speed in numbers that describe what users actually experience.
Timing something, properly
example.mjs
function slugify(title) {
return title.toLowerCase().normalize("NFKD").replace(/[\u0300-\u036f]/g, "")
.replace(/[^a-z0-9]+/g, "-").replace(/^-|-$/g, "");
}
const titles = Array.from({ length: 2000 }, (_, i) => `Café Menu, Item #${i}: Crème Brûlée & Friends`);
// The same work, twenty times.
const runs = [];
for (let run = 0; run < 20; run++) {
const started = performance.now();
for (const title of titles) slugify(title);
runs.push(performance.now() - started);
}
const sorted = [...runs].sort((a, b) => a - b);
const median = sorted[Math.floor(sorted.length / 2)];
console.log("every run, in ms:", runs.map((ms) => ms.toFixed(1)).join(" "));
console.log(`first run ${runs[0].toFixed(1)} ms, median ${median.toFixed(1)} ms, fastest ${sorted[0].toFixed(1)} ms`);
console.log("one slug:", slugify(titles[0]));
check("the first run was noticeably slower than a typical one", runs[0] > 1.3 * median, true);
What node printed, when the build ran it
node example.mjs
every run, in ms: 5.8 3.9 3.7 3.7 3.6 3.6 3.9 3.9 3.4 3.5 3.7 3.4 3.5 3.5 3.4 3.5 3.5 3.5 3.6 3.4 first run 5.8 ms, median 3.6 ms, fastest 3.4 ms one slug: cafe-menu-item-0-creme-brulee-friends ok the first run was noticeably slower than a typical one
performance.now() is the clock to time with: it counts milliseconds, with fractions,
from when the process started, and unlike Date.now() it never jumps when the system
clock is corrected. The twenty runs show why one measurement is not enough. The first is the slowest,
because V8 starts by interpreting code and only compiles it to fast machine code once it notices the
code is hot. After that the times settle, with some noise from everything else the machine is
doing.
So a fair benchmark runs the code several times first, then measures many runs and reports the median. And before any of it, ask whether you are measuring the right thing: a function that takes a millisecond does not matter in a request that spends a second waiting on a database.
Profiling: where does the time go?
A profiler answers that for a whole program. It stops the program thousands of times a
second and notes which function was running. Functions that appear in many samples are where the time
goes. Node has one built in: --cpu-prof writes a .cpuprofile file when the
program exits.
report.mjs
// Unique visitors from a log of 30,000 visits.
function makeLog(count) {
const lines = [];
for (let i = 0; i < count; i++) lines.push(`2026-09-30,visitor-${(i * 7919) % 12000},/page/${i % 40}`);
return lines;
}
function parse(lines) {
return lines.map((line) => {
const [date, visitor, path] = line.split(",");
return { date, visitor, path };
});
}
function uniqueVisitors(visits) {
const seen = [];
for (const visit of visits) {
if (!seen.includes(visit.visitor)) seen.push(visit.visitor);
}
return seen;
}
function format(visitors) {
return visitors.map((visitor, i) => `${i + 1}. ${visitor}`).join("\n");
}
const started = performance.now();
const visitors = uniqueVisitors(parse(makeLog(30_000)));
const text = format(visitors);
console.log(`${visitors.length} unique visitors, a ${text.length}-character report, in ${Math.round(performance.now() - started)} ms`);
top.mjs
import { readFileSync } from "node:fs";
// A .cpuprofile is JSON: a tree of call-stack nodes, plus a list of samples,
// each naming the node that was running when the profiler looked.
const profile = JSON.parse(readFileSync(process.argv[2], "utf8"));
const nodes = new Map(profile.nodes.map((node) => [node.id, node]));
const msPerSample = (profile.endTime - profile.startTime) / profile.samples.length / 1000;
const selfTime = new Map();
for (const id of profile.samples) {
const { functionName, url, lineNumber } = nodes.get(id).callFrame;
const name = url.startsWith("file:")
? `${functionName || "(anonymous)"} ${url.split("/").pop()}:${lineNumber + 1}`
: functionName.startsWith("(") ? functionName : "(inside Node itself)";
selfTime.set(name, (selfTime.get(name) ?? 0) + msPerSample);
}
const total = [...selfTime.values()].reduce((a, b) => a + b, 0);
console.log(" time share where");
for (const [name, ms] of [...selfTime].sort((a, b) => b[1] - a[1]).slice(0, 5)) {
console.log(`${ms.toFixed(0).padStart(4)} ms ${((ms / total) * 100).toFixed(0).padStart(3)}% ${name}`);
}
The terminal, as the build ran it
node --cpu-prof --cpu-prof-name=profile.cpuprofile report.mjs 12000 unique visitors, a 229783-character report, in 825 ms ls profile.cpuprofile report.mjs top.mjs node top.mjs profile.cpuprofile time share where 803 ms 95% uniqueVisitors report.mjs:15 16 ms 2% (anonymous) report.mjs:9 14 ms 2% (garbage collector) 8 ms 1% (inside Node itself) 3 ms 0% makeLog report.mjs:2
The usual way to read a .cpuprofile is to open it in Chrome DevTools (the Performance
panel accepts the file), which draws it as a flame chart. It is only JSON, though, and
top.mjs adds up the samples per function so this page can show the answer as text. The
answer is not subtle: almost all of the time was in uniqueVisitors, a function that
looks like four innocent lines. Parsing 30,000 lines, which you might have guessed was the slow part,
barely registers.
Fixing what the profile found
example.mjs
function uniqueWithIncludes(items) {
const seen = [];
for (const item of items) if (!seen.includes(item)) seen.push(item);
return seen;
}
function uniqueWithSet(items) {
return [...new Set(items)];
}
const results = {};
for (const size of [2500, 5000, 10000]) {
const items = Array.from({ length: size }, (_, i) => `visitor-${i}`);
let started = performance.now();
const a = uniqueWithIncludes(items);
const includesMs = performance.now() - started;
started = performance.now();
const b = uniqueWithSet(items);
const setMs = performance.now() - started;
results[size] = { includesMs, setMs, same: a.length === b.length };
console.log(`${String(size).padStart(5)} visitors: includes ${includesMs.toFixed(1).padStart(6)} ms, Set ${setMs.toFixed(2).padStart(5)} ms`);
}
check("both give the same answer", Object.values(results).every((r) => r.same), true);
check("doubling the input made includes about four times slower", results[10000].includesMs > 2.5 * results[5000].includesMs, true);
check("the Set was over twenty times faster at 10,000", results[10000].setMs * 20 < results[10000].includesMs, true);
What node printed, when the build ran it
node example.mjs
2500 visitors: includes 11.1 ms, Set 1.06 ms 5000 visitors: includes 50.4 ms, Set 2.39 ms 10000 visitors: includes 207.1 ms, Set 1.95 ms ok both give the same answer ok doubling the input made includes about four times slower ok the Set was over twenty times faster at 10,000
seen.includes(item) looks at every element of seen in turn, so each check
gets slower as the list grows, and doing it once per item means the total grows with the
square of the input: double the visitors, four times the work. A Set (lesson
15) answers "have I seen this?" in about the same time however big it is. The code is shorter, too.
Most real speed-ups look like this — not a clever trick, but replacing work that grows with the square
of the input with work that grows in proportion to it — and they are very hard to spot by reading,
and very easy to spot in a profile.
Averages hide the slow requests
example.mjs
import { createHistogram } from "node:perf_hooks";
let cache = null;
function handle(request) {
if (request % 50 === 0) cache = null; // the cache expires now and then
if (cache === null) {
const rows = Array.from({ length: 200_000 }, (_, i) => (i * 7919) % 100_003);
cache = rows.sort((a, b) => a - b); // the slow path: rebuild it
}
return cache[request % cache.length];
}
const histogram = createHistogram(); // records whole numbers
for (let request = 0; request < 2500; request++) {
const started = performance.now();
handle(request);
histogram.record(Math.max(1, Math.round((performance.now() - started) * 1000))); // microseconds
}
const ms = (microseconds) => `${(microseconds / 1000).toFixed(2)} ms`;
console.log("requests:", histogram.count);
console.log("mean: ", ms(histogram.mean));
console.log("median: ", ms(histogram.percentile(50)));
console.log("p99: ", ms(histogram.percentile(99)));
console.log("slowest: ", ms(histogram.max));
check("the median request was faster than the mean", histogram.percentile(50) < histogram.mean, true);
check("and the slowest one in a hundred took far longer than either", histogram.percentile(99) > 10 * histogram.mean, true);
What node printed, when the build ran it
node example.mjs
requests: 2500 mean: 1.08 ms median: 0.00 ms p99: 53.02 ms slowest: 64.13 ms ok the median request was faster than the mean ok and the slowest one in a hundred took far longer than either
Forty-nine requests in fifty found the cache and took so little time that it rounds to 0.00 ms;
one in fifty rebuilt it and took tens of milliseconds. The mean averages the two into a figure that no request actually took,
and describes nobody's experience. The median (the 50th percentile) says what a typical
request took, and the 99th percentile, p99, says what the slowest one in a hundred took —
and a user who loads a page making twenty requests will hit that slow one often. Latency is reported
as percentiles for this reason. createHistogram from node:perf_hooks keeps
them for you without storing every measurement.
More tools, all built in. node --inspect lets Chrome DevTools attach
to a running program and profile it live. performance.mark() and
performance.measure() time named steps and appear in those profiles. And
node --cpu-prof works on a test run too, when it is the tests that are slow.
- Time with
performance.now(). Warm up, run many times, report the median. - Profile before you optimise:
node --cpu-prof, then read the.cpuprofilein DevTools. - The slow part is often an innocent-looking loop inside a loop. Look for work that grows with the square of the input.
- Report latency as percentiles: the median and p99, not the mean.
46 Memory, leaks and the garbage collector
JavaScript manages memory for you. You create objects, and a garbage collector finds the ones nothing can reach any more and frees them. That removes a whole class of bugs, but not all of them: if your program keeps a reference to something, it is never freed, and a server that keeps a little more on every request grows until it dies. That is a memory leak, and this lesson makes one, finds it and fixes it.
What memoryUsage tells you
example.mjs
const mb = (bytes) => `${(bytes / 1024 / 1024).toFixed(1)} MB`;
function snapshot(label) {
gc(); // collect garbage first, so we measure what is live
const m = process.memoryUsage();
console.log(`${label.padEnd(24)} rss ${mb(m.rss).padStart(9)} heapUsed ${mb(m.heapUsed).padStart(8)} arrayBuffers ${mb(m.arrayBuffers).padStart(8)}`);
return m;
}
const start = snapshot("at start");
const buffer = Buffer.alloc(100 * 1024 * 1024, 1); // 100 MB of bytes, all set to 1
const afterBuffer = snapshot("after a 100 MB Buffer");
const objects = Array.from({ length: 1_000_000 }, (_, i) => ({ i })); // a million small objects
const afterObjects = snapshot("after 1,000,000 objects");
check("the Buffer lives outside the JavaScript heap",
[afterBuffer.heapUsed - start.heapUsed < 5 * 1024 * 1024, afterBuffer.arrayBuffers - start.arrayBuffers > 99 * 1024 * 1024],
[true, true]);
check("the objects live inside it", afterObjects.heapUsed - afterBuffer.heapUsed > 20 * 1024 * 1024, true);
check("both are still in use", [buffer.length, objects.length], [104857600, 1000000]);
What node printed, when the build ran it
node --expose-gc example.mjs
at start rss 34.7 MB heapUsed 3.7 MB arrayBuffers 0.1 MB after a 100 MB Buffer rss 136.5 MB heapUsed 3.9 MB arrayBuffers 100.1 MB after 1,000,000 objects rss 198.3 MB heapUsed 42.0 MB arrayBuffers 100.1 MB ok the Buffer lives outside the JavaScript heap ok the objects live inside it ok both are still in use
Three numbers matter. heapUsed is the memory held by JavaScript objects: strings,
arrays, your objects. arrayBuffers is the memory behind Buffers and typed arrays, which
lives outside the JavaScript heap — so a 100 MB Buffer barely moved heapUsed.
rss ("resident set size") is everything the operating system has given the process, the
engine and Node's own code included, and it is the number a container's memory limit is enforced
against.
The panel runs with --expose-gc, which makes a gc() function available so
that it can force a collection before each measurement. Never ship code that calls it; the collector
decides for itself when to run, and does it better. For measuring, it removes the garbage that has
simply not been collected yet.
A leak, and the fix
example.mjs
const mb = (bytes) => (bytes / 1024 / 1024).toFixed(1);
const heap = () => { gc(); return process.memoryUsage().heapUsed; };
// A search endpoint remembers its results, to answer repeat searches instantly.
const cache = new Map();
function searchCached(query) {
if (!cache.has(query)) cache.set(query, { query, results: "r".repeat(1000) + query });
return cache.get(query);
}
// The same idea, holding at most 1,000 results: least recently used goes first.
class LruCache {
#map = new Map();
constructor(max) { this.max = max; }
get(key) {
if (!this.#map.has(key)) return undefined;
const value = this.#map.get(key);
this.#map.delete(key); // re-insert: a Map keeps insertion order,
this.#map.set(key, value); // so the oldest entry is always first
return value;
}
set(key, value) {
this.#map.delete(key);
this.#map.set(key, value);
if (this.#map.size > this.max) this.#map.delete(this.#map.keys().next().value);
}
}
const lru = new LruCache(1000);
function searchLru(query) {
let hit = lru.get(query);
if (!hit) lru.set(query, (hit = { query, results: "r".repeat(1000) + query }));
return hit;
}
const growth = {};
for (const [name, search] of [["unbounded Map", searchCached], ["LRU of 1,000", searchLru]]) {
const base = heap();
growth[name] = [];
for (let i = 1; i <= 40_000; i++) {
search(`query ${i}`); // every search is different, as real ones are
if (i % 10_000 === 0) growth[name].push(heap() - base);
}
console.log(`${name.padEnd(14)} growth after 10k, 20k, 30k, 40k searches: ${growth[name].map((b) => mb(b) + " MB").join(", ")}`);
}
const [first, , , last] = growth["unbounded Map"];
check("the unbounded cache grew with every new search", last > 3 * first, true);
check("the LRU stopped growing once it was full", growth["LRU of 1,000"][3] - growth["LRU of 1,000"][0] < 1024 * 1024, true);
What node printed, when the build ran it
node --expose-gc example.mjs
unbounded Map growth after 10k, 20k, 30k, 40k searches: 5.1 MB, 10.2 MB, 15.0 MB, 20.7 MB LRU of 1,000 growth after 10k, 20k, 30k, 40k searches: 0.5 MB, 0.5 MB, 0.5 MB, 0.5 MB ok the unbounded cache grew with every new search ok the LRU stopped growing once it was full
The first cache is a leak, though it does not look like one. Every distinct search adds an entry and nothing ever removes one, so memory grows in a straight line with the number of different searches the server has ever seen. In a test with ten searches it is invisible; in production, after a few days, the process is killed for running out of memory and restarts, and the leak starts again — which is often how it shows up: a server that is restarted every few days, and a graph of memory like a saw.
The fix is to give the cache a limit. An LRU ("least recently used") cache keeps the most recently
used entries and throws the oldest away when it is full, and a Map, which remembers the
order keys were added, makes one in a dozen lines. The same pattern — a collection that only ever grows
— is behind most leaks: an array of "recent requests" kept for debugging, event listeners added on
every request and never removed (lesson 33), timers never cleared, a closure holding on to a large
object it no longer needs.
WeakMap: data that does not keep its key alive
example.mjs
const mb = (bytes) => (bytes / 1024 / 1024).toFixed(0);
const heap = () => { gc(); return process.memoryUsage().heapUsed; };
function attach(store) {
const users = Array.from({ length: 100_000 }, (_, i) => ({ id: i }));
// Extra data about each user, kept to one side.
for (const user of users) store.set(user, { history: new Array(20).fill(user.id) });
return users;
}
const kept = {};
for (const Store of [Map, WeakMap]) {
const base = heap();
const store = new Store();
let users = attach(store);
const withUsers = heap() - base;
users = null; // the program is finished with the users
kept[Store.name] = heap() - base;
console.log(`${Store.name.padEnd(7)} with the users: ${mb(withUsers)} MB; after dropping them: ${mb(kept[Store.name])} MB`);
globalThis[Store.name + "Store"] = store; // the store itself stays alive either way
}
check("the Map kept every user, and its data, alive", kept.Map > 20 * 1024 * 1024, true);
check("the WeakMap let them go", kept.WeakMap < 10 * 1024 * 1024, true);
What node printed, when the build ran it
node --expose-gc example.mjs
Map with the users: 30 MB; after dropping them: 29 MB WeakMap with the users: 31 MB; after dropping them: 4 MB ok the Map kept every user, and its data, alive ok the WeakMap let them go
The program stopped using its 100,000 users, but a Map with them as keys still refers
to every one, so none of them — and none of the data attached to them — could be freed. A
WeakMap holds its keys weakly: it does not count as a reason to keep them, and
when nothing else refers to a key, the key and its value are collected together. That is exactly what
you want for data about objects you do not own, like per-request or per-connection details
(lesson 15). The price is that a WeakMap cannot be listed or counted, since its contents
can vanish at any moment.
Running out
grow.mjs
const kept = [];
for (let i = 0; ; i++) {
kept.push({ id: i, note: "x".repeat(100) + i }); // never let go of anything
if (i % 50_000 === 0) {
console.log(`${i.toLocaleString("en")} objects, heap ${Math.round(process.memoryUsage().heapUsed / 1024 / 1024)} MB`);
}
}
example.mjs
import { spawnSync } from "node:child_process";
// Run grow.mjs with a deliberately small heap: 64 MB for long-lived objects.
const run = spawnSync(process.execPath, ["--max-old-space-size=64", "grow.mjs"], { encoding: "utf8" });
console.log(run.stdout.trim());
const fatal = run.stderr.split("\n").find((line) => line.startsWith("FATAL ERROR"));
console.log(fatal);
console.log("the process ended with the signal", run.signal);
check("node aborted with 'JavaScript heap out of memory'", fatal.endsWith("JavaScript heap out of memory"), true);
check("killed by SIGABRT, not a normal exit", [run.status, run.signal], [null, "SIGABRT"]);
What node printed, when the build ran it
node example.mjs
0 objects, heap 4 MB 50,000 objects, heap 19 MB 100,000 objects, heap 37 MB 150,000 objects, heap 51 MB 200,000 objects, heap 69 MB FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory the process ended with the signal SIGABRT ok node aborted with 'JavaScript heap out of memory' ok killed by SIGABRT, not a normal exit
The heap has a size limit, and a program that keeps everything reaches it. The garbage collector
tries harder and harder as it gets close — the program slows down badly first — and when a full
collection frees nothing, V8 gives up. The process does not throw an error you could catch; it prints
FATAL ERROR: ... JavaScript heap out of memory, followed by a C++ stack trace from inside
the engine that is of no use to you, and aborts. At a terminal the shell reports exit code 134, which
is 128 plus the number of SIGABRT (lesson 31).
--max-old-space-size (in megabytes) sets the limit. This panel lowered it to make the
crash quick. Raising it is sometimes right, for a program that genuinely needs a lot of memory, but
for a leak it only delays the crash.
Finding a leak in a real program. Take a heap snapshot — with
v8.writeHeapSnapshot(), or by starting node with
--heapsnapshot-signal=SIGUSR2 and sending that signal — then let the program run for a
while and take another. Open both in the Memory panel of Chrome DevTools and compare them: the objects
whose count grew between the two, and what is holding on to them, are the leak.
- The garbage collector frees objects nothing can reach. A leak is a reference you forgot you were keeping.
heapUsedis JavaScript objects; Buffers are counted inarrayBuffers;rssis the whole process.- A collection that only grows is a leak. Give caches a limit, such as an LRU.
- A
WeakMapattaches data to objects without keeping them alive. - Out of heap is a fatal abort, not an exception. Find leaks with heap snapshots.