Skip to content

[Observability] Add opt-in spans for the colocate offload/onload boundary - #443

Draft
0z5a wants to merge 6 commits into
vllm-project:0z5a-branchfrom
0z5a:obs/colocate-offload-spans
Draft

0z5a wants to merge 6 commits into
vllm-project:0z5a-branchfrom
0z5a:obs/colocate-offload-spans

Conversation

@0z5a

@0z5a 0z5a commented Sep 19, 2026 •

Copy link
Copy Markdown

Incremental review: Files changed.

Base: 0z5a-branch at 791f101e20db377b28e15f12a00863baaea2605f.

Purpose

Colocated training currently reports only aggregate Actor.sleep() and Actor.wake_up() times. This change exposes which operations consume that time: memory-saver pause/resume, memory cleanup, process-group teardown/reload, model switching and diagnostic calls.

VIME_OFFLOAD_SPANS=1 enables wall-time spans and one summary per call. The default path skips the extra clock reads and emits nothing. Nested spans retain inclusive child/parent totals, while accounted_s counts root intervals once. Training, tensor transfers and returned values retain their existing behavior.

The submitted diff contains two production files. Test harnesses, logs and their added CI registration were removed; their measured results are retained below.

Validation

  • 8 CPU tests pass: disabled-path clock/log behavior, repeated spans, nested accounting, dotted sibling names, exception unwinding, reset, rounding and output ordering.
  • RTX 5090 Qwen3-0.6B full training smokes cover vLLM rollout, reference/actor forwards, backward and optimizer, checkpoint saving and weight publication.
  • Three independent paired six-round runs compare the previous accounting implementation with this revision. Each arm starts in a fresh process; round zero is excluded. An additional enabled-span training round verifies the emitted ledger.
  • The implementation revision passed Buildkite #1323, DCO and documentation checks before artifact cleanup. The cleanup leaves production code byte-for-byte unchanged; its new head receives the normal automatic checks.

Measured results

Default-disabled spans, Qwen3-0.6B, two prompts × two samples, 16 response tokens maximum. Driver round time includes rollout, training, offload and weight publication.

Pair / order Parent median round (s) Candidate median round (s) Observed ratio
1 / parent → candidate 10.761 9.782 1.100×
2 / candidate → parent 11.836 11.300 1.047×
3 / parent → candidate 11.563 11.516 1.004×
Median paired ratio 1.047×

Generated response lengths vary between arms. These timings do not establish a causal training speedup from the accounting change. The CPU microbenchmark observes approximately 1.1 μs per disabled context-manager invocation; enabled nested accounting costs about 2% more than its previous implementation.

With spans enabled in a separate diagnostic round:

Call Total (s) Accounted (s) Residual (s) Largest segment
sleep 1.435661 1.435575 0.000087 TMS pause: 1.133446 s
wake_up 1.029749 1.029621 0.000128 TMS resume: 0.617490 s

A separate existing --no-offload-train configuration comparison observed a 4.345× median ratio. That result is not caused by the span patch. Multi-rank coverage remains outstanding.

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces an opt-in wall-clock span measurement utility (offload_spans) to profile the performance of the GPU offload and onload operations (sleep and wake_up) in colocate mode, along with corresponding unit tests and pipeline integration. The review feedback highlights two key improvement opportunities: first, resolving a calculation bug where nested spans are double-counted in the total accounted time, and second, refactoring the unit tests to use monkeypatch.setattr instead of importlib.reload to prevent potential state leakage and simplify the test setup.

Comment thread vime/observability/offload_spans.py Outdated
Comment on lines +75 to +78
# The recorded spans are disjoint segments of one call, so their sum is what
# the breakdown actually accounts for; the remainder is call overhead. Summing
# the rounded entries keeps `accounted_s` equal to the table next to it.
accounted = round(sum(entry["total_s"] for entry in payload.values()), 6)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

The current calculation of accounted_s sums all recorded spans. However, the module explicitly supports nested spans (as stated in the docstring and tested in test_parent_includes_children). If nested spans are used, summing all values will double-count the nested child spans, leading to an incorrect accounted_s (which can exceed total_s and result in a negative unaccounted_s).

To fix this, we should only sum the top-level (root) spans by filtering out any span that has a parent span in the payload.

    # Only sum top-level spans to avoid double-counting nested spans
    accounted = round(
        sum(
            entry["total_s"]
            for name, entry in payload.items()
            if not any(name.startswith(parent + ".") for parent in payload if parent != name)
        ),
        6,
    )

Comment on lines +24 to +36
@pytest.fixture(autouse=True)
def _restore_default_module():
"""Every case reloads the module; leave it as the rest of the suite found it."""
yield
importlib.reload(offload_spans)


def _module(monkeypatch, *, enabled: bool):
if enabled:
monkeypatch.setenv("VIME_OFFLOAD_SPANS", "1")
else:
monkeypatch.delenv("VIME_OFFLOAD_SPANS", raising=False)
return importlib.reload(offload_spans)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Reloading modules in tests using importlib.reload is generally an anti-pattern that can lead to subtle bugs and state leakage, especially when other modules import functions from it using from ... import ... (as those imports won't be updated by the reload).

Instead of reloading the module to toggle _ENABLED, we can use monkeypatch.setattr to dynamically set _ENABLED on the imported module. Since monkeypatch automatically restores the original value after each test, we can also completely remove the _restore_default_module fixture.

Suggested change
@pytest.fixture(autouse=True)
def _restore_default_module():
"""Every case reloads the module; leave it as the rest of the suite found it."""
yield
importlib.reload(offload_spans)
def _module(monkeypatch, *, enabled: bool):
if enabled:
monkeypatch.setenv("VIME_OFFLOAD_SPANS", "1")
else:
monkeypatch.delenv("VIME_OFFLOAD_SPANS", raising=False)
return importlib.reload(offload_spans)
def _module(monkeypatch, *, enabled: bool):
monkeypatch.setattr(offload_spans, "_ENABLED", enabled)
return offload_spans

In colocate mode every step hands the GPUs back and forth between Megatron and
vLLM, and Actor.sleep() / Actor.wake_up() sit on the critical path doing it.
Their @Timer totals are the largest single block of a small-model
short-response step, but they say nothing about where inside the two calls the
time goes: sleep() alone is clear_memory(clear_host_memory=True) +
destroy_process_groups() + torch_memory_saver.pause() + two print_memory()
calls, and those have very different fixes.

Add the breakdown, off by default behind VIME_OFFLOAD_SPANS=1:

* vime/observability/offload_spans.py accumulates perf_counter() deltas per span
  name and emits one line per sleep()/wake_up() call with the per-segment
  totals, the accounted share and the residual call overhead. Disabled it
  records nothing and emits nothing.
* Actor.sleep()/wake_up() wrap each step. The segments are disjoint, so their
  sum is directly comparable to the call's own total.

Measured on 1 GPU colocate, Qwen3-0.6B, rollout_batch_size 8 x n_samples 2,
cap 192, 8 rollouts: sleep median 11158 ms of which torch_memory_saver.pause()
is 9681 ms (86.8%); wake_up median 3772 ms of which resume() is 3173 ms (84.1%).
Process-group lifetime is not the cost (destroy 914 ms + reload 8 ms), and
print_memory is free (~5 ms across both calls). The transfer moves ~18.7 GB at
1.67 GB/s out and 4.56 GB/s back over a Gen4 x16 link, so the headroom is in
the transfer itself rather than in the code around it.

Signed-off-by: 0z5a <0z5a@users.noreply.github.com>
Signed-off-by: 0z5a <dezhen.lu@student.uni-tuebingen.de>
@0z5a
0z5a force-pushed the obs/colocate-offload-spans branch from 4bfd159 to 01dc1b7 Compare September 24, 2026 07:07
@0z5a
0z5a marked this pull request as draft September 27, 2026 00:31
Signed-off-by: 0z5a <0z5a@users.noreply.github.com>
Signed-off-by: 0z5a <0z5a@users.noreply.github.com>
Signed-off-by: 0z5a <0z5a@users.noreply.github.com>
@0z5a
0z5a marked this pull request as ready for review October 1, 2026 12:49
Signed-off-by: 0z5a <dezhen.lu@student.uni-tuebingen.de>
Signed-off-by: 0z5a <dezhen.lu@student.uni-tuebingen.de>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant