[Performance]: A gen2 GC collection during serving stalls one engine step for ~100 ms on v0.2.0

Proposal to improve performance

No response

Report of performance regression

No response

Misc discussion on performance

Summary

While measuring per-step latency on v0.2.0 with Huginn, I found that every serving run contains exactly one generation-2 garbage collection, and that it stalls the engine step it overlaps. Typical prelude, recurrent and coda steps take 4–7 ms; the prelude, recurrent or coda step that overlaps the gen2 collection takes 92–133 ms (one run's collection landed in a prefill step instead, see below).

How often: 10 runs, each with a fixed request trace at ~1 req/s (60 s warm-up, 300 s of arrivals, then drain; about 25,000 engine steps in the 300 s window). Each run had exactly one gen2 collection, 10 in total. All fell inside the window, 193–224 s after it started (steps 16,224–17,877 of 23,116–26,050). The warm-up phase had none.
How long: the gen2 pauses were 87–123 ms (median 96 ms). The ~365 gen0 and ~34 gen1 collections per run were each at most 2.6 ms.
Effect: in 5 of 10 runs the overlapped prelude/recurrent/coda step was longer than 100 ms (109–133 ms). In 4 runs it was 92–96 ms. In one run the collection landed in a prefill step (496 ms, where ~410 ms is normal). No prelude/recurrent/coda step longer than 100 ms occurred without a GC overlap.

run	arm	gen2 start, s into the 300 s window	formal step index (0-based)	pause (ms)	objects collected	overlapped stage	step duration (ms)
`run_01`	pinned	200.8	17,022 / 25,198	99	1172	recurrent	109
`run_02`	free	201.7	17,031 / 25,474	87	746	prelude	92
`run_03`	free	205.6	17,129 / 25,312	123	581	recurrent	133
`run_04`	pinned	206.6	17,077 / 25,006	90	952	coda	95
`run_05`	pinned	219.2	17,877 / 24,916	111	1265	prelude	116
`run_06`	free	223.7	17,228 / 23,116	106	813	prelude	112
`run_07`	free	199.3	17,134 / 26,050	93	828	prefill	496
`run_08`	pinned	193.2	16,224 / 25,420	87	840	prelude	92
`run_09`	pinned	198.0	17,014 / 26,026	90	646	coda	96
`run_10`	free	200.8	17,068 / 25,786	114	814	recurrent	122

The "arm" column is only relevant to the unrelated note below. The collection that overlaps a prefill step (run_07) is not counted as a stall.

With the streaming hook, one gen2 collection per run remains, and its allocation source is not yet isolated. My first hook kept one record per call and per step in memory. With that version, ten runs at the same rate gave about 3.4 prelude/recurrent/coda calls above 100 ms per run (34 formal calls over 10 runs, every one overlapping a GC; evidence/older_hook_22112/long_calls.csv). I redesigned the hook so that it streams every row to disk and retains nothing, and with it the count dropped to 0.5 per run (5 calls in 10 runs). The engine, torch, the driver and the hook itself (which still creates per-row dicts, CUDA events and closures, and briefly holds pending events) may all contribute to the heap that triggers it; I cannot tell them apart. I have not measured the object population directly (see the question below).

How it was measured

There are no source edits. The hook attaches at runtime and wraps engine._step, engine._schedule and engine.executor.submit (code/step_timer.py). A gc.callbacks entry records the start, stop, generation, collected and uncollectable fields of every collection into a ledger that is flushed to disk at step end. A step or call overlaps a GC if their intervals intersect. Step duration is the host wall time of engine._step. The hook also records gc.get_threshold(), gc.get_count() and gc.get_stats() at attach and close: the threshold was (700, 10, 10), the process-wide gen2 count went from 4 to 5 during each run, and gc.get_freeze_count() was already 375 at attach and unchanged at close. I do not know where those 375 objects were frozen. The ledger does not record the size of the tracked heap or its composition, only the collected count of each pass (581–1265 for the gen2 pass).

Questions

Should the engine call gc.freeze() after model load and warm-up (perhaps after a gc.collect()), or raise the gen2 threshold, as some Python serving stacks do? I would rather ask than assume that this is acceptable for the engine's lifetime.
Is there a known source of long-lived objects that keeps growing the tracked heap during serving? The gen2 collection appears at about the same point in every run (roughly two thirds through the window), which looks like a steady growth in the number of tracked objects rather than a one-off event. If it helps, I can add a type histogram from gc.get_objects() at attach and close.
I can test a patch. I have the rig above and can run it with gc.freeze() after warm-up, or with a changed threshold, and report the gen2 count, pause and the >100 ms call count.

Unrelated observation (not the main topic)

In the same ten runs, one of five unpinned runs (run_06) was about 3.1% slower per call than the other runs at the same (stage, batch size), and already 3.3% slower in the first half of the window. The pinned arm (CPUs 1–8, PYTHONHASHSEED=0) had no such run; the unpinned arm had default affinity and a random hash seed. End-to-end mean latency had a coefficient of variation of 2.2% in the pinned arm and 6.4% in the unpinned arm. With only five runs per arm, I do not draw an inference about pinning. In three further pinned runs of the same configuration, one was about 1.5% slower per call, so pinning does not prevent the effect. In the slow run the main thread stayed on one logical CPU for the whole window with no migration seen at 1 Hz sampling, and its CPU usage, involuntary context-switch rate (lower, not higher, than the others) and GPU SM clock did not stand out. I do not know the mechanism and I am not asking for action on it; I mention it only so it is not confused with the GC effect.

Separately, about 1.7% of prelude/recurrent/coda steps are more than 20% slower than the median for their stage and batch size, typically by about 3 ms. Almost all of the extra time (about 87%) is inside the host-side executor.submit call. Most of these slow steps occur alone rather than in runs, at no fixed period. They do not line up with GC, GPU clock, power, throttle flags or context-switch counts (sampled at 1 Hz), and the pinned runs have them as often as the unpinned ones.

I do not plan to dig into either of these two effects myself. If anyone familiar with the submit path or with process placement wants to look into them, I can share the per-call logs and run a patch or a profiling build on the same machine.

Configuration

item	value
backend	`vllm-rlt` `v0.2.0`, commit `c08b9d79834bb8b4ff283b15bae2c14c559f6b52`, no source edits
model	Huginn (`huginn-0125`), BF16, torch attention
execution	synchronous, single stream, eager, no CUDA graph
prompt / output	64 / 64 tokens
loops	first output at depth 8; 4 recurrent loops for each later output
scheduling	FCFS, up to 96 requests in flight
workload	one fixed request trace at ~1.05 req/s, 315 requests per run
run shape	60 s warm-up and drain, 300 s arrivals, drain; each run is a fresh process that reloads the weights
threads	`OMP_NUM_THREADS=MKL_NUM_THREADS=4`, `torch.get_num_threads()` = 4
run order	ten runs back to back, alternating pinned and unpinned in the order P F F P P F F P P F
observation	the streaming hook only; GC freeze not applied
other settings	other engine settings are available on request

Data and code

Attachment: issue_attachments.zip
SHA-256: 7d34b667a0396615077b17ec1a568ef58654da27bffd4d252eb90963e717b932

evidence/gc_events.csv: the ten gen2 collections in the table above.
evidence/runs.csv: per-run mean end-to-end latency, counts of calls above 100 ms, GC counts and pause totals, and the per-call latency offsets discussed above.
evidence/steps_run_03.csv: all engine steps in the measurement window for the run shown in the figure.
evidence/older_hook_22112/long_calls.csv: calls above 100 ms from the earlier hook that retained records in memory, including the 34 calls during the formal measurement windows.
evidence/README.md: CSV column definitions.
code/step_timer.py: the streaming timing hook used for the ten runs in the table. It requires the engine and a workload driver.
code/README.md: timing boundaries and hook behavior.

Raw per-call logs are available on request.

Your current environment (if you think it is necessary)

Environment

item	value
GPU	RTX 5090 × 1
CPU	Intel Xeon Platinum 8470Q, 208 logical CPUs
OS	Linux 5.15.0-119-generic
driver / CUDA	595.71.05 / 12.8
Python / PyTorch	3.12.3 / 2.8.0+cu128

Before submitting a new issue...

Make sure you already searched for relevant issues in the issue tracker, and looked for the answer in the documentation.

Interesting work, hope to see your code

I reproduced a steady-state GC pause with the attached step_timer.py and traced it to a reference cycle in the timing hook. The hook assigns timed_collect to ticket.collect. That closure holds the original bound collect method, which in turn holds the ticket. Completed submissions can therefore stay alive until cyclic GC runs.

The patch puts the timing wrapper on a separate object that delegates to the original ticket. The regression test disables automatic cyclic GC and uses a weak reference to check that a completed submission is released immediately. It fails with the original hook and passes with the patch.

I ran five trials on one RTX 5090 using main at a87f6c8, Huginn-0125 in BF16, and the Torch attention backend. I reconstructed a fixed request trace from the published workload settings. Each trial used 60 seconds of warm-up followed by 315 requests at approximately 1.05 requests/s, with 64 prompt tokens and 64 generated tokens per request.

Timing during the measurement window	gen2 GC pauses	Longest decode step	Decode-step p99
Original hook, two trials	74.4 ms, 77.2 ms	77.6 ms, 83.9 ms	6.60–6.63 ms
Patched hook, two trials	0	9.4 ms, 10.9 ms	6.60 ms
Lightweight step timing, one trial	0	8.9 ms	6.45 ms

Both patched trials still had a gen2 pause of about 69 ms during warm-up. The patch removed the steady-state spikes I reproduced, while decode-step p99 was essentially flat.

To try the patch, extract issue_attachments.zip and run the following from the extracted directory containing code/step_timer.py. The patch updates that script and adds the regression test alongside it.

git apply /path/to/issue-169-hook.patch
PYTHONPATH=code python -m pytest -q code/test_step_timer.py

Patch to save as issue-169-hook.patch

diff --git a/code/step_timer.py b/code/step_timer.py
index 2737a42..6a5983b 100644
--- a/code/step_timer.py
+++ b/code/step_timer.py
@@ -215,6 +215,14 @@ def gc_snapshot():
             "monotonic_ns": time.monotonic_ns()}
 
 
+class _TimedSubmission:
+    def __init__(self, ticket, collect):
+        self._ticket = ticket
+        self.collect = collect
+
+    def __getattr__(self, name):
+        return getattr(self._ticket, name)
+
 class StepTimer:
     """Capture nested schedule/runner/engine-step timing without forced waits.
 
@@ -476,7 +484,7 @@ class StepTimer:
                         self.current_step["collect_end_ns"] = c1
                     return result
 
-                ticket.collect = timed_collect
+                ticket = _TimedSubmission(ticket, timed_collect)
             else:
                 call["host_collect_ms"] = 0.0
                 call["host_ms"] = call["host_submit_ms"]
diff --git a/code/test_step_timer.py b/code/test_step_timer.py
new file mode 100644
index 0000000..c6c0043
--- /dev/null
+++ b/code/test_step_timer.py
@@ -0,0 +1,40 @@
+"""A completed timing sample must release its submission without cyclic GC."""
+
+import gc
+import weakref
+from types import SimpleNamespace
+
+from step_timer import StepTimer
+
+
+def test_collected_submission_is_released_without_cyclic_gc(tmp_path):
+    references = []
+
+    class Ticket:
+        has_result = True
+
+        def collect(self):
+            return 42
+
+    def submit(batch):
+        ticket = Ticket()
+        references.append(weakref.ref(ticket))
+        return ticket
+
+    batch = SimpleNamespace(requests=(), phase="coda", loop_count=0, num_tokens=0)
+    engine = SimpleNamespace(
+        model_runner=SimpleNamespace(core_stream=None, boundary_stream=None),
+        executor=SimpleNamespace(submit=submit),
+        _schedule=lambda: batch,
+    )
+    engine._step = lambda: engine.executor.submit(engine._schedule()).collect()
+    timer = StepTimer(engine, tmp_path).attach()
+    was_enabled = gc.isenabled()
+    gc.disable()
+    try:
+        assert engine._step() == 42
+        assert references[0]() is None
+    finally:
+        if was_enabled:
+            gc.enable()
+        timer.close()

@cecilsd

Thanks @cecilsd — you're right, and thanks for the careful diagnosis. The ticket.collect = timed_collect reference cycle is a bug in my timing hook, not in the engine, and your delegating wrapper plus the weakref regression test explain the steady-state numbers you saw.

One thing in your results is still unexplained: the ~69 ms gen2 collection during warm-up, which your patch does not remove. It happens before the measurement window, so it isn't caused by the hook's cycle and isn't covered by the same fix.

Could you please open a separate issue for it to track down where that warm-up heap comes from and discuss it with other contributors?

I'll keep this issue open until the follow-up is filed, then close it as a measurement artifact and link the two. Thanks, and apologies for the cycle in my hook : ).

Navigation Menu

Repository navigation

[Performance]: A gen2 GC collection during serving stalls one engine step for ~100 ms on v0.2.0 #169

Proposal to improve performance

Report of performance regression

Misc discussion on performance

Summary

How it was measured

Questions

Unrelated observation (not the main topic)

Your current environment (if you think it is necessary)

Before submitting a new issue...

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Performance]: A gen2 GC collection during serving stalls one engine step for ~100 ms on v0.2.0 #169

Description

Proposal to improve performance

Report of performance regression

Misc discussion on performance

Summary

How it was measured

Questions

Unrelated observation (not the main topic)

Your current environment (if you think it is necessary)

Before submitting a new issue...

Activity

0z5a commented on Nov 5, 2026

cecilsd commented on Nov 14, 2026

ycjcx123 commented on Nov 15, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions