Skip to content

fix(data-plane): log single-controller metrics before the step is committed - #4044

Merged
terrykong merged 1 commit into
zhiyul/data_plane_observability_metricsfrom
zhiyul/fix/sc-data-plane-log-order
Sep 7, 2026
Merged

fix(data-plane): log single-controller metrics before the step is committed#4044
terrykong merged 1 commit into
zhiyul/data_plane_observability_metricsfrom
zhiyul/fix/sc-data-plane-log-order

Conversation

@ZhiyuLi-Nvidia

Copy link
Copy Markdown
Contributor

Fixes a silent metric loss on the async single-controller path, on top of #3616.

The bug

log_metrics(..., step_finished=True) calls run.log(..., commit=True), which
closes that wandb step. wandb accepts a later log against a closed step,
returns normally, and discards it — no exception, no falsy return.

single_controller.py called the data-plane logger immediately after that
commit:

self._logger.log_metrics(timing_metrics, ..., step_finished=True)  # closes step N
self._log_data_plane_metrics(total_time)                           # dropped

So every data_plane/* series on the async path was computed — snapshot
gathered, deltas taken, breakdown table built — and thrown away.

Why it went unnoticed

  • Silent by construction. No exception, nothing falsy to check. The only
    symptom is an empty chart.
  • stdout still looked healthy. The • data plane: …ms, … MB moved print
    lives inside the discarded call.
  • Invisible to unit tests. A fake logger records the call happily; the drop
    happens inside wandb.
  • The comment asserted the opposite. # step_finished=True here since this is the final log of our current step stopped being true when a log was added
    after it.

grpo_sync had the identical bug. It was caught only because a real GRPO run
showed 85 logged keys and zero data_plane/*, and was fixed there. This path
was never exercised by a run — its docstring says it mirrors grpo_sync, and
it mirrored this too.

The fix

Move one statement above the commit.

The test

Asserts the invariant for every algorithm module that logs data-plane
metrics, rather than for one call site — a third wiring would otherwise repeat
it. Source order is the only observable, since the drop happens inside wandb.

Two details worth review:

  • It compares the call site (rindex), not the first occurrence. The first
    occurrence is the method definition, which trivially precedes everything —
    my first draft of this test passed against the unfixed file.
  • Comment lines are stripped before searching, because the comments name
    step_finished=True too.

Verified by running the test's logic against both versions:

invariant holds
single_controller before fix ✗ (test fails, as intended)
single_controller after fix
grpo_sync

Base

Branched off zhiyul/data_plane_observability_metrics rather than main,
because _log_data_plane_metrics in single_controller.py only exists in
#3616. Against main this would show 51 commits / 66 files; against the
feature branch it is 2 files.

`log_metrics(..., step_finished=True)` calls `run.log(..., commit=True)`,
which closes that wandb step. wandb accepts a later log against a closed
step, returns normally, and discards it -- no exception, no falsy return.

`single_controller` called `_log_data_plane_metrics` immediately *after*
that commit, so every `data_plane/*` series it produced was computed and
dropped. The console still printed "data plane: ...ms" because that print
lives inside the discarded call, so the run looked healthy.

`grpo_sync` had the identical bug and was fixed when a real run showed 85
logged keys and zero `data_plane/*`. This path was never exercised by a run,
so it stayed broken -- its own docstring says it mirrors `grpo_sync`, and it
mirrored this too.

The test asserts the invariant across every algorithm module rather than one
call site, since a third wiring would otherwise repeat it. It compares the
*call* (rindex) rather than the first occurrence, which is the method
definition and would make the assertion vacuously true -- the first draft of
this test passed against the unfixed file.

Signed-off-by: Zhiyu Li <zhiyul@oci-aga-slurm-1-dm-02.cm.cluster>
@ZhiyuLi-Nvidia
ZhiyuLi-Nvidia requested review from a team as code owners September 7, 2026 21:26
@copy-pr-bot

copy-pr-bot Bot commented Sep 7, 2026

Copy link
Copy Markdown

This pull request requires additional validation before any workflows can run on NVIDIA's runners.

Pull request vetters can view their responsibilities here.

Contributors can view more details about this message here.

@ZhiyuLi-Nvidia ZhiyuLi-Nvidia added the CI:Lfast Runs a fast test suite and re-use nightly `main` container (but sync dependencies to PRs version) label Sep 7, 2026
@ZhiyuLi-Nvidia

Copy link
Copy Markdown
Contributor Author

/ok to test d6dbd00

@terrykong
terrykong merged commit 15a6c26 into zhiyul/data_plane_observability_metrics Sep 7, 2026
45 of 47 checks passed
@terrykong
terrykong deleted the zhiyul/fix/sc-data-plane-log-order branch September 7, 2026 22:42
ZhiyuLi-Nvidia added a commit that referenced this pull request Sep 8, 2026
…mitted (#4044)

Co-authored-by: Zhiyu Li <zhiyul@oci-aga-slurm-1-dm-02.cm.cluster>

Signed-off-by: Zhiyu Li <zhiyul@nvidia.com>
ZhiyuLi-Nvidia added a commit that referenced this pull request Sep 9, 2026
…mitted (#4044)

Co-authored-by: Zhiyu Li <zhiyul@oci-aga-slurm-1-dm-02.cm.cluster>

Signed-off-by: Zhiyu Li <zhiyul@nvidia.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

CI:Lfast Runs a fast test suite and re-use nightly `main` container (but sync dependencies to PRs version)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants