A compliance operator told me the moderation queue was slow again. My own request timer said otherwise: the handler was finishing in single-digit milliseconds.
The queries were fine. The indexes were fine. Measured where I had instrumented it, that endpoint was one of the fastest in the service.
The catch was where my instrumentation started: after the request had already passed through everything bolted on in front of the view. I had added audit logging for verification actions, because a human looking at someone's identity documents has to leave a trace. That record went to a remote sink, synchronously, inside the middleware chain.
Put an append to a remote thing on the hot path and you inherit its worst minute as your own worst minute.
So the handler was fast and the request was slow, and the two numbers did not meet, because nothing was measuring the space between them. I spent far too long tuning a read path that was not the problem.
What I do differently now:
I start the clock at the edge, the first byte the server accepted, not at the first line of the view. A handler timer can only exonerate the handler.
Cross-cutting work gets written locally and shipped out of band. The audit trail is a hard requirement; writing it inline is a choice, and a bad one.
Auth, audit, tracing, rate limiting all go into the latency budget explicitly. It is per-request work that nobody calls a feature, so it tends to go unprofiled.
Fast database, fast handler, slow API: the time is probably sitting in the part of the stack you stopped thinking of as code.
I go deeper on these failure modes in long form on my blog: https://polycratia.com/c/872bb7ce
And when you time a request in your own service, it is worth knowing where that clock actually starts...