From d8e064c1d78213bc63b0923167f504861476ee12 Mon Sep 17 00:00:00 2001 From: donald-heddesheimer Date: Sun, 16 Aug 2026 16:25:27 +0000 Subject: [PATCH] Add the llama.cpp case study --- .gitignore | 1 + README.md | 7 ++ docs/case-study.md | 220 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 228 insertions(+) create mode 100644 docs/case-study.md diff --git a/.gitignore b/.gitignore index bf6b173..55ebfc7 100644 --- a/.gitignore +++ b/.gitignore @@ -4,6 +4,7 @@ dev/ # Working notes stay out; the published measurement writeup is tracked. docs/* !docs/overhead.md +!docs/case-study.md !docs/report.svg !docs/render_report_svg.py !docs/timeline.png diff --git a/README.md b/README.md index a0afa7f..070620d 100644 --- a/README.md +++ b/README.md @@ -177,6 +177,13 @@ Wrap stages, not individual small kernels. Below roughly 50 µs of GPU work per scope the instrumentation becomes a visible fraction of the result. [docs/overhead.md](docs/overhead.md) has the measurements behind this. +That figure was cross-checked outside its own benchmark. +[docs/case-study.md](docs/case-study.md) puts cadence on llama.cpp's CUDA +backend, where counting scopes against llama-bench's own throughput puts the cost +at 3044 and 3227 ns/scope in two configurations — and where wrapping every graph +node instead of the graph costs 20% of tokens per second, which is the same +advice as the paragraph above with a price on it. + ## Build and test ```sh diff --git a/docs/case-study.md b/docs/case-study.md new file mode 100644 index 0000000..5047891 --- /dev/null +++ b/docs/case-study.md @@ -0,0 +1,220 @@ +# Case study: instrumenting llama.cpp's CUDA backend + +Everything else in this repository is measured against a benchmark written to be +measured. This is cadence pointed at code it did not grow up with: llama.cpp's +CUDA backend, unmodified except for the instrumentation, running a real model. + +The point was to find out what happens when the library meets a codebase with its +own ideas — CUDA graph capture, kernel fusion, a graph executor rather than a +loop of named stages. Three things came out of it. One validates a number this +repository has been publishing. One is a fact about llama.cpp. One is a defect in +cadence that produces a confidently wrong conclusion, and it is written up here +in full because a case study that only finds good news is not worth reading. + +## Setup + +| | | +|---|---| +| llama.cpp | `4df29be`, built with `-DGGML_CUDA=ON`, Release, sm_86 | +| model | Qwen2.5-1.5B-Instruct, Q4_K_M, 1.04 GiB, 1.78 B params | +| GPU | RTX A4000 (sm_86), CUDA 12.9, clocks **not** pinned | +| harness | `llama-bench -n 128 -r 3`, so every figure is that tool's own throughput number | + +The patch adds three things to `ggml/src/ggml-cuda/ggml-cuda.cu` and nothing +else: a host scope around `ggml_backend_cuda_graph_compute`, a device scope +around `cudaGraphLaunch`, and — in one mode — a device scope per graph node +labelled by `ggml_op_name(node->op)`. The mode is chosen at runtime by +`CADENCE_LLAMA_MODE`, so the same binary produces every row below. + +## What the report says + +Instrumenting only at the graph level, with llama.cpp's CUDA graphs on: + +``` + label scope n mean p50 p95 max jitter distribution + ──────────────────────────────────────────────────────────────────────────────── + graph-compute host 369 8.30µs 8.14µs 9.12µs 18.9µs 11.2µs █▂▂▂▂▂ ▂ + cuda-graph device 367 3.93ms 3.93ms 4.00ms 4.04ms 144µs ▂▅█▃▂▂▂▂▂ ▂▂ + cuda-graph host 367 7.17µs 7.06µs 7.83µs 11.2µs 4.57µs █▇▄▂▂▂▂ ▂ +``` + +Two things are worth reading off it. + +**The GPU measurement independently reproduces llama.cpp's own throughput.** +`cuda-graph` device mean is 3.93 ms; llama-bench reported 248.3 tok/s on the same +run, which is 4.03 ms per token. cadence is measuring the same thing llama.cpp is +measuring, from the other side, and the two agree to within the ~100 µs the host +spends outside the graph. + +**Decode is 99.8% GPU.** The CPU spends 8.30 µs per token issuing a 3.93 ms graph. +That is the `device` and `host` row pair doing exactly what the README says they +are for: when they diverge this far, the loop is compute-bound and no amount of +CPU-side work will help it. + +## The capture guard fires, on somebody else's code + +llama.cpp captures its decode graph with `cudaStreamBeginCapture` and replays it +with `cudaGraphLaunch`. cadence documents that it refuses to record into a +capturing stream, because a `cudaEventRecord` issued during capture is baked into +the graph rather than executed — the event becomes permanently unreadable, and a +flush landing before the capture closes invalidates the capture outright. + +With per-node instrumentation on, the report opens with: + +``` + WARNING 535 scope(s) skipped -- their stream was capturing into a CUDA graph, + which cannot carry timing events; wrap the graph launch instead +``` + +This is the guard working as designed against real third-party code that really +does use CUDA graphs, and the advice in that message — *wrap the graph launch +instead* — is exactly what the `cuda-graph` row above is. + +There is a second, quieter consequence, and the `n` column is the only place it +shows up. Over 367 decodes, the per-node rows report `n` between 88 and 176. +After the graph is captured, `ggml_cuda_compute_forward` is **never called +again**: the nodes live inside the graph. So per-node instrumentation of +llama.cpp measures the handful of pre-capture evaluations and then goes quiet, +while the counts stay honest enough to say so. A tool that reported a mean +without a count would have looked entirely healthy. + +## The measurement that caught my own mistake + +With CUDA graphs disabled (`GGML_CUDA_DISABLE_GRAPHS=1`), per-node scopes run on +every decode and the per-op distribution becomes real. The first version of that +patch put the scope around `ggml_cuda_compute_forward`, which is the obvious line. +The report then claimed 381 µs of device work per iteration against a +`graph-compute` host span of 2.16 ms — most of the GPU time was unaccounted for. + +The cause is in the loop above it: + +```cpp +int nodes_to_skip = ggml_cuda_try_fuse(cuda_ctx, cgraph, i); +if (nodes_to_skip != 0) { + i += nodes_to_skip; + continue; // launches happened inside try_fuse +} +``` + +A fused group launches its work inside `ggml_cuda_try_fuse` and then `continue`s +straight past `ggml_cuda_compute_forward`. A scope on the obvious line sees none +of it. Moving the scope to cover both calls: + +| op | scopes, obvious placement | scopes, fusion covered | +|---|---:|---:| +| `MUL_MAT` | 1,526 | 65,829 | +| `RMS_NORM` | 0 | 22,153 | +| `ROPE` | 10,872 | 21,764 | +| everything else | 23,511 | 23,511 | +| **total** | **35,909** | **133,257** | + +The first placement missed 97.7% of the matrix multiplies and every single +`RMS_NORM` — an entire op type that simply was not in the report. The lesson is +not about cadence; it is that instrumenting somebody else's graph executor at the +line that looks right will quietly miss its fast path, and the only defence is +checking whether the parts add up to the whole. + +## The overhead number holds up outside its own benchmark + +[docs/overhead.md](overhead.md) publishes 3390 ns per `CADENCE_KERNEL` scope from +a synthetic benchmark. llama.cpp offers a way to check that against real work: run +with graphs disabled, count the scopes, and read the throughput cost off +llama-bench. + +| configuration | tok/s | ms/token | scopes/token | ns/scope | +|---|---:|---:|---:|---:| +| uninstrumented | 228.20 | 4.382 | 0 | — | +| per-op, obvious placement | 212.94 | 4.696 | 97 | **3227** | +| per-op, fusion covered | 182.43 | 5.482 | 361 | **3044** | + +Two measurements, taken at scope counts that differ by 3.7x, on somebody else's +kernels, land within 10% of the published figure and within 6% of each other. +That is about as good as an unpinned-clock cross-check gets, and it is the first +evidence in this repository that the number means anything outside the benchmark +that produced it. + +It also settles the README's advice with a real example. "Wrap stages, not +individual small kernels" costs 20.1% of throughput here when taken literally at +361 scopes per token — while the graph-level instrumentation, three scopes per +token, is free: + +| configuration | tok/s | vs its own baseline | +|---|---:|---:| +| baseline, graphs on | 247.41 | — | +| instrumentation linked, mode off | 248.64 | +0.5% | +| graph-level scopes | 248.27 | +0.3% | +| baseline, graphs off | 228.20 | — | +| graph-level scopes, graphs off | 228.05 | −0.1% | +| per-op scopes, graphs off | 182.43 | **−20.1%** | + +(Incidentally: CUDA graphs are worth 8.4% to llama.cpp on this model, 247.41 +against 228.20 tok/s. Not a cadence result, but it fell out of the same runs.) + +## Three defects this turned up in cadence + +None of these are visible on a loop with a handful of stages, which is the only +shape the tests and benchmarks have ever covered. + +**1. The summary line states a conclusion that is the opposite of the truth.** +On the per-op run the report ends: + +``` + device 205µs across 8 label(s) + graph-compute 2.82ms, of which 7.3% is GPU work; 2.61ms is launch and synchronization +``` + +The workload is 99.8% GPU-bound. `WriteSummary` adds one mean per label, which is +correct only when each label occurs once per iteration; here `MUL_MAT` occurs 178 +times per token. Weighting each mean by its actual occurrence rate gives 5.4 ms of +device work per iteration, not 205 µs. The line is not merely imprecise — it +confidently reports the single most important fact about this workload backwards. +The fix is to weight by `count / iterations`, which cadence already knows, or to +withhold the line when a label's count exceeds the iteration count. + +**2. The worst-iteration breakdown is unbounded.** With ~250 spans in an +iteration, `WriteWorstIterations` prints all of them on one line: a single +unreadable paragraph several thousand characters long, three times over. It needs +a cap and a "+N more". + +**3. Iterations are ranked by the wrong span when the host scope does not enclose +the GPU work.** `IterationSpanMs` uses the longest host span as the iteration's +duration, documented on the assumption that a `CADENCE_SCOPE` wraps the loop body. +Here the host scope returns in 8 µs having queued 3.93 ms of GPU work, so the +"slowest iterations" are chosen by host jitter: the run picked an iteration with +an 18.9 µs host span and a perfectly ordinary 3.94 ms GPU span, while the actual +worst GPU iteration (4.04 ms) never appeared. + +## One thing that is not a defect, but caught me anyway + +`CADENCE_KERNEL` resolves its label through a function-local `static`, so the +handle is interned once per *call site*, not once per execution. Passing a label +that varies — `ggml_op_name(node->op)` — files every scope under whichever op ran +first, silently. The headers do say this (`ScopedHost`: "Interns on every +construction"; the macro: "the only form that resolves a label once per call site +rather than once per execution"), and the correct form for a runtime label is the +class directly: + +```cpp +cadence::ScopedKernel scope(ggml_op_name(node->op), cuda_ctx->stream()); +``` + +Documented, and still the first thing I got wrong. Worth knowing before you reach +for a dynamic label. + +## Reproducing + +The patch is a script rather than a diff so it survives llama.cpp moving lines +around, and so it is obvious what was inserted where. It is not in this +repository — llama.cpp is not a dependency of cadence and should not become one — +but it is four insertions, all quoted above. + +```sh +git clone --depth 1 https://github.com/ggml-org/llama.cpp +cmake -B build -DGGML_CUDA=ON -DCMAKE_BUILD_TYPE=Release -DCMAKE_CUDA_ARCHITECTURES=86 +# add cadence's include dir to ggml-cuda, insert the four scopes, rebuild +CADENCE_LLAMA_MODE=graph ./build/bin/llama-bench -m model.gguf -n 128 -r 3 +``` + +Clocks were not pinned (`nvidia-smi -lgc` needs root here), so read the ratios +rather than the absolutes. Every configuration was run against its own baseline +in the same session.