One Line Held the Lock
A Go server I built this summer stopped scaling at two cores.
I didn't know that for two weeks, because 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 wasn't 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'd 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, sat in one function: the event emitter.
The emitter is the observability layer. Every request produces a structured event, JSON-encoded and appended to a log, and the emitter 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, and 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 isn't safe to use from two places at once, and interleaved JSON lines would be worse than slow. But the work is outside the lock 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 test box, so four cores is as far as the curve goes. Near-linear to four isn't proof of linear to thirty-two. I haven't gone looking for the next bottleneck, which is probably the write lock that's still there. I wrote that into the document as an open unknown with a number, so it doesn't get forgotten or 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's 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 didn't 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, even though 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 can't find out whether it was ever true. If I leave the old sentence with a correction on top, they can see the whole arc: the measurement, the wrong reading, the profile, the fix. The wrong reading is part of the evidence. It's how I know the profile was necessary.
The Other Finding
The same measurement pass found something I think is worse, and it isn't fixed yet.
For a query returning 100,000 rows, the endpoint allocated 38 megabytes and shipped the client 85 bytes. That's the architecture, not a measurement error. The query handler builds the entire result set, encodes all of it, and only then asks whether it fits in one block. If it doesn't, it keeps the whole encoded set as a cursor and sends the first block.
Thirty-eight megabytes allocated per query, 85 bytes delivered. A number like that hides behind a good throughput figure for small result sets, and the throughput figures were all for small result sets. The document now has a line saying every performance figure in it was measured with no database attached and small rows, so every number is a ceiling, not a prediction.
The Shape of It
I've watched a lot of engineers put observability into a system and never profile the observability, and I've been one of them. The logger is plumbing. It isn't supposed to be in the hot path. This one was, 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's 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