The server timer starts after admission and stops at the last byte

The dashboard had not moved in five weeks. Server-side request duration held at a p50 of 1.9 seconds and a p95 of 4.2, with the weekly variation you would expect from traffic mix and nothing more. In the same five weeks, two account managers escalated that the assistant "feels slower than it used to", support logged a dozen tickets with the same wording, and the head of sales demonstrated it live on a call and had to apologise for the pause. The engineering response was reasonable given what was on screen: the metrics say nothing changed, so either the complaints are about something other than latency or people are misremembering.

Both sides were right about their own measurement. The histogram behind that dashboard was recorded by a middleware that starts a timer when the request handler is entered and stops it when the handler returns, which is the standard shape for request-duration instrumentation and has been since it was invented for ordinary web services. That timer is an honest measure of how long the service spent on the request. It is not a measure of how long anyone waited, and the difference between those two quantities is where five weeks of complaints were living.

Everything outside the two brackets#

Laying the request out end to end shows how much of it the server timer excludes. The brackets marked below are where the timer starts and stops.

The timer covers one segment of six. On the way in it misses the client's own queueing, DNS and TLS, the network round trip, and any time the request spends in the load balancer's accept queue before a worker picks it up. On the way out it misses parsing, rendering, and paint. Under light load those excluded segments are tens of milliseconds and the server timer is a decent proxy. Under load, or on a client doing real work per token, they are the majority of the wait.

The five weeks of complaints resolved into two causes, neither of which the server could see. The web client had an application-level semaphore of four concurrent requests — a counter that lets four calls be in flight at once and holds every later one in a queue until a slot frees — added a year earlier to keep a document-preview endpoint from swamping the backend, and a change in the sidebar meant three preview requests now fired on page load. An assistant query issued in the first second after load sat in that semaphore for 600 to 1,900 milliseconds before its socket was even opened. Separately, the markdown renderer re-parsed the entire accumulated answer on every streamed delta, which is fine for a 200-token answer and costs about 40 milliseconds of main-thread work per delta by the time the answer is 900 tokens long. On long answers the rendered text lagged the stream by two to four seconds, and the visible last word arrived well after the server had written its last byte and stopped its timer.

Measuring the milestones where they happen#

The fix is to record the three milestones from chapter one on the client's own monotonic clock — a counter that only ever moves forward and is unaffected by the machine's wall-clock time being corrected mid-request — and to emit them as their own series rather than as attributes of the server-side duration histogram. The clock matters: comparing a client wall-clock timestamp against a server wall-clock timestamp mixes in clock skew that can run to hundreds of milliseconds on consumer machines, so every interval below is a difference between two readings of the same monotonic timer.

const t0 = performance.now();
let firstToken: number | null = null;
let firstUseful: number | null = null;
let text = "";

const res = await fetch("/api/ask", { method: "POST", body });
for await (const delta of readSSE(res.body!)) {
  if (firstToken === null) firstToken = performance.now() - t0;
  text += delta.text;
  if (firstUseful === null && VERDICT.test(text)) {
    firstUseful = performance.now() - t0;
  }
  render(text);                     // paint cost lives inside the loop
}
const complete = performance.now() - t0;

beacon("assistant.latency", {
  ttft_ms: firstToken,
  ttuc_ms: firstUseful,
  complete_ms: complete,
  answer_tokens: countTokens(text),
  queued_ms: queueWaitFor(res),     // time spent in the client-side semaphore
});

Three details in that snippet do the work. The timer starts before fetch, not after it, so anything the client does to delay the request is inside the measurement. The render call sits inside the read loop, so the completion figure includes the renderer's cost rather than measuring an idealised stream. And firstUseful is defined by a task-specific predicate — here a regular expression matching the verdict line — because there is no transport event for it and no generic library will find it for you. On a JSON-payload feature the equivalent predicate is "the payload parses", and on a code assistant it is "the first complete line of the function body has arrived".

answer_tokens is on the beacon — the small telemetry payload the client posts to your own collector once the request is done — because completion time is meaningless without it. A p95 of 11 seconds on 1,400-token answers and a p95 of 11 seconds on 200-token answers are different incidents, and the only way to tell them apart afterwards is to have recorded the length.

The VERDICT predicate is the part of this that needs an owner. It encodes a claim about what the user is waiting for, it will drift as the prompt changes, and when it silently stops matching, the time-to-useful-content series goes to null rather than going wrong, which is the failure mode nobody notices. Two habits keep it honest: version it alongside the prompt that produces the format it matches, and alert on the fraction of requests where the predicate never fired. A predicate that matches 99.4% of answers in January and 71% in March is reporting a prompt change, not a latency change.

The beacon also needs a sampling decision, and the temptation is to sample uniformly at 5% to control cost. That is the wrong shape for this data, because the tail is where the information is and a 5% uniform sample of 40,000 daily requests gives 2,000 points, of which 20 sit above p99. Sampling everything above a threshold and a small fraction below it — all requests over 5 seconds, 2% of the rest — costs about the same volume and keeps the part of the distribution the escalations come from.

Attributing a slow request to a segment#

Knowing that the client waited 13.6 seconds while the server worked for 4.2 does not say which of the other five segments took the rest, and the arithmetic that looks obvious here is invalid. Percentiles do not add: the p95 of a sum is not the sum of the p95 of its parts, because the request that was p95 overall is generally not p95 in every segment. Subtracting the server p95 from the client p95 gives a number that corresponds to no request that ever happened.

The way to get an honest attribution is per-request, which means the segments have to be carried on the response rather than reconstructed afterwards. Server-Timing is the standard vehicle, it is readable from the browser's own Performance API, and it costs a header:

@app.middleware("http")
async def timing(request, call_next):
    t_admit = time.perf_counter()
    lb_queue = float(request.headers.get("x-request-start-delta", 0))
    response = await call_next(request)
    response.headers["Server-Timing"] = ", ".join([
        f"lb;dur={lb_queue * 1000:.0f}",
        f"retrieval;dur={request.state.retrieval_ms:.0f}",
        f"model_ttft;dur={request.state.model_ttft_ms:.0f}",
        f"handler;dur={(time.perf_counter() - t_admit) * 1000:.0f}",
    ])
    return response

With those durations joined to the client beacon by request id, you can take the slowest 10% of requests by client completion time and average each segment across exactly that slice:

The two columns tell different stories on purpose. On an average request the handler is 61% of the wait and the intuition behind the server dashboard is roughly correct. On the slow decile the handler is 34%, and the client-side queue and the renderer together are more than half. Latency work aimed at the handler would have addressed a third of the problem the escalations were about, which is why the sequencing matters: attribute first, then optimise.

Percentiles, and which ones the complaints live in#

Chapter one showed that the milestone matters; the other half is which point of the distribution you read it at. Sales, support and account managers are not sampling the median. A user who hits a bad request once in twenty sessions carries that impression into every subsequent one, and a demo in front of a customer is a single draw from the tail with an audience. On this deployment, client-side p50 time to first useful content was 2.4 seconds and p95 was 9.1, and the p95 was where every escalation had come from. Splitting client-side and server-side side by side made the gap legible for the first time:

The p50 gap between the server's 1.9 seconds and the client's 4.1 is the renderer and the network. The p95 gap of 4.2 against 13.6 is the semaphore, which only bites when several requests collide, which is exactly the condition that also loads the renderer. Tail latency has this shape routinely: the causes are correlated, so the requests that are slow for one reason are the same requests that are slow for the others, and the tail is worse than the sum of the medians would suggest. The percentile machinery itself — how to pick targets, how to write the objective, why averaging percentiles across services is invalid — is the subject of the metrics and SLOs work you have already done, and it applies here unchanged.

What client instrumentation does not replace#

Moving measurement to the client does not make the server-side histogram redundant, and teams that delete it end up unable to answer the next question. Server duration is the number that attributes latency to a deployment, a model version, or a code path, because it is the only segment you fully control and the only one recorded with the request's internal context attached. When the client p95 jumps, the first thing worth knowing is whether the server segment moved with it, and that requires both series.

Client telemetry also has biases that server telemetry does not. It is missing for users who block the beacon endpoint, it is skewed towards sessions that completed rather than sessions that were abandoned — precisely the slow ones — and it mixes device performance into every number, so a p99 can be dominated by a population of old phones rather than by anything the service did. The honest reading is that a client p99 is a joint measurement of your system and your users' hardware, and separating those requires slicing by device class or connection type, which most teams do only after the first time it misleads them.

Beyond that, none of this instrumentation makes anything faster. It relocates the numbers to where the waiting happens, and what it usually reveals first is not a mysterious tax but a straightforward one: a request path that does five things one after another when it could do them at the same time. That change is the largest single lever available on most pipelines, and it moves the median and the tail in opposite directions.