A log line turned out to be the slowest thing in a three-second request.
This was a catalog read path on a cross-border commerce platform. Every number I had looked healthy: Postgres queries in single-digit milliseconds, no queue in the path, cheap serialization, no external API call. Response time still climbed toward three seconds whenever traffic picked up, and it settled back on its own once traffic eased. That is the classic shape of a contention problem, so I spent days on database theories.
The actual cause: structured logs were emitted from a synchronous handler that wrote to a log pipeline over TCP, inside the request. When the pipeline fell behind, the socket write blocked, and the request thread blocked with it. Every log call was quietly a network call to a dependency I had never treated as one.
It stayed invisible that long because I had instrumented the things I expected to be slow. I had timers on query time and cache time, and on outbound HTTP. Log emit was assumed to be free, so nothing timed it, and the gap just showed up as unexplained wall-clock time in the handler.
What I do differently now: logging and metrics go through a bounded in-process buffer with a non-blocking handler, and the buffer is allowed to drop under pressure. Losing log lines during an incident is cheap, and I would rather pay that than serialize user requests behind the log shipper. I time the emit path itself too, because anything that can block in the request path deserves a number next to it.
The broader rule I took from it: observability is a dependency. If it can backpressure, it can take your API down, and it will do that from the one place you are not looking.
I wrote up more of these production debugging patterns on my blog, if that's useful: https://polycratia.com/c/5cbdaa86
One thing I'm curious about, from others who run their own services: do you let your logging path drop data under load, or block to keep it complete?