Correction (8 Oct 2026): A reader found two bugs in the attribution code in the first version of this post. (1) Preemption was double-counted: while a request was evicted, the time was charged to preemption and to whatever the engine ran during it, so a 40 ms gap could be charged 60 ms. (2) GC inflated graph-miss time: a GC pause inside an eager decode step was removed from the step's share of the gap but not from the step's total before comparing it with the baseline, inventing graph overhead that wasn't there. Both bugs are fixed below. The engine now records eviction and readmission explicitly, every gap's attribution now sums exactly to the measured gap, and every number comes from a new set of 35 longer runs. The bugs did not touch the measured ITL percentiles; they did distort the breakdown by cause, and the biggest change is that graph misses own far less of the tail than v1 claimed. Thank you for the careful review.
The One-Line Summary: On a CPU demonstrator engine I built to make every stall cause real and measurable, 98% of a typical inter-token gap was the decode forward pass, but at or above p99 the forward pass was only 9–29% of the gap. The rest was preemption, prefill, GC and tokenization landing in the same window, and fixing those one cause at a time took the median p99.9 across five 60-second runs from 950 ms to 50 ms.
What this is, and isn't: every number here comes from a CPU demonstrator: a continuous-batching engine in Python and NumPy on a 2-core VM, not a GPU serving stack. Its "CUDA graph" path is emulated: it pads to a captured batch size and falls back above the largest, like the real thing, but the speed difference it measures is batched vs per-sequence NumPy, not graph replay vs kernel launches. Treat the percentiles and bands as observations from this workload. What transfers is the method: tag each step, partition each gap, reconcile.
The Parable of the Harbour Line Logbook
The Harbour Line promises a train every four minutes. The audit says it delivers: the average gap between departures at Quay Street is 4.2 minutes, and the trains themselves cover the line in exactly the time the timetable says, every time, to the second.
The complaint letters say something else. Waited twenty-five minutes on the platform. Twice this week.
Both are true. The new dispatcher, Odile, is the first person to take that seriously.
The Stopwatch on the Train
Her predecessor had investigated the letters by riding the trains with a stopwatch.
THE STOPWATCH ON THE TRAIN
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Quay St -> Mill Rd 3 min 58 s
Quay St -> Mill Rd 4 min 01 s
Quay St -> Mill Rd 3 min 59 s
Quay St -> Mill Rd 4 min 00 s
... (two hundred rides)
verdict: the trains are fine.
✗ Correct, and useless. Nobody on the platform
was complaining about the ride.
The trains were fine. The question the passengers were asking was not "how fast is the train?" but "why didn't one come?" — and you cannot answer that by timing the train.
The Logbook
Odile does something different. For every departure, she writes down not how long the train took, but everything else that happened on the line since the previous departure.
After a month, the late departures sort themselves into five piles.
ODILE'S LOGBOOK — LATE DEPARTURES, BY WHAT ELSE HAPPENED
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
THE FREIGHT SLOT a freight train was let onto the line between
two passenger trains. Long freight, long gap.
THE ODD-LENGTH TRAIN the platform doors are programmed for 4, 6 and
8 cars. A 9-car train had to be boarded with the
doors worked by hand, one car at a time.
THE SIDING SHUFFLE the yard was full, so a passenger train was
pulled onto a siding to make room. Its riders
sat there until a slot opened, then it was
shunted back. Everyone else waited for the shunt.
THE SWEEP the depot crew walked the whole line checking
every locker — including forty years of archived
paperwork nobody ever opens. The line stops
while they walk.
THE GROUP BOOKING the gate agent, who also waves trains out,
got a tour group of three hundred and sold all
their tickets before waving the next train out.
Not one of the five piles is about the train.
One rule keeps the logbook honest. A rider who spent twenty minutes on the siding is entered under siding, once — even though freight happened to roll past while they sat there. Odile notes the freight in the margin, because it explains why the siding took so long, but she never counts those twenty minutes twice.
Five Piles, Five Fixes
What makes the logbook useful is that every pile has its own remedy, and none of the remedies help the others.
THE FIX FOR EACH PILE
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
freight slot cut freight into short sections that fit
between passenger trains
odd-length train program the doors for every length you run
siding shuffle don't let a new train onto the line unless
the yard has room to spare
sweep seal the archive room; stop filing a paper
form for every single passenger
group booking sell tickets in the street-level office,
not at the gate
Shortening freight does nothing for the sweep.
Sealing the archive does nothing for the siding.
Odile also notices that the piles live at different heights. The odd-length trains turn a four-minute wait into six. Freight turns it into ten or fifteen. The sweep and the group booking are rare, but when they happen it is half an hour. And the siding shuffle is the worst of all — for the riders on the shunted train, the wait can be longer than the trip.
"The trains were never the problem. The problem was everything I let happen between them."
Why It Works
The average measures the train. The bad days measure the line. Once Odile stopped asking how long a departure took and started asking what shared it, every late departure came with its own explanation attached — and a different person to go and fix it.
That is the whole method. The rest of this post does it to a machine that writes one word at a time, for hundreds of people at once.
What Is a Decode-Step Stall?
A serving engine generating text runs a loop. Each iteration — a step — picks a set of requests, runs one forward pass, and emits one new token for every request that is in its decode phase. The inter-token latency (ITL) of a request is the gap between two of its consecutive tokens:
Where the timestamp is taken matters. In this post, is taken inside the engine loop, right after the decode forward pass returns. All tokens of a step share it. That is the engine-emission boundary. It is not when the frontend streams the token or when the client receives it — those add serialization and network time, and in real servers one streamed message can carry more than one token (speculative decoding, for instance), so a client-side "gap" can span several tokens.
In a quiet engine, the gap is one step, and one step is mostly the decode forward pass. But a step is shared: continuous batching means the step that produces your next token also does whatever else the scheduler decided this iteration needed. So every gap can be partitioned exclusively — each millisecond goes to exactly one label:
where is the decode forward pass (on a GPU, the kernels), and is whatever no instrument covered. A decode-step stall is a gap where one of the middle five terms is not zero. This is the serving-engine version of what Dean and Barroso called the tail at scale [9]: rare events that barely move the average but decide the experience.
The claim I tested: the median is mostly the first term; the tail is mostly the middle five. In this demonstrator that held. Whether it holds on your system is exactly what the instrument is for — on fast GPUs, CPU-side overhead can become a large share of every step, not just the tail; vLLM's V1 redesign was motivated by exactly that [7].
The Five Stalls
1. A Prefill Chunk Admitted Into the Batch
A new request needs its whole prompt processed before it can decode — prefill. Modern engines chop prefill into chunks and piggyback the chunks onto decode steps, the idea Sarathi-Serve called stall-free scheduling [1]. vLLM V1 has chunked prefill always on and schedules all pending decodes first, then fills the remaining token budget with prefill [2].
The decodes still wait for the chunk. The knob is the per-step token budget (max_num_batched_tokens in vLLM): vLLM's tuning guide says smaller values give better ITL and larger ones better time-to-first-token [2].
2. A Preemption
The KV cache is a fixed pool. When a running request needs one more block and none is free, the scheduler evicts a victim — either dropping its cache to recompute later, or copying it out to host memory and back (swap). vLLM V1 defaults to recompute [2]. My demonstrator swaps, because the copy is a cleaner thing to time; the victim's wait is the same kind of stall either way, but the cost others pay (a copy here, a re-prefill under recompute) differs.
Preemption has two kinds of victim: everyone in the step pays for the eviction work, and the evicted request emits nothing at all until it is readmitted.
3. A CUDA-Graph Miss on an Unusual Batch Shape
Engines capture CUDA graphs for a fixed set of batch sizes so a decode step is one replay instead of many kernel launches. A batch is padded up to the nearest captured size; vLLM's dispatcher returns CUDAGraphMode.NONE — run eagerly — when the token count exceeds the largest captured size [3]. Actual coverage also depends on the graph mode (full vs piecewise) and on the batch's composition. Recent vLLM versions tie the default capture range to max_num_seqs [4], which is why this tends to bite when someone raises max_num_seqs or trims the capture list.
4. Python Garbage Collection in the Scheduler
The scheduler is Python. Python's cyclic collector periodically walks every tracked container object; a full (generation-2) pass scales with the live heap, and it runs on whichever thread allocated the object that tipped the counter — here, the engine loop.
vLLM freezes the GC heap after startup so static objects are never rescanned, disables collection during graph capture because a GC cycle there can invalidate the graph, and ships VLLM_GC_DEBUG to log collection times [5]. Python 3.14.0 shipped an incremental collector that cut maximum pauses by an order of magnitude on large heaps, and 3.14.5 reverted it to the 3.13 generational collector after production reports of memory pressure [6].
5. A Tokenizer Hiccup
Tokenizing a 300,000-character pasted document is real CPU work. If it happens on the thread that drives the step loop, every in-flight request waits for it. vLLM V1 moved tokenization and detokenization out of the engine-core process so that work overlaps with the core loop [7].
Instrumenting One Engine
The demonstrator: a continuous-batching loop in Python with a random-weight 2-layer transformer in NumPy (d=128); a block-based KV pool (1,000 blocks of 16 tokens); chunked prefill with decode-first scheduling; swap-based preemption of the newest request, with eviction and readmission timestamps recorded explicitly; an emulated "captured graph" path for batch sizes {1, 2, 4, 8, 16, 24, 32} (one padded, batched NumPy call) with a per-sequence fallback above that; a real BPE tokenizer (HuggingFace tokenizers, trained in-process); and Python's real garbage collector. What I call "forward pass" below is CPU forward-pass time in this engine.
The workload: 60 seconds per run, about 6.5 requests/s on average with a 15-second swell (±60%); prompts around 1,000 characters; 1% of requests paste a 150k–400k-character document (truncated to 2,048 tokens after tokenization); outputs averaging about 300 tokens; 400,000 long-lived startup objects standing in for a real server's configs and registries. Each run: 385–422 requests and 112,000–116,000 inter-token gaps. Five runs (seeds 1–5) per configuration, 35 runs in all.
Why 6.5 req/s: the reruns landed on a slower VM than v1 (in the same microbenchmark, the forward pass at batch 32 took 12.8 ms vs 5.6 ms), so I recalibrated the arrival rate to keep the same near-capacity regime: queues drain, the KV pool is under pressure, and batches occasionally cross 32. At the original 10 req/s this VM was overloaded — see the sidebar below. Absolute numbers differ from v1 for that reason.
The Step Tag
Every step records what it did, as (segment, start, end) windows. Trimmed from the engine (the full source is at the end):
def step(self, now0):
tag = {"seg": [], "t0": now0, ...}
# 1. intake: arrivals become waiting requests (tokenizer runs here)
while self.trace and self.trace[0].arrival <= now0:
r = self.trace.pop(0)
t = time.perf_counter()
r.prompt = tokenize(r.text)[: cfg.max_model_len]
tag["seg"].append(("tok", t, time.perf_counter()))
self.waiting.append(r)
# 2. swap-in: readmission is an explicit, timestamped event
...
r.evictions[-1][1] = time.perf_counter() # readmitted
...
# 3. reserve a KV slot for every decode; may evict the newest request
...
# 4-5. leftover token budget goes to prefill chunks
...
tag["seg"].append(("prefill", t, time.perf_counter()))
# 6. decode: emulated captured path, or per-sequence fallback above every captured size
i = bisect.bisect_left(cfg.capture_sizes, B)
graph = cfg.capture_sizes[i] if i < len(cfg.capture_sizes) else None
...
tag["seg"].append(("decode", t, time.perf_counter()))
now = time.perf_counter() # the emission timestamp for every token in this step
and eviction is stamped at the moment it happens:
def _preempt(self, r):
...
r.evictions.append([time.perf_counter(), None]) # evicted (before the copy-out)
GC is timed with the standard library, two clock reads per collection:
gc.callbacks.append(self._gc_cb)
def _gc_cb(self, phase, info):
if phase == "start": self._gc_t0 = time.perf_counter()
else: self.gc_log.append((self._gc_t0, time.perf_counter(), info["generation"]))
The run dumps every step, segment, GC pause, emission, eviction and request to a raw log file. Every number below is recomputed from those raw logs by a separate analysis script.
Partitioning a Gap — and What v1 Got Wrong
The rule now is a strict partition of the window between two emissions, using the request's actual state:
- While the request is evicted (explicit eviction → readmission events), every millisecond is preemption. Whatever the engine ran meanwhile is recorded separately as context, never added to the gap.
- Otherwise, GC pauses take precedence over whatever segment they landed in; then each segment's GC-free overlap goes to its label.
- Decode time is split into graph-miss excess and forward pass using the step's GC-free decode time against a GC-free baseline fit on captured-path steps, then applied proportionally to the part of the segment inside the gap.
- Whatever no segment covers is residual. By construction the parts sum to the gap, and the analysis checks that they do.
Verbatim from attribution.py:
def _graph_fraction(self, i, st):
"""Share of this step's (GC-free) decode time that is graph-miss excess."""
if st["graph"] != "eager": return 0.0
if i not in self._dnet: self._dnet[i] = decode_net_ms(st, self.gci)
full = self._dnet[i]
if full <= 0: return 0.0
base = self.slope * st["n_decode"] + self.icpt
return max(0.0, full - base) / full
def _charge(self, x, y, acc):
"""Charge window [x, y] (s) segment-by-segment into acc (ms). Returns covered ms."""
gc = self.gci.overlap(x, y)
acc["gc"] += gc * 1e3
covered = gc
for i, st in self._steps_overlapping(x, y):
for name, a, b in st["seg"]:
a, b = max(a, x), min(b, y)
if b <= a: continue
net = (b - a) - self.gci.overlap(a, b)
covered += net
lab = SEG_LABEL[name]
if lab == "decode":
f = self._graph_fraction(i, st)
acc["graph"] += net * f * 1e3
acc["kernel"] += net * (1 - f) * 1e3
else:
acc[lab] += net * 1e3
return covered * 1e3
def gap(self, t0, t1, evictions=()):
"""Partition one gap. Returns (parts, context): parts sum exactly to the gap."""
parts = {k: 0.0 for k in LABELS}
context = {k: 0.0 for k in LABELS}
ev = [(a, b if b is not None else t1) for a, b in evictions if a < t1 and (b is None or b > t0)]
for a, b in ev: # evicted: all of it is preemption
a, b = max(a, t0), min(b, t1)
if b > a:
parts["preempt"] += (b - a) * 1e3
cov = self._charge(a, b, context) # what the engine was doing meanwhile
context["residual"] += (b - a) * 1e3 - cov
for a, b in _subtract(t0, t1, ev): # live: charge what actually ran
cov = self._charge(a, b, parts)
parts["residual"] += (b - a) * 1e3 - cov
return parts, context
(kernel is the label name in code; in this demonstrator it means CPU forward-pass time.)
Here are the reviewer's two controlled examples, run through the v1 function unchanged:
EX1 gap 40.0 ms -> prefill 30.0 + preempt 30.0 = 60.0 ms attributed
EX2 gap 30.0 ms -> gc 20.00 graph 6.67 (correct graph excess: 0)
v1 charged 60 ms inside a 40 ms gap, and invented 6.67 ms of graph overhead out of a GC pause. The same two cases, plus four more, as unit tests against the corrected partitioner:
PASS test_reviewer_example_1_eviction_not_double_counted
PASS test_reviewer_example_2_gc_does_not_inflate_graph_excess
PASS test_real_graph_excess_survives_gc_removal
PASS test_partial_overlap_with_gap_is_proportional
PASS test_gc_after_emission_and_residual_reconcile
PASS test_mixed_step_prefill_tok_swap_and_decode
In the first case the corrected partition gives 30 ms preemption plus 10 ms forward pass, which is the 40 ms gap; the 30 ms of other requests' prefill is recorded as context. In the second it gives 20 ms GC, 10 ms forward pass and 0 ms graph excess.
Across all 35 runs and about 4 million gaps, the largest difference between a gap and the sum of its parts was 5.7 × 10⁻¹⁴ ms. And no gap skipped engine steps without a recorded eviction covering it. v1 inferred preemption from skipped steps; that check now verifies the explicit events agree with that inference rather than relying on it.
The p99, Decomposed
All results: five runs per configuration. Each run is the unit of evidence here, not each gap. A run has ~114,000 gaps, but they are far from independent: one GC pause stalls every request in the batch at once, and one preemption burst evicts several. So I report each run separately, or as a median with the min–max across the five.
Median Is the Forward Pass. Tail Is Not.
For each token, the share of its gap that was the decode forward pass (baseline configuration):
FORWARD-PASS SHARE OF A GAP (median), baseline: clean vs tail tokens
run 1: clean 98% tail 23%
run 2: clean 98% tail 29%
run 3: clean 98% tail 11%
run 4: clean 98% tail 18%
run 5: clean 98% tail 9%
In an ordinary gap, the forward pass is 98% of the wait in all five runs. In a gap at or above that run's p99 it is 9–29%. In this engine, making the forward pass faster improves typical tokens almost one-for-one and the tail far less.
Where the Tail Time Went
The share of all tail time (tokens with ITL ≥ p99) by label. With the corrected attribution, these are additive and each row sums to 100%:
BASELINE: WHERE TAIL TIME WENT (tokens with ITL >= p99), additive, sums to 100%
run p99 prefill preempt graph gc tok kernel residual
1 30.9 23.0% 57.2% 0.4% 4.4% 3.6% 11.0% 0.4%
2 34.1 45.2% 12.2% 0.7% 7.6% 9.9% 23.6% 0.8%
3 50.3 3.5% 93.2% 0.2% 0.8% 1.2% 1.0% 0.0%
4 47.0 5.3% 90.0% 0.1% 1.6% 1.0% 1.9% 0.1%
5 62.8 12.4% 77.1% 0.2% 2.1% 5.3% 2.8% 0.2%
(kernel = CPU forward pass.) Three things stand out:
- Preemption holds most of the tail time in four of five runs (57–93%). Run 2 drew a lighter trace (44 preemptions instead of 142–318), and its tail is mostly prefill.
- Count and time disagree. By count, prefill was the most common primary cause of a tail token in every run (649–880 of ~1,150 tail tokens). By time, preemption dominates: fewer tokens, but each one enormous.
- Graph misses own almost none of the tail: 0.1–0.7%. This is the largest correction from v1, which reported up to 7%. Part of that was the GC bug; part was the old labeling. Graph misses here are frequent and small: 1.7% of all gap time (median; 1.3–4.1% per run), which makes them mostly a p90–p99 effect rather than a tail one.
The Histogram
Every gap from run 4 (the run whose p99, 47.0 ms, is the median of the five), binned, with each bin's tokens split by primary cause: the largest cause, if it is ≥1 ms and ≥25% of the gap. · means no cause met that bar, which in practice means the forward pass. P prefill, C graph miss (emulated), S preemption, G GC, T tokenizer.
ITL HISTOGRAM BY PRIMARY CAUSE, baseline, run 4 (p99 = 47.0 ms)
ITL ms tokens share of the bin's tokens by primary cause
0-5 13760 ····································
5-10 17747 ····································
10-15 37670 ····································
15-20 35524 ···································P
20-30 8907 ······················PPPPPPPPCCCCCC
30-50 1460 ···PPPPPPPPPPPPPPPPPPPPPPPPPPPPPPCC
50-80 589 ··PPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPP
80-120 111 PPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPS
120-200 58 PPPPPPPPPPPPPPPPPPPPSTTTTTTTTTTTTTT
200-400 170 PPPPPPPPPPPPPPSSGGGGGGGGGGGGGGGGTTTT
400-800 11 SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
800-inf 171 SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
Across the five baseline runs the causes overlap but have different centres of mass. Graph misses sat at 15–120 ms. GC, apart from a few small pauses, sat at 120–400 ms. The tokenizer spread from 15 to 400 ms, and prefill appeared everywhere from 0 to 800 ms. Preemption started around 30 ms and was the only cause above 800 ms. This run is tidier than most: here, every gap above 400 ms is preemption, but in run 3, 23 of the 53 gaps in the 400–800 ms bin were prefill. So read these bands as loose observations about this engine and workload, not as a law. A GPU engine with a faster forward pass and a different prefill cost will put them somewhere else.
The Fix Ladder
One cause at a time, each rung keeping every fix above it. Median and [min–max] across five runs, in ms:
FIX LADDER (5 runs x 60 s each; median [min-max] across runs; ms)
rung p50 p99 p99.9 max
baseline 13.7 [10.5-16.0] 47.0 [30.9-62.8] 950 [149-7395] 9466 [895-12764]
+gc.freeze 14.3 [7.9-14.7] 49.0 [27.0-60.7] 581 [112-953] 3805 [368-6100]
+compact history 11.3 [6.0-14.7] 40.4 [21.6-49.2] 258 [56-827] 2268 [451-5165]
+graphs to 48 12.3 [10.6-14.0] 37.3 [31.9-50.6] 234 [122-447] 2971 [1295-3824]
+budget 256 12.6 [9.4-14.8] 29.5 [25.2-32.7] 149 [54-542] 1933 [612-2646]
+tokenize off-loop 12.5 [10.8-15.5] 29.6 [26.3-39.0] 133 [53-967] 2698 [889-4210]
+admit watermark 12.0 [10.4-14.1] 27.8 [24.2-32.5] 50 [31-70] 108 [39-651]
End to end, on medians: p99 47.0 → 27.8 ms, p99.9 950 → 50 ms, worst gap 9,466 → 108 ms. The median ITL's range barely moved (10.5–16.0 → 10.4–14.1 ms). Read adjacent rungs with the ranges in view: with five runs, several single-rung steps overlap and are suggestive rather than established. At the ends of the ladder, the p99.9 and max ranges don't overlap at all; p99 overlaps only between 30.9 and 32.5 ms, because run 1's baseline drew light traffic.
And the tail's composition, rung by rung (median across runs). The shares sum to 100%, so when one cause shrinks, the others' shares grow even if their absolute time didn't change. Read it for which column each fix drives toward zero:
MEDIAN TAIL-TIME SHARE PER RUNG (5 runs)
prefill preempt graph gc tok fwd residual
baseline 12.4% 77.1% 0.2% 2.1% 3.6% 2.8% 0.2%
+gc.freeze 14.0% 70.6% 0.1% 1.6% 5.7% 5.7% 0.2%
+compact history 23.1% 59.0% 0.2% 0.0% 7.4% 8.3% 0.3%
+graphs to 48 30.5% 49.0% 0.0% 0.0% 6.6% 9.8% 0.5%
+budget 256 12.0% 56.0% 0.0% 0.0% 8.9% 25.7% 0.3%
+tokenize off-loop 8.5% 63.2% 0.0% 0.0% 0.0% 27.4% 0.8%
+admit watermark 34.7% 0.2% 0.0% 0.0% 0.0% 63.2% 1.9%
What each rung did:
gc.freeze() after startup. Generation-2 pauses during serving dropped from 137–242 ms to 30–90 ms, because the startup heap stopped being rescanned. The one-off gc.collect() before freezing costs 112–130 ms on this rung (107–167 ms across all frozen rungs), at startup, before any request. Median p99.9 950 → 581 ms; p99 did not move.
Compact history. The engine kept a Python object per emitted token: a record plus a dict of five top-k logprob objects, the way a metrics store or streaming buffer might. Moving that into a flat array("d"), which the collector can't see, cut generation-0 collections from ~380–400 per run to 20–44, and no generation-2 collection ran during serving in any of the five runs. GC's share of the tail went to 0.
Capture graphs up to max_num_seqs (emulated). Fallback steps went from 0–983 per run on the previous rung (207–1,087 at baseline) to zero. Its share of tail time was already under 1%; this fix mostly helps the p90–p99 body.
Token budget 2,048 → 256. The largest single p99 step: median 37.3 → 29.5 ms, with ranges that overlap only between 31.9 and 32.7 ms.
Tokenize off the engine loop. The tokenizer's share of the tail went to zero, but the percentiles didn't clearly move (p99 29.5 → 29.6, p99.9 149 → 133, ranges overlapping). On a 2-core VM, the tokenizer worker process competes with the engine for the same cores. It moves the stall from blocking to contention without removing the work. In v1's runs, this rung made p99 slightly worse. In production, the frontend should run on cores the engine core doesn't need, which is what vLLM V1's process split is for [7].
Admission watermark. Don't admit a new request unless 10% of KV blocks would stay free. Preemptions fell from 23–346 per run on the previous rung to 0–7, and the median worst gap from 2,698 to 108 ms. This time the cost showed up clearly: TTFT p50 rose in all five runs against the previous rung (for example 164 → 931 ms in run 4, 4.6 → 5.6 s in run 3, which was transiently overloaded at its traffic peak). The waiting moved from the middle of people's answers to before they start. That is usually the right trade, but it is a trade.
After the last rung, the tail is 63% forward pass and 35% prefill. Same run as the histogram above:
ITL HISTOGRAM BY PRIMARY CAUSE, +admit watermark, run 4 (p99 = 27.1 ms)
ITL ms tokens share of the bin's tokens by primary cause
0-5 19076 ····································
5-10 18967 ···································P
10-15 52473 ···································P
15-20 18896 ····························PPPPPPPP
20-30 6059 ················PPPPPPPPPPPPPPPPPPPP
30-50 578 ·········PPPPPPPPPPPPPPPPPPPPPPPPPPP
50-80 57 ····················PPPPPPPPPPPPPPPP
80-120 67 ···································S
120-200 1 SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
200-400 2 SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
400-800 2 SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
800-inf 0
One thing I could not explain. Of the 67 gaps in the 80–120 ms bin, 66 are untagged. They average 103.5 ms, and 92.7 ms of that is forward pass: decode steps that ran five or more times slower than usual. None of the five instrumented causes covers it. CPU contention from the tokenizer worker or noise from the VM are the obvious suspects, but my instrument can't see the OS scheduler. It's the sixth pile.
Sidebar: When the Engine Is Overloaded
My first rerun used the original 10 req/s on this slower VM, which turned out to be past capacity: TTFT p50 of 2–17 seconds, and a queue that never drained. The same corrected analysis on those 35 runs: preemption held 67–96% of baseline tail time, the next five rungs moved median p99.9 around inside the noise (593–3,177 ms), and only the admission watermark changed the tail, from 1,022 to 56 ms median p99.9. Under overload, the tail is a capacity problem first, and admission control is the fix that matters.
Each Cause, Its Own Fix
| Cause | Where it sat (5 baseline runs, loosely) | How you see it | Fix | What the fix costs |
|---|---|---|---|---|
| Prefill chunk | anywhere, 0–800 ms | prefill segments in the step | smaller token budget; disaggregate prefill [8] | TTFT at higher prefill load |
| Graph miss (emulated) | 15–120 ms, <1% of tail time | fallback / padded size per step | capture sizes up to max_num_seqs
|
graph memory, startup time |
| Preemption | 30 ms up; the only cause above 800 ms | explicit eviction → readmission | admission watermark; more KV; smaller max_num_seqs
|
TTFT (rose in 5/5 runs) |
| GC | mostly 120–400 ms | gc.callbacks |
gc.freeze(); no per-token Python objects |
negligible here |
| Tokenizer | 15–400 ms | tokenize segments on the loop | separate process with its own cores | a process, IPC, CPU |
In this experiment, each targeted cause's share of the tail went to zero (or near it) at its rung. GC took two rungs, gc.freeze() then compact history. The other columns shifted because shares are relative, not because the fixes acted on them.
Doing This on a Real GPU Engine
I haven't run this instrument against vLLM or SGLang in this post; that's the next one. Here is what changes when you do:
WHAT TO RECORD, AND THE TRAPS
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
forward pass CUDA launches are ASYNCHRONOUS [10]: a host timer around
the forward call measures the launch, not the work.
Bracket it with CUDA events, or use Nsight Systems /
the PyTorch profiler, and correlate with host stamps.
prefill vs decode a mixed batch is ONE forward pass. There is no host
"prefill segment" to time; split its cost by kernel
(profiler) or attribute by the step's token mix.
preemption record eviction and readmission per request from the
scheduler. Do not infer it from skipped steps.
graph mode what the CUDA-graph dispatcher returned for the step
(FULL / PIECEWISE / NONE) and the padded size [3].
GC gc.callbacks in the engine-core process, or
VLLM_GC_DEBUG=1 [5].
tokenizer measured in the frontend process, plus the time the
request then waits before the engine core sees it.
timestamps say which boundary: engine emission, frontend stream,
or client receipt. A streamed chunk can hold several
tokens.
critical path with async scheduling, CPU work for step N+1 can
overlap GPU work for step N. Charge a gap only with
what was on the path between its two emissions.
Then join everything on time windows and partition each gap the same way, with the same reconciliation check.
Reproducing This
ENVIRONMENT
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
CPU Intel Xeon @ 2.80 GHz, 2 cores, 1 thread/core (cloud VM)
Python 3.13.16
NumPy 2.5.3 (OpenBLAS 0.3.34)
tokenizers 0.23.2
threads OPENBLAS_NUM_THREADS=1, OMP_NUM_THREADS=1 (set before import)
PROCEDURE
for seed in 1..5, for each rung:
ITL_RATE=6.5 python3 run.py "<rung>" <seed> 60 -> raw/<rung>__s<seed>.npz
python3 analyze.py raw/*.npz > results.jsonl
python3 test_attribution.py
arrival traces are deterministic in the seed (make_trace) and are also
saved inside every raw file, with all step, segment, GC, emission,
eviction and request timestamps.
The complete engine, the partitioner, the analysis and the runner are below, exactly as they ran. I also have the 35 raw timing logs (about 46 MB); ask in the comments if you want them.
Five 60-second runs per configuration is preliminary evidence, not a benchmark. The p99.9 and max columns rest on about a hundred gaps and a single gap per run respectively, and they are the noisiest numbers here. Longer and more repeated runs would tighten them.
Quick Reference Card
DECODE-STEP STALLS: CHEAT SHEET
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
THE PARTITION (exclusive; must sum to the gap)
ITL = fwd + prefill + preempt + graph + gc + tok + residual
evicted time -> preempt (engine activity = context, not added)
GC -> gc, carved out of its segment
graph excess -> GC-free decode time minus GC-free baseline
uncovered -> residual
check: |gap - sum(parts)| ~ 0 for every gap
MEASURED (CPU demonstrator, 5 runs x 60 s, median [range], ms)
p50 p99 p99.9
baseline 13.7 [10.5-16.0] 47.0 [30.9-62.8] 950 [149-7395]
all fixes 12.0 [10.4-14.1] 27.8 [24.2-32.5] 50 [31-70]
forward pass = 98% of a typical gap, 9-29% of a tail gap
TAIL TIME, BASELINE (these runs)
preemption 12-93% | prefill 4-45% | gc 1-8% | tok 1-10% | graph <1%
by COUNT prefill leads; by TIME preemption leads
FIXES
prefill smaller token budget
graph capture up to max_num_seqs
preempt admission watermark (TTFT rose in 5/5 runs)
gc gc.freeze() + no per-token Python objects
tok separate process WITH its own cores
Key Takeaways
- In this demonstrator, the median ITL was the forward pass and the tail was everything else: 98% vs 9–29% forward pass. Measure it on your own system before assuming it; on fast GPUs, CPU overhead can show up in every step.
- Partition, don't sum. Each millisecond of a gap gets exactly one label, evicted time goes to preemption, and the parts must reconcile to the gap. My first version broke both rules and over-counted.
- Record preemption explicitly. Eviction and readmission are events. Inferring them from missing steps only works when every running request decodes every step.
- Count and time disagree. Prefill crossed p99 most often; preemption held the most tail time. Report both.
- Each fix drove its own cause's column to zero; no single fix touched them all. The shares are relative, so the other columns shifted, but no one rung took out more than one cause (GC needed two).
- Fixes have costs that land elsewhere. The watermark raised TTFT in every run, and off-loop tokenization on two cores bought nothing.
- Treat runs, not gaps, as your sample size. One GC pause stalls a whole batch at once.
The One-Sentence Summary
On a CPU demonstrator, inter-token latency at the median was the forward pass and at p99 was mostly scheduling and runtime, so I tagged every step, partitioned every gap exclusively by cause, checked that the parts summed to the gap, and fixed one cause at a time, taking median p99.9 across five runs from 950 ms to 50 ms without touching the forward pass.
What's Next?
This post starts a new series, Inference Engineering — what actually happens between a request arriving and a token leaving, measured rather than described.
- The same instrument on vLLM: CUDA events, explicit scheduler events, and how the bands move when the forward pass is 10× faster than the scheduler.
- Chunked prefill vs disaggregated prefill: when shrinking the token budget stops being enough.
- Preemption, measured: recompute vs swap, and the queueing math behind an admission watermark.
- The CPU overhead floor: when the scheduler, not the GPU, sets your ITL.
Follow me for the next article in the Inference Engineering series!
Let's Connect!
If the Harbour Line logbook made p99 make sense, drop a heart!
Questions? Ask in the comments — I read and respond to every one.
Check my partition. The first version of this post had two attribution bugs, and a reader found both by building small controlled cases and running my code on them. That's the best review a measurement post can get. If you can construct a gap my partitioner charges wrongly, I want to see it. 🚉
References
[1] A. Agrawal, N. Kedia, A. Panwar, J. Mohan, N. Kwatra, B. Gulavani, A. Tumanov and R. Ramjee, Taming Throughput-Latency Tradeoff in LLM Inference with Sarathi-Serve, OSDI 2024.
[2] vLLM documentation, Optimization and Tuning — preemption mode, chunked prefill and max_num_batched_tokens.
[3] vLLM API reference, vllm.v1.cudagraph_dispatcher.
[4] vLLM forum, Why is CUDA graph capture sizes limited by max_num_seqs.
[5] vLLM API reference, vllm.utils.gc_utils — freeze_gc_heap, freeze_gc_for_cudagraph_capture, VLLM_GC_DEBUG.
[6] Python documentation, What's New in Python 3.14 — the incremental GC and its reversion in 3.14.5.
[7] vLLM team, vLLM V1: A Major Upgrade to vLLM's Core Architecture, 2025.
[8] Y. Zhong, S. Liu, J. Chen, J. Hu, Y. Zhu, X. Liu, X. Jin and H. Zhang, DistServe: Disaggregating Prefill and Decoding for Goodput-optimized Large Language Model Serving, OSDI 2024.
[9] J. Dean and L. A. Barroso, The Tail at Scale, Communications of the ACM, 2013.
[10] M. Harris, How to Implement Performance Metrics in CUDA C/C++, NVIDIA Technical Blog — why host timers measure kernel launch rather than execution, and CUDA events.
Full Source
engine.py — the demonstrator engine
"""nano-engine: a CPU continuous-batching LLM server loop, instrumented so every
decode step records *what else happened in that step*.
The model is a random-weight transformer stack in numpy. The point is not the
tokens it emits; it is that every mechanism that stretches a decode step is the
real mechanism, executed for real:
prefill chunked prefill admitted into the same step as the decodes
preempt KV pool exhausted -> victim's KV copied out (swap) and back in
graph batch sizes with no "captured" fast path run op-by-op (eager)
gc Python's cyclic GC, timed with gc.callbacks
tok incoming prompts tokenized inline on the engine thread
"""
import os
os.environ.setdefault("OPENBLAS_NUM_THREADS", "1")
os.environ.setdefault("OMP_NUM_THREADS", "1")
import gc, time, json, random, bisect, sys
from array import array
from dataclasses import dataclass, field
from concurrent.futures import ProcessPoolExecutor
import numpy as np
# ---------------------------------------------------------------- tokenizer
_TOK = None
WORDS = ("the of and to in is for on that with as by at from this be are was it an or "
"kernel batch token cache latency decode prefill scheduler memory throughput "
"request queue model layer tensor shape graph block swap stream budget").split()
def make_text(rng, n_chars):
out, n = [], 0
while n < n_chars:
w = rng.choice(WORDS)
if rng.random() < 0.08: # numbers and odd tokens
w = f"{rng.randint(0, 99999)}{rng.choice(['ms', '%', 'x', '.0'])}"
out.append(w); n += len(w) + 1
return " ".join(out)
def get_tokenizer():
global _TOK
if _TOK is None:
from tokenizers import Tokenizer, models, trainers, pre_tokenizers
tok = Tokenizer(models.BPE(unk_token="[UNK]"))
tok.pre_tokenizer = pre_tokenizers.ByteLevel(add_prefix_space=False)
rng = random.Random(0)
corpus = [make_text(rng, 400) for _ in range(3000)]
tok.train_from_iterator(corpus, trainers.BpeTrainer(vocab_size=4096, show_progress=False))
_TOK = tok
return _TOK
def tokenize(text): # also the worker entry point
return get_tokenizer().encode(text).ids
# ---------------------------------------------------------------- model
D, L, FF = 128, 2, 512
MAXLEN = 2048 + 640
CAUSAL = np.triu(np.full((MAXLEN, MAXLEN), -1e9, np.float32), k=1) # built once
class Model:
def __init__(self, seed=0):
r = np.random.default_rng(seed)
s = 1 / np.sqrt(D)
self.Wqkv = [r.standard_normal((D, 3 * D), dtype=np.float32) * s for _ in range(L)]
self.Wo = [r.standard_normal((D, D), dtype=np.float32) * s for _ in range(L)]
self.W1 = [r.standard_normal((D, FF), dtype=np.float32) * s for _ in range(L)]
self.W2 = [r.standard_normal((FF, D), dtype=np.float32) / np.sqrt(FF) for _ in range(L)]
self.emb = r.standard_normal((4096, D), dtype=np.float32) * 0.1
def _layer(self, l, x, kv_list, positions):
"""x: (n, D) rows; kv_list[i] = (K, V, length) arrays this row attends over."""
qkv = x @ self.Wqkv[l]
q, k, v = qkv[:, :D], qkv[:, D:2 * D], qkv[:, 2 * D:]
att = np.empty_like(q)
for i, (K, V, end) in enumerate(kv_list):
K[l, positions[i]] = k[i]; V[l, positions[i]] = v[i]
Kl, Vl = K[l, :end], V[l, :end]
sc = Kl @ q[i] * (1 / np.sqrt(D))
sc = np.exp(sc - sc.max()); att[i] = (sc / sc.sum()) @ Vl
x = x + att @ self.Wo[l]
return x + np.maximum(x @ self.W1[l], 0) @ self.W2[l]
def forward(self, tok_ids, kv_list, positions):
x = self.emb[np.asarray(tok_ids) % 4096]
for l in range(L):
x = self._layer(l, x, kv_list, positions)
return np.abs(x[:, :8].sum(1) * 1000).astype(np.int64) % 4096
def forward_prefill(self, ids, K, V, start):
"""One chunk of one prompt: dense causal attention over the prefix."""
x = self.emb[np.asarray(ids) % 4096]; n = len(ids); end = start + n
mask = CAUSAL[start:end, :end]
for l in range(L):
qkv = x @ self.Wqkv[l]
K[l, start:end] = qkv[:, D:2 * D]; V[l, start:end] = qkv[:, 2 * D:]
sc = qkv[:, :D] @ K[l, :end].T
sc *= 1 / np.sqrt(D); sc += mask
sc -= sc.max(1, keepdims=True); np.exp(sc, out=sc); sc /= sc.sum(1, keepdims=True)
x = x + (sc @ V[l, :end]) @ self.Wo[l]
x = x + np.maximum(x @ self.W1[l], 0) @ self.W2[l]
def forward_eager(self, tok_ids, kv_list, positions):
"""No captured graph: every sequence is its own small launch."""
return np.concatenate([self.forward([t], [kv], [p])
for t, kv, p in zip(tok_ids, kv_list, positions)])
# ---------------------------------------------------------------- requests
@dataclass(eq=False)
class Logprob: # like an OpenAI-style top-k logprob entry
logprob: float; rank: int; decoded: str = None
@dataclass(eq=False)
class TokenEvent: # per-token record kept for streaming/metrics
req: "Request"; tid: int; t: float; logprobs: dict
@dataclass(eq=False)
class Request:
rid: int; arrival: float; text: str; max_new: int
prompt: list = None
computed: int = 0 # tokens whose KV is materialised
out: list = field(default_factory=list)
emit_t: list = field(default_factory=list)
emit_step: list = field(default_factory=list)
K: np.ndarray = None; V: np.ndarray = None
swapped: tuple = None
first_token_t: float = None
evictions: list = field(default_factory=list) # [t_evicted, t_readmitted] pairs, explicit
@property
def total_len(self): return len(self.prompt) + len(self.out)
def blocks_needed(self, n): return -(-n // BLOCK)
BLOCK = 16
# ---------------------------------------------------------------- engine
@dataclass
class Config:
name: str = "baseline"
max_num_seqs: int = 48
token_budget: int = 2048 # max_num_batched_tokens
capture_sizes: tuple = (1, 2, 4, 8, 16, 24, 32)
kv_blocks: int = 1000
admit_watermark: float = 0.0 # fraction of blocks kept free before admitting
gc_freeze: bool = False
async_tokenize: bool = False
compact_history: bool = False # per-token records in a flat array, not objects
max_model_len: int = 2048
class Engine:
def __init__(self, cfg, model, trace):
self.cfg, self.m, self.trace = cfg, model, trace
self.free_blocks = cfg.kv_blocks
self.waiting, self.running, self.swapped, self.done = [], [], [], []
self.steps = [] # one dict per step: the tags
self.gc_log = []
self.pool = ProcessPoolExecutor(1, initializer=get_tokenizer) if cfg.async_tokenize else None
self.pending_tok = []
self.history = [] # all TokenEvents: long-lived heap, like a metrics store
self.flat = array("d") # the same data, invisible to the GC
gc.callbacks.append(self._gc_cb)
def _gc_cb(self, phase, info):
if phase == "start": self._gc_t0 = time.perf_counter()
else: self.gc_log.append((self._gc_t0, time.perf_counter(), info["generation"]))
# ---- KV accounting
def _alloc(self, r, new_len):
need = r.blocks_needed(new_len) - r.blocks_needed(r.computed)
if need > self.free_blocks: return False
self.free_blocks -= need
if r.K is None or r.K.shape[1] < new_len:
cap = min(self.cfg.max_model_len + 1024, max(new_len, 256) * 2)
K = np.zeros((L, cap, D), np.float32); V = np.zeros_like(K)
if r.K is not None: K[:, :r.computed] = r.K[:, :r.computed]; V[:, :r.computed] = r.V[:, :r.computed]
r.K, r.V = K, V
return True
def _free(self, r):
self.free_blocks += r.blocks_needed(r.computed)
# ---- one engine step
def step(self, now0):
tag = {"seg": [], "t0": now0, "tok_ms": 0.0, "prefill_ms": 0.0, "swap_ms": 0.0,
"decode_ms": 0.0, "n_decode": 0, "n_prefill_tok": 0, "graph": None,
"preempted": 0, "swapped_in": 0}
cfg = self.cfg
# 1. intake: arrivals become waiting requests (tokenizer runs here)
while self.trace and self.trace[0].arrival <= now0:
r = self.trace.pop(0)
if self.pool:
self.pending_tok.append((r, self.pool.submit(tokenize, r.text)))
else:
t = time.perf_counter()
r.prompt = tokenize(r.text)[: cfg.max_model_len]
tag["tok_ms"] += (time.perf_counter() - t) * 1e3
tag["seg"].append(("tok", t, time.perf_counter()))
self.waiting.append(r)
for item in [p for p in self.pending_tok if p[1].done()]:
item[0].prompt = item[1].result()[: cfg.max_model_len]
self.waiting.append(item[0]); self.pending_tok.remove(item)
# 2. swap-in preempted requests if room (they go first: FCFS)
t = time.perf_counter()
while self.swapped and len(self.running) < cfg.max_num_seqs:
r = self.swapped[0]
if r.blocks_needed(r.computed + 1) + 8 > self.free_blocks: break
self.swapped.pop(0)
Kh, Vh = r.swapped
r.K = np.zeros((L, Kh.shape[1] * 2, D), np.float32); r.V = np.zeros_like(r.K)
r.K[:, :r.computed] = Kh; r.V[:, :r.computed] = Vh
r.swapped = None
self.free_blocks -= r.blocks_needed(r.computed)
r.evictions[-1][1] = time.perf_counter() # readmitted
self.running.append(r); tag["swapped_in"] += 1
tag["swap_ms"] += (time.perf_counter() - t) * 1e3
tag["seg"].append(("swap", t, time.perf_counter()))
# 3. decodes first: every running request that has finished prefill
decodes = [r for r in self.running if r.computed >= len(r.prompt)]
t = time.perf_counter()
for r in list(decodes):
if r not in decodes: continue # already preempted as someone's victim
while not self._alloc(r, r.computed + 1) and self.running:
victim = self.running[-1] # newest running request
self._preempt(victim); tag["preempted"] += 1
if victim in decodes: decodes.remove(victim)
if victim is r: break
tag["swap_ms"] += (time.perf_counter() - t) * 1e3
tag["seg"].append(("swap", t, time.perf_counter()))
# 4. leftover budget goes to prefill chunks (running partials, then waiting)
budget = cfg.token_budget - len(decodes)
chunks = []
for r in [r for r in self.running if r.computed < len(r.prompt)]:
n = min(budget, len(r.prompt) - r.computed)
if n > 0 and self._alloc(r, r.computed + n): chunks.append((r, n)); budget -= n
while self.waiting and budget > 0 and len(self.running) < cfg.max_num_seqs:
r = self.waiting[0]
reserve = cfg.admit_watermark * cfg.kv_blocks
if self.free_blocks - r.blocks_needed(len(r.prompt)) < reserve: break
n = min(budget, len(r.prompt))
if not self._alloc(r, n): break
self.waiting.pop(0); self.running.append(r); chunks.append((r, n)); budget -= n
# 5. execute prefill chunks
t = time.perf_counter()
for r, n in chunks:
ids = r.prompt[r.computed: r.computed + n]
self.m.forward_prefill(ids, r.K, r.V, r.computed)
r.computed += n
tag["n_prefill_tok"] += n
tag["prefill_ms"] = (time.perf_counter() - t) * 1e3
tag["seg"].append(("prefill", t, time.perf_counter()))
# 6. execute decodes: captured fast path or eager
if decodes:
B = len(decodes)
i = bisect.bisect_left(cfg.capture_sizes, B)
graph = cfg.capture_sizes[i] if i < len(cfg.capture_sizes) else None
ids = [(r.out[-1] if r.out else r.prompt[-1]) for r in decodes]
kvs = [(r.K, r.V, r.computed + 1) for r in decodes]
pos = [r.computed for r in decodes]
t = time.perf_counter()
if graph is not None:
pad = graph - B # padded rows: real work, discarded
toks = self.m.forward(ids + ids[:1] * pad, kvs + kvs[:1] * pad, pos + pos[:1] * pad)[:B]
else:
toks = self.m.forward_eager(ids, kvs, pos)
tag["decode_ms"] = (time.perf_counter() - t) * 1e3
tag["seg"].append(("decode", t, time.perf_counter()))
tag["graph"] = graph if graph is not None else "eager"
tag["n_decode"] = B
now = time.perf_counter()
sidx = len(self.steps)
for r, tk in zip(decodes, toks):
r.computed += 1; r.out.append(int(tk))
r.emit_t.append(now); r.emit_step.append(sidx)
if r.first_token_t is None: r.first_token_t = now
tk = int(tk)
if cfg.compact_history:
self.flat.extend((r.rid, tk, now, -0.1, -1.1, -2.1, -3.1, -4.1))
else:
ev = TokenEvent(r, tk, now, {tk + j: Logprob(-0.1 - j, j + 1) for j in range(5)})
self.history.append(ev)
if len(r.out) >= r.max_new:
self.running.remove(r); self._free(r); r.K = r.V = None
self.done.append(r)
tag["t1"] = time.perf_counter()
if tag["seg"] or decodes or chunks: # don't log idle spins
tag["seg"] = tuple(tag["seg"])
self.steps.append(tag)
def _preempt(self, r):
self.running.remove(r)
if r.computed < len(r.prompt): # mid-prefill: just restart it
self._free(r); r.computed = 0; r.K = r.V = None; self.waiting.insert(0, r); return
r.evictions.append([time.perf_counter(), None]) # evicted (before the copy-out)
r.swapped = (r.K[:, :r.computed].copy(), r.V[:, :r.computed].copy())
r.K = r.V = None
self._free(r); self.swapped.append(r)
def run(self):
start = time.perf_counter()
for r in self.trace: r.arrival += start
if self.cfg.gc_freeze:
gc.collect(); gc.freeze()
while self.trace or self.waiting or self.running or self.swapped or self.pending_tok:
now = time.perf_counter()
if not (self.waiting or self.running or self.swapped):
if self.pending_tok: # only waiting on the tokenizer worker
time.sleep(0.0005)
elif self.trace[0].arrival > now:
time.sleep(self.trace[0].arrival - now); continue
self.step(now)
gc.callbacks.remove(self._gc_cb)
if self.pool: self.pool.shutdown()
if self.cfg.gc_freeze: gc.unfreeze()
return start
# ---------------------------------------------------------------- workload
def make_trace(seed=1, duration=40.0, rate=6.0):
rng = random.Random(seed)
t, rid, out = 0.0, 0, []
while t < duration:
# non-homogeneous Poisson (thinning): traffic swells and ebbs on a 15 s cycle
t += rng.expovariate(rate * 1.6)
if rng.random() > (1 + 0.6 * np.sin(2 * np.pi * t / 15)) / 1.6: continue
if rng.random() < 0.01: # someone pastes a whole document
n_chars = rng.randint(150_000, 400_000)
else:
n_chars = int(rng.lognormvariate(6.9, 0.6)) # ~1k chars median
out.append(Request(rid, t, make_text(rng, n_chars), max_new=min(1000, int(rng.expovariate(1 / 280)) + 16)))
rid += 1
return out
def startup_heap():
"""What a real server drags around: configs, vocab maps, registries."""
return [{"id": i, "name": f"obj{i}", "meta": [i, str(i)]} for i in range(400_000)]
attribution.py — the exclusive gap partitioner
"""Exclusive, additive partition of each inter-token gap.
Every millisecond of a gap [t0, t1] goes to exactly one label:
preempt the request was evicted (explicit eviction -> readmission events),
or the step was copying KV out/in for someone's preemption
gc a garbage-collection pause (overrides whatever segment it landed in)
prefill prefill chunks executing in the step
tok tokenizer running on the engine loop
graph decode time above what a captured (batched) step of that size costs
kernel the rest of the decode forward pass
residual time covered by none of the above (loop bookkeeping, emission, OS)
While a request is evicted, the engine's activity in that window is recorded
separately as `context` -- it explains why readmission took as long as it did,
but it is not added to the gap a second time.
"""
import bisect
import numpy as np
CAUSES = ["prefill", "preempt", "graph", "gc", "tok"]
LABELS = CAUSES + ["kernel", "residual"]
SEG_LABEL = {"tok": "tok", "swap": "preempt", "prefill": "prefill", "decode": "decode"}
class GCIndex:
"""Sorted, non-overlapping GC pauses with fast overlap queries."""
def __init__(self, gcs):
g = sorted((float(a), float(b)) for a, b in gcs)
self.a = [x for x, _ in g]
self.b = [y for _, y in g]
def overlap(self, x, y):
if y <= x or not self.a: return 0.0
i = max(0, bisect.bisect_left(self.b, x)) # first pause ending after x
tot = 0.0
while i < len(self.a) and self.a[i] < y:
tot += max(0.0, min(self.b[i], y) - max(self.a[i], x)); i += 1
return tot
def decode_net_ms(step, gci):
"""Decode segment duration with any GC inside it removed (ms)."""
tot = 0.0
for name, x, y in step["seg"]:
if name == "decode": tot += (y - x) - gci.overlap(x, y)
return tot * 1e3
def fit_baseline(steps, gci):
"""GC-free decode ms vs padded batch size, fit on captured-path steps only."""
pts = [(s["graph"], decode_net_ms(s, gci)) for s in steps if isinstance(s["graph"], (int, np.integer))]
xs, ys = zip(*pts)
return np.polyfit(xs, ys, 1)
def _subtract(t0, t1, holes):
"""[t0, t1] minus a list of intervals -> list of live windows."""
out, cur = [], t0
for x, y in sorted(holes):
x, y = max(x, t0), min(y, t1)
if y <= x: continue
if x > cur: out.append((cur, x))
cur = max(cur, y)
if cur < t1: out.append((cur, t1))
return out
class Partitioner:
def __init__(self, steps, gcs, baseline=None):
self.steps = steps
self.t0s = [s["t0"] for s in steps]
self.gci = GCIndex(gcs)
self.slope, self.icpt = baseline if baseline is not None else fit_baseline(steps, self.gci)
self._dnet = {}
def _steps_overlapping(self, x, y):
i = max(0, bisect.bisect_right(self.t0s, x) - 1)
while i < len(self.steps) and self.steps[i]["t0"] < y:
if self.steps[i]["t1"] > x: yield i, self.steps[i]
i += 1
def _graph_fraction(self, i, st):
"""Share of this step's (GC-free) decode time that is graph-miss excess."""
if st["graph"] != "eager": return 0.0
if i not in self._dnet: self._dnet[i] = decode_net_ms(st, self.gci)
full = self._dnet[i]
if full <= 0: return 0.0
base = self.slope * st["n_decode"] + self.icpt
return max(0.0, full - base) / full
def _charge(self, x, y, acc):
"""Charge window [x, y] (s) segment-by-segment into acc (ms). Returns covered ms."""
gc = self.gci.overlap(x, y)
acc["gc"] += gc * 1e3
covered = gc
for i, st in self._steps_overlapping(x, y):
for name, a, b in st["seg"]:
a, b = max(a, x), min(b, y)
if b <= a: continue
net = (b - a) - self.gci.overlap(a, b)
covered += net
lab = SEG_LABEL[name]
if lab == "decode":
f = self._graph_fraction(i, st)
acc["graph"] += net * f * 1e3
acc["kernel"] += net * (1 - f) * 1e3
else:
acc[lab] += net * 1e3
return covered * 1e3
def gap(self, t0, t1, evictions=()):
"""Partition one gap. Returns (parts, context): parts sum exactly to the gap."""
parts = {k: 0.0 for k in LABELS}
context = {k: 0.0 for k in LABELS}
ev = [(a, b if b is not None else t1) for a, b in evictions if a < t1 and (b is None or b > t0)]
for a, b in ev: # evicted: all of it is preemption
a, b = max(a, t0), min(b, t1)
if b > a:
parts["preempt"] += (b - a) * 1e3
cov = self._charge(a, b, context) # what the engine was doing meanwhile
context["residual"] += (b - a) * 1e3 - cov
for a, b in _subtract(t0, t1, ev): # live: charge what actually ran
cov = self._charge(a, b, parts)
parts["residual"] += (b - a) * 1e3 - cov
return parts, context
def label(gap, parts, floor_ms=1.0, frac=0.25):
k = max(CAUSES, key=parts.get)
return k if parts[k] >= floor_ms and parts[k] >= frac * gap else "clean"
test_attribution.py — unit tests, including both reported bugs
import math
from attribution import Partitioner, LABELS
def st(t0, t1, segs, graph=16, n=1):
return {"t0": t0, "t1": t1, "seg": tuple(segs), "graph": graph, "n_decode": n}
def close(a, b, tol=1e-6): return math.isclose(a, b, abs_tol=tol)
def total(p): return sum(p[k] for k in LABELS)
def test_reviewer_example_1_eviction_not_double_counted():
# 40 ms gap: evicted 0-30 ms while OTHER requests' prefill ran, then a 10 ms decode.
steps = [st(0.000, 0.030, [("prefill", 0.000, 0.030)], graph=None, n=0),
st(0.030, 0.040, [("decode", 0.030, 0.040)])]
p, ctx = Partitioner(steps, [], baseline=(0.0, 10.0)).gap(0.0, 0.040, evictions=[(0.0, 0.030)])
assert close(p["preempt"], 30) and close(p["kernel"], 10) and close(p["prefill"], 0)
assert close(total(p), 40)
assert close(ctx["prefill"], 30) # engine activity during eviction: recorded, not added
def test_reviewer_example_2_gc_does_not_inflate_graph_excess():
# eager decode segment of 30 ms = 10 ms work + 20 ms GC; captured baseline for B=1 is 10 ms.
steps = [st(0.000, 0.030, [("decode", 0.000, 0.030)], graph="eager", n=1)]
p, _ = Partitioner(steps, [(0.005, 0.025)], baseline=(0.0, 10.0)).gap(0.0, 0.030)
assert close(p["gc"], 20) and close(p["graph"], 0) and close(p["kernel"], 10)
assert close(total(p), 30)
def test_real_graph_excess_survives_gc_removal():
# eager decode 40 ms = 30 ms work + 10 ms GC; baseline 10 ms -> excess 20 ms
steps = [st(0.000, 0.040, [("decode", 0.000, 0.040)], graph="eager", n=1)]
p, _ = Partitioner(steps, [(0.010, 0.020)], baseline=(0.0, 10.0)).gap(0.0, 0.040)
assert close(p["gc"], 10) and close(p["graph"], 20) and close(p["kernel"], 10)
def test_partial_overlap_with_gap_is_proportional():
# gap covers only the second half of an eager 40 ms decode (baseline 10 -> 75% excess)
steps = [st(0.000, 0.040, [("decode", 0.000, 0.040)], graph="eager", n=1)]
p, _ = Partitioner(steps, [], baseline=(0.0, 10.0)).gap(0.020, 0.040)
assert close(p["graph"], 15) and close(p["kernel"], 5) and close(total(p), 20)
def test_gc_after_emission_and_residual_reconcile():
# emission at 10 ms, GC 12-40 ms outside any segment, next decode 40-50 ms
steps = [st(0.000, 0.045, [("decode", 0.000, 0.010)]),
st(0.045, 0.050, [("decode", 0.045, 0.050)])]
p, _ = Partitioner(steps, [(0.012, 0.040)], baseline=(0.0, 5.0)).gap(0.010, 0.050)
assert close(p["gc"], 28) and close(p["kernel"], 5) and close(p["residual"], 7)
assert close(total(p), 40)
def test_mixed_step_prefill_tok_swap_and_decode():
steps = [st(0.0, 0.050, [("tok", 0.000, 0.005), ("swap", 0.005, 0.007),
("prefill", 0.007, 0.040), ("decode", 0.040, 0.048)])]
p, _ = Partitioner(steps, [], baseline=(0.0, 8.0)).gap(0.0, 0.050)
assert close(p["tok"], 5) and close(p["preempt"], 2) and close(p["prefill"], 33)
assert close(p["kernel"], 8) and close(p["residual"], 2) and close(total(p), 50)
if __name__ == "__main__":
import sys
fails = 0
for name, fn in list(globals().items()):
if name.startswith("test_"):
try: fn(); print("PASS", name)
except AssertionError: fails += 1; print("FAIL", name)
sys.exit(fails)
run.py — runs one rung and dumps raw timing logs
"""Run the nano-engine under one rung of the fix ladder and dump raw timing logs.
python3 run.py "<rung>" <seed> <duration_s> -> raw/<rung-slug>__s<seed>.npz
Everything reported in the article is recomputed from these files by analyze.py.
All timestamps are seconds relative to engine start (time.perf_counter()).
"""
import sys, os, re, json, time
import numpy as np
import engine as E
LADDER = [
("baseline", dict()),
("+gc.freeze", dict(gc_freeze=True)),
("+compact history", dict(compact_history=True)),
("+graphs to 48", dict(capture_sizes=(1, 2, 4, 8, 16, 24, 32, 40, 48))),
("+budget 256", dict(token_budget=256)),
("+tokenize off-loop", dict(async_tokenize=True)),
("+admit watermark", dict(admit_watermark=0.10)),
]
CONFIGS, _acc = {}, {}
for _name, _delta in LADDER: # each rung keeps every fix above it
_acc = {**_acc, **_delta}; CONFIGS[_name] = dict(_acc)
RATE = float(os.environ.get("ITL_RATE", "10.0"))
SEG_CODE = {"tok": 0, "swap": 1, "prefill": 2, "decode": 3}
def slug(name): return re.sub(r"[^a-z0-9]+", "-", name.lower()).strip("-")
def run(name, seed, duration):
cfg = E.Config(name=name, **CONFIGS[name])
E.get_tokenizer()
heap = E.startup_heap() # stays alive for the run, like a real server's
trace = E.make_trace(seed=seed, duration=duration, rate=RATE)
tr = np.array([(r.rid, r.arrival, len(r.text), r.max_new) for r in trace])
eng = E.Engine(cfg, E.Model(), trace)
w0 = time.perf_counter()
start = eng.run()
wall = time.perf_counter() - w0
T = lambda t: t - start
st = eng.steps
steps = np.array([(T(s["t0"]), T(s["t1"]), s["n_decode"], s["n_prefill_tok"],
-1 if s["graph"] is None else (0 if s["graph"] == "eager" else s["graph"]),
s["preempted"], s["swapped_in"]) for s in st])
segs = np.array([(i, SEG_CODE[n], T(a), T(b)) for i, s in enumerate(st) for n, a, b in s["seg"]])
gcs = np.array([(T(a), T(b), g) for a, b, g in eng.gc_log]).reshape(-1, 3)
emis = np.array([(r.rid, T(t), k) for r in eng.done for t, k in zip(r.emit_t, r.emit_step)])
evs = np.array([(r.rid, T(a), T(b) if b is not None else np.nan) for r in eng.done for a, b in r.evictions]).reshape(-1, 3)
reqs = np.array([(r.rid, T(r.arrival), len(r.prompt), r.max_new, T(r.first_token_t)) for r in eng.done])
os.makedirs("raw", exist_ok=True)
path = f"raw/{slug(name)}__s{seed}.npz"
np.savez_compressed(path, steps=steps, segs=segs, gcs=gcs, emissions=emis, evictions=evs,
requests=reqs, trace=tr, wall=wall,
config=json.dumps({"rung": name, "seed": seed, "duration": duration,
"rate": RATE, **{k: v for k, v in vars(cfg).items()}}, default=str))
del heap
return path
if __name__ == "__main__":
print(run(sys.argv[1], int(sys.argv[2]), float(sys.argv[3])))
analyze.py — recomputes every number from the raw logs
"""Recompute every reported number from raw/*.npz.
python3 analyze.py raw/*.npz > results.jsonl
"""
import sys, json
import numpy as np
from attribution import Partitioner, LABELS, CAUSES, label
SEG_NAME = {0: "tok", 1: "swap", 2: "prefill", 3: "decode"}
BINS = [0, 5, 10, 15, 20, 30, 50, 80, 120, 200, 400, 800, 1e9]
def load(path):
z = np.load(path, allow_pickle=False)
cfg = json.loads(str(z["config"]))
steps = []
for t0, t1, nd, npf, g, pre, swi in z["steps"]:
g = int(g)
steps.append({"t0": t0, "t1": t1, "n_decode": int(nd), "n_prefill_tok": int(npf),
"graph": None if g == -1 else ("eager" if g == 0 else g),
"preempted": int(pre), "seg": []})
for i, c, a, b in z["segs"]:
steps[int(i)]["seg"].append((SEG_NAME[int(c)], a, b))
for s in steps: s["seg"] = tuple(s["seg"])
return z, cfg, steps
def analyze(path):
z, cfg, steps = load(path)
first_t0 = steps[0]["t0"]
gcs_all = z["gcs"]
startup_gc = [g for g in gcs_all if g[1] <= first_t0] # e.g. gc.collect() before freeze
serving_gc = [g for g in gcs_all if g[1] > first_t0]
P = Partitioner(steps, [(a, b) for a, b, _ in gcs_all])
emis, evs = z["emissions"], z["evictions"]
ev_by = {}
for rid, a, b in evs: ev_by.setdefault(int(rid), []).append((a, None if np.isnan(b) else b))
by_req = {}
for rid, t, k in emis: by_req.setdefault(int(rid), []).append((t, int(k)))
gaps, parts, labs, ctx_tot = [], [], [], {k: 0.0 for k in LABELS}
worst_err, skipped_unexplained = 0.0, 0
for rid, em in by_req.items():
ev = ev_by.get(rid, [])
for (ta, ka), (tb, kb) in zip(em, em[1:]):
p, ctx = P.gap(ta, tb, ev)
g = (tb - ta) * 1e3
worst_err = max(worst_err, abs(sum(p.values()) - g))
if kb > ka + 1 and not any(a < tb and (b is None or b > ta) for a, b in ev):
skipped_unexplained += 1
for k in LABELS: ctx_tot[k] += ctx[k]
gaps.append(g); parts.append(p); labs.append(label(g, p))
gaps = np.array(gaps)
p50, p90, p99, p999 = np.percentile(gaps, [50, 90, 99, 99.9])
tail = gaps >= p99
tail_ms = gaps[tail].sum()
share = {k: float(sum(p[k] for p, t in zip(parts, tail) if t) / tail_ms) for k in LABELS}
share_all = {k: float(sum(p[k] for p in parts) / gaps.sum()) for k in LABELS}
kshare = np.array([p["kernel"] / g for p, g in zip(parts, gaps)])
clean = np.array([l == "clean" for l in labs])
req = z["requests"]
ttft = (req[:, 4] - req[:, 1]) * 1e3
n_tok = len(emis)
hist = []
for lo, hi in zip(BINS[:-1], BINS[1:]):
sel = [l for g, l in zip(gaps, labs) if lo <= g < hi]
hist.append({"lo": lo, "hi": hi, "n": len(sel), **{k: sel.count(k) for k in CAUSES + ["clean"]}})
st = z["steps"]
return {
"rung": cfg["rung"], "seed": cfg["seed"], "duration": cfg["duration"],
"requests": int(len(req)), "tokens": int(n_tok), "gaps": int(len(gaps)),
"tok_per_s": n_tok / float(z["wall"]),
"itl_p50": p50, "itl_p90": p90, "itl_p99": p99, "itl_p999": p999, "itl_max": float(gaps.max()),
"ttft_p50": float(np.percentile(ttft, 50)), "ttft_p99": float(np.percentile(ttft, 99)),
"tail_share": share, "all_share": share_all,
"tail_count": {k: int(sum(1 for l, t in zip(labs, tail) if t and l == k)) for k in CAUSES + ["clean"]},
"fwd_share_clean_median": float(np.median(kshare[clean])),
"fwd_share_tail_median": float(np.median(kshare[tail])),
"evicted_context_ms": ctx_tot,
"reconcile_max_err_ms": worst_err, "skipped_steps_without_eviction": skipped_unexplained,
"preemptions": int(st[:, 5].sum()), "eager_steps": int((st[:, 4] == 0).sum()),
"max_decode_B": int(st[:, 2].max()),
"gen2_serving_ms": [round((b - a) * 1e3, 1) for a, b, g in serving_gc if g == 2],
"gen2_startup_ms": [round((b - a) * 1e3, 1) for a, b, g in startup_gc if g == 2],
"gc_counts": {int(g): int((gcs_all[:, 2] == g).sum()) for g in (0, 1, 2)},
"hist": hist,
}
if __name__ == "__main__":
for path in sys.argv[1:]:
print(json.dumps(analyze(path), default=float), flush=True)
Top comments (0)