Tracing One Request Through a Model

1. What is it?#

A step-by-step account of everything that happens between “user sends a prompt” and “user sees a token.” Not the abstraction — the actual operations, in order, with sizes.

2. Why does it exist?#

Because most performance problems are located by knowing where in this sequence they occur, and most people’s mental model of it has gaps. Once you can recite the trace, a profiler timeline becomes readable rather than intimidating.

3. Simple analogy#

A parcel’s journey. You don’t understand a shipping delay by knowing “it takes 3 days.” You understand it by knowing the legs: collection, sorting hub, line haul, local depot, delivery. Then a delay has a location, and locations have fixes.

4. The complete trace#

Setup: Llama-3-8B, BF16, one H100, prompt “Explain gravity briefly”, 100 output tokens.

Phase 0 — arrival (CPU, ~0.5-2 ms)#

1.  TLS termination, HTTP/1.1 request parsed
2.  JSON decoded → {"messages":[...], "max_tokens":100, "temperature":0.7}
3.  Auth, rate limit check, tenant lookup
4.  Chat template applied → a single prompt string
5.  TOKENIZE: "<|begin_of_text|>...Explain gravity briefly..." → [128000, 849, 21435, ...]
        7 tokens. Cost: ~50 µs (Rust tokenizer)
6.  Request object created, pushed to the scheduler queue

Phase 1 — scheduling (CPU, 0 to hundreds of ms)#

7.  Scheduler wakes at the next iteration boundary
8.  Checks: is there KV cache space for 7 prompt tokens + 100 generated?
        needed = 107 × 128 KiB = 13.4 MB → 7 blocks of 16 tokens
9.  Checks prefix cache: does a prefix of this prompt already have KV? (Section V.11)
10. Admits the request into the running batch

This is where TTFT is lost under load. Steps 7-10 can be instant or can be 2 seconds.

Phase 2 — prefill (GPU, ~3-8 ms for 7 tokens)#

11. Token ids copied H2D: 7 × 8 bytes = 56 bytes over PCIe (~5 µs, all overhead)
12. Embedding gather: 7 rows × 4096 × 2 bytes = 57 KB read from the 1 GB table
        x: (1, 7, 4096)

13. FOR EACH OF 32 LAYERS:
      a. RMSNorm(x)                                     read/write 57 KB
      b. qkv projections — often fused into one GEMM:
             (7, 4096) @ (4096, 6144)                   0.35 GFLOP, 50 MB weights
             → q (7,32,128), k (7,8,128), v (7,8,128)
      c. RoPE applied to q and k using positions 0..6
      d. K and V written into the paged KV cache
             7 tokens × 8 kv_heads × 128 × 2 × 2 bytes = 28 KB
      e. FlashAttention prefill kernel:
             causal, S=7 → scores never materialized
             ~0.03 GFLOP
      f. o_proj (7,4096)@(4096,4096)                    0.23 GFLOP, 33 MB
      g. residual add
      h. RMSNorm
      i. gate+up fused GEMM (7,4096)@(4096,28672)       1.65 GFLOP, 235 MB
      j. SiLU × up (fused into the GEMM epilogue)
      k. down GEMM (7,14336)@(14336,4096)               0.82 GFLOP, 117 MB
      l. residual add

    Per layer: ~3.1 GFLOP, ~435 MB of weight reads
    × 32:      ~99 GFLOP, ~14 GB of weight reads

14. Final RMSNorm
15. LM head — ONLY for the last position:
        (1, 4096) @ (4096, 128256)                      1.05 GFLOP, 1.05 GB
        → logits (1, 128256)
        (computing all 7 positions would cost 7x for nothing)

Time: memory 14 GB / 3350 GB/s = 4.2 ms;  compute 100 GFLOP / 700 TFLOP/s = 0.14 ms
      → 4.2 ms, memory bound (because the prompt is tiny)

    With a 2000-token prompt instead:
      compute 28.6 TFLOP / 700 TFLOP/s = 41 ms;  memory still ~14 GB = 4.2 ms
      → 41 ms, COMPUTE bound.  ← the crossover happens around 200-400 prompt tokens

Phase 3 — sampling (GPU, ~0.1 ms)#

16. logits / temperature (0.7)
17. top-p filtering: sort or use a threshold kernel, keep the smallest set with cum. prob ≥ p
18. softmax over the survivors
19. multinomial sample → token id 578 ("Gravity")
20. Check stop conditions (EOS, stop strings, max_tokens)
    ALL OF THIS STAYS ON THE GPU. A D2H copy here would add ~0.5 ms per token.

Phase 4 — decode loop (GPU, ~5 ms per token × 99)#

21. FOR EACH NEW TOKEN:
      x = embed[token]                       (1, 1, 4096)
      FOR EACH LAYER:
        same as prefill but S_q = 1:
          - projections are (1,4096)@(4096,·)  → GEMV-shaped, memory bound
          - attention reads the WHOLE KV cache for this sequence
          - KV cache grows by 128 KiB per token
      lm_head, sample, emit

    Per token: ~16 GFLOP, ~16.1 GB read
    → 16.1/3350 = 4.8 ms  (memory bound by ~200x)

Phase 5 — streaming out (CPU, ~50 µs per token)#

22. token id → text via the detokenizer (careful: multi-byte UTF-8 spans tokens!)
23. wrap in SSE: data: {"choices":[{"delta":{"content":"Gravity"}}]}\n\n
24. write to the socket, flush

Phase 6 — completion#

25. EOS token generated, or max_tokens reached
26. Send data: [DONE]
27. FREE THE KV CACHE BLOCKS  ← 13.4 MB returned to the pool
28. Emit metrics: ttft, itl distribution, tokens in/out, tenant, model

The totals#

TTFT = 2 ms (CPU) + queue + 4.2 ms (prefill) + 0.1 ms (sample) + network
     ≈ 7 ms + queue + network
ITL  ≈ 4.8 ms
E2E  ≈ 7 + 99 × 4.8 = 482 ms

5. What this trace teaches#

Where time goes (batch 1, short prompt):

Decode loop      99 × 4.8 = 475 ms   98.5%
Prefill                     4.2 ms    0.9%
CPU work                    2.5 ms    0.5%
Sampling                    0.1 ms    0.02%

Where time goes (batch 64, 2000-token prompts):

Prefill (amortized)         ~41 ms per request, but overlapped
Decode                      ~6 ms per step, producing 64 tokens
→ system throughput ~10,600 tokens/sec
→ each user still sees ~6 ms ITL

The two numbers that matter: 16 GB read per decode step (weights) and 128 KiB per token (KV growth). Everything else is detail.

6. Under the hood: what a profiler shows#

An Nsight Systems timeline of one decode step, 8B model:

CPU  |--python--|--launch×~350--|          |--python--|
GPU            |█|█|█|██|█|█|█|█|██|...|██|
                ▲                          ▲
                first kernel               lm_head (largest single kernel)

Without CUDA graphs: visible gaps between kernels, CPU is the bottleneck at batch 1
With CUDA graphs:    one launch, kernels back-to-back, ~25% faster

Count the kernels: ~10 per layer × 32 + embedding + head + sampling ≈ 350. At 5 µs launch overhead each, that is 1.75 ms of CPU work per token — a third of your 4.8 ms ITL, doing nothing useful.

7-9. Performance, production, mistakes#

Performance: the trace tells you where every optimization applies:

Production: instrument each phase separately. queue_wait, prefill_ms, decode_ms, detokenize_ms, network_ms as separate metrics. When TTFT regresses, you’ll know which phase.

Mistakes: computing logits for all prefill positions (step 15); D2H copies during sampling (step 19); detokenizing per token without handling multi-byte UTF-8 boundaries (step 22 — produces mojibake for non-Latin scripts); forgetting to free KV on client disconnect (step 27 — leaks capacity).

10. Hands-on exercise#

A. Instrument the trace. Add timing around each phase in a real server (vLLM has --disable-log-requests off, and exposes detailed metrics). Reproduce the breakdown table for your model and hardware.

B. Find the prefill/decode crossover. For your model, find the prompt length at which prefill time equals one decode step. Then find where prefill becomes compute-bound.

C. Count kernels. Use nsys profile or torch.profiler to count kernel launches per decode step. Multiply by launch overhead. What fraction of your ITL is launch overhead?

D. Break the UTF-8. Generate text in a non-Latin script token by token, detokenizing each token independently. Observe the mojibake. Fix it with incremental detokenization.

11. Interview questions#

1. Walk me through what happens from HTTP request to first token.
2. At what prompt length does prefill become compute-bound? Why?
3. Where in the trace does prefix caching apply, and what does it save?
4. Why must sampling happen on the GPU?
5. How many kernel launches per token, and why does that matter at batch 1?
6. What happens to KV cache blocks when a client disconnects mid-generation?

12. Further reading#

• [REFERENCE] vLLM source: llm_engine.py, scheduler.py, model_runner.py — read them alongside this trace
• Next: 02 — Computational graphs and operators