Measure Before You Guess: How Long, How Much and Where

Kenji teaches at a coaching centre in Mirpur. Every evening his script reads the day's sign-ins and prints a report of the students who came. In the first week it was instant. Now the centre is bigger, and the report takes long enough for Kenji to make tea.

Kenji is sure he knows why. "It is the string building," he says. "Adding lines with += copies the whole report every time." He spends an evening rewriting it with an array and join. The report is exactly as slow as before.

Amara does not guess. She puts a stopwatch around each part of the script and runs it once. One part takes almost all the time, and it is not the string. This module is about Amara's habit: measure first, then change one thing, then measure again. It covers three questions. How long does it take? How much memory does it hold? And when it breaks, where?

A slow program and a wrong guess

Here is a small copy of Kenji's script. It makes 30000 sign-ins from 6000 students, keeps each student once, and builds the report. The whole thing is timed with one stopwatch.

const signIns = [];
for (let i = 0; i < 30000; i++) signIns.push("s" + ((i * 7919) % 6000));

const start = performance.now();
const students = [];
for (const id of signIns) {
  if (!students.includes(id)) students.push(id);
}
let report = "";
for (const id of students) report += id + " present\n";
const ms = performance.now() - start;

console.log(students.length + " students, " + report.length + " characters");
console.log("whole script: " + ms.toFixed(1) + " ms");

6000 students, 82890 characters
whole script: 296.0 ms

The first line is the result, and it is right. The second line is the time on this run, in milliseconds. One number for the whole script tells you that it is slow. It does not tell you which part. Kenji's guess filled that gap, and the guess was wrong.

performance.now: a stopwatch in milliseconds

performance.now() returns the number of milliseconds since the program started, as a decimal number. You read it twice and subtract. The difference is how long the code between the two readings took.

const a = performance.now();
let sum = 0;
for (let i = 0; i < 1000000; i++) sum += i;
const b = performance.now();

console.log(typeof a, a < b);
console.log("sum " + sum);
console.log("the loop took " + (b - a).toFixed(2) + " ms");

number true
sum 499999500000
the loop took 4.80 ms

The reading is a plain number, and the second reading is always larger. It is a monotonic clock: it only moves forward, even if someone changes the computer's time. Date.now() is the wall clock, in whole milliseconds, and it can jump. For measuring code, use performance.now().

The last line changes a little every time you run it. Other programs share the machine, and the engine does extra work the first time code runs. So a time is always "on this run". Lesson 03 builds a small helper that runs code several times and keeps the middle value.

Time one part at a time

Amara's first move was to put a stopwatch around each part. Then the numbers can be compared with each other on the same run.

const signIns = [];
for (let i = 0; i < 30000; i++) signIns.push("s" + ((i * 7919) % 6000));

let t = performance.now();
const students = [];
for (const id of signIns) {
  if (!students.includes(id)) students.push(id);
}
const dedupeMs = performance.now() - t;

t = performance.now();
let report = "";
for (const id of students) report += id + " present\n";
const reportMs = performance.now() - t;

console.log("keep each student once: " + dedupeMs.toFixed(1) + " ms");
console.log("build the report:       " + reportMs.toFixed(1) + " ms");
console.log("dedupe is the slow part: " + (dedupeMs > reportMs * 10));

keep each student once: 282.1 ms
build the report:       0.5 ms
dedupe is the slow part: true

Look at the third line first. It compares the two parts, and it holds on every run, even though the times in milliseconds change. The += loop was never the problem. The time goes into students.includes(id). Each call walks the whole students array, so 30000 sign-ins make tens of millions of comparisons.

That comparison line is a good habit. A time on its own changes from run to run. A comparison between two parts on the same run is far more stable, and it is the thing you actually decide on.

Change one thing, then measure again

Now Amara changes only the slow part. A Set (Module 16 teaches it in full) is a collection that keeps each value once and answers "is this here?" without walking everything. She swaps the array for a Set and measures again, the same way.

const signIns = [];
for (let i = 0; i < 30000; i++) signIns.push("s" + ((i * 7919) % 6000));

let t = performance.now();
const seen = [];
for (const id of signIns) if (!seen.includes(id)) seen.push(id);
const withArray = performance.now() - t;

t = performance.now();
const set = new Set();
for (const id of signIns) set.add(id);
const withSet = performance.now() - t;

console.log("same students: " + (seen.length === set.size));
console.log("array and includes: " + withArray.toFixed(1) + " ms");
console.log("Set:                " + withSet.toFixed(1) + " ms");

same students: true
array and includes: 309.8 ms
Set:                5.0 ms

The first line checks that both ways give the same answer. Never skip that: a fast wrong answer is not an improvement. The other two lines are this run's times. The Set is faster on this run by a wide margin, and Lesson 04 explains why in terms of cost.

Notice what Amara did not do. She did not rewrite the report, the reading or anything else. One measured problem, one change, one measurement to prove it. Kenji's evening of work went into a part that cost almost nothing.

How much memory: process.memoryUsage

Time is one question. Memory is the second. process.memoryUsage() returns an object of byte counts. The one you will read most is heapUsed: the bytes the JavaScript heap holds right now. The heap is the memory where objects, arrays and strings live.

const mb = (bytes) => Math.round(bytes / 1024 / 1024);
const before = process.memoryUsage().heapUsed;

const marks = [];
for (let i = 0; i < 1000000; i++) marks.push({ roll: i, mark: i % 100 });

const after = process.memoryUsage().heapUsed;
console.log("objects kept: " + marks.length);
console.log("heap grew by about " + mb(after - before) + " MB");
console.log("more than 20 MB: " + (after - before > 20 * 1024 * 1024));

objects kept: 1000000
heap grew by about 67 MB
more than 20 MB: true

The program keeps a million small objects, and the heap grows by the amount on the second line. It is "about", for two reasons. The heap also holds garbage that the collector has not cleaned yet. And the engine reserves memory in chunks, not object by object. So read heapUsed as a rough level, and compare levels, as the third line does.

The other fields matter too. rss is all the memory the operating system gave the process, code and buffers included. heapTotal is how much heap the engine has reserved. Lesson 02 shows each field, and Lesson 05 explains the garbage collector behind them.

Where it broke: the stack trace

The third question comes when a program stops with an error. In Module 10 you met err.stack, the text that lists the stack frames: the chain of calls that were running when the error was made. The first line names the error. Then each line starting with at is one frame, the innermost first.

function toCents(price) {
  return Math.round(price.amount * 100);
}
function total(rows) {
  return rows.reduce((sum, row) => sum + toCents(row.price), 0);
}
function report(rows) {
  return "total " + total(rows);
}
try {
  console.log(report([{ price: { amount: 120.5 } }, { cost: 30 }]));
} catch (err) {
  console.log(err.message);
  for (const line of err.stack.split("\n").filter((l) => l.includes("main.js"))) {
    console.log(line.trim().replace(/[^\s(]*main\.js/, "main.js"));
  }
}

Cannot read properties of undefined (reading 'amount')
at toCents (main.js:2:27)
at main.js:5:42
at total (main.js:5:15)
at report (main.js:8:21)
at Object.<anonymous> (main.js:11:15)

Read the frames from the top. toCents broke on line 2: the second row has no price, so price is undefined, and reading amount fails. The next frame has no name. It is the arrow function on line 5, which reduce calls for each row. Then come total, report, and Object.<anonymous>, Node's name for the top of the file.

Each frame ends with the file, the line and the column. The program keeps only the frames of main.js and drops the folder, so you see only your own code.

A stack trace answers "where" in one read. Without it you would add prints to every function until you found the bad one. With it you go straight to line 2 and ask why row.price is missing.

The stack exists even when nothing breaks. The widget below replays a run of the same functions with good data. The deepest call, toCents, captures new Error().stack without throwing it, and the frames come from that real text. Watch each frame pushed when its function starts, then popped when it returns its value.

The deepest frame is the one the stack trace prints first. That is why a trace reads "inside out": the innermost call is on top, and your top-level code is at the bottom. Lesson 02 shows the same picture across an await, where the stack is rebuilt for you.

Three questions, three tools

Every slow or broken program raises one of three questions. Each has a first tool.

The rest of this module grows each column. Lesson 02 adds the other tools: console.time, console.table, console.assert, the debugger. Lessons 03 and 04 turn measurements into decisions about structures and algorithms. Lesson 05 opens the engine. Lesson 06 collects the interview's favourite question: "what does this print?"

const t0 = performance.now();          // milliseconds since start, a decimal
work();
const ms = performance.now() - t0;     // how long work() took, on this run

const m = process.memoryUsage();       // { rss, heapTotal, heapUsed, external, arrayBuffers }
m.heapUsed;                            // bytes the JavaScript heap holds now

try { work(); } catch (err) {
  err.stack;                           // "Error: why" + one "at ..." line per frame
}

function timeIt(label, fn) {
  const t0 = performance.now();
  const result = fn();
  console.log(label + ": " + (performance.now() - t0).toFixed(2) + " ms");
  return result;
}

const words = timeIt("make words", () => Array.from({ length: 200000 }, (_, i) => "w" + (i % 500)));
const lengths = timeIt("measure them", () => words.map((w) => w.length));
const longest = timeIt("find the longest", () => Math.max(...lengths.slice(0, 50000)));
console.log("longest word: " + longest + " characters");

make words: 34.98 ms
measure them: 4.01 ms
find the longest: 0.67 ms
longest word: 4 characters

const level = () => process.memoryUsage().heapUsed;
const remembered = [];
function squareKeep(n) {
  const answer = { n, square: n * n };
  remembered.push(answer);
  return answer.square;
}
function squareForget(n) {
  return n * n;
}

let before = level();
for (let i = 0; i < 300000; i++) squareForget(i);
const forgetGrowth = level() - before;

before = level();
for (let i = 0; i < 300000; i++) squareKeep(i);
const keepGrowth = level() - before;

console.log("kept answers: " + remembered.length);
console.log("keeping grew the heap more: " + (keepGrowth > forgetGrowth));
console.log("keeping grew it by over 5 MB: " + (keepGrowth > 5 * 1024 * 1024));

kept answers: 300000
keeping grew the heap more: true
keeping grew it by over 5 MB: true

const values = [5, 3, 9, 1];
for (let round = 1; round <= 3; round++) {
  const t0 = performance.now();
  const sorted = [...values].sort((a, b) => a - b);
  const ms = performance.now() - t0;
  console.log("round " + round + ": " + sorted.join(",") + " in " + ms.toFixed(4) + " ms");
}

round 1: 1,3,5,9 in 0.0219 ms
round 2: 1,3,5,9 in 0.0090 ms
round 3: 1,3,5,9 in 0.0032 ms

const lines = [];
let t0 = performance.now();
for (let i = 0; i < 2000; i++) lines.push("row " + i);
const quiet = performance.now() - t0;

t0 = performance.now();
let printed = 0;
for (let i = 0; i < 2000; i++) {
  if (i % 1000 === 0) console.log("row " + i);
  printed++;
}
const noisy = performance.now() - t0;
console.log("printing cost more than the work: " + (noisy > quiet));

row 0
row 1000
printing cost more than the work: true

let big = new Array(2000000).fill(7);
const holding = process.memoryUsage().heapUsed;
big = null;
const after = process.memoryUsage().heapUsed;
console.log("dropped right away: " + (after < holding - 1024 * 1024));

dropped right away: false

5
start 0
read 12
parse 47
sort 51
print 60

parse 35
total 60

const input = require("fs").readFileSync(0, "utf8");
const tokens = input.split(/\s+/).filter(Boolean);
let at = 0;
const next = () => tokens[at++];
const nextInt = () => Number(next());
const out = [];

// your code: read with next() and nextInt(), push every line of output to out

console.log(out.join("\n"));

6
4 7 4 9 7 7

const input = require("fs").readFileSync(0, "utf8");
const tokens = input.split(/\s+/).filter(Boolean);
let at = 0;
const next = () => tokens[at++];
const nextInt = () => Number(next());
const out = [];

// your code: read with next() and nextInt(), push every line of output to out

console.log(out.join("\n"));

includes 8
set 6

8
enter main
enter load
exit load
enter render
enter row
enter cell
exit cell
exit row

const input = require("fs").readFileSync(0, "utf8");
const tokens = input.split(/\s+/).filter(Boolean);
let at = 0;
const next = () => tokens[at++];
const nextInt = () => Number(next());
const out = [];

// your code: read with next() and nextInt(), push every line of output to out

console.log(out.join("\n"));

depth 4
main > render > row > cell

Next: every tool for measuring and debugging, one by one, from console.time to the debugger.