Skip to content

Commit cdbbc96

Browse files
Zhiyu Liclaude
andcommitted
fix(data-plane): a max below its own median, and a fraction above 1
Auditing the cross-process e2e output rather than reporting it turned up two contradictions that shipped. A maximum below its own median. The e2e printed put: max_ms 133.5 p50_ms 175.0 p99_ms 248.5 get: max_ms 0.0063 p50_ms 0.050 p99_ms 0.099 and not one of those four percentiles is data: 100 + 150*0.50 = 175, 100 + 150*0.99 = 248.5, 0 + 0.1*0.50 = 0.05. Two causes. The percentiles came off the cumulative histogram while the max was step-scoped, so they described different windows; and interpolation spreads a bucket's samples uniformly across it, so calls clustered low in a wide bucket read high -- 160 calls of exactly 120 ms all land in (100, 250] and interpolate to a p50 of 175, above every call observed. Both fixed. Percentiles are now differenced per step, so they share a window with the max, and clamped to it, because a true percentile cannot exceed the maximum and the maximum is measured exactly. They are withheld below 50 calls in the window; on a wide DP degree a step clears that easily, and on a narrow one silence beats bucket geometry. A fraction above 1. `frac_of_step` read 1.054 -- correct arithmetic on a `wall_ms` summed over ten processes that ran concurrently, and nonsense as "105% of the step". Renamed to `busy_frac_mean` and divided by the process count: the mean fraction of the step a process spent in the data plane, bounded, and the question people actually ask. The audit also found three ways the harness was lying, now fixed there: workers "read" through `lambda: None` so their timings measured nothing; the driver wrote the whole batch instead of the advantages delta, which is why bytes_written was exactly 2x bytes_read; and the 131 ms/put denominator is NoOpDataPlaneClient doing Python bookkeeping, not a wire. With those corrected the driver's share drops to ~9% of cluster volume and observability costs 1.2%. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Zhiyu Li <zhiyul@oci-aga-slurm-1-dm-02.cm.cluster>
1 parent af257d1 commit cdbbc96

3 files changed

Lines changed: 111 additions & 7 deletions

File tree

nemo_rl/data_plane/README.md

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -456,6 +456,21 @@ affine fit, throughput — is recomputed from the merged totals, never
456456
averaged across ranks (averaging per-rank percentiles does not give a
457457
cluster percentile).
458458

459+
Two things read differently in the cluster view and are named to say so:
460+
461+
- **`busy_frac_mean`**, not `frac_of_step`. `wall_ms` is summed over
462+
processes that ran concurrently, so dividing it by one step's wall clock
463+
exceeds 1 whenever they overlapped (measured 1.054 across ten processes).
464+
The mean fraction of the step a process spent in the data plane is
465+
bounded and answers the question people ask of it.
466+
- **Percentiles are per step and clamped to the exact `max_ms`**, and are
467+
withheld entirely below 50 calls in the window. Bucket interpolation
468+
spreads a bucket's samples uniformly across it, so calls clustered low in
469+
a wide bucket read high — 160 calls of 120 ms all land in `(100, 250]`
470+
and interpolate to a p50 of 175, above every call observed and above the
471+
max reported beside it. The max is measured exactly, so it is the tighter
472+
bound.
473+
459474
`grpo_train_sync` fans out to the driver and every policy worker, and logs
460475
the combined result under `data_plane/cluster/` instead of the driver's
461476
own. It falls back to `data_plane/driver/` when the fan-out finds only one

nemo_rl/data_plane/observability.py

Lines changed: 45 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -95,6 +95,13 @@ class DataPlaneEvent(TypedDict):
9595
# few lines carry the identity of what broke.
9696
_MAX_HASH_MISMATCH_LOGS = 20
9797

98+
# Calls needed in a window before a percentile off the histogram means
99+
# anything. Below this the interpolation returns bucket geometry: one sample
100+
# in (100, 250] yields p50 = 100 + 150*0.50 = 175 and p99 = 248.5 whatever
101+
# the call actually took. Reporting that next to an exact ``max_ms`` produced
102+
# a max below its own median.
103+
_MIN_SAMPLES_FOR_PERCENTILE = 50
104+
98105

99106
class _FieldDigest(NamedTuple):
100107
"""One fingerprint per row, plus how far it can be trusted.
@@ -571,9 +578,18 @@ def cluster_step_metrics(
571578
"""
572579
wall_ms = merged["total_wall_ms"] - prev.get("total_wall_ms", 0.0)
573580
overhead_ms = merged["self_ms"] - prev.get("self_ms", 0.0) + collect_ms
581+
# Not ``frac_of_step``: ``wall_ms`` here is the SUM over processes that
582+
# ran concurrently, so dividing by one step's wall clock gives a number
583+
# that exceeds 1 whenever they overlapped (measured 1.054 across ten
584+
# processes) -- correct arithmetic, but it reads as "105% of the step".
585+
# The mean fraction of the step a process spent in the data plane is
586+
# bounded and answers the question people ask of it.
587+
n_procs = max(merged.get("n_processes", 1), 1)
574588
metrics: dict[str, float] = {
575589
"wall_ms": wall_ms,
576-
"frac_of_step": (wall_ms / 1e3 / step_time_s) if step_time_s > 0 else 0.0,
590+
"busy_frac_mean": (
591+
wall_ms / 1e3 / (step_time_s * n_procs) if step_time_s > 0 else 0.0
592+
),
577593
"comm_volume_mb": (
578594
merged["comm_volume_bytes"] - prev.get("comm_volume_bytes", 0)
579595
)
@@ -582,7 +598,7 @@ def cluster_step_metrics(
582598
/ 1e6,
583599
"bytes_read_mb": (merged["bytes_read"] - prev.get("bytes_read", 0)) / 1e6,
584600
"bytes_outstanding_mb": merged["bytes_outstanding"] / 1e6,
585-
"n_processes": merged.get("n_processes", 0),
601+
"n_processes": n_procs,
586602
"observability_overhead_ms": overhead_ms,
587603
"observability_overhead_frac": (overhead_ms / wall_ms if wall_ms > 0 else 0.0),
588604
}
@@ -595,11 +611,33 @@ def cluster_step_metrics(
595611
metrics[f"{op}/calls"] = calls
596612
metrics[f"{op}/wall_ms"] = stats["wall_ms"] - prev_op.get("wall_ms", 0.0)
597613
metrics[f"{op}/max_ms"] = stats["max_ms"]
598-
# Percentiles are worth reporting here and not per process: this
599-
# histogram is the sum over every rank, so it is the real cluster
600-
# distribution rather than one process's handful of calls.
601-
metrics[f"{op}/p50_ms"] = stats["p50_ms"]
602-
metrics[f"{op}/p99_ms"] = stats["p99_ms"]
614+
# Percentiles over THIS step's calls, summed across ranks, not over
615+
# the lifetime: a cumulative percentile beside a step-scoped max is
616+
# two different windows on one chart, and it showed a max below its
617+
# own median. Emitted only when the window holds enough calls to
618+
# out-resolve the buckets -- with a wide DP degree a step easily
619+
# clears it, and on a narrow one the honest answer is silence.
620+
step_hist = [
621+
now - was
622+
for now, was in zip(
623+
stats["latency_hist"],
624+
prev_op.get("latency_hist") or [0] * len(stats["latency_hist"]),
625+
)
626+
]
627+
if sum(step_hist) >= _MIN_SAMPLES_FOR_PERCENTILE:
628+
# Clamped to the exact max. Interpolation spreads a bucket's
629+
# samples uniformly across it, so calls clustered low in a wide
630+
# bucket read high -- 160 calls of 120 ms all land in (100, 250]
631+
# and interpolate to a p50 of 175, above every call observed. A
632+
# true percentile cannot exceed the maximum, and the maximum is
633+
# measured exactly, so it is the tighter bound.
634+
ceiling = stats["max_ms"]
635+
metrics[f"{op}/p50_ms"] = min(
636+
percentile_from_hist(step_hist, 0.50), ceiling
637+
)
638+
metrics[f"{op}/p99_ms"] = min(
639+
percentile_from_hist(step_hist, 0.99), ceiling
640+
)
603641
return metrics
604642

605643

tests/unit/data_plane/test_observability.py

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -743,6 +743,23 @@ def test_cluster_step_metrics_report_their_own_cost():
743743
client.close()
744744

745745

746+
def test_cluster_busy_fraction_is_bounded():
747+
"""``wall_ms`` is summed over processes that ran concurrently, so
748+
dividing it by one step's wall clock exceeds 1 whenever they
749+
overlapped — measured 1.054 across ten processes, which reads as
750+
'105% of the step'. The mean per-process fraction is bounded."""
751+
# Physical fixture: each rank spends 500 ms inside a 1 s step. A rank
752+
# cannot spend longer in the data plane than the step lasted, so a
753+
# fixture that implies it would be testing the arithmetic on impossible
754+
# input rather than the metric.
755+
ranks = [_rank_with([100.0] * 5) for _ in range(10)]
756+
metrics = cluster_step_metrics(merge_snapshots(ranks), {}, 1.0)
757+
758+
assert "frac_of_step" not in metrics
759+
assert 0.0 <= metrics["busy_frac_mean"] <= 1.0, metrics["busy_frac_mean"]
760+
assert metrics["n_processes"] == 10
761+
762+
746763
def test_cluster_overhead_includes_the_collection_fan_out():
747764
"""The fan-out is the larger half of the bill. Reporting only the per-op
748765
wrapper understated the real cost by ~19x in the cross-process e2e
@@ -765,3 +782,37 @@ def test_cluster_overhead_includes_the_collection_fan_out():
765782
)
766783
assert delta == pytest.approx(2.31, rel=1e-6)
767784
client.close()
785+
786+
787+
def _rank_with(latencies_ms):
788+
client = MetricsDataPlaneClient(NoOpDataPlaneClient())
789+
now = monotonic()
790+
for ms in latencies_ms:
791+
client._emit("put", "p", 1, 1_000, now - ms / 1e3, "ok")
792+
return client.snapshot()
793+
794+
795+
def test_cluster_percentiles_never_exceed_the_measured_max():
796+
"""Bucket interpolation spreads a bucket's samples uniformly across it,
797+
so calls clustered low in a wide bucket read high: 160 calls of 120 ms
798+
all land in (100, 250] and interpolate to a p50 of 175 — above every
799+
call observed, and above the exact max reported beside it. The max is
800+
the tighter bound, so the percentiles are clamped to it."""
801+
merged = merge_snapshots([_rank_with([120.0] * 20) for _ in range(8)])
802+
metrics = cluster_step_metrics(merged, {}, 1.0)
803+
804+
assert metrics["put/max_ms"] == pytest.approx(120.0, abs=2.0)
805+
assert metrics["put/p50_ms"] <= metrics["put/max_ms"]
806+
assert metrics["put/p99_ms"] <= metrics["put/max_ms"]
807+
assert metrics["put/p50_ms"] <= metrics["put/p99_ms"]
808+
809+
810+
def test_cluster_percentiles_withheld_below_a_useful_sample_count():
811+
"""A percentile off a handful of calls is bucket geometry, not data.
812+
Silence beats a number that looks like an answer."""
813+
few = merge_snapshots([_rank_with([120.0] * 3) for _ in range(2)]) # 6 calls
814+
many = merge_snapshots([_rank_with([120.0] * 20) for _ in range(8)]) # 160
815+
816+
assert "put/p50_ms" not in cluster_step_metrics(few, {}, 1.0)
817+
assert "put/max_ms" in cluster_step_metrics(few, {}, 1.0), "max always works"
818+
assert "put/p50_ms" in cluster_step_metrics(many, {}, 1.0)

0 commit comments

Comments
 (0)