My benchmark harness was wrong fourteen ways before it measured anything

I built a harness to measure whether reverse proxies buffer Server-Sent
Events. The results are in the last post.
This post is about the harness, which was wrong in fourteen ways before it
produced a single number I would stand behind.

That is not a confession of sloppiness. It is the normal state of measurement
code, and the reason it stays wrong is structural: a benchmark harness is the
one piece of software whose output nobody can independently check. If your web
app returns the wrong price, a user complains. If your harness returns 1.02
instead of 1.00, it goes in a blog post and gets quoted back at you for two
years.

So here is every defect I found in mine, the lie each one would have told, and
the specific experiment that proved the fix worked. That last column is the
point of the whole post.

The worst one was invisible in the output

The suite runs several cells, each measuring six endpoints ten times. Two
guards protect it: one audits whether the emitter actually paced frames at the
interval it was told, the other requires a direct unproxied baseline to look
clean.

On an early run the pacing guard failed, so I ran it again. It failed again. It
passed on the sixth attempt, and I had a full table of clean-looking numbers.

Nothing in that table recorded that it took six attempts.

Re-running a measurement until the guard passes selects for moments when the
machine happened to be quiet. It is not a small bias, either. When I removed
the retry and took exactly one honest attempt, one cell out of six
certified. The other five were unmeasurable on that host. Six tries had
converted "this laptop cannot measure this" into a publishable table.

The falsification: run once, count what survives. Six of six became one of
six.

The fix was not just to stop retrying. It was to make the policy visible: the
suite now states in its own output that it makes exactly one attempt per cell
and never retries, and a cell that fails is labelled UNMEASURABLE with the
guard's own reason instead of quietly absent.

The guard had a tenth of the power it appeared to have

A reviewer found this one and it is my favourite defect of the set.

The runner audited the emitter's pacing after each cell. The emitter stores its
send log keyed by a request id. The runner used one id for all ten runs,
and the emitter overwrote the log on every stream.

So the guard audited the last run. The other nine went into the median
unaudited. It looked like ten runs of protection and it was one.

The falsification: give each run its own id and print the ids actually
audited. Three runs, three ids, three independent drift figures. Before the
fix there was one.

It blamed a proxy for its own stalls

The pacing guard recorded a timestamp after each write to the client. Writes
block. So when a buffering proxy applied backpressure, the emitter's write
blocked, and the guard recorded that as emitter drift — which fails the
guard and voids the cell.

Read that again in terms of what it does to a result. The cells most likely to
contain the finding are the cells most likely to be thrown away for
instrument error.

The fix: record the timestamp before the write, so the log measures when
the emitter woke up on schedule rather than when the downstream deigned to
accept bytes.

It perturbed the thing it was measuring

The emitter's Docker healthcheck spawned a fresh CPython interpreter, inside
the container, once per second, forever. Next to a loop whose entire job is
millisecond-accurate pacing.

It is obvious written down. It was invisible in a compose file.

The falsification: the drift spikes that voided five cells were 10.44 to
10.75ms against a 10.00ms tolerance. Cheap, infrequent probe instead, and the
same host measured 0.22ms.

The metric's core logic had no test at all

The headline number is frames per read: SSE frames received divided by the
number of recv() calls that delivered at least one. A frame arriving alone
gives 1.0. Forty-one frames in a single read gives 41.0.

Everything rests on incrementing the arrival counter once per read, not
once per frame. That distinction is the entire metric.

There was no test for it. Four tests covered the client, and all four used a
naturally-incremental stream where per-frame and per-read give the same answer.
A client with the increment in the wrong place passed all four.

The falsification: I wrote a relay that drains an entire upstream response
and then flushes it in one go, and asserted both sides of the contrast —
buffered at 21.00, direct at 1.00. Then I moved the increment inside the
per-frame loop and confirmed the test fails. It reports 1 arrival where 21 are
expected.

That test now pins the metric in git. The version of it I ran by hand, before
committing it, proved nothing to anyone but me.

It undercounted frames, silently

The SSE frame counter looked for blank-line terminators across reads, keeping
a tail of unconsumed bytes between calls. It counted with a non-overlapping
scan and trimmed the tail with a rightmost search. Those two can disagree
about which bytes a terminator occupied.

Given three or more consecutive newlines split across a read boundary, the tail
was trimmed past a newline the counter had not consumed, and frames were
lost. Not mangled, not errored — quietly absent from the count that every
published number derives from.

s = b"data: a\n\n" + b"\n\n" + b"data: b\n\n"   # event, blank-line keep-alive, event
s.count(b"\n\n")               -> 3
one read                       -> 3   correct
split at offset 10             -> 2   one event gone

A blank-line keep-alive next to an event boundary produces exactly this shape,
and real SSE endpoints send those.

The falsification: a 20,000-trial fuzz over an alphabet of only \n and
X, asserting the split total always equals the whole-string count. Zero
mismatches after the fix.

My own fuzz had passed this bug. I had built it from realistic SSE payloads,
which never generate three consecutive newlines. A fuzz alphabet has to
include the delimiter you are testing, not just plausible data.

The guard trusted the log it was auditing

The pacing audit sorted the emitter's send log by sequence number, then used
each entry's position as its expected time slot. It never checked the sequence
was complete.

Feed it seq [0,1,1,2] or [0,1,3,4] and it mapped entries to the wrong
planned timestamps and returned pass.

This is the function whose entire purpose is to not trust the instrument.

The falsification: both malformed logs now exit non-zero with "send log is
malformed", and a contiguous log still passes — so the check cannot be
satisfied by rejecting everything.

The self-test certified a server it had not started

selftest.sh launched the emitter in the background, waited for /healthz to
answer, then certified the host.

Three compounding mistakes. The launch was backgrounded, so a bind failure
exited a background job and set -e never saw it. The readiness probe was
curl /healthz, which any listener satisfies. And nothing ever checked the
process it launched was still alive.

I found it because a run printed Address already in use and then reached
== rig OK. A leftover emitter from an earlier run was squatting on the port.
The numbers happened to be valid. The script could not have known.

The falsification: a twelve-line decoy server that answers /healthz with
ok and does nothing else. It used to earn a rig-OK. It now gets refused with
"port already occupied".

A self-test that can certify against an unknown process is worse than no
self-test, because it produces confidence instead of an error.

Two smaller ones, same shape

The tests could not tell a median from a mean. Every gap sequence in the
metrics tests was uniform or all-zero, so median, mean and max were
indistinguishable. Swapping statistics.median for statistics.mean passed
all seven tests. Falsification: gaps of [10,10,10,200], where median is 10,
mean is 57.5 and max is 200, so each is separately falsifiable.

The leak guard was blind to the only secret in play. It grepped the tree
for the DigitalOcean API token prefix dop_v1_. The credential this code path
actually handles is a model access key, prefixed doo_v1_. Three letters, not
two. Falsification: planting a doo_v1_ string left the guard reporting "no
token material in the tree".

Then I built a mechanism that did not exist

This is the part I would most like to skip, which is how I know it belongs
here.

Measuring on macOS, I saw Caddy and Traefik take about 42ms to first token
while nginx took 2ms. The first request after startup was fast; every reused
one was slow. That is the signature of a delayed-ACK stall on a pooled
upstream connection. I had a mechanism, I could name which condition would
reproduce it, and I built a 2×2 to demonstrate it. One cell hit — warm pool,
Nagle enabled, 42.39ms — exactly where predicted and nowhere else.

Three things then dismantled it.

A reviewer pointed out my nginx config has no upstream{} block and no
keepalive, so nginx never pools upstream connections at all. It sat
permanently in the "fresh" regime that Caddy and Traefik only reach on their
first request. I had not been comparing proxies. I had been comparing pooled
against unpooled and reading the difference as a proxy property.

Then I ran the emitter alone — no proxy, no Docker, nothing in the path — for
40 runs. It produced 30 to 45ms spikes by itself. p90 of 10.89ms, max of
44.50ms.

Then I moved to Linux and the effect vanished across all nine cells and every
condition, pooled or fresh, Nagle on or off.

It was a Docker Desktop artifact. I had a mechanism, a prediction, and a
confirming observation, and the thing did not exist. The single hit in the
predicted cell was chance, and one observation is not a finding no matter how
well it fits the story you already have.

What actually made the difference

Not care. I was being careful the entire time.

Falsify every fix. For each defect above, the question was not "does it
pass now" but "does the test fail when I reintroduce the bug". Substitute the
mean and watch it fail. Move the increment per-frame and watch it fail. Plant
the token prefix and watch it fail. A fix you cannot falsify is a fix you are
taking on faith.

Isolate before attributing. Every wrong mechanism I built came from
measuring a composite and blaming one component. The emitter-alone run settled
in ten minutes what a 2×2 had failed to settle.

Make the exclusion rule declared, mechanical, and published. I do still
discard individual runs — 1.7% to 11.7% per cell, because across roughly 2,400
timed writes the chance of one scheduling hiccup approaches certainty. That is
legitimate where retry-until-green was not, and the difference is exactly four
properties: the criterion is stated in advance, it is mechanical, it is
measured on the instrument side independently of the result being tested, and
every exclusion is counted in the published table. Retrying until green fails
all four.

The check that convinced me: re-enabling Nagle on the emitter doubled the
exclusion rate from 5.0% to 10.0% and left every proxy number unchanged. The
exclusions were removing apparatus noise, not shaping the answer.

Write down the tolerance reasoning. My first guard used a flat millisecond
budget. At a 5ms emit interval a flat 5ms permits 100% error; a flat 10%
demands 0.2ms, which is below the scheduling granularity of a shared vCPU.
Neither is a tolerance, they are just numbers. It became max(2ms, 20% of
interval) and the behaviour is now falsifiable in both directions: 4ms of
drift fails at a 5ms interval while 1.5ms passes, and 25ms fails at 50ms.

Publish the numbers that are not findings. Frames per read has a noise
floor around 1.02 — the direct, unproxied path measures 1.02. Quoting 1.02
for a proxy as if it differed from 1.00 is reading noise as signal, and I only
know that because something forced me to look at the baseline column.

The uncomfortable part

Half of these were found by review, not by me. The guard auditing one run in
ten, the timestamp after the blocking write, the nginx pooling confound that
killed my best mechanism — all three came from someone reading the whole diff
at once and asking what a number was allowed to prove.

My own pre-flight check on the plan had passed the task whose code could not
pass its own tests. I had verified that code and tests both existed and were
plausible, not that the code would actually pass the tests it shipped with.
Tracing assertions one at a time is the only version of that check worth
running.

The harness is fine now. Nine cells certify, the guards fail closed, and the
metric is pinned in git by a test that fails when you break it. But it took
three Critical and fourteen Important defects to get there, and the interesting
ones were never the coding errors. They were the measurement errors: a guard
with a tenth of its advertised power, a timestamp on the wrong side of a
blocking write, a healthcheck perturbing the thing it checked, and a retry loop
doing to my own numbers precisely what the harness existed to prevent.

If you have a benchmark you have never tried to break, you do not have a
benchmark. You have a number.

Comments

[Raknaos]

"Re-running a measurement until the guard passes selects for moments when the machine happened to be quiet" is the sentence. And the honest number being one cell out of six instead of six out of six is exactly the kind of result that never makes it into a blog post, because the table looks the same size either way and only the footnote changed.

Making the policy part of the output rather than part of the code is the part I'd steal. UNMEASURABLE with the guard's own reason is still information; a silently absent cell is just a hole someone else has to interpret later.

The backpressure one also bit us. We measure timings on a relay that pushes SSE-ish streams, and timestamps were captured after the write, so a buffering proxy applied backpressure and our own component got blamed for the stall. Recording before the write sounds trivial until you've spent a week chasing a regression that was purely in how you woke up.

[Jo Do]

"Wrong fourteen ways before it measured anything" is the honest preface every benchmark should have and almost none do. The measuring instrument is always the first system under test, and with SSE you get it double: the harness has to be dumber than the proxies or it fixes the very buffering you're hunting. Your 206ms HAProxy result from the last post is a perfect example of why this matters - that number is invisible to every integration test, because tests assert content, not arrival time. Streaming correctness is a timing property, and timing properties only exist under real network behavior, which is exactly what test environments remove. The harness IS the result here; the proxy numbers are just what it happened to catch first.