Profiling End-to-End Latency

Users do not experience your average response time. They experience the moment the first word appears. A support assistant that takes 4 seconds to start answering and then streams smoothly feels faster than one that starts in 1 second and then stalls — even when the second has the lower total time.

The two clocks are:

• Time to first token (TTFT): request received → first token streamed to the user. This is the perceived latency. It covers queueing, prompt assembly, retrieval, and the model's prefill of the entire input.
• Total generation time: request received → last token generated. This is the cost-relevant time. It covers everything in TTFT plus the decode loop that produces the remaining tokens.

They diverge because of how generation works. The model processes the entire input in one parallel prefill pass — that is the TTFT floor. Then it generates output tokens one at a time, sequentially. A 500-token answer spends most of its wall-clock time in decode, which the user perceives as 'typing,' not 'waiting.'

The implication for optimization is direct: if users complain about slowness, profile TTFT first. If the bill is the problem, profile total time. Optimizing the wrong clock is the most common latency mistake in LLM applications.

End-to-end latency is a sum of stages, and the stages have different owners. The profiler's job is to attribute milliseconds to each stage so the right team fixes the right bottleneck.

import time

class StageTimer:
    def __init__(self):
        self.marks = {}

    def mark(self, name):
        self.marks[name] = time.perf_counter()

    def report(self, start_name):
        start = self.marks[start_name]
        return {name: round((t - start) * 1000, 1)
                for name, t in self.marks.items()}

timer = StageTimer()
timer.mark('request_received')

time.sleep(0.02)   # queue wait
timer.mark('dequeued')

time.sleep(0.05)   # prompt assembly + retrieval
timer.mark('context_ready')

time.sleep(0.35)   # model prefill → first token
timer.mark('first_token')

time.sleep(0.60)   # decode remaining tokens
timer.mark('last_token')

print(timer.report('request_received'))

Output:

{'request_received': 0.0, 'dequeued': 20.0, 'context_ready': 70.0,
 'first_token': 420.0, 'last_token': 1020.0}

The non-obvious line is the report comprehension: it computes each mark's offset from request_received, so the marks double as both cumulative timestamps and stage boundaries. Subtract consecutive marks to get per-stage durations:

queue wait:        20ms   (20 - 0)
context assembly:  50ms   (70 - 20)
prefill (TTFT):    350ms  (420 - 70)
decode:            600ms  (1020 - 420)

TTFT is 420ms; total is 1020ms. The decode loop is the largest single segment, but it is also the segment the user perceives as progress. The prefill — 350ms of silence before anything appears — is where perceived latency lives.

In production these marks become spans in the trace you built in tracing LLM calls, and the per-stage durations feed the dashboards from metering token usage.

In a RAG pipeline, the model call is not automatically the bottleneck. Retrieval and reranking routinely dominate — and optimizing the model call is then pure waste.

A typical breakdown for a support assistant:

The reranker is the usual surprise. A cross-encoder over 50 candidates is a real model call with real latency, and it runs on the critical path before the main model can start. Teams that profile only the LLM call see 'the model is slow' and miss that the reranker is 40% of the wait.

This is why diagnosing RAG failure modes starts with retrieval metrics, not model metrics — and why reranking with cross-encoders carries its own latency budget. The fix is usually not a faster model but a smaller candidate set, a cached embedding, or a cheaper reranker.

The practical rule: profile the pipeline before you optimize it. The stage that dominates is rarely the stage you assumed.

Profiling one request tells you where the time went. Budgets tell you when the average request is misbehaving — and which stage to hold accountable.

Set a budget per stage, not just for the total:

TTFT budget: 800ms
├── queue + auth:     100ms
├── query rewrite:    150ms
├── retrieval:        250ms
├── reranking:        250ms
└── model prefill:    200ms  (overlaps with the above in practice)

The budgets sum to more than the total because stages overlap — retrieval and reranking can run concurrently, and prefill starts as soon as the first chunks arrive. The total budget is the contract; the per-stage budgets are the diagnostic breakdown when the contract breaks.

Alert on sustained breach, not single requests. A single 2-second TTFT is a cold start; a p95 TTFT above budget for 30 minutes is a regression. The distinction matters because the fixes are different: cold starts need warm pools, regressions need a rollback.

Streaming changes the alerting target. Once you stream responses, total generation time hides behind token rendering — the user sees text appear and stops waiting. The metric that matters shifts to TTFT and to inter-token gaps, which are the 'stalls' users notice mid-answer. Alert on inter-token p95, not just TTFT, or you will ship a stream that starts fast and stutters.