When p95 explodes and p50 barely moves, the time is not in the model

Latency on a search path is reported as percentiles, and a percentile is a statement about a population of requests rather than about any single one. p50 is the request in the middle of that population: half of the requests are faster and half are slower. p95 is the request only one in twenty beats. Two percentiles of the same population describe two different requests, so a change that moves them by different amounts is saying that those two requests are not paying for the same things.

Reranking is where that distinction arrives early and hard. Reranking is a second pass over search results: a cheap retriever runs over a whole document collection and returns a shortlist of candidates, and a slower, more accurate model then scores each candidate against the query and puts the shortlist back in order. A rerank vendor publishes a number for that second model — 30 ms to score fifty documents, for the model in this system — and the number describes the forward pass alone. The request a user waits on contains the forward pass and six other things, and only one of those seven behaves the way the published number does.

Constant work moves both percentiles together#

Start from the smallest true statement available: if some component takes the same amount of time on every request, that amount is added to every member of the population. Adding the same constant to every member of a population shifts every percentile of it by that constant. The middle request gets slower by the constant, the one-in-twenty request gets slower by the constant, and the gap between them is exactly what it was before. A component with a fixed duration cannot change the shape of a latency distribution; it can only slide the whole distribution along.

Turn that round and it becomes a diagnostic. If p50 and p95 moved by different amounts, then at least one component in the request path has a duration that varies from request to request, and the size of the disagreement bounds how much it varies. This is the step worth being slow about, because it does the work that tracing is usually credited with, and it does it from two numbers on a dashboard.

The next question is which components can vary and which cannot. A component varies when its duration depends on something outside the request: how many other requests are in flight when this one arrives, how long the process has been sitting idle, how many sub-requests this one issues and how slow the unluckiest of them turns out to be. A component does not vary when its duration is fixed by its own inputs. A transformer forward pass over a fixed number of pairs at a fixed sequence length runs the same kernels over the same tensor shapes and performs the same count of arithmetic operations every time it is called. Neither the model's weights nor the GPU's clock rate knows anything about how busy the endpoint is.

There is one exception and it is worth naming, because it is the seam where model time acquires a load dependence. Dynamic batching changes the tensor shapes according to how many requests happened to arrive together, so the forward pass genuinely does take longer when the batch is fuller. That is a configuration somebody chose rather than a property of the model, which is why the waiting it causes is instrumented as its own segment further down rather than being folded into the model's own time.

The tempting mistake here is to treat a vendor's published benchmark as evidence about a production tail. A benchmark of 30 ms for fifty documents is measured on a warm instance, with nothing else in the queue, on inputs of a fixed length. It is constant by construction: it returns the same number whether the endpoint serving it is idle or saturated. A quantity that cannot move when the dangerous property moves is not evidence about that property, and the benchmark being true is exactly what makes it so easy to reach for. It answers a question nobody in a latency incident is asking.

Put this system's two changes through the diagnostic. Median latency went from 80 ms to 140 ms, a rise of 60 ms, which is consistent with a model doing roughly the work the vendor described plus some overhead — at the median, the system is behaving as designed. The tail went from 210 ms to 1,900 ms, a rise of 1,690 ms, which is nearly thirty times as much as the median moved. Divide that tail growth by the whole of the vendor's quoted model time and it comes to a factor of fifty-six: the tail grew by fifty-six times the entire budget the model was ever supposed to consume. No amount of variance in a fixed-size forward pass over fixed-length inputs produces a 56× spread, so something whose duration depends on what else is happening in the system is in the request path.

Take the request apart#

Reranking adds more to a request than a model call. The candidates arrive from the first stage as document IDs and scores, their text has to be fetched from wherever text lives, that text has to be serialised and shipped to whatever process holds the GPU, the request has to wait its turn there, it may wait further while a batch forms around it, and only then does the forward pass happen.

Six of those arrows are not the model: the trip to the index, the trip to the document store, building the request body, pushing it over the wire, the admission queue and the batch window. They are the same six steps the paragraph above walked through, and every one of them has a duration that depends on something other than the query. Instrumenting each as its own span — a named, timed segment of a distributed trace, recorded with its start and end so the pieces of one request can be added up — and exporting them turns the incident from an argument into a table, and the export is the cheap part — a span around each call and a percentile aggregation per span name.

{
  "trace_id": "b91f…", "percentile": "p95", "total_ms": 1904,
  "spans": [
    {"name": "retrieve.hybrid",       "ms": 96},
    {"name": "hydrate.passages",      "ms": 190},
    {"name": "serialize.request",     "ms": 31},
    {"name": "http.rerank",           "ms": 1523,
     "children": [
       {"name": "queue.wait",         "ms": 781},
       {"name": "batch.wait",         "ms": 48},
       {"name": "model.forward",      "ms": 34},
       {"name": "cold.start",         "ms": 640},
       {"name": "wire.transfer",      "ms": 20}]},
    {"name": "sort.and.cut",          "ms": 2}
  ]
}

Two sums are worth doing on that trace before reading any of it as a story. The five children of http.rerank come to 781 plus 48 plus 34 plus 640 plus 20, which is 1,523 — their parent's own figure, with nothing left over. A decomposition that closes exactly on its whole licenses a strong claim: there is no sixth thing inside that box. Whatever else turns out to be wrong, it is not something the instrumentation missed inside the rerank call, and no fix needs to begin by looking for unmeasured time in there.

The top level does not close the same way. Adding the five top-level spans — 96, 190, 31, 1,523 and 2 — gives one thousand eight hundred and forty-two milliseconds against a total of 1,904, leaving a little over sixty milliseconds unattributed. That residual is the search API's own time between its calls, and naming it is more useful than papering over it: it is the size of the part of the request nobody instrumented, and it is small enough that no attribution decision below turns on where it went.

Five different problems wearing one number#

Laying the p50 and p95 breakdowns next to each other separates the components that are constant from the ones that are load-dependent, and the separation is stark.

The levels in that table are less informative than the gaps between the two columns, because the argument above was about growth rather than about size. Subtracting each p50 from its p95 turns it into a column of differences, and that column is not a spread of comparable numbers. Two rows carry more than four fifths of it between them: queue.wait, which was 4 ms and is 781, and cold.start, which was nothing at all and is 640. hydrate.passages supplies most of what remains. model.forward supplies 3 ms, which is under a five-hundredth of the total growth, and it is the only row in the table whose two columns are close enough together to call the same number.

The p95 column and the trace above are the same request seen twice, so one more check is available. The whole of that request is 1,904 ms and the model's own share of it is 34 ms, and 34 multiplied by 56 is 1,904 exactly. That is the same multiple the opening comparison produced from a completely different pair of inputs — the vendor's benchmark and the two percentile deltas, neither of which knows anything about spans. Two instruments landing on one number is what makes the trace trustworthy: it reproduces, from inside a single request, a ratio derived from outside the system entirely.

The model.forward row moves by 3 ms between the median and the ninety-fifth percentile, which matches the vendor's benchmark and confirms it. Replacing that model with one twice as fast takes 34 ms to 17 ms and brings p95 from 1,904 to 1,887, an improvement of 0.9% on a number that needs to fall by 74%. Those two percentages describe the same objective from opposite ends: falling by 74% leaves roughly a quarter of the current tail standing, which is the same objective the opening comparison described as being exceeded by a factor of four. The proposal was not wrong about the smaller model being faster; it was aimed at 2% of the problem.

The hydrate.passages row is the one most likely to be missed entirely, because it does not feel like part of reranking. Vector indexes store IDs and vectors, so the passage text has to come from somewhere else — Postgres, S3, a document store — and a loop issuing fifty point lookups has a tail equal to the slowest of fifty independent draws from the store's latency distribution.

That phrase is worth converting into arithmetic, because the arithmetic is what makes the row's size stop being surprising. Suppose a single lookup is 2 ms at p50 and 40 ms at p99. By the definition of a p99, one lookup comes in under 40 ms ninety-nine times in a hundred. All fifty come in under it with the probability of ninety-nine hundredths multiplied by itself fifty times, which is about three fifths, so the slowest of the fifty is above 40 ms on something like two requests in five. Now ask the question the span's own p95 asks, which is the level all fifty clear nineteen times out of twenty. For fifty independent draws to clear a level that often, that level has to be one a single lookup clears about nine hundred and ninety-nine times in a thousand. A fan-out of fifty reads its store at three nines while most teams are only charting it at two, and this is the standard mechanism by which a fan-out turns a good median into a bad tail. Replacing the loop with one WHERE id = ANY($1) query took this span from 190 ms to 24 ms at p95, and it required no change to the reranker at all.

Serialisation is the same story at smaller scale, and it grows with depth in a way that catches people who raise k without re-measuring. Fifty passages of 220 tokens are about 60 KB of JSON once escaping and field names are counted, and that body has to be built, gzipped or not, pushed across a network hop, parsed, and tokenised at the other end. Depth 200 is four times depth 50 and the body scales with it, so it is 240 KB per request; at the busy hour's 26 requests per second that is 6 MB/s of body on a path that previously carried query strings, and JSON parsing alone becomes tens of milliseconds. Three fixes exist and they compose: truncate each passage to the reranker's sequence window before sending, since anything past 512 tokens is discarded on arrival anyway; switch the transport to protobuf or gRPC, which typically halves both the bytes and the parse time; or send document IDs and let the rerank service read the text from a cache it shares with the retrieval tier, which removes the payload entirely at the cost of a deployment coupling.

The batch window is the one span where the fix has a genuine trade in it. Dynamic batching collects arriving requests for up to some delay so the GPU processes them together, and a 50 ms window means a request arriving into an empty queue waits the full 50 ms for companions who never come. Shortening the window to 10 ms cuts that wait by 40 ms at low load and reduces average batch size at high load, which lowers throughput and therefore raises the queueing multiplier that dominates the tail. The chain there runs in one direction and is worth following link by link: a shorter window means fewer pairs per forward pass, which means fewer pairs per second of GPU, which means a lower service rate, which at an unchanged arrival rate means higher utilisation, which is the input the next section's multiplier is computed from. Adaptive windows — flush as soon as the batch reaches the GPU's efficient size, or as soon as the queue is empty — get most of both, and are worth configuring before anyone touches the window constant.

Queueing is where the tail actually comes from#

The 781 ms of queue wait is arithmetic rather than misfortune. A single replica serving 50 pairs per request at 1,500 pairs per second handles 30 requests per second when saturated; the busy hour was delivering 26 requests per second. Utilisation at 0.87 gives a waiting-time multiplier around $1/(1-\rho) \approx 7.7$ over the service time, and the multiplier grows without bound as utilisation approaches 1 — which is the same reason a checkout line with one till and a customer arriving every 70 seconds for a 60-second transaction has a queue that never settles, even though the till is idle for a sixth of the time.

That comparison is an analogy and it breaks in two places worth knowing. A supermarket queue is visible, so customers balk and leave, which caps it; an HTTP client does not balk, it waits until its own timeout, so nothing bounds the queue except a deadline that fires long after the request has cost what it was going to cost. And a till serves one customer at a time, where a GPU serves a whole batch at once — which is the entire reason the batch window exists, and the reason shortening it makes the queue worse rather than better.

The multiplier and the measured span also need reconciling, because at first reading they disagree. A replica clearing thirty requests a second gives each one a service time of about a thirtieth of a second, and multiplying that by 7.7 lands on roughly a quarter of a second, well short of the 781 ms in the column. The gap is not slack in either number. The multiplier is derived for the average wait, and the column reports a ninety-fifth percentile of the same queue. In a single-server queue the waiting time has an exponential tail, and the ninety-fifth percentile of an exponential sits at about three times its own mean. Roughly a quarter of a second times about three is the figure in the column, and the two numbers are one queue read at two points of its own distribution rather than two claims in conflict.

Any component with a hard capacity behaves this way, and a connection pool at 90% utilisation is the version most backend engineers have already debugged. What makes the reranker a particularly sharp instance is that it was inserted into a path whose other components had generous headroom, so a single GPU replica became the narrowest point in the system on the day it shipped. Capacity planning for a rerank endpoint means picking a target utilisation first — 0.6 is a reasonable default, giving a multiplier of 2.5 — and deriving replica count from peak arrival rate, rather than provisioning for average load and discovering the multiplier at the busy hour.

Cold starts sit in a different category, because they are not load-dependent at all; they are idleness-dependent. A scale-to-zero endpoint with a four-minute idle timeout pays a container pull and a model load, 8 to 20 seconds, on the first request after a quiet gap. In a system with steady traffic that never fires. In this one, traffic outside business hours arrives in clumps every few minutes, so roughly 1.2% of requests hit a cold instance, which is enough to be invisible at p50, visible at p95, and dominant at p99. Setting a minimum instance count of one removed the span and added $730 a year, which is the entire fix.

Two things about that 1.2% are worth being exact about, because both are places a reader can form a confident wrong belief. The first is what it does to an average: a penalty of 640 ms paid by roughly one request in eighty moves the mean latency of the population by about eight milliseconds. A dashboard tracking mean response time is flat while one request in a hundred is more than a second worse, so the mean is a defence that does not move when the dangerous property moves. The second is that a rate of one in eighty puts cold requests above the ninety-eighth percentile of the population, which means cold starts on their own set p99 and not p95. The exemplar trace above nonetheless carries both a cold start and a saturated queue, and those two causes belong to different hours — one to peak load and one to the quiet gaps. A percentile picks a request out of a mixed population rather than describing a typical one, which is why the per-span columns are what attribution should be read from, and the exemplar is best used for the closure check it passed above.

Where the model really is the largest span#

None of this means model time is irrelevant. At depth 500 with a 435-million-parameter cross-encoder, model.forward becomes 900 ms and is legitimately the largest span, and then a distilled model or a cascade is exactly right. The two inputs that put it there are depth and model size, and both are visible before any measurement, so the argument in this chapter is not a rule about rerankers so much as a reading of one configuration. The claim is narrower than it can look: the ratio between p50 growth and p95 growth tells you which kind of problem you have before any tracing starts, and a tail that grows twenty times faster than the median is a queueing, fan-out or cold-start signature rather than a compute one.

Attribution also does not survive being done once. The fixes above changed the shape — with hydration batched, replicas at three, and a warm minimum, p95 came to 288 ms with retrieve.hybrid at 96 ms as the largest single span, which makes the first stage the next thing to look at rather than the reranker. Each round of tuning relocates the bottleneck, and the spans have to stay instrumented so the next relocation is legible instead of surprising. The version of this that goes wrong is a team that traces during an incident, fixes the top span, and removes the instrumentation as cleanup, which guarantees that the next regression starts from two dashboard numbers again.

There is one more limit on the diagnostic, and it is the case where a component varies for reasons internal to the request rather than external to it. A first stage whose posting lists are deeper on rare terms — the retrieve.hybrid row, which moves from 61 ms to 96 ms — varies with the query itself, so it does separate the percentiles without any queue being involved. The rule still holds in the direction it is used here, because that variation is bounded by how unusual a query can be, and it is nowhere near large enough to produce a fifty-six-fold gap. A component that varies with the query moves the tail by tens of milliseconds; a component that varies with the state of the system moves it by seconds.

The honest end state of this work is a reranker running at 288 ms p95 for twenty points of nDCG@10, arrived at by changing a database query, a replica count and an idle timeout, and never by changing the model the whole investigation started out blaming. The general form is the one worth carrying to the next system: read the two percentile deltas first, decide from their ratio whether the problem is compute or contention, and only then spend an afternoon on spans.

It is worth noticing what has been assumed throughout, because the arithmetic that justified three replicas and a warm minimum rests on it entirely: that twenty points was on offer. In a system whose first stage already returns short, focused passages in nearly the right order, the same three replicas and the same instrumentation buy two points, and every trade in this chapter has to be priced again against a benefit an order of magnitude smaller.