One Line Held the Lock
A Go server I built this summer stopped scaling at two cores.
I did not know that for two weeks, and the reason I did not know is that the load tests were good. Tens of thousands of queries per second on a laptop, 256 simultaneous conversations responding faster per request than a single one, no queueing cliff. The document that wrote up the results said the server was maxing out the CPU on four cores and was not waiting on locks. That sentence was wrong, and the way it was wrong is the whole story.
The Table
Hold the workload fixed at 64 conversations and change how many cores the runtime is allowed to use.
One core: about 28,600 queries per second. Two cores: about 51,300. Four cores: about 51,000.
The third and fourth cores bought nothing. Nineteen thousand four hundred nanoseconds per operation on two cores, nineteen thousand five hundred on four. A 192-core server would have performed like a laptop. Every hardware-sizing conversation I had been having was meaningless until that was fixed, and I had been having them.
The Profile
A mutex profile named the cause outright. Ninety-nine point eight two percent of all lock delay in the process, 190.64 seconds of it piled up in a three-second run, all of it in one function. The event emitter.
The emitter is the observability layer. Every request produces a structured event, JSON-encoded, appended to a log. It held one lock for the whole process while it did the encoding. So every connection on every endpoint queued behind every other connection's log formatting. The diagnostic instrument was the bottleneck.
The fix is the boring one. Marshal first. Hold the lock only for the write. The lock still forces the writes to happen one at a time, and that part has to stay. An io.Writer is not safe to use from two places at once, and interleaved JSON lines would be worse than slow. But the work is outside it now. The output is byte-identical. The marshal function and the encoder both HTML-escape by default and neither had options set, so the only difference is a trailing newline, which I now add myself.
Accumulated lock delay: 190.64 seconds to 0.365 milliseconds. Four cores: 51,000 to 99,000 queries per second. Near-linear at about 1.9 times per doubling across the measured range.
What It Does Not Establish
Four cores is the whole of the test box, so four cores is as far as the curve goes. Near-linear to four is not proof of linear to thirty-two. I have not gone looking for the next bottleneck, which is probably the write lock that is still there. I wrote that into the document as an open unknown with a number, so it does not get forgotten and does not get rounded up to "scales."
One note in the other direction. The load generator shares those cores with the server, so per-core throughput is understated, not overstated. That is the kind of caveat I want on a performance claim: it tells you which way the error points.
The Correction
The document that first reported the scaling results said the server flattened at around 57,000 queries per second, CPU-saturated on four cores, not lock-bound. That sentence stood for a while. When the profile came back, I did not edit it. I put a dated correction block above it that says: that was wrong, it was lock-bound, and the plateau was not at four cores but at two.
I do that in every document now, and I want to say why, because it looks like clutter. A performance document is a record of what was believed and when. If I silently fix the sentence, a reader who remembers the old number cannot find out whether it was ever true. If I leave the old sentence with a correction on top of it, they can see the whole arc: the measurement, the wrong reading, the profile, the fix. The wrong reading is part of the evidence. It is how I know the profile was necessary.
The Other Finding
The same measurement pass found something I think is worse, and it is not fixed yet.
For a query returning 100,000 rows, the endpoint allocated 38 megabytes and shipped the client 85 bytes. That is not a measurement error. It is the architecture. The query handler builds the entire result set, encodes the entire thing, and only then asks whether it fits in one block. If it does not, it keeps the whole encoded set as a cursor and sends the first block.
Thirty-eight megabytes allocated per query, 85 bytes delivered. That is the kind of number that hides behind a good throughput figure for small result sets, and the throughput figures were all for small result sets. I have a line in the document now that says every performance figure here was measured with no database attached and small rows, so every number is a ceiling, not a prediction.
The Shape of It
I have watched a lot of engineers put observability into a system and never profile the observability. I have been one of them. The logger is plumbing. It is not supposed to be in the hot path. It was in the hot path with a lock around it, and it capped a server at two cores for two weeks while the test suite stayed green and the throughput numbers looked great.
The thing that fails is never the part you instrumented. Sometimes it is the instrument.
-- Justin Higgins. Software Engineer, Midwest. Profiled the logger and found the ceiling.
Companion pieces: Everything Looks Like Everything - the part that fails is the part nobody thought to check. Twelve Days of Green Tests - the same build, a different instrument.
Reactions, disagreements, war stories: jchigg2000.dev@gmail.com