Debugging: measure first, guess later

A bug report arrives and within a minute somebody has a theory. The theory is plausible, it fits the symptom, and it sends two people into a part of the code that has nothing to do with the problem. I have paid for that afternoon often enough to change the order I work in. Reproduce, narrow, measure, and only then allow myself a theory.

Why the first theory is the most expensive one

The first theory is formed before any evidence exists, out of whatever you happen to have been working on that week. That makes it a description of your recent attention rather than of the system. It is also sticky. Once someone writes "probably a cache problem" in a channel, every later observation gets read as support for it, and the observations that do not fit get explained away rather than followed.

The cost is not the sentence. The cost is where everyone looks next. While three people read the cache layer, nobody reads the one log line that names the failing function.

I do not ban theories, because they are how people think. I delay them by one step and I make them cheap to test. When a theory shows up early, it goes into the issue as a line with a price attached: "theory: the cache returns a stale row. Test: log the row version at read time, five minutes." A theory that costs five minutes to kill is useful. A theory that costs an afternoon and cannot be killed is a belief.

The order that finds bugs

1. Reproduce. Get to a command, a request or a click path that fails more often than not. Until you have that, every change you make is a guess about whether it helped.
2. Narrow. Cut the space in half, then in half again, both across changes and across input. The goal is not the cause yet, only a smaller box.
3. Measure. Put numbers on the edges of that box: how long, how many, how big.
4. Theorise. Now a theory is cheap, because it has to explain numbers that already exist, and most candidate theories die on contact with them.

Each step you skip gets paid back later at a worse rate. Skipping the reproduction means you never learn whether the fix worked. Skipping the narrowing means you measure the wrong region. Skipping the measurement means your theory explains a story rather than a system.

How to narrow, twice

There are two bisections and most bugs need both. The first one is across changes:

git bisect start
git bisect bad
git bisect good v1.4.0
git bisect run ./check.sh
git bisect reset

check.sh exits 0 when the build is good and 1 when it is bad. Twenty commits become five runs. The discipline is in the script: it has to fail for the reason you care about and not for a missing dependency, so run it once on a known bad commit and once on a known good one before you trust the walk. For an intermittent bug, make the script run the check five times and report bad if any run fails.

The second bisection is across input. When an import of ten thousand rows fails and a small test file does not, split the file in half and run both halves. Four or five rounds later you have one record that fails on its own, and that record is usually more informative than a week of reading code. When both halves pass but the whole file fails, that is a finding rather than a dead end: the bug is in the interaction between records, so look at anything shared across them, such as a counter, a connection or a batch buffer.

Read the error you got

The most common failure in a debugging session is reading the error you expected instead of the one on the screen. Take this:

POST /api/import 500
TypeError: cannot read properties of undefined (reading 'id')
  at normaliseContact (import.js:212)

Read it word by word and it gives three facts. It is a 500 and not a timeout, so the request reached the handler. It is a property access on something undefined, so a lookup returned nothing rather than throwing. And it happened in normalisation, before any database write. Anyone who spent that morning on connection pools was working from the error they expected.

When the message names nothing useful, fix the message before continuing. An error that says "import failed" becomes an error that carries the batch id, the row number and the length of the field that broke, and the next occurrence answers the question by itself. Making the next hour cheaper is legitimate work in the middle of an investigation, and it is the same habit as putting the right three fields in your logs.

Measure the box before you touch it

Three numbers at the edges of the suspect region settle most arguments: a duration, a count and a size.

const t0 = Date.now();
const rows = await loadRows(batchId);
log.info({ batchId, rows: rows.length, ms: Date.now() - t0 }, 'loaded');

Put one of those at the entry and one at the exit of the region, then run the failing case once. In my experience at least one number contradicts something everybody believed: the count going in is not the count coming out, or the step that "takes no time" takes four seconds. A measurement that surprises you is worth more than ten that confirm you, and this is the same discipline as measuring a page on a real phone instead of arguing about which library is heavy.

Write the failing case down before you fix it

Before the fix, turn the reproduction into a test:

test('import keeps rows whose name field is missing', async () => {
  const result = await importRows([{ phone: '5551112233' }]);
  expect(result.failed).toBe(0);
});

Three things happen when you write it first. You find out whether you really narrowed the bug, because a test you cannot write is a bug you have not located. You get a red bar that goes green for a reason you can point at, instead of a fix that seems to help. And the case stays in the suite, which is what stops the same bug arriving again after a refactor six months from now. This is also what makes a fix safe to ship on its own, in the spirit of small reversible steps.

Knowing when to stop

After about ninety minutes without the search space getting smaller, I stop. Not because of willpower, because the returns have gone. What matters is how you stop. Write three lines in the issue: what I know, what I have ruled out, and the next test I would run. Coming back to those three lines costs a minute, and re-deriving them costs an hour.

The answer often arrives the next morning, and I think the reason is unglamorous: away from the keyboard you stop defending the theory you spent the afternoon on, and the fact that never fitted it gets a hearing.

What to watch out for

• Fixing the reproduction instead of the bug. A guard around the undefined value makes the error go away and leaves the missing record missing. Ask what should have been there, not how to survive its absence.
• Bugs that move when you look at them. Adding a log statement changes timing and can hide a race. When that happens, record the evidence instead of stepping through it: timestamps, ids and ordering written to a file, then read afterwards.
• Two bugs at once. The signature is contradictory evidence and a bisect that gives a nonsense commit. Split them by finding one symptom you can reproduce on demand and ignoring the other until it is fixed.
• Shared environments. A colleague deploying in the middle of your bisect will make a good commit look bad. Narrow on a machine nobody else is changing.

The order matters more than any single technique in it. Reproducing tells you when you are done, narrowing tells you where to look, measuring tells you what is actually happening, and a theory that arrives after those three has to survive contact with facts instead of generating them. Most of the hours I have lost to debugging were not lost to hard bugs, they were lost to acting on a confident sentence somebody said in the first minute, mine included.