Where the other half goes: profiling a decode step on Apple Silicon without a profiler

Carmen, my assistant, and my coding sessions run on GLM-5.3-Flash on a Mac Studio M3 Ultra, through mlx-vlm's server. This week I fixed its prompt cache (previous post), so a warm turn now starts in about 0.3 seconds. What is left of a turn is decode: 34 to 36 ms per token at Carmen's context sizes, 28 to 29 tokens per second.

The model reads about 12 GB of weights per token: 4-bit routed experts, 6-bit everything else. The M3 Ultra moves 819 GB/s, so the floor is 14.6 ms per token. We spend 34. This post is about finding where the other 20 ms go, and what that turned up.

Three ways to measure that lie

The obvious profiler is a stopwatch around each op with a sync after it. On this machine one mx.eval of a trivial op costs about 0.19 ms. A decode step is roughly 1,600 kernels, most of them 0.02 to 0.3 ms. A sync-per-op profiler would measure itself. Coarser syncs (once per layer, 45 per step) still add 8 ms to a 34 ms step and change the pipelining they are supposed to observe.

The second option is Metal System Trace, which records every kernel on the GPU timeline with no code changes. It needs Xcode, and my server does not have it. Installing 12 GB of Xcode on a production box to answer one question felt wrong, and MTL_CAPTURE_ENABLED needs a restart into a different environment anyway.

The third option is the one I tried first and had to throw away: run an op K times inside the step and read the marginal cost from the decode rate. It fails because of the GPU's caches. A 100 MB matrix-vector product repeated with the same weights costs 0.02 to 0.05 ms per extra copy; the same product against a different 100 MB matrix costs 0.15 to 0.18 ms, which is what the bandwidth says it should. Repeating an op on its own weights measures the cache, not the op.

Repeating on siblings

The version that works: repeat the segment K times per layer, but run the K−1 extra copies on sibling layers of the same kind, spaced n/K layers apart so their weights are long gone from the cache, and attach the extra outputs to the real output with mx.depends. MLX's lazy evaluation drops unreferenced work entirely (I checked: unreferenced extras cost nothing), and depends forces them to execute without adding a kernel. The real path is untouched, so the outputs stay bit-identical; the decode rate drops by (K−1) times the segment's true in-pipeline cost, with no sync anywhere.

The whole thing lives behind a flag file in the model's runtime. The first line of the file names the mode; a driver script builds a 20k-token conversation, runs a baseline, then repeat SEG 4 for each of twenty-one segments with baselines interleaved, and turns rates into milliseconds. Thirty-five requests of 96 tokens, four minutes, baseline spread ±0.3 ms. Two controls with K=1 must match the baseline, and did.

One caveat the numbers themselves revealed: Metal runs independent kernels concurrently, so an extra copy can hide inside gaps of the main path. The lm_head (515 MB) measured 0.41 ms per copy, which would be 1.25 TB/s. For bandwidth-heavy segments the method gives a lower bound; for launch-bound segments and for the split between attributed and unattributed time it is exact enough.

The map

Per decode step at a 19.9k-token context, 35.8 ms per token:

A few of the individual rows are worth knowing. The routed experts cost 9.6 ms per step, 0.22 ms per layer for 113 MB of weights, or 520 GB/s: this matches an earlier wire probe and is as good as gather_qmm gets on this hardware. The big input projection of the linear-attention layers runs at 650 GB/s. Compiling the FFN block saves 2.5 ms per step over eager. The hyper-connections, four tiny kernels per layer, add up to 2 ms of pure launch cost. And the indexer is 60% of the whole difference between a short context (30.9 ms per token) and a 20k one (35.8): the sort runs over T/4 pools and the rest is forty launches per layer.

The bandwidth bucket loses 6.4 ms inside MLX's own matrix-vector kernels at M=1; an exact custom kernel I wrote earlier matches gather_qmm to the microsecond, so that is upstream work, not mine. The other three buckets are where a runtime can still act.

The CPU side

The remainder deserved its own instrument, so I timed the batched generator's step function in the generation thread: graph construction, the async_eval call, the wait for the previous step's tokens, and everything between two steps.

The thread never waits for the GPU at the place the code expects it to. The whole step sits inside async_eval, which is not asynchronous from this thread's point of view. Per-thread CPU accounting and a sampling profile say what happens in there: the thread traverses the graph, allocates buffers and encodes the Metal kernels itself, 22 ms of CPU in a 30 ms step, and blocks on Metal back-pressure the rest of the time. A second thread, Metal's completion machinery, burns another 14 ms per step running MLX's per-command-buffer cleanup.

So the step is GPU-bound, but only by about 8 ms. Two consequences follow. Any GPU-side gain beyond roughly 25% makes the Python thread the bottleneck unless the kernel count drops too, so kernel fusion pays on both sides and pure kernel speedups do not. And background CPU load on the box now has a measurable cost: with the generation thread at 73% duty, five HuggingFace downloads at 250 MB/s took 4% off decode.

The knob

The per-command-buffer cleanup was the clue. MLX encodes a decode step into Metal command buffers, and device.cpp commits one after 50 ops or when the distinct input buffers it references exceed 50 "MB" of elements (the Ultra defaults). GLM's weight matrices are 27 to 113 MB each, so the byte rule trips about once per layer: a step spans 45 to 90 command buffers, and each boundary costs about 20 µs on the GPU plus a completion handler on the CPU.

A toy chain of 3,200 tiny dependent kernels measures 8.8 ms per step with the defaults and 7.7 ms with 200 ops per buffer. Both limits are environment variables read once at import, so the test is a restart. Three arms on the live server, same prompts, output hashes compared across arms:

+5% at Carmen's context, +7.7% at short context, identical outputs, cold prefill unchanged (50.4 s vs 49.9 for 20k tokens), memory flat at a 169.7 GB peak during the cold prefill. With the downloads and the speech-to-text worker paused, the setting reads 35.5 tokens per second short and 29.8 at 20k. I kept the byte limit at 400 rather than removing it: it bounds how long prefill temporaries are held, and 400 keeps that harmless while cutting the buffers per decode step to about seven. As a side effect, the downloads now cost 1.5% instead of 4%, because each step needs less CPU.

It is in the production plist now. It is the cheapest gain of the week: two variables, no code, no rounding change.

Where it does not help

Before writing this, I tried the same two variables on the other model this box serves, a dense Qwen3.8-27B at 8-bit on the same launcher, with the same pauses for both arms:

Nothing, and slightly worse at long context. The difference is the shape of a step. GLM's is about 1,600 launches, most of them small: MoE routing, hybrid attention, hyper-connections. Qwen's is about 1,000 large matrix-vector products, each of which dwarfs a buffer boundary. The knob is a property of launch-heavy architectures, not of MLX in general. If your model is a DeepSeek-style MoE with a hybrid attention stack, try it and compare output hashes; if it is dense, expect nothing.

What's next

The map ranks the remaining runtime work by measured size. The indexer as one Metal kernel, scoring pools and selecting the top 512 in one pass instead of forty launches, is worth 2.5 to 2.7 ms per step at 20k and grows with context, which is where my coding sessions live. Fusing the hyper-connections and the router is another 2 to 3 ms spread over a hundred small kernels. Together that is about 15% of a step, and because both cut launches they also relieve the CPU thread that is 8 ms from becoming the limiter.

None of it is as large as the two things outside the runtime: gated speculative decoding for code turns (our own measurements say +24% with native MTP and up to +47% with a block drafter on code, and a loss on Carmen's short answers, which a per-request acceptance gate would avoid), and compact tool-call output on Carmen's side, which is about 22% fewer tokens per turn for one prompt edit.

The command-buffer numbers are with the MLX project as ml-explore/mlx#4521: larger defaults on Ultra-class devices, or a byte limit that scales with the weights, is a one-line change for them.

Reproducing

The two variables go in the environment of whatever launches the server; for a launchd job that is the plist. The profiler, the step timer, the driver scripts and the rate check with hash comparison are flag-gated and inert by default; they live in my GLM runtime repo and in the server patch set, with a runbook (docs/decode-profiler.md). If you try the variables on a different model, run the same prompts under both settings and compare output hashes before you compare rates; the second table above is what a fair check looks like.