A Timer Is Not a Measurement

My benchmark prints two numbers from the same loop. How many reads per second, and how long a single read takes.

Throughput said a read costs 66 nanoseconds. The single-read column, same run, same operation, said 170.

Both numbers had been on my screen for days. I had never put them next to each other.

First, the boring fix

P99KV is a small in-memory key-value store I am building to learn performance work from the bottom up. Last night I changed one return type.

- std::optional<std::string> get(key) const;
+ const std::string*         get(key) const;

That looks like a style preference. It is not. The old signature returned a copy of the stored value, and libstdc++ only keeps strings up to 15 characters inside the string object itself. My values are 32 bytes.

So every successful read asked the allocator for memory, copied 32 bytes into it, handed the caller a value it read once and dropped, then gave the memory back. A malloc and a free, per read, to deliver bytes that were already sitting in the map.

I verified the threshold rather than trusting my memory of it. A counting operator new says a 32-character copy costs exactly one allocation, and a 10-character copy costs none.

What that was worth

Five interleaved runs of each build, medians, one pinned core, -O2. GET hit went from 9,583,395 reads per second to 15,221,732. That is 104 nanoseconds per read down to 66, a 59% gain, and the before and after ranges do not overlap at any run.

The two workloads I did not touch are the interesting part of that table. GET miss moved 3.3% and SET moved 5.5%, both well inside the run-to-run spread. A miss never copied a value, and I never touched the write path, so neither should have moved. They did not. That is the control that says I measured the change and not the weather.

Then the part that was actually worth learning

A 2.6x disagreement between two numbers describing the same operation is not a rounding problem. One of them was wrong, and I did not know which.

The throughput loop clocks once around 200,000 operations and divides. The latency loop clocks every single operation, so it can sort the results and report percentiles. That second loop is the one I trusted for p50, p95 and p99, because percentiles are the whole reason the project is called P99KV.

So I pointed the harness at nothing. Two steady_clock::now() calls wrapped around an empty statement, 200,000 times, sorted the same way.

measuring nothing at all, with the same instrument:
  p50 40 ns   p95 40 ns   p99 41 ns
  mean cost of one Clock::now() pair: 76.1 ns

Forty nanoseconds to measure an empty line. And the pair of clock calls costs 76 nanoseconds to execute, against the 66 nanoseconds a read actually takes.

The instrument was more expensive than the thing it was measuring.

That explains the gap in both directions. The reported number carries the clock's own cost, and the clock calls sit on either side of the operation, forcing ordering and denying the processor the overlap it would otherwise find across iterations. I was not measuring a read. I was measuring a read held still between two timestamps.

The part I should have caught

I have shipped three tools whose entire job is refusing to state something they cannot prove. FetchGate returns UNKNOWN rather than let a model summarise a page it never read. ReachGate returns UNKNOWN rather than call a vulnerability unreachable on a search that ran out of budget. TrustGate refuses an agent action it cannot justify, with a receipt you can check afterwards.

All three exist because a confident wrong answer is worse than an honest missing one.

And then I wrote a benchmark that reported a confident wrong answer in a column labelled p99, and I read it for days without once asking what the number was made of.

A 200 is not a read. A timer is not a measurement.

What changes

• Percentiles come from batches, not from per-operation timestamps. Clock one block of N operations, divide, repeat, and build the distribution from the block times. At 66 nanoseconds per read there is no honest way to time a single one with a 40-nanosecond instrument.
• CMakeLists.txt gets a default build type. It had none, which means a plain cmake -S . -B build produced an unoptimised binary. Any benchmark I ran without remembering to pass -O2 by hand was measuring nothing useful at all.
• The numbers go in the repo. A BENCHMARKS.md with the hardware, the flags, the command and the table, so the next claim I make about this project is one someone else can re-run.

How this was measured

Because the point of the article is that unexamined measurements lie, here is what produced these numbers. AMD Ryzen 9 8940HX, Ubuntu under WSL2, g++ 15.2.0, -O2 -DNDEBUG, pinned to one core with taskset. 50,000 entries, 200,000 operations per measurement, five runs of each build interleaved so thermal and scheduler drift hit both equally, medians reported.

Two honest limits. This is WSL2, not bare metal, so treat the absolute figures as indicative and the before-and-after comparison as the real result. And the p99 improvement I could show you, 782 nanoseconds down to 501, has overlapping ranges across runs, which makes it noise rather than a finding. Throughput is the only hard number here. Reporting the p99 anyway would have repeated the exact mistake the article is about.

Links

• P99KV on GitHub
• The commit
• A 200 Is Not a Read