Skip to content

[logging] Rollout time split + async-trainer GPU/phase/buffer observability#1900

Draft
eicherseiji wants to merge 2 commits into
NovaSky-AI:mainfrom
eicherseiji:seiji/rollout-llm-vs-env-time-metrics
Draft

[logging] Rollout time split + async-trainer GPU/phase/buffer observability#1900
eicherseiji wants to merge 2 commits into
NovaSky-AI:mainfrom
eicherseiji:seiji/rollout-llm-vs-env-time-metrics

Conversation

@eicherseiji

@eicherseiji eicherseiji commented Jul 14, 2026

Copy link
Copy Markdown
Contributor

What does this PR do?

Adds observability for the async RL trainer, motivated by a post-mortem where reconstructing where GPU time went required correlating Prometheus (GPU/disk, wall-clock keyed) against W&B (phase timings, step keyed) by hand — the two never joined. Four additions, each closing part of that gap.

1. Split rollout trajectory time into inference-engine wait vs env.step()

generate/trajectory_{llm,env}_time_{mean,p90,max} and generate/frac_time_in_env. Only the total per-trajectory time existed (trajectory_completion_time_*, #1804); it cannot tell an engine-bound rollout from an environment-bound one — the first question for multi-turn/agentic envs. Plumbed like the existing e2e_time (optional, omitted if any trajectory didn't record it). (Original scope of this PR.)

2. Fix: RayGpuMonitor was never running on the async trainer

RayGpuMonitor (#1712) is constructed in RayPPOTrainer.__init__ and flushed in the base loop, but FullyAsyncRayPPOTrainer overrides train() and never calls .start()/.flush()/.stop(). Net effect: async RL runs logged zero ray/ GPU keys despite enable_ray_gpu_monitor=True (default) — verified against real runs. Now started at loop entry, flushed per step into the committed payload, stopped in the finally.

3. skyrl_training_phase gauge → Prometheus (skyrl/train/utils/phase_metrics.py)

Emits the loop's current macro-phase (waiting_for_buffer/converting/training/weight_sync/eval/checkpoint, default generating) through ray.util.metrics, which Ray exports to the same Prometheus that scrapes node GPU metrics. That makes avg(ray_node_gpus_utilization) by (Phase) a single-store query instead of a manual cross-tracker correlation — and it still works after a cluster restart, when the tracker may be unreachable. Set at each existing Timer() boundary; best-effort (silently no-ops if Ray metrics are unavailable, so it never breaks training or tests).

4. Buffer run-ahead depth as a metric

async/gen_buffer_qsize + async/gen_buffer_maxsize, sampled at step start (previously only in a tqdm postfix). Distinguishes a throughput-limited generator (buffer low) from a gate-limited one (buffer at the staleness-bounded maxsize) — different fixes.

Scope note

Began as (1); (2)–(4) broaden it into a small async-observability PR — happy to split (2)–(4) into a follow-up if preferred. Deliberately not included: a skyrl_node_role{train|inference} gauge (inference node ids aren't cleanly reachable from the trainer) — noted as a follow-up.

Tests

  • tests/train/utils/test_phase_metrics.py (new): exactly-one-active-phase invariant, context-manager restore, no-op-when-Ray-unavailable. 4 passed.
  • tests/train/generators/test_skyrl_gym_generator.py: 30 passed (incl. test_llm_vs_env_time_split_metrics).
  • pre-commit (ruff / black / gitleaks) clean on changed files.

Trainer wiring (items 2–4) mirrors the base-trainer pattern and is verified by unit tests + lint; not exercised end-to-end here (needs a GPU cluster).

🤖 Generated with Claude Code

eicherseiji and others added 2 commits July 14, 2026 20:38
… env.step

Rollout timing is currently reported only as a total per trajectory
(`generate/trajectory_completion_time_*`, added in NovaSky-AI#1804). That total cannot
distinguish an engine-bound rollout from an environment-bound one, which is the
first question to ask when GPU utilization sags during generation.

Accumulate, per trajectory in `agent_loop`, the wall-clock time spent awaiting
`inference_engine_client.generate()` and the time spent in `env.step()`, and
report:

  generate/trajectory_llm_time_{mean,p90,max}
  generate/trajectory_env_time_{mean,p90,max}
  generate/frac_time_in_env

`frac_time_in_env` is time-weighted (sum over sum) so long trajectories count
proportionally rather than each trajectory contributing equally.

The two components need not sum to `e2e_time`; the remainder is tokenization,
chat-template rendering and other in-loop bookkeeping. Both are plumbed like the
existing `e2e_time`: optional, and omitted entirely if any trajectory in the
batch did not record them.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
… gauge, buffer depth

Three observability additions to the fully-async RL trainer, all motivated by a
post-mortem where reconstructing GPU idle time required correlating Prometheus
(GPU/disk, wall-clock keyed) against W&B (phase timings, step keyed) by hand.

1. Wire RayGpuMonitor into the async loop. It is constructed in the base
   RayPPOTrainer and flushed in the base loop, but FullyAsyncRayPPOTrainer
   overrides train() and never started or flushed it -- so runs on the async
   trainer logged zero `ray/` GPU keys despite `enable_ray_gpu_monitor=True`.
   Start it at loop entry, flush per step into the committed payload, stop it in
   the finally.

2. Publish a `skyrl_training_phase` gauge via `ray.util.metrics`
   (skyrl/train/utils/phase_metrics.py). Ray exports these to the same
   Prometheus that scrapes node GPU metrics, so
   `avg(ray_node_gpus_utilization) by (Phase)` becomes a single-store query
   instead of a manual cross-tracker correlation -- and it works after a cluster
   restart, when the experiment tracker may be unreachable. Set at each existing
   Timer() phase boundary (waiting_for_buffer / converting / training /
   weight_sync / eval / checkpoint); best-effort, never raises.

3. Log `async/gen_buffer_qsize` and `async/gen_buffer_maxsize` at step start.
   Run-ahead depth was previously only in a tqdm postfix; as a metric it
   distinguishes a throughput-limited generator (buffer low) from a
   gate-limited one (buffer at the staleness-bounded maxsize).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
@CharlieFRuan CharlieFRuan changed the title [logging] Split rollout trajectory time into inference-engine wait vs env.step [logging] Rollout time split + async-trainer GPU/phase/buffer observability Jul 15, 2026
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