--- type: reference title: LLM Performance Diagnosis description: "Probing why a served model is slow: the flat-depth probe, offload duty-cycle arithmetic, and step-shape attribution." tags: [performance, profiling, moe, pcie, prefix-cache, routing, telemetry] timestamp: 2026-10-19T00:00:00-07:00 --- # LLM Performance Diagnosis When a served endpoint is slower than wanted and someone names a suspect ("PCIe is saturated", "the gather is the bound"), throughput arithmetic cannot settle it — it is usually circular (it assumes the suspect consumes the step). Get data in this order; the profiler window alone has retired multi-day optimization plans. ## 1. Is decode context-bound at all? (the flat-depth probe) Sweep decode across context depth. **Flat** ⇒ attention over history is not the cost; the problem is per-token expert movement and KV/attention tuning is ruled out entirely. A genuinely context-bound server shows a clear downward slope. Record cold vs warm separately — a small gap means the cache is working. The canonical flat run (fp8 expert-offload shape, a few hundred to sixteen thousand tokens of context) is in 's profile. ## 2. Duty-cycle arithmetic (the "GPU not fully utilized" answer) Symptom: smooth ~25–35 % utilization with 100 % peaks on an expert-offload MoE. This is the EXPECTED signature, not a fault: ``` per decode step: compute burst ~100 ms (100 %) → expert-gather wait ~400 ms (~0 %) resident fraction = arena slots / total experts (e.g. 6574/24576 ≈ 27 %) PCIe bytes/token = miss_rate × lookups × slab_bytes (0.73 × 480 × 2.344 MiB ≈ 0.84 GB) predicted duty ≈ compute_ms / (compute_ms + wait_ms) ``` Validate the terms against the deployed engine's boot plan ([[RDNA4 MoE Expert Offload VRAM Budget]]). If predicted ≈ observed, the low average is structural. Note small-transfer reality: bulk bandwidth (91 % of ceiling at 1 GiB) overstates what 2–3 MiB slabs get (~72 % plus ~20 % per-transfer latency). Before blaming the link, measure it ([[PCIe Link and Atomics]]) and compare the engine's effective gather rate to the measured slab-size bandwidth — a 40–50 % gap is the software read path, not the wire. `rocm-smi --showuse` reads ~0 % during the whole multi-minute weight load: show VRAM (`--showmeminfo vram`) as the load-progress signal. ## 3. Kernel-time attribution (the profiler window) Run BEFORE building any replacement kernel. 1. Stop + mask production; boot the shape under test with ONLY the profiler config added. vLLM argv: `--profiler-config '{"profiler":"torch","torch_profiler_dir":"/prof","torch_profiler_with_stack":false,"torch_profiler_record_shapes":false,"torch_profiler_with_memory":false,"torch_profiler_dump_cuda_time_total":false}'` — `with_stack=false` is load-bearing (with stacks the stop hangs and the trace buffer grows ~40 GB → kernel OOM-kill of the engine core, anon-rss ~95 GB; the worker-side stop can hang 5 min on ROCm/kineto). Bind-mount `/prof`. If a shell substitutes values into that JSON, verify the escapes actually landed. 2. Window it: warm request → `POST /start_profile` → N generations of ≥128 tokens (~15 s of traffic) → `POST /stop_profile` (client may time out at 60 s; the trace still lands). `telemetry_report` has ONE caller: the gpu_worker profiler-stop path. Overhead is small enough to keep decode comparable (9.6 vs 9.9–10.0 tok/s measured). 3. **Parse ON THE SERVER** (traces are 100–150 MB gzipped, GB expanded). Rank `ph=="X"` events with `cat in {kernel, gpu_memcpy, gpu_memset}` by summed `dur` (µs): report % of device time, launch count AND µs/call (22 µs × 708k launches is a different problem than 4 ms × 4k), plus the first-to-last event span (fraction of wall the device was busy). Aggregate by FULL mangled name (template args are the tuning signal) and by stripped symbol. **Trap: `gpu_user_annotation` events masquerade as GPU time** (a naive sum reported 63 % in one `execute_context_0(...)` entry; spans overlap and can exceed the wall clock). 4. Divide by the window's token count → ms/token; if kernel time ≈ step time, the table IS the optimization plan. Worked example (GLM-5.3-Flash, 2×GPU, offload, decode 9.9 tok/s): ``` 34.8 % 708,500 launches vectorized_elementwise_kernel <- the actual bound 10.0 % 42,000 MoE W4A16 GEMM 8.9 % 83,160 router/top-k (sort-based) 6.5 % 133,920 hyper-connection pre/post kernels 1.05 % 20,664 ``` No amount of link arithmetic would have produced those two conclusions: the suspect was 1 %, and the mass was pointwise glue from an uncompiled trunk — whose own boot log names the cause (`FULL_DECODE_ONLY` override). It predicted a negative result in advance (spec decode cannot help a shape whose per-token cost scales with the token count) which matched an unexplained flat MTP measurement. ## 4. Telemetry without benchmarking (live hosts) When benching is forbidden (production serving), mine the runtime's own per-request telemetry — it measures the real workload and costs nothing. - llama.cpp (root unit, `-lv 3`): `sudo journalctl -u --since "-3h" --no-pager` → `slot print_timing` lines (prompt eval, eval, total, `graphs reused`, `draft acceptance … mean len`, `n_gen = N, tg = X t/s, tg_3s = …`). - halogen (rootless quadlet): `journalctl --user -u ` (**never sudo** — per-user storage) → `serve_api: mtp 28 tok in 0.66s = 42.45 t/s | 16 rounds, commit 1.75/round | prompt 58, prefill 0.92s | detok 24us/tok`. - Read the envelope, never one sample: short-prompt `prompt eval` is overhead-dominated (57 tok @ 168 t/s) — quote the longest available (1106 tok @ 1013 t/s); decode and acceptance are content-dependent (0.46–0.76 measured on one unchanged build); `graphs reused > 0` / `selected slot by LCP similarity` prove prefix-cache reuse. - **Attribute PCIe without touching the model:** background `nvidia-smi dmon -s t -c 16 -o T`, ONE ordinary `max_tokens=200` request, `wait` at the end (without it ssh closes and the client dies — the journal shows `W srv stop: cancel task` and NO print_timing while curl still reports plausible status). Measured: peak ~230 MB/s against a ~7,900 MB/s link = ~3 %, 0 at idle — the sampled-logits stream, not the transport, is decode traffic on that shape. - One `max_tokens=200` request is production traffic and fine; anything that pins the card is a bench → stop-and-mask first. Check WHICH instance you are reading (`systemctl status | head -12`; task ids jump across restarts). The engine's own ledger (`KV self size`, `n_slots` `n_ctx_slot`) outranks your model of it. ## 5. The fork's data path (before blaming the link) Offload engines pick between DMA copy-in and read-through UVA dereference inside the GEMM. Grep the installed package for the LRU/offload module and read the BRANCH CONDITION, not just the env names. A token-count threshold decides the path, and it interacts with spec decoding: an MTP step is k+1 tokens, so the step can silently cross the threshold onto the slow path as draft depth grows. Check the threshold's premise: a default tuned at 12.4 MiB/expert does not transfer to 2.344 MiB/expert, where copy-in can be several times faster. TunableOp ghost-skip: `CLAV_TUNABLEOP_SWEEP=1` alone does NOTHING under expert offload (`CLAV_TUNABLEOP_WITH_OFFLOAD=1` required) check for the skip line before concluding autotuning ran. Gather-geometry knobs read at import time → each arm is a full reload. ## 6. RAM-bandwidth-bound MoE ceiling (before recommending a quant) ``` routed experts/token = top_k × n_layers bytes/token = routed_params × bytes_per_param + shared_expert_bytes ceiling (tok/s) = measured_bandwidth / bytes_per_token ``` Measure the HOST's real bandwidth, never assume DIMM ratings: 4-DIMM AM5 boards downclock to DDR5-3600 regardless of 5600 sticks (two large DIMMs beat four small). Single-threaded reads under-report dual-channel ~4x — use the multi-threaded plateau of a checksumming reader (`scripts` pattern: `/tmp/bw.c`, 1/2/4/8/16 threads). Worked example (DeepSeek-V4.1-Flash): 6×40 experts × 35.4M params = 8.5B params/token; at 3 bpw + 0.53 GB shared = **3.7 GB/token** → 42 GB/s ⇒ **11.3 tok/s ceiling**. Sanity anchors: H100 NVL + CPU offload 226 GB ⇒ 5.8–9.0 tok/s; 2×3090 + 768 GB DDR4 ⇒ 12.2. CPU compute rarely binds below 4 bpw (~5.3 flops/byte ⇒ ~223 GFLOPS at 42 GB/s); PCIe expert STREAMING is worse than CPU compute (Gen5 x8 ~22.7 GB/s effective < half of RAM); prefill reads the union of a batch's experts (prefill ≈ bandwidth / total_expert_bytes × ubatch). A quant that fits only by ignoring the Engram table does not fit (Engram = sparse n-gram lookup, NVMe-tolerant; the routed experts are not). An iGPU GTT aperture is an ALIAS of the same RAM, not extra memory. ## 7. IBS model-access attribution (AMD CPUs) Real CPU access patterns for mmap'd weights, live, no stop (established on [[frank-archon]], 2026-09-26, ~2.7M attributed samples in 75 s). Reference: `scripts/frank-archon-expert-activity.py` (self-contained dump + sample + analyze; `--analyze-only`). 1. GGUF header-only scan (ms for a 50 GiB part) → tensor extents. **Extents from CONSECUTIVE offsets, never a type-size table** — a wrong per-element size silently under-covers every tensor and dumps tail samples into a junk bucket (first run lost 59 % of expert samples; a uniform gap/exps ratio ~1.4 across parts is the tell). Data start = `(tell + 31) & ~31`. 2. `/proc//maps` VMAs (7-group regex; pgoff = group 4, path = group 7) matched against part files; multi-VMA per part is normal. 3. `sudo perf record -e ibs_op// -c 50000 --data -o out.perf -p -- sleep ` WHILE a mixed workload runs (idle perf numbers mean nothing). `sudo perf script -i out.perf -F addr` for addresses. 4. Attribute: bisect VMAs, `foff = pgoff + (addr − vma_start)`, bisect tensor starts; per-expert index = `int(lo / (span / N_EXPERTS))` (expert-major rows). 5. Verify before believing histograms: gap ≈ 0, every tensor-bearing part nonzero, and MoE blocks should be FLAT by construction (top-k fires every block every token) — a non-flat block histogram means mis-attribution first. Established law: expert routing is per-block flat, per-EXPERT skewed. ## 8. Prefix-cache-aware routing (multi-replica serving) Measure with a **sequential-turn client**, not only a batch benchmark — a batch of distinct prompts parallelises prefill across replicas and hides the problem. The two failure modes: round-robin loses every other cache hit (90k-token contexts: warm-turn TTFT 2676 ms round-robin vs 1096 ms pinned) pinning-everything loses a card (16 requests: 18.6 s spread vs 30.1 s pinned). **The rule that gets both: route by request shape** — a request carrying more than one message is a continuation (agent loop re-sending its context) → pin to the replica that served that prefix; anything else → spread with a COUNTER, not a prefix hash. Add failover: demote a replica on connection failure and retry on a live one BEFORE writing anything to the client (safe pre-stream; never retry after streaming started). The wall no policy fixes: **a running sequence and its cached prefix draw on the SAME pool.** Three concurrent 50–80k families against 122,636 tokens/card thrash under every placement and admission policy tried (counter placement, load-balanced placement, one-large-request-per-card admission, both chunk directions — the last COSTS KV in both directions). When the working set exceeds aggregate KV, say so: the levers are capacity, fewer concurrent large contexts, or a different platform. Traps: a lifetime hit-rate counter is not a per-request verdict (probe directly: same prompt twice to an idle replica — 22.3 s cold → 1.4 s warm); salt corpora; record sample sizes; `vllm bench serve` needs `--tokenizer `; verify metric names against the live endpoint before dashboards. Test shape: drive the routing function directly with synthetic bodies (stdlib-only policy module) conversation identity is the FIRST N KiB of prompt — a shorter tested prefix hashes differently per turn and pinning silently never happens. ## 9. Decode cadence under a prefill (the step-shape census) "Decode turns to sludge the moment a long prompt arrives, then recovers" is not a link or a gather story — on a chunked-prefill engine the unit of interference is **the step**. A step that carries a prefill chunk takes the chunk's time, and every decode row sharing that step waits that long for its next token. Chunk size is `min(remaining, --checkpoint-interval, --max-num-batched-tokens)`, so on a hybrid model the interval caps it before the budget does. Census it without touching the model — the engine's own counters (`/stats`, `/metrics`, cumulative since boot): ``` decode-only step = step_ns_decode / steps_decode shared step = (step_ns - step_ns_decode) / (steps_prefill + steps_mixed) ``` Then bucket a day of `decode_tokens_per_second` by `prefill_tokens_per_second` (Prometheus `query_range`, step 120 s) and **check the lag**: correlate decode with prefill at lag 0 and again at 2-14 minutes. Lag-0-only ⇒ step-time contention, the chunk is holding the device. A lagged tail ⇒ residency churn — the prefill's working set evicted something decode needs (expert slab, KV) and decode pays after the prefill is over. `preemptions` separates the third shape: a preempted-and-recomputed sequence stops producing entirely and then re-prefills from token 0, which is a stall, not sludge. **Split the step ledger before choosing a knob.** Three counters decide which mechanism you are looking at, and none is a rate: `engine_step_seconds_decode_total / engine_steps_decode_total` is the mean **decode-only** step, and `(step_seconds_total − step_seconds_decode_total) / (steps_total − steps_decode_total)` is the mean **chunk step** (a chunk alone, or a chunk with decode rows beside it). On frank-archon's live 1.8.1 shape that pair is **15.5 ms against 166 ms**, with 4.7 % of the steps holding 34 % of the step time. Decode-only steps themselves move only 14.1 → 16.4 ms between a prefill-free minute and a heavy one, and the lagged buckets stay flat: so a decode-rate collapse on that box is **step time sharing**, and the eviction/residency story is worth ~10 % of one step — not a lever. **Four traps in the PromQL above.** Learn them before trusting a bucket: - **Latency is `vllm:`, cadence is `radiance:`.** The TTFT / inter-token / per-output-token / e2e histograms and the running/waiting gauges exist only under the vLLM compatibility prefix; preemption is `vllm:num_preemptions_total` (the counter) while `radiance:num_requests_preempted` is the *instant* depth. A `radiance:`-only query finds no latency and no preemption, and reads as "the endpoint never stalls anyone". - **The tps gauges are 1 s decayed windows, batch-pooled.** Per-stream rate is `decode_tokens_per_second / vllm:num_requests_running`. With a 15 s scrape, a 120 s step samples one scrape in eight — use step ≤ 30 s for a bucket table. - **Every counter resets at a restart and the metric set changes with the build.** Prove the window is one shape (`up`, or the first sample of a counter that only the current build exports) before ranking buckets; frank-archon's 48 h window straddled two containers, and one bucket's "collapse" turned out to belong entirely to the older one. - **A 2-minute mean step time dilutes the chunk.** The sharp variable is the phase ratio in the query above, never `step_seconds/steps` — 4.7 % of steps cannot move a mean that is 95 % decode. Three instruments the PromQL above cannot reach: - **The engine's own step-detail histograms (`prefill_steps_duration`, `prefill_step_tokens`, `token_queue_wait`) are exported but reach no target**, and the arena / expert slab / heat engine / prefill stager have **no metric at all**. Per-request forensics mean `curl localhost:7770/stats` on the endpoint's own host — same phase counters plus `preemptions` (the count), the chunk geometry, and the expert/link byte totals. `/diagnostics` answers "is the *box* the limit" in one call: configuration drift, the VRAM split, each card's link chain and clocks, findings with fixes. - **`prefix_hit_cut_tokens_total` measures prefill load you created for yourself.** On a hybrid (linear + paged) model a prefix hit reuses only as far as the last **linear-state** checkpoint, so cached tokens are replayed as prefill and stall decoders for it; frank-archon ran 38 % of all its prefill tokens that way, every `prefix_hit_cuts_total` labelled `reason="no_snapshot"`. A high prefill rate is not always a client that sends new tokens. Retention is `--checkpoint-policy` - exactly three names, `geometric-backoff` (default), `tip-only`, `keep-all`, one owner: [[frank-archon]]. - **Bucket the arriving request too** — `histogram_quantile` over `vllm:time_to_first_token_seconds_bucket` by the same prefill series. The decode gauge only sees sequences that are already running; the one waiting for its first token pays the same steps and shows in no decode number. Knobs, in the order worth trying them (radiance GUIDE §4.5; the pinned source is the referee): - `--prefill-interleave N` — after a chunk step taken beside decoders, the next N steps carry decode rows only and admit nothing. **The knob that acts on the measured mechanism.** Decoders keep their cadence; the prefilling prompt pays in TTFT and an arriving request waits out the held steps. Counts as `engine_steps_held_total` — if that counter is zero, nothing is protecting anyone. - `--busy-prefill-chunk N` — pins a shared chunk's share of the step. **`auto` is a prefill-speed setting, not decoder protection:** it reserves `1 + spec` rows per decoding sequence plus an eighth of the budget per *waiting* request or prefill, and the source refuses to halve for "decode rows alone", so a shape can run `auto` and still lose every chunk step. Prove engagement from `engine_prefill_chunks_capped_total` against the chunk-step count. The floor is the prefill stager's smallest pass — the largest arena level that lends, plus one, named on the startup line `prefill staging: … a step of more than N tokens copies the pooled experts of …` — and under it every routed layer reads its pooled experts synchronously: the vendor prices the whole job (four decoders plus a long prompt) at **29.5 s with a 2048 chunk and 31.9 s at 512**, so shrinking the chunk blindly buys latency in both directions. - `--prefill-span N` — needs `--max-num-batched-tokens` of N intervals. A *lone* prefill then carries N intervals a step (on an expert-tiered box only from 8 intervals, where the vendor's own measurement says a span starts to win), while **every other step is planned at the shared budget** — a lending arena level that also keeps the stager's ring, the one combination the chunk knob cannot express. Priced by the vendor at 320 MiB a card of expert residency, ~3 % off the KV pool, and TTFT-neutral on one of his two 2×R9700 boxes: measure your own prompt lengths first. - `--max-num-batched-tokens` alone — the blunt rung, and the only one older pins have. It raises the arena the expert slab loses, and on this payload its resonance is violent (MNBT 2560 collapses decode — [[frank-archon]]). Two traps. **The arena/slab coupling makes a shared step expensive twice:** the full-plan arena is reclaimed from the expert slab *synchronously before the step*, and the loan regrows only after a quiet interval, so every step of a prefill run — the decode-only ones included — runs on the smaller slab. And **re-check `prefix_hit_rate` / `prefix_evictions` after any chunk or span change**: the arena, the staging ring and the KV pool are the same memory, and the failure looks like turn two taking exactly as long as turn one. Availability is a version question, not a config question: `--busy-prefill-chunk`, `--prefill-interleave` and `--prefill-span` are absent from older pins — prove it on the running container (`podman exec --help | grep -iE "prefill|chunk"`) or from `/diagnostics`'s `configuration` block, never from a vendored tree, and check a source clone's depth before dating a flag from `git log -S` (a `--depth 1` clone reports its own tip for every search). Run on: [[frank-archon]] — owner of the live census, the measured step pair, and the arms. ## Related - the window discipline and usage-counter law - [[PCIe Link and Atomics]] — link probing and the streaming-vs-compute ceiling - [[RDNA4 MoE Expert Offload VRAM Budget]] — the plan behind duty-cycle terms - [[frank-archon]] — the endpoint where §9's step-shape census was run