Here is a short story about a performance bug where the interesting part is not the bug. It is the forty minutes we spent being confidently wrong in writing.

A page that took 2.5x its sibling

Walking our own site, one page stood out. Our engineering blog index answered slower than everything around it, reproducibly — four samples, not one:

/blog              1.01s  0.87s  0.82s  0.83s
/foodforthought    0.39s  0.33s  0.42s  0.37s

The first useful thing we did was stop looking at time_total. curl will tell you where the time went, and the two numbers that matter are different:

curl -s -o /dev/null -w "%{time_starttransfer} %{time_total} %{size_download}\n" <url>

time_starttransfer is time to first byte — the server thinking. time_total minus that is the bytes arriving. Measured:

/blog              ttfb 1.15-1.18s   total 1.19-1.29s   93 KB
/foodforthought    ttfb 0.46-0.48s   total 0.52-0.58s   84 KB

Transfer was about 50–100 ms on every page. The slow page was 11% larger than the control and took 2.4x the time to first byte. So it was not the payload; it was the render.

The second useful thing was choosing a better control. "A blog index is slow" has an obvious explanation — it is a list, lists are work. But we have a second blog on the site, a different section with its own list page, and it answered in 0.28–0.35s. Same shape of page, a third of the time. That killed the theory in one call, which is what a good control is for.

The suspicious loop, and the number that fooled us

The index builds its list from MDX files on disk. Reading the loader, the shape was bad in an obvious way: it read and parsed every post, built full metadata for each — including a reading-time estimate, which tokenises the entire body — and only then filtered down to the posts that are actually published. We have 195 files. Eight of them are listed.

So: 187 post bodies tokenised and thrown away on every request. A satisfying culprit.

We timed it before believing it, which is the right instinct:

read + frontmatter parse, all 195 files      35.6 ms
reading-time over all 195 bodies             90.7 ms
the whole loop                               97.3 ms

Ninety-seven milliseconds. And the gap was about seven hundred.

So we concluded the loop was not the cause, wrote that the remainder was unexplained and "not in this file as far as I measured", shipped the filter-first fix anyway on the grounds that work you discard is work not worth doing, and put the conclusion in a comment at the top of the function where the next reader would find it.

Then we re-measured

The fix deployed. The honest thing to do with a prediction is check it, so we checked it, expecting no change.

before   /blog ttfb ~1.165s   control ~0.47s   ratio ~2.5x
after    /blog ttfb ~0.34s    control ~0.27s   ratio ~1.28x

The excess over the control went from roughly 695 ms to roughly 70 ms.

The number we would have over-claimed

Look again at those two lines, because the raw times are a trap. The control also got faster — 0.47s to 0.27s — and nothing about the control changed. Some of the improvement in the absolute numbers belongs to the platform or the network, not to us.

That is why the number to publish is the ratio, and why the samples have to be interleaved: request the suspect, request the control, divide, repeat. Conditions that drift affect both halves of each pair, so the ratio survives drift in a way a stopwatch does not. Six pairs:

1.15  1.26  1.26  1.29  1.37  1.94     median 1.28

Half an hour later, a second window of six pairs: 1.10 1.13 1.13 1.16 1.47 1.58, median 1.15. The improvement held.

Two things keep this from being a story about luck. The deploy that was live contained exactly two changed files — the loader and its test — so there was nothing else in it to credit. And the ratio was measured the same way before and after.

Why 97 ms was not 97 ms

The mistake is embarrassing in a specific and useful way.

We timed 195 file reads on a laptop, on a local SSD, with the operating system's page cache hot from the three previous runs. The code runs in a serverless function reading from a filesystem that is nothing like that. Our measurement was real; it was just a measurement of the wrong machine, and a measurement of the wrong machine is not a bound on the right one.

The part that stings: three lines below our own conclusion, in the same comment, we had written "serverless I/O is not a warm local filesystem, so the real saving could be larger or smaller." We wrote the caveat that refuted the claim, put it underneath the claim, and then reasoned as though we had not. A caveat has to constrain the conclusion in the same breath or it is decoration.

So the comment got corrected, with the numbers and with what the new measurement still does not show — and it does not show much. There is no server-side instrumentation anywhere in this. It is black-box timing across one change, and a residual 1.15–1.28x over the control is still unexplained. We are not claiming we understand the page; we are claiming the gap closed and that we no longer believe our own earlier arithmetic about why it could not.

The test that survived being wrong

One piece of this aged well, and not by accident.

The test written alongside the fix asserts no timing at all. It asserts that the cheap path returns exactly what the expensive path would have returned — same posts, same order — that reading time is still populated for the posts that are kept, and that the filter happens before the metadata is built. Then it pins the two facts that make the saving non-trivial: that more than fifty files exist on disk, and that fewer than that come back.

None of those assertions depended on our being right about the cause. When the causal story flipped, the test did not need a line changed. If we had asserted "this page responds in under 400 ms", we would have shipped a test that was either flaky or a lie, and we would have had to edit it to match whichever story we currently believed.

Assert the structural property you are confident in, not the number you are guessing at. It survives you being wrong, which, on the evidence, is a thing worth designing for.

What we would do again

Split time to first byte from transfer before forming any theory about a slow page. It took one flag and eliminated the payload immediately.
Find a control of the same kind as the suspect, not just any fast page. The second blog list did more work than three more samples of the first would have.
Interleave the suspect with the control and read the ratio. The absolute times moved for reasons that had nothing to do with us.
Time the suspected hot loop before believing it — and then ask, out loud, whether the machine you timed it on is the machine that runs it.
Go back and fix the comment. A wrong claim in prose next to working code is worse than no comment, because the next person to read it has no reason to doubt it.

We Timed the Loop on the Wrong Machine