From a1ee62ab5626af1fba0342ab1084701cbc1a7e32 Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Thu, 20 Aug 2026 01:51:45 -0700 Subject: [PATCH 1/7] perf: rc_2 (+39.50%) Landed by repair-bot on outer loop 1. Measured gain for this commit: +39.50%. Test case: disagg_upload-gen_only-gb200_deepseek-r1-fp4_8k1k_con1_ctx1_dep4_gen1_tep8_eplb0_mtp3_ccb-NIXL; NVBug: 6627789 Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../disaggregated/slurm/benchmark/submit.py | 35 +++++++++++++------ jenkins/scripts/perf/local/submit.py | 14 ++++++-- jenkins/scripts/perf/submit.py | 14 ++++++-- 3 files changed, 48 insertions(+), 15 deletions(-) diff --git a/examples/disaggregated/slurm/benchmark/submit.py b/examples/disaggregated/slurm/benchmark/submit.py index c1f797074208..d2618bf7ddd8 100644 --- a/examples/disaggregated/slurm/benchmark/submit.py +++ b/examples/disaggregated/slurm/benchmark/submit.py @@ -304,17 +304,30 @@ def build_worker_environment(worker_config, env_config, role, benchmark_mode, upsert_env_config(env_config, 'worker_env_var', 'TRTLLM_DISAGG_BENCHMARK_GEN_ONLY', 'TRTLLM_DISAGG_BENCHMARK_GEN_ONLY=1') - if benchmark_mode == "gen_only" and role == "GEN": - # GEN worker only: skipping transfer-state polling helps the generation - # worker, but the same flag on the CTX worker has been seen to hang - # gen_only runs with KV blocks never released. - upsert_env_config(env_config, 'gen_worker_env_var', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') - concurrency = _parse_positive_concurrency(concurrency) - upsert_env_config(env_config, 'gen_worker_env_var', - 'TLLM_BENCHMARK_REQ_QUEUES_SIZE', - f'TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency}') + if benchmark_mode == "gen_only": + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically load-bearing + # on the CTX worker for gen_only throughput on NIXL disagg workloads + # (removing it on CTX regressed deepseek-r1-fp4 8k1k dep4/tep8 by + # -27.9 %; see NVBug 6627789 / bisect PR #17535). Default: apply on + # both workers, matching the pre-PR contract. Workloads that observed + # the CTX-side hang the PR was scoped for can opt out by exporting + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0 in the submitting + # shell; only the GEN worker receives the flag in that case. + _apply_ctx_kv_overlap = os.environ.get( + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX', '1') != '0' + if _apply_ctx_kv_overlap: + upsert_env_config(env_config, 'worker_env_var', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') + elif role == "GEN": + upsert_env_config(env_config, 'gen_worker_env_var', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') + if role == "GEN": + concurrency = _parse_positive_concurrency(concurrency) + upsert_env_config(env_config, 'gen_worker_env_var', + 'TLLM_BENCHMARK_REQ_QUEUES_SIZE', + f'TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency}') # 2. Add profiling env vars to env_config (conditional) if nsys_on: diff --git a/jenkins/scripts/perf/local/submit.py b/jenkins/scripts/perf/local/submit.py index b311c1cf035d..5c211bb06c6d 100755 --- a/jenkins/scripts/perf/local/submit.py +++ b/jenkins/scripts/perf/local/submit.py @@ -901,8 +901,18 @@ def main(): srun_args_lines.append("--container-env=TRTLLM_DISAGG_BENCHMARK_GEN_ONLY") elif "gen_only" in bm_config.get("mode", ""): concurrency = bm_config.get("concurrency", 1) - # GEN worker only: the same flag on the CTX worker has been seen to - # hang gen_only runs with KV blocks never released. + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically + # load-bearing on the CTX worker for gen_only throughput on + # NIXL disagg (removing it on CTX regressed deepseek-r1-fp4 + # 8k1k dep4/tep8 by -27.9 %; see NVBug 6627789 / PR #17535). + # Default: apply on both workers, matching the pre-PR + # contract. Workloads that observed the CTX-side hang the PR + # was scoped for can opt out by exporting + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0. + if os.environ.get("TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX", "1") != "0": + ctx_worker_env_vars = ( + f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 {ctx_worker_env_vars}" + ) gen_worker_env_vars = ( f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 " f"TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency} {gen_worker_env_vars}" diff --git a/jenkins/scripts/perf/submit.py b/jenkins/scripts/perf/submit.py index e30ecc72ec54..2f9bb8f67468 100755 --- a/jenkins/scripts/perf/submit.py +++ b/jenkins/scripts/perf/submit.py @@ -896,8 +896,18 @@ def main(): srun_args_lines.append("--container-env=TRTLLM_DISAGG_BENCHMARK_GEN_ONLY") elif benchmark_mode == "gen_only": concurrency = benchmark_config.get("concurrency", 1) - # GEN worker only: the same flag on the CTX worker has been seen to - # hang gen_only runs with KV blocks never released. + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically + # load-bearing on the CTX worker for gen_only throughput on + # NIXL disagg (removing it on CTX regressed deepseek-r1-fp4 + # 8k1k dep4/tep8 by -27.9 %; see NVBug 6627789 / PR #17535). + # Default: apply on both workers, matching the pre-PR + # contract. Workloads that observed the CTX-side hang the PR + # was scoped for can opt out by exporting + # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0. + if os.environ.get("TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX", "1") != "0": + ctx_worker_env_vars = ( + f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 {ctx_worker_env_vars}" + ) gen_worker_env_vars = ( f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 " f"TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency} {gen_worker_env_vars}" From b4489c76263ca1c29ef262825a3b4a5e83f5ea25 Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Sun, 23 Aug 2026 21:53:28 -0700 Subject: [PATCH 2/7] Revert "perf: rc_2 (+39.50%)" This reverts commit a1ee62ab5626af1fba0342ab1084701cbc1a7e32. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../disaggregated/slurm/benchmark/submit.py | 35 ++++++------------- jenkins/scripts/perf/local/submit.py | 14 ++------ jenkins/scripts/perf/submit.py | 14 ++------ 3 files changed, 15 insertions(+), 48 deletions(-) diff --git a/examples/disaggregated/slurm/benchmark/submit.py b/examples/disaggregated/slurm/benchmark/submit.py index d2618bf7ddd8..c1f797074208 100644 --- a/examples/disaggregated/slurm/benchmark/submit.py +++ b/examples/disaggregated/slurm/benchmark/submit.py @@ -304,30 +304,17 @@ def build_worker_environment(worker_config, env_config, role, benchmark_mode, upsert_env_config(env_config, 'worker_env_var', 'TRTLLM_DISAGG_BENCHMARK_GEN_ONLY', 'TRTLLM_DISAGG_BENCHMARK_GEN_ONLY=1') - if benchmark_mode == "gen_only": - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically load-bearing - # on the CTX worker for gen_only throughput on NIXL disagg workloads - # (removing it on CTX regressed deepseek-r1-fp4 8k1k dep4/tep8 by - # -27.9 %; see NVBug 6627789 / bisect PR #17535). Default: apply on - # both workers, matching the pre-PR contract. Workloads that observed - # the CTX-side hang the PR was scoped for can opt out by exporting - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0 in the submitting - # shell; only the GEN worker receives the flag in that case. - _apply_ctx_kv_overlap = os.environ.get( - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX', '1') != '0' - if _apply_ctx_kv_overlap: - upsert_env_config(env_config, 'worker_env_var', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') - elif role == "GEN": - upsert_env_config(env_config, 'gen_worker_env_var', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', - 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') - if role == "GEN": - concurrency = _parse_positive_concurrency(concurrency) - upsert_env_config(env_config, 'gen_worker_env_var', - 'TLLM_BENCHMARK_REQ_QUEUES_SIZE', - f'TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency}') + if benchmark_mode == "gen_only" and role == "GEN": + # GEN worker only: skipping transfer-state polling helps the generation + # worker, but the same flag on the CTX worker has been seen to hang + # gen_only runs with KV blocks never released. + upsert_env_config(env_config, 'gen_worker_env_var', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP', + 'TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1') + concurrency = _parse_positive_concurrency(concurrency) + upsert_env_config(env_config, 'gen_worker_env_var', + 'TLLM_BENCHMARK_REQ_QUEUES_SIZE', + f'TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency}') # 2. Add profiling env vars to env_config (conditional) if nsys_on: diff --git a/jenkins/scripts/perf/local/submit.py b/jenkins/scripts/perf/local/submit.py index 5c211bb06c6d..b311c1cf035d 100755 --- a/jenkins/scripts/perf/local/submit.py +++ b/jenkins/scripts/perf/local/submit.py @@ -901,18 +901,8 @@ def main(): srun_args_lines.append("--container-env=TRTLLM_DISAGG_BENCHMARK_GEN_ONLY") elif "gen_only" in bm_config.get("mode", ""): concurrency = bm_config.get("concurrency", 1) - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically - # load-bearing on the CTX worker for gen_only throughput on - # NIXL disagg (removing it on CTX regressed deepseek-r1-fp4 - # 8k1k dep4/tep8 by -27.9 %; see NVBug 6627789 / PR #17535). - # Default: apply on both workers, matching the pre-PR - # contract. Workloads that observed the CTX-side hang the PR - # was scoped for can opt out by exporting - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0. - if os.environ.get("TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX", "1") != "0": - ctx_worker_env_vars = ( - f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 {ctx_worker_env_vars}" - ) + # GEN worker only: the same flag on the CTX worker has been seen to + # hang gen_only runs with KV blocks never released. gen_worker_env_vars = ( f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 " f"TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency} {gen_worker_env_vars}" diff --git a/jenkins/scripts/perf/submit.py b/jenkins/scripts/perf/submit.py index 2f9bb8f67468..e30ecc72ec54 100755 --- a/jenkins/scripts/perf/submit.py +++ b/jenkins/scripts/perf/submit.py @@ -896,18 +896,8 @@ def main(): srun_args_lines.append("--container-env=TRTLLM_DISAGG_BENCHMARK_GEN_ONLY") elif benchmark_mode == "gen_only": concurrency = benchmark_config.get("concurrency", 1) - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP is empirically - # load-bearing on the CTX worker for gen_only throughput on - # NIXL disagg (removing it on CTX regressed deepseek-r1-fp4 - # 8k1k dep4/tep8 by -27.9 %; see NVBug 6627789 / PR #17535). - # Default: apply on both workers, matching the pre-PR - # contract. Workloads that observed the CTX-side hang the PR - # was scoped for can opt out by exporting - # TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX=0. - if os.environ.get("TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP_CTX", "1") != "0": - ctx_worker_env_vars = ( - f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 {ctx_worker_env_vars}" - ) + # GEN worker only: the same flag on the CTX worker has been seen to + # hang gen_only runs with KV blocks never released. gen_worker_env_vars = ( f"TRTLLM_DISABLE_KV_CACHE_TRANSFER_OVERLAP=1 " f"TLLM_BENCHMARK_REQ_QUEUES_SIZE={concurrency} {gen_worker_env_vars}" From d463136f60925ad55c4c895e440ed09295d09217 Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Sun, 23 Aug 2026 22:23:56 -0700 Subject: [PATCH 3/7] [None][test] Exclude idle iterations from the gen_only device step time metric d_mean_gen_worker_per_iter_device_step_time is a mean over per-iteration prev_device_step_time values from gen_server_*.log. Because the device runs asynchronously, the value logged at iteration N is the loop period of iteration N-1 -- so an iteration that scheduled zero requests, and therefore did no GPU work, contributes its entire idle wait (KV-cache transfer) to the NEXT row's device step time. One such iteration is enough to move the mean by tens of percent on an otherwise unchanged workload. That is what nvbugs 6627789 reported as a +19.33% regression. In the culprit run's gen_server_0.log, iter 259 has num_scheduled_requests = 0 and host_step_time = 1456.699ms, and iter 260 duly reports prev_device_step_time = 1450.614ms. Dropping that single row per file inverts the measured gap from +19.33% to -3.59%: 8.471 -> 7.561 ms on the parent and 10.109 -> 7.290 ms on the culprit, with 511 of 512 samples retained on each side. Two changes: - _scan_gen_worker_device_step_time now parses num_scheduled_requests and drops a row whose immediately preceding iteration scheduled none. The adjacency check (pred_iter == cur_iter - 1) makes the filter degrade to keeping the row under rank interleaving or an iteration-counter reset, which is the safe direction. The zero-request row itself is kept: its own prev_device_step_time describes the previous iteration, which did real work. - The benchmark log now carries the median, stdev, P75 and P99 alongside the existing mean, and all five are uploaded. The filter is deliberately incomplete -- the parent's iter 261 still reports 112.07 ms because its own predecessor did schedule work, drained-queue tail bleeding one iteration further -- so the mean is not self-diagnosing on its own. Published next to it, stdev 4.63 ms says "do not trust this mean" where stdev 0.115 ms says "do", which no single number can. regression_metrics is unchanged: only the mean can fail a build. The four new metrics get baselines and appear in s_regression_info but are inert until history accrues. Renaming the gated metric was avoided on purpose -- OpenSearch baseline keys are derived from it by string surgery, so a rename would orphan its history. The filter can only lower a minimize metric, so it cannot trip a false regression; it lands as a one-off ~11% improvement that decays out of the rolling baseline window. Adds unit coverage for _scan_gen_worker_device_step_time, _stats_at_mode_ngen and gen_worker_log_sizes, which had none: the off-by-one exclusion using the real log lines from the bug, the adjacency guard releasing on a non-adjacent or unparseable predecessor, the iter < 5 cutoff, num_generation_tokens mode bucketing and its tie rule, each of the five statistics, cross-worker averaging, the retention cap, and a round trip through parse_metrics_from_output asserting no metric regex shadows another. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../defs/perf/README_test_perf_sanity.md | 30 +- .../integration/defs/perf/test_perf_sanity.py | 356 ++++++++++---- .../scripts/test_perf_sanity_helpers.py | 437 +++++++++++++++++- 3 files changed, 712 insertions(+), 111 deletions(-) diff --git a/tests/integration/defs/perf/README_test_perf_sanity.md b/tests/integration/defs/perf/README_test_perf_sanity.md index 53fc8c346b5f..a97b867e07af 100644 --- a/tests/integration/defs/perf/README_test_perf_sanity.md +++ b/tests/integration/defs/perf/README_test_perf_sanity.md @@ -24,32 +24,40 @@ For the underlying regression pipeline architecture (three-layer design, baselin | List | Count | Contents | |------|-------|----------| | `MAXIMIZE_METRICS` | 8 | Throughputs (`d_seq_throughput`, `d_token_throughput`, `d_total_token_throughput`, `d_user_throughput`) + TPOT (`d_mean_tpot`, `d_median_tpot`, `d_p99_tpot`) + spec-decoding `d_al` | -| `MINIMIZE_METRICS` | 10 | TTFT, ITL, E2EL latencies (mean/median/P99 for each) + `d_mean_gen_worker_per_iter_device_step_time` (gen_only-only) | +| `MINIMIZE_METRICS` | 14 | TTFT, ITL, E2EL latencies (mean/median/P99 for each) + the five gen_only-only `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` | | `REGRESSION_METRICS` | 2 default | `d_token_throughput`, `d_total_token_throughput` — gate pass/fail for all modes **except disagg gen_only**. `d_al` is appended at runtime when any client runs spec decoding. | -**Disagg gen_only override**: For `disagg_upload-gen_only-*` tests, regression is gated **only** on `d_mean_gen_worker_per_iter_device_step_time`. Token-based throughput numbers are dominated by KV-cache transfer time in gen_only mode and are not a useful regression signal there. +**Disagg gen_only override**: For `disagg_upload-gen_only-*` tests, regression is gated **only** on `d_mean_gen_worker_per_iter_device_step_time`. Token-based throughput numbers are dominated by KV-cache transfer time in gen_only mode and are not a useful regression signal there. The other four device-step-time statistics are uploaded for diagnosis but are **not** gated. -#### `d_mean_gen_worker_per_iter_device_step_time` (gen_only only) +#### `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` (gen_only only) -This metric is parsed from each `gen_server_{i}.log` produced by the disagg run (one per gen worker, in the run's `output_dir`). Lines look like: +These metrics are parsed from each `gen_server_{i}.log` produced by the disagg run (one per gen worker, in the run's `output_dir`). Lines look like: ``` -[TRT-LLM] [I] [_torch][RANK 0] iter = 5, ..., host_step_time = 6.79ms, prev_device_step_time = 6.94ms, ... +[TRT-LLM] [I] [_torch][RANK 0] iter = 5, ..., num_scheduled_requests = 1, ..., host_step_time = 6.79ms, prev_device_step_time = 6.94ms, ... ``` The device value reported at iter `N` is the device step time of iter `N-1` (device runs async). **Per-client computation** (DisaggTestCmds.run_cmd, BENCHMARK branch): 1. Immediately before launching each client, snapshot `os.path.getsize()` of every `gen_server_{i}.log`. After the client's benchmark subprocess returns, only the bytes between that snapshot and current EOF are parsed — so each client gets its own segment of gen-worker iterations rather than sharing a single global average. -2. Per file (per segment): streaming Welford mean of `prev_device_step_time` over all iters with `iter >= 5` (iters 0-4 are excluded: iter 0/1 include KV-cache transfer wait time, and iters 2-4 are warmup that has not yet reached steady state). Lines where `prev_device_step_time = N/A` (e.g. iter 1) do not match the parser and are skipped. Welford keeps memory at O(1) and is numerically stable for arbitrarily large iteration counts. -3. Across files: average the per-file means → per-client metric value. -4. The per-client value is appended as the trailing line of `trtllm-benchmark.{server_idx}.{client_idx}.log`: +2. Per file (per segment), collect the `prev_device_step_time` of every *usable* iteration. A row is usable when all of the following hold: + - `iter >= 5` — iter 0/1 include KV-cache transfer wait time, and iters 2-4 are warmup that has not yet reached steady state. Lines where `prev_device_step_time = N/A` (e.g. iter 1) do not match the parser and are skipped anyway. + - Its immediately preceding iteration did **not** report `num_scheduled_requests = 0`. Such an iteration did no GPU work, so its loop period is pure idle (waiting on KV-cache transfer) — and because the device runs async, that idle period is what the *next* row's `prev_device_step_time` reports. One such row inflated this mean by 19% on nvbugs 6627789 while the steady-state iterations were unchanged at ~7.3 ms. The `nsr = 0` row itself is kept: its own value describes the previous iteration, which did do work. The exclusion requires the predecessor's iter number to be exactly `cur_iter - 1`; if it is not adjacent, or did not parse, the row is kept (failing toward inclusion rather than silently dropping real data). +3. Per file, bucket the usable rows by `num_generation_tokens` and keep only the **mode** bucket (ties → the larger token count). Concurrency ramps down at the tail of a run, so the trailing iterations do less work per step and are not comparable to the plateau. A file with no parseable `num_generation_tokens` anywhere falls back to all of its usable rows (nvbugs 6487036 / 6487040: the field rendered as `tensor(256)` and matched nothing). +4. Compute mean, median, stdev (ddof=1, `0.0` for fewer than two samples), P75 and P99 of that bucket per file, then average each statistic across files (unweighted) → the per-client metric values. Averaging a median across workers is not itself a median of the pooled sample; it is the same unweighted per-file rule the mean has always used, kept for consistency and continuity of baselines. +5. Because the percentiles and stdev need the whole sample, the scan retains rows rather than streaming; retention is capped per worker (`_MAX_RETAINED_ITER_ROWS`) so a pathological log cannot grow it without bound. +6. The per-client values are appended to `trtllm-benchmark.{server_idx}.{client_idx}.log`, one statistic per line: ``` - Average Per Iter Device Step Time (ms): + Average Per Iter Device Step Time (ms): + Median Per Iter Device Step Time (ms): + Stdev Per Iter Device Step Time (ms): + P75 Per Iter Device Step Time (ms): + P99 Per Iter Device Step Time (ms): ``` - Downstream `parse_metrics_from_output` picks it up via `GEN_ONLY_PERF_METRIC_LOG_QUERIES`. + Downstream `parse_metrics_from_output` picks them up via `GEN_ONLY_PERF_METRIC_LOG_QUERIES`. It breaks out of its regex loop on the first match per line, so each statistic must stay on its own line with a distinct leading word. -If the metric cannot be parsed for a `gen_only` run, `check_test_failure` raises `RuntimeError` and no data is uploaded. +If the mean cannot be parsed for a `gen_only` run, `check_test_failure` raises `RuntimeError` and no data is uploaded. ### Match Keys diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index 8111dfee8c0c..382c6786cb91 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -17,6 +17,7 @@ import copy import fcntl import glob +import math import os import re import secrets @@ -37,7 +38,7 @@ from ..conftest import get_llm_root, llm_models_root from ._model_paths import MODEL_PATH_DICT as _MODEL_PATH_DICT_BASE -from .perf_regression_utils import process_and_upload_test_results +from .perf_regression_utils import _percentile, process_and_upload_test_results # Sanity-side path differs from test_perf for this key; preserve historical value. MODEL_PATH_DICT = { @@ -178,15 +179,49 @@ def server_ready_timeout(default: int, mode: str) -> int: "al": re.compile(r"Mean Avg Decoded Tokens per Iter:\s+(-?[\d\.]+)"), } -# gen_only-only metric: appended to each trtllm-benchmark log by +# gen_only-only metrics: appended to each trtllm-benchmark log by # DisaggTestCmds.run_cmd after parsing gen_server_*.log; only forwarded to # the database for gen_only mode. +# +# The distribution is published, not just the mean, because the mean alone is +# not self-diagnosing: a single anomalous iteration can move it by >30% while +# the workload is unchanged (nvbugs 6627789), and the only way a reader can +# tell that from a real regression is to see the spread next to it. Only the +# mean is regression-gated (see regression_metrics in the gen_only branch); +# the other four are uploaded for diagnosis. +# +# One statistic per line, and the leading words must stay mutually exclusive: +# parse_metrics_from_output breaks out of the regex loop on the first match per +# line, so a shared prefix would silently shadow whichever pattern lost the +# ordering race. GEN_ONLY_PERF_METRIC_LOG_QUERIES = { "mean_gen_worker_per_iter_device_step_time": re.compile( r"Average Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" ), + "median_gen_worker_per_iter_device_step_time": re.compile( + r"Median Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" + ), + "std_gen_worker_per_iter_device_step_time": re.compile( + r"Stdev Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" + ), + "p75_gen_worker_per_iter_device_step_time": re.compile( + r"P75 Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" + ), + "p99_gen_worker_per_iter_device_step_time": re.compile( + r"P99 Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" + ), } +# Every gen_only device-step-time metric, in log-line order. The mean is first +# because it is the gated one and the only one check_test_failure keys on. +GEN_ONLY_DEVICE_STEP_TIME_METRICS = ( + "mean_gen_worker_per_iter_device_step_time", + "median_gen_worker_per_iter_device_step_time", + "std_gen_worker_per_iter_device_step_time", + "p75_gen_worker_per_iter_device_step_time", + "p99_gen_worker_per_iter_device_step_time", +) + # Per-iter prev_device_step_time logged by each gen worker. Example line: # [TRT-LLM] [I] [_torch][RANK 0] iter = 5, global_rank = 0, ..., # host_step_time = 6.79ms, prev_device_step_time = 6.94ms, ..., @@ -203,6 +238,59 @@ def server_ready_timeout(default: int, mode: str) -> int: # _scan_gen_worker_device_step_time. _DEVICE_STEP_TIME_RE = re.compile(r"iter\s*=\s*(\d+),.*?prev_device_step_time\s*=\s*([\d.]+)\s*ms") _NUM_GEN_TOKENS_RE = re.compile(r"'num_generation_tokens':\s*(\d+)") +# num_scheduled_requests from the same line. An iteration that scheduled zero +# requests did no GPU work, so its loop period is pure idle (waiting on KV-cache +# transfer) -- and because the device runs async that period is reported by the +# NEXT iteration's prev_device_step_time. Such a row is excluded; see +# _scan_gen_worker_device_step_time. The ' = ' spelling is what +# py_executor.py's iteration log actually emits (do not copy the ': ' form in +# examples/wide_ep/slurm_scripts/process_gen_iterlog.py, which is stale). +_ITER_NSR_RE = re.compile(r"iter\s*=\s*(\d+),.*?num_scheduled_requests\s*=\s*(\d+)") + +# Hard cap on retained per-iteration samples per gen worker. The percentile and +# stdev statistics need the whole sample, so the scan cannot be O(1) memory the +# way a streaming mean could. A steady-state run holds ~512 rows per worker +# (~16 KB), so this bound is ~1000x headroom and exists only to keep a +# pathological log (a runaway worker, a concatenated log) from growing the +# scan without limit. Excess rows are dropped, not sampled: truncating the tail +# keeps the steady-state plateau these statistics describe. +_MAX_RETAINED_ITER_ROWS = 500_000 + + +class _IterRow(NamedTuple): + """One usable per-iteration sample from a gen worker log. + + ngen is the line's num_generation_tokens, or None when it did not parse + (see _scan_gen_worker_device_step_time for why such rows are retained). + """ + + ngen: Optional[int] + device_step_time: float + + +class _DeviceStepTimeStats(NamedTuple): + """Distribution of gen-worker per-iter device step time, in ms.""" + + mean: float + median: float + std: float + p75: float + p99: float + + +def _stdev(values: List[float]) -> float: + """Sample standard deviation (ddof=1). Returns 0.0 for fewer than 2 values. + + ddof=1 because the iterations are a sample of the workload's steady state, + not its entire population. A single-sample file reports 0.0 rather than + raising: the metric is diagnostic, and a run that produced one usable + iteration has bigger problems than its spread. + """ + n = len(values) + if n < 2: + return 0.0 + mean = sum(values) / n + return math.sqrt(sum((v - mean) ** 2 for v in values) / (n - 1)) def gen_worker_log_sizes(output_dir: str, num_gen_servers: int) -> List[int]: @@ -223,36 +311,46 @@ def _scan_gen_worker_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: Optional[List[int]] = None, -) -> Tuple[List[Tuple[Dict[int, Tuple[int, float]], int, float]], int]: +) -> List[List[_IterRow]]: """Single-pass scan of the gen logs. - Returns (per_file_scans, total_count): - - per_file_scans: one entry per file that produced >=1 usable row, each - a tuple (by_ngen, all_count, all_mean): - * by_ngen maps num_generation_tokens -> (count, Welford mean of - prev_device_step_time) over rows with iter >= 5, a numeric - prev_device_step_time, and a parseable num_generation_tokens on - the same line. - * all_count / all_mean are the count and Welford mean of - prev_device_step_time over ALL iter >= 5 numeric rows in the file, - including those whose num_generation_tokens did not parse. This is - the fallback aggregate used when a worker never emits a parseable - num_generation_tokens (nvbugs 6487036 / 6487040): PR #16298 began - requiring num_generation_tokens on every line, so a worker whose - states dict renders it as e.g. tensor(256) would drop to no - buckets and the metric would wrongly parse to None. - - total_count: the number of iter >= 5 rows with a numeric - prev_device_step_time across all files. - - Memory is O(distinct num_generation_tokens per file), a small constant - in practice (steady-state plus a shrinking tail). + Returns one list of _IterRow per file that produced at least one usable + row. A row is usable when iter >= 5, prev_device_step_time is numeric, and + the row is not the successor of an empty iteration (below). _IterRow.ngen + is None when num_generation_tokens did not parse on that line; such rows + are retained rather than dropped so a worker whose states dict renders it + unparseably (e.g. tensor(256), nvbugs 6487036 / 6487040) still produces a + metric instead of None -- PR #16298 began requiring num_generation_tokens + on every line, and dropping those rows would silently lose the metric. + + Empty-iteration successors are excluded. An iteration with + num_scheduled_requests == 0 did no GPU work, so its loop period is entirely + idle -- typically waiting for KV-cache transfer in a disaggregated run -- + and because the device runs one step behind, that idle period is what the + NEXT iteration reports as prev_device_step_time. Averaging it in credits + the GPU with hundreds or thousands of milliseconds of "step time" that no + kernel spent, which is how nvbug 6627789 read a +19% regression out of two + runs whose steady-state iterations were both ~7.3 ms. + + The row is dropped only when the immediately preceding parsed line is + provably the predecessor iteration: pred_iter == cur_iter - 1. If the + predecessor is missing, unparseable, or non-adjacent (interleaved ranks + writing to a shared log, a restarted iteration counter), the row is KEPT. + That is the safe direction to fail: the exclusion is an accuracy + improvement on a metric that must keep reporting, so a scan that cannot + prove a row is idle-contaminated should behave exactly as it did before. + Note the num_scheduled_requests == 0 row itself is kept -- its own + prev_device_step_time describes the previous iteration, which did work. + + Memory is O(retained rows), bounded by _MAX_RETAINED_ITER_ROWS per file: + the percentile and stdev statistics need the whole sample, unlike the + streaming mean this replaced. errors="replace" guards against invalid UTF-8: tqdm progress bars (model load) write partial multibyte sequences that would otherwise raise UnicodeDecodeError mid-scan. """ - per_file_scans: List[Tuple[Dict[int, Tuple[int, float]], int, float]] = [] - total_count = 0 + per_file_rows: List[List[_IterRow]] = [] for i in range(num_gen_servers): log_path = os.path.join(output_dir, f"gen_server_{i}.log") if not os.path.isfile(log_path): @@ -264,85 +362,123 @@ def _scan_gen_worker_device_step_time( else 0 ) - by_ngen: Dict[int, Tuple[int, float]] = {} - all_count = 0 - all_mean = 0.0 + rows: List[_IterRow] = [] + prev_iter: Optional[int] = None + prev_nsr: Optional[int] = None with open(log_path, errors="replace") as f: if seek_to: f.seek(seek_to) for line in f: + # Every iteration line carries this literal, including the ones + # whose value is 'N/A', so this fast-reject cannot skip a line + # the num_scheduled_requests tracking below needs to see. + if "prev_device_step_time" not in line: + continue + # Snapshot the predecessor before this line overwrites it. + pred_iter, pred_nsr = prev_iter, prev_nsr + nsr_m = _ITER_NSR_RE.search(line) + if nsr_m is None: + prev_iter, prev_nsr = None, None + else: + prev_iter, prev_nsr = int(nsr_m.group(1)), int(nsr_m.group(2)) + m = _DEVICE_STEP_TIME_RE.search(line) if m is None: continue - if int(m.group(1)) < 5: + cur_iter = int(m.group(1)) + # iter 0/1 include KV-cache transfer wait; 2-4 are warmup. + if cur_iter < 5: continue - total_count += 1 - dt = float(m.group(2)) - # All-iter fallback aggregate (every usable row). - all_count += 1 - all_mean += (dt - all_mean) / all_count - # Per-ngen bucket (only rows with a parseable ngen). - ngen_m = _NUM_GEN_TOKENS_RE.search(line) - if ngen_m is None: + if pred_nsr == 0 and pred_iter is not None and pred_iter == cur_iter - 1: + continue + if len(rows) >= _MAX_RETAINED_ITER_ROWS: continue - ngen = int(ngen_m.group(1)) - count, mean = by_ngen.get(ngen, (0, 0.0)) - count += 1 - mean += (dt - mean) / count - by_ngen[ngen] = (count, mean) - if all_count: - per_file_scans.append((by_ngen, all_count, all_mean)) - return per_file_scans, total_count + ngen_m = _NUM_GEN_TOKENS_RE.search(line) + rows.append( + _IterRow( + ngen=int(ngen_m.group(1)) if ngen_m is not None else None, + device_step_time=float(m.group(2)), + ) + ) + if rows: + per_file_rows.append(rows) + return per_file_rows -def _mean_at_mode_ngen( - per_file_scans: List[Tuple[Dict[int, Tuple[int, float]], int, float]], -) -> Optional[float]: - """Aggregate per-file scans into a single mean. +def _stats_at_mode_ngen( + per_file_rows: List[List[_IterRow]], +) -> Optional[_DeviceStepTimeStats]: + """Aggregate per-file rows into one set of distribution statistics. Within each file pick the num_generation_tokens value with the most - iterations (the mode) and take its Welford mean; ties break to the + iterations (the mode) and describe only that bucket; ties break to the largest ngen because the steady-state plateau is the upper of any tied - clusters. Mode is more robust than strict == max — a one-off spike where + clusters. Mode is more robust than strict == max -- a one-off spike where a single iter's ngen briefly exceeds the sustained batch would otherwise - collapse the mean to 1-2 samples. When a file produced usable rows but no - parseable num_generation_tokens on any of them, fall back to the file's - all-iter mean so a present metric is never lost (nvbugs 6487036 / - 6487040). Then average the per-file means across workers. Returns None if - no file had a usable row. + collapse the statistics to 1-2 samples. Iterations near the end of a run + have a shrinking num_generation_tokens as sequences finish and land in + smaller-ngen buckets, so they do not drag the mean below steady state. + When a file produced usable rows but no parseable num_generation_tokens on + any of them, fall back to that file's whole sample so a present metric is + never lost (nvbugs 6487036 / 6487040). + + Then average each statistic across workers, unweighted -- one vote per + worker, matching how the mean has always been combined. Averaging a median + or a percentile across workers is not itself a median or a percentile of + the pooled sample; these are per-worker statistics summarised across + workers, which is the comparison the regression check makes. + + Returns None if no file had a usable row. """ - means: List[float] = [] - for by_ngen, _all_count, all_mean in per_file_scans: + per_file_stats: List[_DeviceStepTimeStats] = [] + for rows in per_file_rows: + by_ngen: Dict[int, List[float]] = {} + for row in rows: + if row.ngen is not None: + by_ngen.setdefault(row.ngen, []).append(row.device_step_time) if by_ngen: - _mode_ngen, (_count, mean) = max(by_ngen.items(), key=lambda kv: (kv[1][0], kv[0])) - means.append(mean) + _mode_ngen, values = max(by_ngen.items(), key=lambda kv: (len(kv[1]), kv[0])) else: - # No parseable ngen anywhere in this worker; use the all-iter mean. - means.append(all_mean) - if not means: + # No parseable ngen anywhere in this worker; use every row. + values = [row.device_step_time for row in rows] + if not values: + continue + per_file_stats.append( + _DeviceStepTimeStats( + mean=sum(values) / len(values), + median=_percentile(values, 50), + std=_stdev(values), + p75=_percentile(values, 75), + p99=_percentile(values, 99), + ) + ) + if not per_file_stats: return None - return sum(means) / len(means) + num_files = len(per_file_stats) + return _DeviceStepTimeStats(*(sum(column) / num_files for column in zip(*per_file_stats))) def parse_gen_worker_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: Optional[List[int]] = None, -) -> Optional[float]: - """Mean per-iter prev_device_step_time (ms) across all gen workers. - - For each gen_server_{i}.log, bucket iter >= 5 rows by - num_generation_tokens, pick the bucket with the most rows (the mode; ties - break to the largest ngen), and take that bucket's mean. Then average - those per-file means across the num_gen_servers workers. Iterations near - the end of a run have a shrinking num_generation_tokens as sequences - finish and land in smaller-ngen buckets, so they don't drag the mean - below the steady-state cost. Using the mode (rather than strict == max) - is robust against a single iter whose ngen briefly spikes above the - sustained batch, which would otherwise collapse the mean to 1-2 samples. - A worker whose num_generation_tokens never parses falls back to its - all-iter mean rather than being dropped to None. Returns None only if no - usable line is found in any file. +) -> Optional[_DeviceStepTimeStats]: + """Per-iter prev_device_step_time statistics (ms) across all gen workers. + + For each gen_server_{i}.log, take the iter >= 5 rows that are not the + successor of an empty (num_scheduled_requests == 0) iteration, bucket them + by num_generation_tokens, pick the bucket with the most rows (the mode; + ties break to the largest ngen), and describe that bucket with mean, + median, stdev, P75 and P99. Then average each statistic across the + num_gen_servers workers. A worker whose num_generation_tokens never parses + falls back to its whole sample rather than being dropped to None. Returns + None only if no usable line is found in any file. + + The mean is the regression-gated statistic; the other four are uploaded + for diagnosis, because a mean on its own cannot distinguish a slower + workload from one anomalous iteration. See + _scan_gen_worker_device_step_time for the empty-iteration exclusion and + _stats_at_mode_ngen for the bucket selection. When start_offsets is provided, only the bytes from start_offsets[i] to end-of-file are considered for gen_server_{i}.log — used to slice out a @@ -357,10 +493,8 @@ def parse_gen_worker_device_step_time( accept a truncated prefix while the log was still flushing across NFS (nvbugs 6487036 / 6487040 / 6487038). """ - per_file_scans, _total_count = _scan_gen_worker_device_step_time( - output_dir, num_gen_servers, start_offsets - ) - return _mean_at_mode_ngen(per_file_scans) + per_file_rows = _scan_gen_worker_device_step_time(output_dir, num_gen_servers, start_offsets) + return _stats_at_mode_ngen(per_file_rows) def add_perf_metric_value( @@ -374,17 +508,26 @@ def add_perf_metric_value( - Always copies every key in PERF_METRIC_LOG_QUERIES as `d_`. - Adds `d_al` only when spec_decoding=True; non-spec rows omit it so OpenSearch baselines don't blend the two populations. - - Adds `d_mean_gen_worker_per_iter_device_step_time` only for the - disagg gen_only mode (the only mode whose regression is gated on it). + - Adds the `d_*_gen_worker_per_iter_device_step_time` family only for the + disagg gen_only mode (the only mode that emits them). Of these only the + mean is regression-gated; the rest are uploaded for diagnosis. + + A missing or non-numeric gen_only statistic is omitted rather than + forwarded: typeCheckForOpenSearchDB rejects both None and int for a `d_` + key, so uploading one would fail the whole row instead of just losing a + diagnostic column. check_test_failure separately hard-fails a gen_only run + whose mean is absent, before results are uploaded. """ for metric_name in PERF_METRIC_LOG_QUERIES: new_data[f"d_{metric_name}"] = metrics[metric_name] if spec_decoding: new_data["d_al"] = metrics["al"] if benchmark_mode == "gen_only": - new_data["d_mean_gen_worker_per_iter_device_step_time"] = metrics[ - "mean_gen_worker_per_iter_device_step_time" - ] + for metric_name in GEN_ONLY_DEVICE_STEP_TIME_METRICS: + value = metrics.get(metric_name) + if value is None: + continue + new_data[f"d_{metric_name}"] = float(value) # Metrics where larger is better @@ -410,8 +553,16 @@ def add_perf_metric_value( "d_mean_e2el", "d_median_e2el", "d_p99_e2el", - # gen_only-only: per-iter device step time averaged across gen workers + # gen_only-only: per-iter device step time across gen workers. Lower is + # better for all five, including the spread statistics -- a tighter + # distribution is a more trustworthy measurement as well as a steadier + # workload. Only the mean is listed in regression_metrics; the other four + # get baselines but cannot fail a build (see check_regression). "d_mean_gen_worker_per_iter_device_step_time", + "d_median_gen_worker_per_iter_device_step_time", + "d_std_gen_worker_per_iter_device_step_time", + "d_p75_gen_worker_per_iter_device_step_time", + "d_p99_gen_worker_per_iter_device_step_time", ] # Default key metrics that determine regression (throughput metrics only). @@ -1420,30 +1571,45 @@ def _append_gen_worker_device_step_time( pending_device_step_time: List[dict], outputs: List[str], ) -> None: - """Wait for GEN log flush, then append each pending client metric. + """Wait for GEN log flush, then append each pending client's metrics. A sentinel timeout is a bounded teardown fallback, not a reason to discard metrics that are already present in the GEN logs. If the fallback parse finds no usable metric, check_test_failure still fails the gen_only run before results are uploaded. + + Five lines are written, one statistic each -- see + GEN_ONLY_PERF_METRIC_LOG_QUERIES for why they must not share a leading + word. The mean keeps its original wording and 2 decimals so existing + log readers and dashboards are unaffected; the four new lines use 4 + decimals because the stdev of a healthy run is O(0.1 ms) and would + round to two significant figures away at 2. """ if not pending_device_step_time: return self.wait_for_gen_log_sentinels() for record in pending_device_step_time: - device_step_time_mean = parse_gen_worker_device_step_time( + stats = parse_gen_worker_device_step_time( self.test_output_dir, self.num_gen_servers, start_offsets=record["start_offsets"], ) - if device_step_time_mean is None: + if stats is None: continue - summary_line = f"Average Per Iter Device Step Time (ms): {device_step_time_mean:.2f}" + summary_lines = "\n".join( + [ + f"Average Per Iter Device Step Time (ms): {stats.mean:.2f}", + f"Median Per Iter Device Step Time (ms): {stats.median:.4f}", + f"Stdev Per Iter Device Step Time (ms): {stats.std:.4f}", + f"P75 Per Iter Device Step Time (ms): {stats.p75:.4f}", + f"P99 Per Iter Device Step Time (ms): {stats.p99:.4f}", + ] + ) with open(record["benchmark_file_path"], "a") as benchmark_ctx: - benchmark_ctx.write(f"\n{summary_line}\n") + benchmark_ctx.write(f"\n{summary_lines}\n") idx = record["output_index"] - outputs[idx] = f"{outputs[idx]}\n{summary_line}\n" + outputs[idx] = f"{outputs[idx]}\n{summary_lines}\n" def get_server_logs(self, server_idx: int) -> List[str]: server_logs = [] diff --git a/tests/unittest/scripts/test_perf_sanity_helpers.py b/tests/unittest/scripts/test_perf_sanity_helpers.py index 941e787e357b..f309c2fe85f2 100644 --- a/tests/unittest/scripts/test_perf_sanity_helpers.py +++ b/tests/unittest/scripts/test_perf_sanity_helpers.py @@ -122,9 +122,9 @@ def parse_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: list[int], - ) -> float: + ) -> perf_sanity._DeviceStepTimeStats: parse_calls.append((output_dir, num_gen_servers, start_offsets)) - return 7.25 + return perf_sanity._DeviceStepTimeStats(mean=7.25, median=7.2, std=0.115, p75=7.3, p99=7.42) monkeypatch.setattr( perf_sanity, @@ -135,7 +135,434 @@ def parse_device_step_time( commands._append_gen_worker_device_step_time(pending, outputs) assert parse_calls == [(str(tmp_path), 2, [10, 20])] - assert outputs == ["benchmark output\nAverage Per Iter Device Step Time (ms): 7.25\n"] - assert benchmark_log.read_text(encoding="utf-8").endswith( - "\nAverage Per Iter Device Step Time (ms): 7.25\n" + expected = ( + "Average Per Iter Device Step Time (ms): 7.25\n" + "Median Per Iter Device Step Time (ms): 7.2000\n" + "Stdev Per Iter Device Step Time (ms): 0.1150\n" + "P75 Per Iter Device Step Time (ms): 7.3000\n" + "P99 Per Iter Device Step Time (ms): 7.4200\n" ) + assert outputs == [f"benchmark output\n{expected}"] + assert benchmark_log.read_text(encoding="utf-8").endswith(f"\n{expected}") + + +def test_missing_device_step_time_appends_nothing( + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + """A None parse must leave the log untouched. + + check_test_failure raises on the absent mean later; writing a partial or + placeholder line here would upload a fabricated number instead. + """ + benchmark_log = tmp_path / "trtllm-benchmark.0.0.log" + benchmark_log.write_text("benchmark output", encoding="utf-8") + outputs = ["benchmark output"] + pending = [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_log), + "start_offsets": [0, 0], + } + ] + commands = perf_sanity.DisaggTestCmds( + server_cmds=[], + client_cmds={}, + timeout=1, + hostname="localhost", + disagg_serving_type="BENCHMARK", + num_ctx_servers=1, + num_gen_servers=2, + output_dir=str(tmp_path), + test_output_dir=str(tmp_path), + ) + monkeypatch.setattr( + perf_sanity.DisaggTestCmds, + "wait_for_gen_log_sentinels", + lambda self: True, + ) + monkeypatch.setattr( + perf_sanity, + "parse_gen_worker_device_step_time", + lambda *args, **kwargs: None, + ) + + commands._append_gen_worker_device_step_time(pending, outputs) + + assert outputs == ["benchmark output"] + assert benchmark_log.read_text(encoding="utf-8") == "benchmark output" + + +# --------------------------------------------------------------------------- +# Gen-worker per-iteration device step time +# --------------------------------------------------------------------------- + + +def _iter_line( + iter_no: int, + nsr: int, + device_step_time: str, + ngen: int = 256, + host_step_time: float = 7.4, +) -> str: + """One gen-worker iteration log line, in py_executor.py's real format. + + Keep the ' = ' spelling and the field order: the parsers depend on both. + """ + return ( + f"[TRT-LLM] [I] [_torch][RANK 0] iter = {iter_no}, global_rank = 0, " + f"rank = 0, num_scheduled_requests = {nsr}, kv_cache_util = 0.1, " + f"currank_total_requests = 0/1, host_step_time = {host_step_time}ms, " + f"prev_device_step_time = {device_step_time}, " + "timestamp = 08-23-2026 01:02:03, " + "states = {'num_ctx_requests': 0, 'num_ctx_tokens': 0, " + f"'num_generation_tokens': {ngen}}}" + ) + + +def _write_gen_log(tmp_path: Path, index: int, lines: list[str]) -> None: + path = tmp_path / f"gen_server_{index}.log" + path.write_text("\n".join(lines) + "\n", encoding="utf-8") + + +def _scan(tmp_path: Path, num_gen_servers: int = 1) -> list[list]: + return perf_sanity._scan_gen_worker_device_step_time(str(tmp_path), num_gen_servers, None) + + +def test_empty_iteration_successor_is_excluded(tmp_path: Path) -> None: + """Nvbugs 6627789, verbatim from the culprit run's gen_server_0.log. + + iter 259 scheduled zero requests and spent 1456.7 ms idle; the device + reports that idle period as iter 260's prev_device_step_time. Averaging it + in turned an unchanged ~7.3 ms workload into a +19% "regression". + """ + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(258, 1, "7.326848030090332ms", host_step_time=7.426261901855469), + _iter_line(259, 0, "7.391776084899902ms", host_step_time=1456.6991329193115), + _iter_line(260, 1, "1450.6143798828125ms", host_step_time=2.572298049926758), + _iter_line(261, 1, "7.31ms"), + ], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [ + 7.326848030090332, + 7.391776084899902, + 7.31, + ], "the 1450.61 ms row must be dropped, and only that row" + + +def test_the_empty_iteration_row_itself_is_kept(tmp_path: Path) -> None: + """Iter 259's own value describes iter 258, which did real work.""" + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(258, 1, "7.32ms"), + _iter_line(259, 0, "7.39ms"), + _iter_line(260, 1, "1450.61ms"), + ], + ) + + rows = _scan(tmp_path) + + assert 7.39 in [row.device_step_time for row in rows[0]] + + +def test_non_adjacent_predecessor_does_not_trigger_the_exclusion( + tmp_path: Path, +) -> None: + """The guard fails toward keeping the row. + + Under rank interleaving or a counter reset the previous *line* is not the + previous *iteration*, so its num_scheduled_requests says nothing about + what this row measured. Dropping real data is the worse error. + """ + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(100, 0, "7.30ms"), + _iter_line(200, 1, "999.0ms"), + ], + ) + + rows = _scan(tmp_path) + + assert 999.0 in [row.device_step_time for row in rows[0]] + + +def test_unparseable_predecessor_does_not_trigger_the_exclusion( + tmp_path: Path, +) -> None: + _write_gen_log( + tmp_path, + 0, + [ + "[TRT-LLM] [I] iter = ?, num_scheduled_requests = ?, prev_device_step_time = 1.0ms", + _iter_line(201, 1, "999.0ms"), + ], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [999.0] + + +def test_warmup_iterations_are_excluded(tmp_path: Path) -> None: + """Iter 0/1 include KV-cache transfer wait; 2-4 have not reached steady state.""" + _write_gen_log( + tmp_path, + 0, + [_iter_line(n, 1, f"{n}.0ms") for n in range(1, 8)], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [5.0, 6.0, 7.0] + + +def test_na_device_step_time_is_skipped(tmp_path: Path) -> None: + """Iter 1's 'N/A' does not match the value regex, and must not crash.""" + _write_gen_log( + tmp_path, + 0, + [_iter_line(5, 1, "N/A"), _iter_line(6, 1, "7.3ms")], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [7.3] + + +def test_unparseable_num_generation_tokens_is_retained_as_none( + tmp_path: Path, +) -> None: + """Nvbugs 6487036 / 6487040: the field rendered as tensor(256). + + Such a row keeps its device step time so the all-rows fallback in + _stats_at_mode_ngen has something to work with. + """ + line = _iter_line(5, 1, "7.3ms").replace("'num_generation_tokens': 256", "") + _write_gen_log(tmp_path, 0, [line]) + + rows = _scan(tmp_path) + + assert rows[0][0].ngen is None + assert rows[0][0].device_step_time == 7.3 + + +def test_retention_is_capped(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> None: + """The percentiles need the sample, so a pathological log must be bounded.""" + monkeypatch.setattr(perf_sanity, "_MAX_RETAINED_ITER_ROWS", 3) + _write_gen_log( + tmp_path, + 0, + [_iter_line(n, 1, f"{n}.0ms") for n in range(5, 25)], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [5.0, 6.0, 7.0] + + +def test_missing_gen_log_is_skipped_not_fatal(tmp_path: Path) -> None: + _write_gen_log(tmp_path, 1, [_iter_line(5, 1, "7.3ms")]) + + rows = _scan(tmp_path, num_gen_servers=3) + + assert len(rows) == 1 + + +def test_start_offsets_slice_each_clients_own_segment(tmp_path: Path) -> None: + """Per-client byte offsets, not one global average over the whole run.""" + first = _iter_line(5, 1, "1.0ms") + second = _iter_line(6, 1, "2.0ms") + path = tmp_path / "gen_server_0.log" + path.write_text(f"{first}\n{second}\n", encoding="utf-8") + + rows = perf_sanity._scan_gen_worker_device_step_time(str(tmp_path), 1, [len(first) + 1]) + + assert [row.device_step_time for row in rows[0]] == [2.0] + + +def test_stdev_of_fewer_than_two_samples_is_zero() -> None: + assert perf_sanity._stdev([]) == 0.0 + assert perf_sanity._stdev([7.3]) == 0.0 + + +def test_stdev_uses_ddof_one() -> None: + assert perf_sanity._stdev([1.0, 3.0]) == pytest.approx(1.4142135623730951) + + +def _rows(*specs: tuple[int | None, float]) -> list: + return [perf_sanity._IterRow(ngen=ngen, device_step_time=v) for ngen, v in specs] + + +def test_all_five_statistics_on_a_known_sample() -> None: + values = [1.0, 2.0, 3.0, 4.0, 100.0] + stats = perf_sanity._stats_at_mode_ngen([_rows(*((256, v) for v in values))]) + + assert stats.mean == pytest.approx(22.0) + assert stats.median == pytest.approx(3.0) + assert stats.std == pytest.approx(43.617656975128774) + assert stats.p75 == pytest.approx(4.0) + assert stats.p99 == pytest.approx(96.16) + + +def test_only_the_mode_num_generation_tokens_bucket_is_used() -> None: + """Concurrency ramps down at the tail; those iterations do less work.""" + stats = perf_sanity._stats_at_mode_ngen( + [_rows((256, 7.0), (256, 7.0), (256, 7.0), (8, 1.0), (4, 1.0))] + ) + + assert stats.mean == pytest.approx(7.0) + + +def test_mode_bucket_tie_prefers_the_larger_token_count() -> None: + stats = perf_sanity._stats_at_mode_ngen([_rows((256, 7.0), (8, 1.0))]) + + assert stats.mean == pytest.approx(7.0) + + +def test_no_parseable_token_count_falls_back_to_every_row() -> None: + stats = perf_sanity._stats_at_mode_ngen([_rows((None, 6.0), (None, 8.0))]) + + assert stats.mean == pytest.approx(7.0) + + +def test_statistics_are_averaged_unweighted_across_workers() -> None: + """The same per-file rule the mean has always used, for all five.""" + stats = perf_sanity._stats_at_mode_ngen( + [ + _rows((256, 6.0)), + _rows((256, 8.0), (256, 8.0), (256, 8.0)), + ] + ) + + assert stats.mean == pytest.approx(7.0) + assert stats.median == pytest.approx(7.0) + + +def test_no_usable_rows_reports_none() -> None: + assert perf_sanity._stats_at_mode_ngen([]) is None + + +def test_parse_gen_worker_device_step_time_end_to_end(tmp_path: Path) -> None: + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(5, 1, "7.0ms"), + _iter_line(6, 0, "7.0ms"), + _iter_line(7, 1, "500.0ms"), + _iter_line(8, 1, "9.0ms"), + ], + ) + + stats = perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 1) + + assert stats.mean == pytest.approx(23.0 / 3) + assert stats.median == pytest.approx(7.0) + + +def test_parse_gen_worker_device_step_time_reports_none_with_no_logs( + tmp_path: Path, +) -> None: + assert perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 2) is None + + +def test_every_written_line_parses_and_none_shadows_another( + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + """Round trip: the five appended lines through the upload-side regexes. + + parse_metrics_from_output is a closure inside PerfSanityTestConfig, so its + first-match-per-line loop is reproduced here. That loop is the reason the + five lines must carry mutually exclusive leading words -- a shared prefix + would silently shadow whichever pattern lost the ordering race. + """ + benchmark_log = tmp_path / "trtllm-benchmark.0.0.log" + benchmark_log.write_text("benchmark output", encoding="utf-8") + outputs = [""] + commands = perf_sanity.DisaggTestCmds( + server_cmds=[], + client_cmds={}, + timeout=1, + hostname="localhost", + disagg_serving_type="BENCHMARK", + num_ctx_servers=1, + num_gen_servers=1, + output_dir=str(tmp_path), + test_output_dir=str(tmp_path), + ) + monkeypatch.setattr( + perf_sanity.DisaggTestCmds, + "wait_for_gen_log_sentinels", + lambda self: True, + ) + _write_gen_log( + tmp_path, + 0, + [_iter_line(n, 1, f"{7.0 + n / 100:.4f}ms") for n in range(5, 30)], + ) + + commands._append_gen_worker_device_step_time( + [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_log), + "start_offsets": None, + } + ], + outputs, + ) + + metrics: dict[str, float] = {} + for line in outputs[0].split("\n"): + for name, regex in perf_sanity.GEN_ONLY_PERF_METRIC_LOG_QUERIES.items(): + if name in metrics: + continue + match = regex.search(line) + if match: + metrics[name] = float(match.group(1)) + break + + assert set(metrics) == set(perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS) + assert metrics["mean_gen_worker_per_iter_device_step_time"] == pytest.approx(7.17, abs=0.01) + assert metrics["std_gen_worker_per_iter_device_step_time"] > 0.0 + + +def test_every_device_step_time_metric_is_a_minimize_metric() -> None: + """A metric absent from both lists raises ValueError in check_regression.""" + for name in perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS: + assert f"d_{name}" in perf_sanity.MINIMIZE_METRICS + + +def test_add_perf_metric_value_skips_absent_statistics() -> None: + """TypeCheckForOpenSearchDB rejects both None and int for a d_ key.""" + metrics = dict.fromkeys(perf_sanity.PERF_METRIC_LOG_QUERIES, 1.0) + metrics["mean_gen_worker_per_iter_device_step_time"] = 7 + + new_data: dict = {} + perf_sanity.add_perf_metric_value(new_data, metrics, False, "gen_only") + + assert new_data["d_mean_gen_worker_per_iter_device_step_time"] == 7.0 + assert isinstance(new_data["d_mean_gen_worker_per_iter_device_step_time"], float) + assert "d_p99_gen_worker_per_iter_device_step_time" not in new_data + + +def test_add_perf_metric_value_omits_the_family_outside_gen_only() -> None: + """e2e and ctx_only never emit these lines, so they must not be uploaded.""" + metrics = dict.fromkeys(perf_sanity.PERF_METRIC_LOG_QUERIES, 1.0) + metrics["mean_gen_worker_per_iter_device_step_time"] = 7.0 + + new_data: dict = {} + perf_sanity.add_perf_metric_value(new_data, metrics, False, "e2e") + + assert not [key for key in new_data if "gen_worker_per_iter" in key] From 66362336ea4b8e44c2dab856c2c3e66ea934ed73 Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Mon, 24 Aug 2026 20:42:06 -0700 Subject: [PATCH 4/7] Revert "[None][test] Enable warmup request for gen_only perf sanity lanes (#17098)" This reverts commit 77bc7f012cdfc86780b94931d5b97b79b0bffafd. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../integration/defs/perf/test_perf_sanity.py | 21 +------------------ 1 file changed, 1 insertion(+), 20 deletions(-) diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index 382c6786cb91..8ccd4724bd04 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -1054,11 +1054,6 @@ def __init__( self.model_path = "" self.dataset_file = client_config_data.get("dataset_file", "") self.use_nv_sa_benchmark = client_config_data.get("use_nv_sa_benchmark", False) - # Derived from lane identity only (gen_only + concurrency == 1); do not - # set this from lane YAML. warmup is intentionally not a baseline match - # key, which is only sound while its value stays fully determined by - # benchmark_mode and concurrency. - self.warmup = client_config_data.get("warmup", False) self.env_vars = env_vars # spec_decoding flag is retained for DB matching (b_eos column). --ignore-eos # is now always passed; output-length stability with spec decoding comes from @@ -1137,15 +1132,11 @@ def _to_default_benchmark_cmd(self) -> List[str]: str(self.concurrency * self.iterations), "--max-concurrency", str(self.concurrency), + "--no-test-input", "--percentile-metrics", "ttft,tpot,itl,e2el", "--ignore-eos", ] - # benchmark_serving's initial single-prompt test run (excluded from - # metrics) doubles as a warmup request; keep it disabled unless the - # lane requests one. - if not self.warmup: - benchmark_cmd.append("--no-test-input") if dataset_path: benchmark_cmd.append("--dataset-name") benchmark_cmd.append("trtllm_custom") @@ -1203,7 +1194,6 @@ def to_db_data(self) -> dict: "b_trust_remote_code": self.trust_remote_code, "b_use_nv_sa_benchmark": self.use_nv_sa_benchmark, "b_eos": self.spec_decoding, - "b_warmup": self.warmup, "s_client_log_link": "", "s_client_env_vars": self.env_vars, } @@ -2248,15 +2238,6 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): "use_nv_sa_benchmark": use_nv_sa_benchmark, "accuracy_config": accuracy_data, "only_run_accuracy": only_run_accuracy, - # gen_only measures a single round (iterations forced to 1 - # above), so one-time costs like the cache transceiver's lazy - # connection setup would otherwise land entirely on the - # measured TTFT. Scoped to concurrency == 1: the gen executor's - # fill gate (TLLM_BENCHMARK_REQ_QUEUES_SIZE) only opens once - # `concurrency` requests are queued, so a lone warmup request - # would deadlock higher-concurrency lanes — which amortize the - # cold start anyway. - "warmup": benchmark_mode == "gen_only" and concurrency == 1, } client_config = ClientConfig( client_config_data, From 096fb51842f90b48304cc039ca9b11d1a79709ea Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Mon, 24 Aug 2026 20:49:38 -0700 Subject: [PATCH 5/7] [None][test] Gate the gen_only per-iter device step time median The mean alone cannot distinguish a real slowdown from a single anomalous iteration: both raise it. The median moves only when the typical iteration moves, so gating the pair makes the CI report self-diagnosing -- both up is a regression, mean-only up is a tail artifact worth reading the std for. The median has no baseline history yet. check_regression skips any metric whose baseline is absent or non-positive (continue), so it is inert until enough runs accrue and cannot fail a build before then. check_test_failure still keys its hard failure on the mean alone. All five statistics come from the same _DeviceStepTimeStats, so the mean is absent only if all of them are. The gated list is now the module constant GEN_ONLY_REGRESSION_METRICS, with tests pinning that every gated name is both emitted into the benchmark log and present in MINIMIZE_METRICS -- check_regression only iterates the maximize and minimize lists, so a gated name absent from both would look armed while never being checked. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../defs/perf/README_test_perf_sanity.md | 4 +- .../integration/defs/perf/test_perf_sanity.py | 39 +++++++++++++++---- .../scripts/test_perf_sanity_helpers.py | 15 +++++++ 3 files changed, 49 insertions(+), 9 deletions(-) diff --git a/tests/integration/defs/perf/README_test_perf_sanity.md b/tests/integration/defs/perf/README_test_perf_sanity.md index a97b867e07af..1af2f9af4ebf 100644 --- a/tests/integration/defs/perf/README_test_perf_sanity.md +++ b/tests/integration/defs/perf/README_test_perf_sanity.md @@ -27,7 +27,9 @@ For the underlying regression pipeline architecture (three-layer design, baselin | `MINIMIZE_METRICS` | 14 | TTFT, ITL, E2EL latencies (mean/median/P99 for each) + the five gen_only-only `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` | | `REGRESSION_METRICS` | 2 default | `d_token_throughput`, `d_total_token_throughput` — gate pass/fail for all modes **except disagg gen_only**. `d_al` is appended at runtime when any client runs spec decoding. | -**Disagg gen_only override**: For `disagg_upload-gen_only-*` tests, regression is gated **only** on `d_mean_gen_worker_per_iter_device_step_time`. Token-based throughput numbers are dominated by KV-cache transfer time in gen_only mode and are not a useful regression signal there. The other four device-step-time statistics are uploaded for diagnosis but are **not** gated. +**Disagg gen_only override**: For `disagg_upload-gen_only-*` tests, regression is gated on `d_mean_gen_worker_per_iter_device_step_time` **and** `d_median_gen_worker_per_iter_device_step_time`. Token-based throughput numbers are dominated by KV-cache transfer time in gen_only mode and are not a useful regression signal there. The two are gated together because they fail on different shapes of slowdown: the mean catches a cost spread thinly across many iterations, the median catches a shift in the typical iteration while ignoring outliers. A real slowdown moves both; a single anomalous iteration moves only the mean. `d_{std,p75,p99}_...` are uploaded for diagnosis but are **not** gated. + +A newly added gated metric has no baseline history, and `check_regression` skips any metric whose baseline is absent or non-positive (`continue`), so the median cannot fail a build until enough runs accrue. #### `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` (gen_only only) diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index 8ccd4724bd04..dc2e17f2b9c7 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -186,9 +186,10 @@ def server_ready_timeout(default: int, mode: str) -> int: # The distribution is published, not just the mean, because the mean alone is # not self-diagnosing: a single anomalous iteration can move it by >30% while # the workload is unchanged (nvbugs 6627789), and the only way a reader can -# tell that from a real regression is to see the spread next to it. Only the -# mean is regression-gated (see regression_metrics in the gen_only branch); -# the other four are uploaded for diagnosis. +# tell that from a real regression is to see the spread next to it. The mean +# and median are both regression-gated (see regression_metrics in the gen_only +# branch) because they fail on different shapes of slowdown; std/p75/p99 are +# uploaded for diagnosis only. # # One statistic per line, and the leading words must stay mutually exclusive: # parse_metrics_from_output breaks out of the regex loop on the first match per @@ -213,7 +214,8 @@ def server_ready_timeout(default: int, mode: str) -> int: } # Every gen_only device-step-time metric, in log-line order. The mean is first -# because it is the gated one and the only one check_test_failure keys on. +# because it is the one check_test_failure keys on; mean and median are both +# regression-gated, std/p75/p99 are diagnostic. GEN_ONLY_DEVICE_STEP_TIME_METRICS = ( "mean_gen_worker_per_iter_device_step_time", "median_gen_worker_per_iter_device_step_time", @@ -222,6 +224,21 @@ def server_ready_timeout(default: int, mode: str) -> int: "p99_gen_worker_per_iter_device_step_time", ) +# The regression gate for disagg gen_only lanes. Mean and median are both gated +# because they fail on different shapes of slowdown: the mean catches a cost +# spread thinly across many iterations, the median catches a shift in the typical +# iteration while ignoring outliers. A real slowdown moves both; a single +# anomalous iteration moves only the mean, so the pair is self-diagnosing on the +# CI report itself. std/p75/p99 are uploaded for diagnosis but not gated. +# +# Every name here must also appear in MINIMIZE_METRICS (or MAXIMIZE_METRICS): +# check_regression only iterates those two lists, so a gated name absent from +# both is silently never checked. test_perf_sanity_helpers.py pins that. +GEN_ONLY_REGRESSION_METRICS = ( + "d_mean_gen_worker_per_iter_device_step_time", + "d_median_gen_worker_per_iter_device_step_time", +) + # Per-iter prev_device_step_time logged by each gen worker. Example line: # [TRT-LLM] [I] [_torch][RANK 0] iter = 5, global_rank = 0, ..., # host_step_time = 6.79ms, prev_device_step_time = 6.94ms, ..., @@ -556,7 +573,7 @@ def add_perf_metric_value( # gen_only-only: per-iter device step time across gen workers. Lower is # better for all five, including the spread statistics -- a tighter # distribution is a more trustworthy measurement as well as a steadier - # workload. Only the mean is listed in regression_metrics; the other four + # workload. Mean and median are listed in regression_metrics; std/p75/p99 # get baselines but cannot fail a build (see check_regression). "d_mean_gen_worker_per_iter_device_step_time", "d_median_gen_worker_per_iter_device_step_time", @@ -2534,8 +2551,10 @@ def check_test_failure(self): f"is missing 'Mean Avg Decoded Tokens per Iter' in benchmark output. " ) # gen_only tests must report mean_gen_worker_per_iter_device_step_time - # (parsed from gen_server_*.log). It is the sole regression metric for - # gen_only, so a missing value must hard-fail rather than silently upload. + # (parsed from gen_server_*.log). It is a regression metric for gen_only, + # so a missing value must hard-fail rather than silently upload. Checking + # the mean alone is sufficient: all five statistics come from the same + # _DeviceStepTimeStats, so the mean is absent only if all of them are. if ( self.runtime == "multi_node_disagg_server" and self.server_configs[server_idx][2].benchmark_mode == "gen_only" @@ -2723,7 +2742,11 @@ def add_dict_prefix(config_dict: dict, prefix_name: str) -> dict: if self.runtime == "multi_node_disagg_server" and any( sc[2].benchmark_mode == "gen_only" for sc in self.server_configs ): - regression_metrics = ["d_mean_gen_worker_per_iter_device_step_time"] + # See GEN_ONLY_REGRESSION_METRICS for why the median is gated too. + # It has no baseline history yet, and check_regression skips any + # metric whose baseline is absent or non-positive, so it stays inert + # until enough runs accrue -- it cannot fail a build before then. + regression_metrics = list(GEN_ONLY_REGRESSION_METRICS) else: regression_metrics = list(REGRESSION_METRICS) has_spec_decoding = any( diff --git a/tests/unittest/scripts/test_perf_sanity_helpers.py b/tests/unittest/scripts/test_perf_sanity_helpers.py index f309c2fe85f2..65af3d0b32ef 100644 --- a/tests/unittest/scripts/test_perf_sanity_helpers.py +++ b/tests/unittest/scripts/test_perf_sanity_helpers.py @@ -566,3 +566,18 @@ def test_add_perf_metric_value_omits_the_family_outside_gen_only() -> None: perf_sanity.add_perf_metric_value(new_data, metrics, False, "e2e") assert not [key for key in new_data if "gen_worker_per_iter" in key] + + +def test_every_gated_metric_is_checkable() -> None: + """check_regression only iterates maximize + minimize; a gated name absent + from both is silently never checked, so the gate would look armed and be + dead. Pin the pair so adding a third gated statistic cannot regress it.""" + checkable = set(perf_sanity.MINIMIZE_METRICS) | set(perf_sanity.MAXIMIZE_METRICS) + for name in perf_sanity.GEN_ONLY_REGRESSION_METRICS: + assert name in checkable, f"{name} is gated but check_regression never sees it" + + +def test_every_gated_metric_is_actually_emitted() -> None: + """A gated metric the log never carries is skipped by 'not in new_data'.""" + emitted = {f"d_{name}" for name in perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS} + assert set(perf_sanity.GEN_ONLY_REGRESSION_METRICS) <= emitted From 9002c9a0018bfc395c3e4603897de605ec6f2154 Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Mon, 24 Aug 2026 21:44:48 -0700 Subject: [PATCH 6/7] [None][test] Key the empty-iteration exclusion per emitting rank Addresses a review finding on PR 18011. _scan_gen_worker_device_step_time kept ONE prev_iter/prev_nsr slot per file, so two ranks interleaved in one gen_server log would be read as each other's predecessor. That degrades asymmetrically, and the harmful direction is the silent one: a foreign rank's line landing between the num_scheduled_requests = 0 line and its successor supplies a nonzero num_scheduled_requests, so the idle-contaminated row SURVIVES -- the exclusion quietly stops excluding while still looking armed. The mirror case (a foreign idle iteration dropping one ordinary row) is harmless. Predecessor state is now keyed on the emitting rank, read off the same line via global_rank (unambiguous, unlike the trailing 'rank = '). A line carrying neither falls into a single bucket, reproducing the previous single-rank behaviour exactly. This closes a latent, configuration-dependent hole rather than a live defect: py_executor.py logs only rank 0 unless TLLM_PROFILE_LOG_RANKS is set (default "0"), no lane in tests/ or jenkins/ sets it, and both nvbug 6627789 artifact sets are 518/518 global_rank = 0. But server_env_var is free-form lane YAML, so a lane could set it. Also corrects two docstrings that still said the mean is the only regression-gated statistic; the median has been gated since 096fb518. Two tests pin both directions, and replaying the real artifacts confirms the change is a no-op on single-rank data: every statistic reproduces and exactly one row is still dropped per file. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- .../defs/perf/README_test_perf_sanity.md | 2 +- .../integration/defs/perf/test_perf_sanity.py | 50 ++++++++++++------ .../scripts/test_perf_sanity_helpers.py | 51 ++++++++++++++++++- 3 files changed, 85 insertions(+), 18 deletions(-) diff --git a/tests/integration/defs/perf/README_test_perf_sanity.md b/tests/integration/defs/perf/README_test_perf_sanity.md index 1af2f9af4ebf..144d24f6d795 100644 --- a/tests/integration/defs/perf/README_test_perf_sanity.md +++ b/tests/integration/defs/perf/README_test_perf_sanity.md @@ -45,7 +45,7 @@ The device value reported at iter `N` is the device step time of iter `N-1` (dev 1. Immediately before launching each client, snapshot `os.path.getsize()` of every `gen_server_{i}.log`. After the client's benchmark subprocess returns, only the bytes between that snapshot and current EOF are parsed — so each client gets its own segment of gen-worker iterations rather than sharing a single global average. 2. Per file (per segment), collect the `prev_device_step_time` of every *usable* iteration. A row is usable when all of the following hold: - `iter >= 5` — iter 0/1 include KV-cache transfer wait time, and iters 2-4 are warmup that has not yet reached steady state. Lines where `prev_device_step_time = N/A` (e.g. iter 1) do not match the parser and are skipped anyway. - - Its immediately preceding iteration did **not** report `num_scheduled_requests = 0`. Such an iteration did no GPU work, so its loop period is pure idle (waiting on KV-cache transfer) — and because the device runs async, that idle period is what the *next* row's `prev_device_step_time` reports. One such row inflated this mean by 19% on nvbugs 6627789 while the steady-state iterations were unchanged at ~7.3 ms. The `nsr = 0` row itself is kept: its own value describes the previous iteration, which did do work. The exclusion requires the predecessor's iter number to be exactly `cur_iter - 1`; if it is not adjacent, or did not parse, the row is kept (failing toward inclusion rather than silently dropping real data). + - Its immediately preceding iteration did **not** report `num_scheduled_requests = 0`. Such an iteration did no GPU work, so its loop period is pure idle (waiting on KV-cache transfer) — and because the device runs async, that idle period is what the *next* row's `prev_device_step_time` reports. One such row inflated this mean by 19% on nvbugs 6627789 while the steady-state iterations were unchanged at ~7.3 ms. The `nsr = 0` row itself is kept: its own value describes the previous iteration, which did do work. The exclusion requires the predecessor's iter number to be exactly `cur_iter - 1`; if it is not adjacent, or did not parse, the row is kept (failing toward inclusion rather than silently dropping real data). "Predecessor" is tracked **per emitting rank** (`global_rank`, read off the same line), so ranks interleaved in one file are never read as each other's predecessor. `py_executor.py` logs only rank 0 unless `TLLM_PROFILE_LOG_RANKS` is set and no lane sets it today — but a single shared predecessor slot would fail in the *wrong* direction on a mixed-rank file, letting a foreign rank's nonzero `num_scheduled_requests` mask the idle iteration so the exclusion quietly stops excluding while still looking armed. 3. Per file, bucket the usable rows by `num_generation_tokens` and keep only the **mode** bucket (ties → the larger token count). Concurrency ramps down at the tail of a run, so the trailing iterations do less work per step and are not comparable to the plateau. A file with no parseable `num_generation_tokens` anywhere falls back to all of its usable rows (nvbugs 6487036 / 6487040: the field rendered as `tensor(256)` and matched nothing). 4. Compute mean, median, stdev (ddof=1, `0.0` for fewer than two samples), P75 and P99 of that bucket per file, then average each statistic across files (unweighted) → the per-client metric values. Averaging a median across workers is not itself a median of the pooled sample; it is the same unweighted per-file rule the mean has always used, kept for consistency and continuity of baselines. 5. Because the percentiles and stdev need the whole sample, the scan retains rows rather than streaming; retention is capped per worker (`_MAX_RETAINED_ITER_ROWS`) so a pathological log cannot grow it without bound. diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index dc2e17f2b9c7..5dfa42f0c955 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -263,6 +263,20 @@ def server_ready_timeout(default: int, mode: str) -> int: # py_executor.py's iteration log actually emits (do not copy the ': ' form in # examples/wide_ep/slurm_scripts/process_gen_iterlog.py, which is stale). _ITER_NSR_RE = re.compile(r"iter\s*=\s*(\d+),.*?num_scheduled_requests\s*=\s*(\d+)") +# The emitting rank, used to key _scan_gen_worker_device_step_time's predecessor +# bookkeeping so that interleaved ranks in one file cannot be read as each +# other's predecessor. +# py_executor.py only logs rank 0 by default (TLLM_PROFILE_LOG_RANKS, default +# "0"), and no lane sets that variable today -- both artifact sets for nvbug +# 6627789 are 518/518 global_rank = 0. But the variable accepts "all" or a rank +# list and lane YAML can inject arbitrary server env vars, and in a mixed-rank +# file the failure would be silent in the WRONG direction: the contaminated +# row's immediate predecessor line would usually belong to a different rank, +# whose num_scheduled_requests is nonzero, so the exclusion would quietly stop +# excluding while still looking armed. Matching global_rank (not the trailing +# 'rank = ') keeps this unambiguous; a line with neither shares one bucket, +# which is exactly the pre-existing single-rank behaviour. +_ITER_RANK_RE = re.compile(r"global_rank\s*=\s*(\d+)") # Hard cap on retained per-iteration samples per gen worker. The percentile and # stdev statistics need the whole sample, so the scan cannot be O(1) memory the @@ -349,10 +363,12 @@ def _scan_gen_worker_device_step_time( kernel spent, which is how nvbug 6627789 read a +19% regression out of two runs whose steady-state iterations were both ~7.3 ms. - The row is dropped only when the immediately preceding parsed line is - provably the predecessor iteration: pred_iter == cur_iter - 1. If the - predecessor is missing, unparseable, or non-adjacent (interleaved ranks - writing to a shared log, a restarted iteration counter), the row is KEPT. + The row is dropped only when that rank's immediately preceding parsed line + is provably the predecessor iteration: pred_iter == cur_iter - 1. + Predecessor state is kept per emitting rank (_ITER_RANK_RE), so ranks + interleaved in one file are never read as each other's predecessor. If the + predecessor is missing, unparseable, or non-adjacent (a restarted iteration + counter, the first line after a seek), the row is KEPT. That is the safe direction to fail: the exclusion is an accuracy improvement on a metric that must keep reporting, so a scan that cannot prove a row is idle-contaminated should behave exactly as it did before. @@ -380,8 +396,8 @@ def _scan_gen_worker_device_step_time( ) rows: List[_IterRow] = [] - prev_iter: Optional[int] = None - prev_nsr: Optional[int] = None + # rank -> (iter, num_scheduled_requests) of that rank's previous line. + prev_by_rank: Dict[Optional[int], Tuple[Optional[int], Optional[int]]] = {} with open(log_path, errors="replace") as f: if seek_to: f.seek(seek_to) @@ -391,13 +407,15 @@ def _scan_gen_worker_device_step_time( # the num_scheduled_requests tracking below needs to see. if "prev_device_step_time" not in line: continue - # Snapshot the predecessor before this line overwrites it. - pred_iter, pred_nsr = prev_iter, prev_nsr + # Snapshot this rank's predecessor before this line overwrites it. + rank_m = _ITER_RANK_RE.search(line) + rank = int(rank_m.group(1)) if rank_m is not None else None + pred_iter, pred_nsr = prev_by_rank.get(rank, (None, None)) nsr_m = _ITER_NSR_RE.search(line) if nsr_m is None: - prev_iter, prev_nsr = None, None + prev_by_rank[rank] = (None, None) else: - prev_iter, prev_nsr = int(nsr_m.group(1)), int(nsr_m.group(2)) + prev_by_rank[rank] = (int(nsr_m.group(1)), int(nsr_m.group(2))) m = _DEVICE_STEP_TIME_RE.search(line) if m is None: @@ -491,9 +509,10 @@ def parse_gen_worker_device_step_time( falls back to its whole sample rather than being dropped to None. Returns None only if no usable line is found in any file. - The mean is the regression-gated statistic; the other four are uploaded - for diagnosis, because a mean on its own cannot distinguish a slower - workload from one anomalous iteration. See + The mean and the median are the regression-gated statistics + (GEN_ONLY_REGRESSION_METRICS); the other three are uploaded for diagnosis, + because a mean on its own cannot distinguish a slower workload from one + anomalous iteration. See _scan_gen_worker_device_step_time for the empty-iteration exclusion and _stats_at_mode_ngen for the bucket selection. @@ -526,8 +545,9 @@ def add_perf_metric_value( - Adds `d_al` only when spec_decoding=True; non-spec rows omit it so OpenSearch baselines don't blend the two populations. - Adds the `d_*_gen_worker_per_iter_device_step_time` family only for the - disagg gen_only mode (the only mode that emits them). Of these only the - mean is regression-gated; the rest are uploaded for diagnosis. + disagg gen_only mode (the only mode that emits them). Of these the mean + and the median are regression-gated (GEN_ONLY_REGRESSION_METRICS); the + rest are uploaded for diagnosis. A missing or non-numeric gen_only statistic is omitted rather than forwarded: typeCheckForOpenSearchDB rejects both None and int for a `d_` diff --git a/tests/unittest/scripts/test_perf_sanity_helpers.py b/tests/unittest/scripts/test_perf_sanity_helpers.py index 65af3d0b32ef..0bbefc32fc1e 100644 --- a/tests/unittest/scripts/test_perf_sanity_helpers.py +++ b/tests/unittest/scripts/test_perf_sanity_helpers.py @@ -204,14 +204,18 @@ def _iter_line( device_step_time: str, ngen: int = 256, host_step_time: float = 7.4, + rank: int = 0, ) -> str: """One gen-worker iteration log line, in py_executor.py's real format. Keep the ' = ' spelling and the field order: the parsers depend on both. + rank defaults to 0 because that is the only rank py_executor.py logs unless + TLLM_PROFILE_LOG_RANKS is set; pass it to build a mixed-rank file. """ return ( - f"[TRT-LLM] [I] [_torch][RANK 0] iter = {iter_no}, global_rank = 0, " - f"rank = 0, num_scheduled_requests = {nsr}, kv_cache_util = 0.1, " + f"[TRT-LLM] [I] [_torch][RANK {rank}] iter = {iter_no}, " + f"global_rank = {rank}, " + f"rank = {rank}, num_scheduled_requests = {nsr}, kv_cache_util = 0.1, " f"currank_total_requests = 0/1, host_step_time = {host_step_time}ms, " f"prev_device_step_time = {device_step_time}, " "timestamp = 08-23-2026 01:02:03, " @@ -313,6 +317,49 @@ def test_unparseable_predecessor_does_not_trigger_the_exclusion( assert [row.device_step_time for row in rows[0]] == [999.0] +def test_interleaved_ranks_do_not_defeat_the_exclusion(tmp_path: Path) -> None: + """Predecessor state is per rank, so a foreign line cannot mask the idle one. + + py_executor.py logs rank 0 only unless TLLM_PROFILE_LOG_RANKS says otherwise, + but lane YAML can inject that variable. With one shared predecessor slot, + rank 1's line between rank 0's iters 259 and 260 would supply a nonzero + num_scheduled_requests and the 1450 ms row would survive -- the exclusion + silently off while still looking armed. + """ + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(258, 1, "7.32ms", rank=0), + _iter_line(259, 0, "7.39ms", rank=0), + _iter_line(259, 4, "7.40ms", rank=1), + _iter_line(260, 1, "1450.61ms", rank=0), + ], + ) + + rows = _scan(tmp_path) + + assert 1450.61 not in [row.device_step_time for row in rows[0]] + + +def test_another_ranks_idle_iteration_does_not_drop_a_valid_row( + tmp_path: Path, +) -> None: + """The mirror image: rank 1 going idle must not cost rank 0 a good sample.""" + _write_gen_log( + tmp_path, + 0, + [ + _iter_line(259, 0, "7.39ms", rank=1), + _iter_line(260, 1, "7.31ms", rank=0), + ], + ) + + rows = _scan(tmp_path) + + assert [row.device_step_time for row in rows[0]] == [7.39, 7.31] + + def test_warmup_iterations_are_excluded(tmp_path: Path) -> None: """Iter 0/1 include KV-cache transfer wait; 2-4 have not reached steady state.""" _write_gen_log( From d3853f91bc7f8131e91f72120c3f7b5905490d1e Mon Sep 17 00:00:00 2001 From: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> Date: Mon, 24 Aug 2026 21:53:32 -0700 Subject: [PATCH 7/7] [None][test] Fix pre-commit codespell and ruff D205 findings Two pre-commit hooks failed on this branch: - codespell: "unparseable" -> "unparsable" in a scanner docstring. Reworded rather than added to the hook's -L ignore list. The two test function names carrying the same spelling are renamed for consistency; codespell never flagged them because its tokenizer treats '_' as a word character, so a snake_case identifier is one token. - ruff D205: test_every_gated_metric_is_checkable's docstring ran its summary across three lines. Restructured into summary + blank line + body. No behaviour change. Verified with ruff 0.9.4 (the version pinned in .pre-commit-config.yaml), codespell with the CI -L arguments, the 33 helper unit tests, and a replay of both nvbug 6627789 artifact sets, whose statistics are unchanged. Signed-off-by: chenfeiz0326 <203214996+chenfeiz0326@users.noreply.github.com> --- tests/integration/defs/perf/test_perf_sanity.py | 2 +- tests/unittest/scripts/test_perf_sanity_helpers.py | 12 +++++++----- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index 5dfa42f0c955..cba9f548180c 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -367,7 +367,7 @@ def _scan_gen_worker_device_step_time( is provably the predecessor iteration: pred_iter == cur_iter - 1. Predecessor state is kept per emitting rank (_ITER_RANK_RE), so ranks interleaved in one file are never read as each other's predecessor. If the - predecessor is missing, unparseable, or non-adjacent (a restarted iteration + predecessor is missing, unparsable, or non-adjacent (a restarted iteration counter, the first line after a seek), the row is KEPT. That is the safe direction to fail: the exclusion is an accuracy improvement on a metric that must keep reporting, so a scan that cannot diff --git a/tests/unittest/scripts/test_perf_sanity_helpers.py b/tests/unittest/scripts/test_perf_sanity_helpers.py index 0bbefc32fc1e..21f6f7a721b1 100644 --- a/tests/unittest/scripts/test_perf_sanity_helpers.py +++ b/tests/unittest/scripts/test_perf_sanity_helpers.py @@ -300,7 +300,7 @@ def test_non_adjacent_predecessor_does_not_trigger_the_exclusion( assert 999.0 in [row.device_step_time for row in rows[0]] -def test_unparseable_predecessor_does_not_trigger_the_exclusion( +def test_unparsable_predecessor_does_not_trigger_the_exclusion( tmp_path: Path, ) -> None: _write_gen_log( @@ -386,7 +386,7 @@ def test_na_device_step_time_is_skipped(tmp_path: Path) -> None: assert [row.device_step_time for row in rows[0]] == [7.3] -def test_unparseable_num_generation_tokens_is_retained_as_none( +def test_unparsable_num_generation_tokens_is_retained_as_none( tmp_path: Path, ) -> None: """Nvbugs 6487036 / 6487040: the field rendered as tensor(256). @@ -616,9 +616,11 @@ def test_add_perf_metric_value_omits_the_family_outside_gen_only() -> None: def test_every_gated_metric_is_checkable() -> None: - """check_regression only iterates maximize + minimize; a gated name absent - from both is silently never checked, so the gate would look armed and be - dead. Pin the pair so adding a third gated statistic cannot regress it.""" + """A gated metric absent from both lists would look armed and never be checked. + + check_regression only iterates maximize + minimize, so pin the pair: adding a + third gated statistic cannot silently regress into a dead gate. + """ checkable = set(perf_sanity.MINIMIZE_METRICS) | set(perf_sanity.MAXIMIZE_METRICS) for name in perf_sanity.GEN_ONLY_REGRESSION_METRICS: assert name in checkable, f"{name} is gated but check_regression never sees it"