Live step-shape census on frank-archon (radiance 1.0.13, boot of 2026-10-15): decode-only steps run 18.7 ms, prefill+mixed steps 317 ms — 60 % of engine wall-clock inside 8 % of the steps — and a day of Prometheus shows decode at 13.3 t/s median while prefill runs >=1000 t/s against 106-240 t/s when it does not. The lag test says the penalty is confined to the prefill window: no lingering expert-residency tail, and preemptions are zero. Adds the method as LLM Performance Diagnosis S9 (counter arithmetic, the lagged bucket correlation that separates step contention from residency churn, and the four radiance knobs with their published costs), and the endpoint's own numbers plus the verdict as two frank-archon laws: --busy-prefill-chunk and --prefill-interleave are absent from this pin (proven via the running container's --help), so MNBT is the only crank here and an image bump is gated by the 1.2.0 numerics dead end. No behavior change; docs only.
289 lines
17 KiB
Markdown
289 lines
17 KiB
Markdown
---
|
||
type: reference
|
||
title: LLM Performance Diagnosis
|
||
description: Probing why a served LLM is slow — the flat-depth probe, the expert-offload duty-cycle arithmetic, kernel-time attribution via the profiler window, live telemetry without benchmarking, RAM-bandwidth ceilings, IBS tensor attribution, prefix-cache-aware routing, and the step-shape census behind decode stalls under a prefill.
|
||
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 [[Tcclaviger Fork Ops]]'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 <the long-suspected expert gather>
|
||
```
|
||
|
||
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 also
|
||
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 <unit> --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 <unit>` (**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/<pid>/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 <pid> --
|
||
sleep <dur>` 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 <local path>`; 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.
|
||
|
||
Knobs, in the order worth trying them (radiance GUIDE §4.5):
|
||
|
||
- `--prefill-interleave N` — after a chunk step taken beside decoders, the next N
|
||
steps carry decode rows only and admit nothing. Decoders keep their cadence; the
|
||
prompt pays that in TTFT. Counts as `engine_steps_held_total`.
|
||
- `--busy-prefill-chunk MODE` — the chunk's share of a step that has other work:
|
||
`auto` (default) reserves a row plus the draft window per decode row behind it and
|
||
an eighth of the budget per waiting prefill/request, `off` lets the chunk take the
|
||
whole step (admission never runs while it does), `N` pins the share. Never under
|
||
the prefill stager's smallest pass — the startup line names it, and below it every
|
||
routed layer reads its pooled experts synchronously, which costs the prefill far
|
||
more than sharing saves. Counts as `engine_prefill_chunks_capped_total`.
|
||
- `--max-num-batched-tokens` — the blunt rung, and the only one older pins have. The
|
||
vendor's curve on a 48-layer MoE at 200k on two cards: chunk 512 → 1750 t/s, 1024
|
||
→ 2200, 2048 → 2706 (a 185k prompt: 138 s against 91 s), so halving the stall
|
||
costs ~19 % of prefill. Raising it past the interval buys nothing and loses expert
|
||
residency to the arena.
|
||
- `--prefill-span N` — the inverse trade: a *lone* prefill carries N intervals a step
|
||
while every shared step is planned at a smaller shared budget, which on an
|
||
expert-tiered box lends that arena back to the expert slab. Vendor TP2
|
||
expert-tiered TTFT deltas vs a plain 2048 budget: −6.1 % at 2k, +2.3 % at 18k,
|
||
+49.1 % at 250k — long prompts only.
|
||
|
||
Two traps. **The arena/slab coupling makes a shared step doubly expensive on an
|
||
expert-tiered shape**: the full-plan arena takes VRAM the resident expert slab would
|
||
have had (320 MiB/card at TP2 for a 4096 budget), so the decode rows inside that step
|
||
also read experts over the link — a smaller shared budget helps twice. And **re-check
|
||
`prefix_hit_rate` / `prefix_evictions` after any chunk change**: the arena and the KV
|
||
pool are the same memory, and the failure looks like turn two taking as long as turn
|
||
one.
|
||
|
||
Availability is a version question, not a config question: `--busy-prefill-chunk` and
|
||
`--prefill-interleave` are absent from older pins — prove it on the running container
|
||
(`podman exec <c> <binary> --help | grep -iE "prefill|chunk"`), never from the vendored
|
||
tree, and check the 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]] (radiance 1.0.13, TP2 `expert_tiered`, budget 2048 = interval
|
||
2048) — the measured census and the verdict for this fleet's shape are that page's.
|
||
|
||
## Related
|
||
|
||
- [[LLM Bench Windows and Measurement]] — 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
|
||
- [[vLLM Porting and Compile Triage]] — the compile fix for the pointwise-glue bound
|
||
- [[frank-archon]] — the endpoint where §9's step-shape census was run
|