diff --git a/jenkins/L0_Test.groovy b/jenkins/L0_Test.groovy index 7da23e071794..a3f398e844ee 100644 --- a/jenkins/L0_Test.groovy +++ b/jenkins/L0_Test.groovy @@ -6509,7 +6509,7 @@ def launchTestJobs(pipeline, testFilter, globalVars) "GB300-36_GPUs-9_Nodes-PyTorch-Disagg-PerfSanity-CTX1-NODE1-GPU4-GEN4-NODE2-GPU8-Post-Merge", "gb300-flex-aws-cmh", "l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8", - 2, + 3, 36, 9 ) @@ -6518,7 +6518,7 @@ def launchTestJobs(pipeline, testFilter, globalVars) "GB300-40_GPUs-10_Nodes-PyTorch-Disagg-PerfSanity-CTX6-NODE1-GPU4-GEN1-NODE4-GPU16-Post-Merge", "auto:gb300-flex", "l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16", - 2, + 3, 40, 10 ) @@ -6527,7 +6527,7 @@ def launchTestJobs(pipeline, testFilter, globalVars) "GB300-44_GPUs-11_Nodes-PyTorch-Disagg-PerfSanity-CTX3-NODE1-GPU4-GEN1-NODE8-GPU32-Post-Merge", "gb300-flex-aws-cmh", "l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32", - 2, + 3, 44, 11 ) @@ -6536,7 +6536,7 @@ def launchTestJobs(pipeline, testFilter, globalVars) "GB300-56_GPUs-14_Nodes-PyTorch-Disagg-PerfSanity-CTX12-NODE1-GPU4-GEN1-NODE2-GPU8-Post-Merge", "auto:gb300-flex", "l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8", - 2, + 3, 56, 14 ) diff --git a/jenkins/scripts/perf/README.md b/jenkins/scripts/perf/README.md index 8c2f89679615..3164dc8e1e69 100644 --- a/jenkins/scripts/perf/README.md +++ b/jenkins/scripts/perf/README.md @@ -147,16 +147,26 @@ wins when set. Test-ID format: ``` -perf/test_perf_sanity.py::test_e2e[--[-]] +perf/test_perf_sanity.py::test_e2e[-[-]-[-]] ``` - `` = `disagg` | `aggr` -- `` (disagg) = `e2e` | `gen_only` | `ctx_only` +- `` = `e2e` | `gen_only` with `disagg`, or `ctx_only` with `aggr`. + `ctx_only` reads a disaggregated YAML but runs its ctx worker as a single + aggregated server, so it is spelled `aggr-ctx_only-` +- `` — optional instrumentation flag, orthogonal to ``; the only + one today is `time_breakdown`, which additionally uploads the per-request + lifecycle spans as `d_tb__`. It changes what the run *records*, + never the workload or the launch topology, so `--benchmark-mode` is still + handed the bare ``. Supported for `disagg-e2e` and `aggr-ctx_only` - `` matches a YAML file in `tests/scripts/perf-sanity/disaggregated/` (or `aggregated/`) - `` — only for normal aggregated tests — the `name:` field of one of the YAML's `server_configs` entries +A disagg `` may itself contain `-` (`..._ccb-NIXL`), so the stem is +everything after the mode and the optional modifier, not a fixed segment count. + `run_disagg.sh` errors out if any entry still contains the literal placeholder `CHANGE_ME`. diff --git a/jenkins/scripts/perf/local/README.md b/jenkins/scripts/perf/local/README.md index b8730295a17c..7673eb896796 100644 --- a/jenkins/scripts/perf/local/README.md +++ b/jenkins/scripts/perf/local/README.md @@ -29,6 +29,8 @@ slurm_launch.sh (generated) - `--test-list`: Test string, e.g., `perf/test_perf_sanity.py::test_e2e[aggr-config-test_name]`. If both `--test-list` and `--config-file` are provided, `--test-list` takes precedence. - `--config-file`: Path to config YAML file. - `--test-name`: Test name (only used for aggregated mode when `--config-file` is provided). +- `--benchmark-mode`: `e2e` | `gen_only` | `ctx_only` (only used for a disagg `--config-file`; with `--test-list` the mode is read off the test id). +- `--time-breakdown`: Also record the per-request lifecycle breakdown. This adds the `time_breakdown` modifier segment to the generated test id (`disagg-e2e-time_breakdown-`); the modifier is orthogonal to `--benchmark-mode` and does not change the workload. - `--time`: SLURM time limit (default: `02:00:00`). - `--mounts`: Container mounts. - `--work-dir`: Work directory (used for both workdir and container-workdir). diff --git a/jenkins/scripts/perf/local/configs/example.conf b/jenkins/scripts/perf/local/configs/example.conf index fc7371a41a78..72dfeffc3f4b 100644 --- a/jenkins/scripts/perf/local/configs/example.conf +++ b/jenkins/scripts/perf/local/configs/example.conf @@ -61,9 +61,14 @@ llm_models_path="${YOUR_LLM_MODELS_PATH:-/path/to/llm_models}" mounts="$trtllm:$trtllm,$llm_models_path:$llm_models_path" # Test ID(s). Format: -# perf/test_perf_sanity.py::test_e2e[disagg--] +# perf/test_perf_sanity.py::test_e2e[-[-]-] # The matches a file in tests/scripts/perf-sanity/disaggregated/. -# is e2e | gen_only | ctx_only. +# - is disagg-e2e | disagg-gen_only | aggr-ctx_only: ctx_only reads +# the same disagg yaml but runs a single server, so it takes the aggr prefix. +# is an optional instrumentation flag, orthogonal to the mode; the only +# one today is time_breakdown, e.g. +# perf/test_perf_sanity.py::test_e2e[disagg-e2e-time_breakdown-] +# perf/test_perf_sanity.py::test_e2e[aggr-ctx_only-time_breakdown-] # # Two ways to declare tests — use ONE of these: # diff --git a/jenkins/scripts/perf/local/submit.py b/jenkins/scripts/perf/local/submit.py index 071db58f7293..5aac3f8e8f6d 100755 --- a/jenkins/scripts/perf/local/submit.py +++ b/jenkins/scripts/perf/local/submit.py @@ -49,6 +49,30 @@ def _import_precheck_config(llm_src): "DISAGG_CONFIG_FOLDER", "tests/scripts/perf-sanity/disaggregated" ) +# Optional instrumentation segments that may follow the benchmark mode in a test +# id. Keep in sync with test_perf_sanity.py:TEST_ID_MODIFIERS -- the grammar is +# only decidable because no config file stem starts with one of these. +TIME_BREAKDOWN_MODIFIER = "time_breakdown" +TEST_ID_MODIFIERS = (TIME_BREAKDOWN_MODIFIER,) + +# Benchmark modes test_perf_sanity.py actually mints a time_breakdown test id +# for. gen_only is deliberately absent: its regression metric is the gen-worker +# device step time, so the lifecycle spans add nothing there, and the collector +# generates no such id. Keep in sync with the two *_TIME_BREAKDOWN_CONFIGS loops +# in test_perf_sanity.py:get_disagg_test_cases. +TIME_BREAKDOWN_BENCHMARK_MODES = ("e2e", "ctx_only") + + +def format_test_label(benchmark_mode: str, time_breakdown: bool = False) -> str: + """Compose the mode segment(s) of a test id. + + Mirrors test_perf_sanity.py:format_test_label so the regenerated id matches + the collected one. + """ + if time_breakdown: + return f"{benchmark_mode}-{TIME_BREAKDOWN_MODIFIER}" + return benchmark_mode + def get_llm_src_default(): """Get default llm_src path by going up 4 directories from this script.""" @@ -90,41 +114,74 @@ def parse_test_string(test_case_name: str): Test name formats: - Disagg e2e: disagg_upload-e2e-{config_base} + - Disagg e2e + lifecycle breakdown: disagg_upload-e2e-time_breakdown-{config_base} - Disagg gen_only: disagg_upload-gen_only-{config_base} - ctx_only: aggr_upload-ctx_only-{config_base} (runs aggr mode but reads disagg config) + - ctx_only + lifecycle breakdown: aggr_upload-ctx_only-time_breakdown-{config_base} - Regular aggr: aggr_upload-{config}-{server_name} + The optional modifier segment (TEST_ID_MODIFIERS) sits between the benchmark + mode and the config stem and is orthogonal to the mode. + Returns: - tuple: (config_base_name, select_pattern, runtime_mode, benchmark_mode) + tuple: (config_base_name, select_pattern, runtime_mode, benchmark_mode, + time_breakdown) - runtime_mode: "aggregated" or "disaggregated" - - benchmark_mode: "e2e", "gen_only", "ctx_only", or None (for normal aggr) + - benchmark_mode: "e2e", "gen_only", "ctx_only", or None (normal aggr) + - time_breakdown: True when the "time_breakdown" modifier is present """ labels = test_case_name.split("-") - assert len(labels) > 1, "perf_sanity test must have a config file!" + # ValueError rather than assert throughout: these are test-id grammar + # violations, and `python -O` removes assert statements, which would turn a + # malformed id into a silent IndexError or a submission against the wrong + # config instead of a clear rejection. Matches the sibling parser in + # jenkins/scripts/perf/submit.py, which already raises. + if len(labels) <= 1: + raise ValueError(f"perf_sanity test must have a config file: {test_case_name}") + + def split_modifiers(rest, benchmark_mode): + """Peel the optional modifier segment off the front of the stem.""" + time_breakdown = bool(rest) and rest[0] == TIME_BREAKDOWN_MODIFIER + if time_breakdown: + rest = rest[1:] + if not rest: + raise ValueError(f"Test name has a modifier but no config: {test_case_name}") + # Same reason the --config-file path refuses this combination below: the id + # is well-formed and parses fine, but test_perf_sanity.py never generates + # it, so pytest would exit "no tests ran" after the whole job has been + # queued, built and allocated. + if time_breakdown and benchmark_mode not in TIME_BREAKDOWN_BENCHMARK_MODES: + raise ValueError( + f"The {TIME_BREAKDOWN_MODIFIER} modifier is not generated for " + f"benchmark_mode {benchmark_mode!r}; supported modes are " + f"{', '.join(TIME_BREAKDOWN_BENCHMARK_MODES)}: {test_case_name}" + ) + return time_breakdown, "-".join(rest) prefix = labels[0] is_disagg_prefix = "disagg" in prefix is_aggr_prefix = "aggr" in prefix + time_breakdown = False if is_disagg_prefix: - # Disagg format: disagg_upload-{e2e|gen_only}-{config_base} - assert len(labels) > 2, "Disagg test must have benchmark_mode and config!" + # Disagg format: disagg_upload-{e2e|gen_only}[-{modifier}]-{config_base} + if len(labels) <= 2: + raise ValueError(f"Disagg test must have benchmark_mode and config: {test_case_name}") benchmark_mode = labels[1] # e2e or gen_only - assert benchmark_mode in ("e2e", "gen_only"), ( - f"Invalid benchmark_mode for disagg: {benchmark_mode}" - ) + if benchmark_mode not in ("e2e", "gen_only"): + raise ValueError(f"Invalid benchmark_mode for disagg: {benchmark_mode}") runtime_mode = "disaggregated" - config_base_name = "-".join(labels[2:]) + time_breakdown, config_base_name = split_modifiers(labels[2:], benchmark_mode) select_pattern = None elif is_aggr_prefix: # Check if this is ctx_only (aggr_upload-ctx_only-{config_base}) if len(labels) > 2 and labels[1] == "ctx_only": - # ctx_only: aggr_upload-ctx_only-{config_base} + # ctx_only: aggr_upload-ctx_only[-{modifier}]-{config_base} # Runs in aggregated mode but reads disagg config benchmark_mode = "ctx_only" runtime_mode = "aggregated" - config_base_name = "-".join(labels[2:]) + time_breakdown, config_base_name = split_modifiers(labels[2:], benchmark_mode) select_pattern = None else: # Regular aggr: aggr_upload-config_yml or aggr_upload-config_yml-server_config_name @@ -136,7 +193,7 @@ def parse_test_string(test_case_name: str): else: raise ValueError(f"Invalid test name prefix: {prefix}") - return config_base_name, select_pattern, runtime_mode, benchmark_mode + return config_base_name, select_pattern, runtime_mode, benchmark_mode, time_breakdown def get_config_yaml_path(llm_src, config_base_name, benchmark_mode): @@ -541,18 +598,21 @@ def generate_pytest_command( runtime_mode, benchmark_mode, waives_file="", + time_breakdown=False, ): """Generate pytest command and test list.""" # Generate test list content based on runtime_mode and benchmark_mode if runtime_mode == "disaggregated": - # disagg_upload-{e2e|gen_only}-{config_base} + # disagg_upload-{e2e|gen_only}[-{modifier}]-{config_base} + label = format_test_label(benchmark_mode, time_breakdown) test_list_content = ( - f"perf/test_perf_sanity.py::test_e2e[disagg-{benchmark_mode}-{config_file_base_name}]" + f"perf/test_perf_sanity.py::test_e2e[disagg-{label}-{config_file_base_name}]" ) elif benchmark_mode == "ctx_only": - # aggr_upload-ctx_only-{config_base} + # aggr_upload-ctx_only[-{modifier}]-{config_base} + label = format_test_label("ctx_only", time_breakdown) test_list_content = ( - f"perf/test_perf_sanity.py::test_e2e[aggr-ctx_only-{config_file_base_name}]" + f"perf/test_perf_sanity.py::test_e2e[aggr-{label}-{config_file_base_name}]" ) else: # Normal aggr: aggr-{config}-{select_pattern} @@ -656,6 +716,13 @@ def main(): choices=["", "e2e", "gen_only", "ctx_only"], help="Benchmark mode for disagg config (when --config-file is provided)", ) + parser.add_argument( + "--time-breakdown", + action="store_true", + help="Record the per-request lifecycle breakdown; adds the " + f"'{TIME_BREAKDOWN_MODIFIER}' modifier segment to the generated test id " + "(when --config-file is provided)", + ) parser.add_argument( "--partition", required=True, @@ -745,9 +812,13 @@ def main(): # --test-list takes precedence over --config-file if args.test_list: test_case_name = extract_test_case_name(args.test_list) - config_file_base_name, select_pattern, runtime_mode, benchmark_mode = parse_test_string( - test_case_name - ) + ( + config_file_base_name, + select_pattern, + runtime_mode, + benchmark_mode, + time_breakdown, + ) = parse_test_string(test_case_name) config_yaml = get_config_yaml_path(llm_src, config_file_base_name, benchmark_mode) elif args.config_file: config_yaml = os.path.abspath(args.config_file) @@ -767,11 +838,24 @@ def main(): else: runtime_mode = "disaggregated" select_pattern = None + time_breakdown = args.time_breakdown + # Refuse here rather than at collection: the id this would compose + # (e.g. `disagg-gen_only-time_breakdown-`) is well-formed and + # parses fine, but test_perf_sanity.py never generates it, so pytest + # would exit "no tests ran" after the whole job has been queued, + # built and allocated. + if time_breakdown and benchmark_mode not in TIME_BREAKDOWN_BENCHMARK_MODES: + raise ValueError( + f"--time-breakdown is not supported for --benchmark_mode " + f"{benchmark_mode!r}; supported modes are " + f"{', '.join(TIME_BREAKDOWN_BENCHMARK_MODES)}" + ) else: # Aggr config runtime_mode = "aggregated" benchmark_mode = None select_pattern = args.test_name + time_breakdown = False if not select_pattern: raise ValueError("--test-name is required for aggregated config") else: @@ -784,9 +868,11 @@ def main(): # would carry `_upload` while test_perf_sanity.py creates its working dir # under the stripped form — producing two divergent folders. if runtime_mode == "disaggregated": - test_case_name = f"disagg-{benchmark_mode}-{config_file_base_name}" + label = format_test_label(benchmark_mode, time_breakdown) + test_case_name = f"disagg-{label}-{config_file_base_name}" elif benchmark_mode == "ctx_only": - test_case_name = f"aggr-ctx_only-{config_file_base_name}" + label = format_test_label("ctx_only", time_breakdown) + test_case_name = f"aggr-{label}-{config_file_base_name}" else: test_case_name = f"aggr-{config_file_base_name}-{select_pattern}" @@ -867,6 +953,7 @@ def main(): runtime_mode, benchmark_mode, waives_file=args.waives_file, + time_breakdown=time_breakdown, ) # Write test list file diff --git a/jenkins/scripts/perf/submit.py b/jenkins/scripts/perf/submit.py index e30ecc72ec54..a10ddb3f4d46 100755 --- a/jenkins/scripts/perf/submit.py +++ b/jenkins/scripts/perf/submit.py @@ -22,13 +22,18 @@ Three test shapes are supported (all flow through the same parsing logic): 1. Multi-node aggregated: aggr[_upload]-{config_base}-{server_name} runtime_mode = "aggregated", benchmark_mode = None - 2. Multi-node ctx_only disagg: aggr[_upload]-ctx_only-{config_base} + 2. Multi-node ctx_only disagg: aggr[_upload]-ctx_only[-{modifier}]-{config_base} runtime_mode = "aggregated", benchmark_mode = "ctx_only" (reads disagg yaml, but launches via the aggregated single-pytest path using the ctx worker's parallel sizes) - 3. Multi-node disagg e2e/gen: disagg[_upload]-{e2e|gen_only}-{config_base} + 3. Multi-node disagg e2e/gen: disagg[_upload]-{e2e|gen_only}[-{modifier}]-{config_base} runtime_mode = "disaggregated", benchmark_mode in {"e2e", "gen_only"} +The optional {modifier} segment is an instrumentation flag that is orthogonal to +the benchmark mode; the only one today is "time_breakdown", which launches +exactly like its bare mode and differs only in what the harness asks the servers +and the client to record. + Test name → yaml folder mapping mirrors test_perf_sanity.py:parse_test_string. """ @@ -40,6 +45,7 @@ import re import shlex import sys +from typing import List, Optional, Tuple import yaml from benchmark_utils import parse_positive_concurrency @@ -62,6 +68,20 @@ def _import_precheck_config(llm_src): AGG_CONFIG_FOLDER = "tests/scripts/perf-sanity/aggregated" DISAGG_CONFIG_FOLDER = "tests/scripts/perf-sanity/disaggregated" +# Optional instrumentation segments that may follow the benchmark mode in a test +# id. Keep in sync with test_perf_sanity.py:TEST_ID_MODIFIERS -- the grammar is +# only decidable because no config file stem starts with one of these. +TIME_BREAKDOWN_MODIFIER = "time_breakdown" +TEST_ID_MODIFIERS = (TIME_BREAKDOWN_MODIFIER,) + +# Benchmark modes test_perf_sanity.py actually mints a time_breakdown test id +# for. gen_only is deliberately absent: its regression metric is the gen-worker +# device step time, so the lifecycle spans add nothing there, and the collector +# generates no such id. Keep in sync with the two *_TIME_BREAKDOWN_CONFIGS loops +# in test_perf_sanity.py:get_disagg_test_cases and with the identical constant in +# jenkins/scripts/perf/local/submit.py. +TIME_BREAKDOWN_BENCHMARK_MODES = ("e2e", "ctx_only") + # --------------------------------------------------------------------------- # # Test list parsing @@ -316,11 +336,41 @@ def select_test_case_line(test_list_path, llm_src, script_prefix_lines, split_gr return selected[0] -def parse_test_case_name(llm_src, selected_line): +def _split_modifiers( + rest: List[str], bracket_content: str, benchmark_mode: str +) -> Tuple[bool, str]: + """Peel the optional modifier segment off the front of the config stem. + + Mirrors test_perf_sanity.py:parse_test_string.split_modifiers. + Returns (time_breakdown, config_base_name). + """ + time_breakdown = bool(rest) and rest[0] == TIME_BREAKDOWN_MODIFIER + if time_breakdown: + rest = rest[1:] + if not rest: + raise ValueError(f"Test name has a modifier but no config: {bracket_content}") + # Reject here rather than let the id through: it is well-formed and parses + # fine, but test_perf_sanity.py never generates it, so pytest would exit "no + # tests ran" after the whole job has been queued, built and allocated -- and + # every gate reports green on an empty selection. + if time_breakdown and benchmark_mode not in TIME_BREAKDOWN_BENCHMARK_MODES: + raise ValueError( + f"The {TIME_BREAKDOWN_MODIFIER} modifier is not generated for " + f"benchmark_mode {benchmark_mode!r}; supported modes are " + f"{', '.join(TIME_BREAKDOWN_BENCHMARK_MODES)}: {bracket_content}" + ) + return time_breakdown, "-".join(rest) + + +def parse_test_case_name( + llm_src: str, selected_line: str +) -> Tuple[str, Optional[str], Optional[str], str, bool]: """Parse the selected test-list line. - Returns (config_yaml_path, server_name, benchmark_mode, runtime_mode). - See the module docstring for the supported test name shapes. + Returns (config_yaml_path, server_name, benchmark_mode, runtime_mode, + time_breakdown). server_name is None for every disagg shape and for ctx_only; + benchmark_mode is None for a normal aggregated case. See the module docstring + for the supported test name shapes. """ line = selected_line @@ -332,12 +382,13 @@ def parse_test_case_name(llm_src, selected_line): if len(parts) < 2: raise ValueError(f"Invalid test name (need at least prefix and config): {bracket_content}") + time_breakdown = False prefix = parts[0] if "disagg" in prefix: if len(parts) < 3: raise ValueError( - f"Invalid disagg test format. Expected disagg[_upload]-{{e2e|gen_only}}-" - f"{{config_base}}, got: {bracket_content}" + f"Invalid disagg test format. Expected disagg[_upload]-" + f"{{e2e|gen_only}}[-{{modifier}}]-{{config_base}}, got: {bracket_content}" ) benchmark_mode = parts[1] if benchmark_mode not in ("e2e", "gen_only"): @@ -346,15 +397,20 @@ def parse_test_case_name(llm_src, selected_line): ) runtime_mode = "disaggregated" server_name = None - config_base_name = "-".join(parts[2:]) + time_breakdown, config_base_name = _split_modifiers( + parts[2:], bracket_content, benchmark_mode + ) config_yaml_path = os.path.join(llm_src, DISAGG_CONFIG_FOLDER, f"{config_base_name}.yaml") elif "aggr" in prefix: if len(parts) > 2 and parts[1] == "ctx_only": - # ctx_only: aggr[_upload]-ctx_only-{config_base}; reads disagg yaml. + # ctx_only: aggr[_upload]-ctx_only[-{modifier}]-{config_base}; + # reads disagg yaml. benchmark_mode = "ctx_only" runtime_mode = "aggregated" server_name = None - config_base_name = "-".join(parts[2:]) + time_breakdown, config_base_name = _split_modifiers( + parts[2:], bracket_content, benchmark_mode + ) config_yaml_path = os.path.join( llm_src, DISAGG_CONFIG_FOLDER, f"{config_base_name}.yaml" ) @@ -381,7 +437,7 @@ def parse_test_case_name(llm_src, selected_line): if not os.path.exists(config_yaml_path): raise FileNotFoundError(f"Config file not found: {config_yaml_path}") - return config_yaml_path, server_name, benchmark_mode, runtime_mode + return config_yaml_path, server_name, benchmark_mode, runtime_mode, time_breakdown # --------------------------------------------------------------------------- # @@ -808,7 +864,9 @@ def main(): ) if selected_test_skipped: print("Selected test is SKIP-waived; cache-transceiver precheck will not run") - config_yaml, server_name, benchmark_mode, runtime_mode = parse_test_case_name( + # time_breakdown only changes what the harness records, never the launch + # topology or the mode token handed to the precheck, so it is unused here. + config_yaml, server_name, benchmark_mode, runtime_mode, _time_breakdown = parse_test_case_name( args.llm_src, selected_test_line, ) diff --git a/tensorrt_llm/serve/perf_metrics.py b/tensorrt_llm/serve/perf_metrics.py index 60fa821946f8..73846d4ca72c 100644 --- a/tensorrt_llm/serve/perf_metrics.py +++ b/tensorrt_llm/serve/perf_metrics.py @@ -22,10 +22,18 @@ HTTP/1.1 200 OK Content-Type: application/json Server-Timing: server_queue;dur=1.250000, server_ttft;dur=8.500000, server_e2e;dur=24.000000 - X-TRTLLM-Start-End-Time: server-start;ts=12345.123456, server-end;ts=12345.147456 + X-TRTLLM-Start-End-Time: server-start;ts=12345.123456, server-end;ts=12345.147456, + server-srv-start;ts=12345.122000, server-srv-ttft;ts=12345.132000 X-TRTLLM-Step-Metrics: server-step-0-forward;dur=2.100000, server-step-0-sample;dur=0.400000 X-TRTLLM-Ctx-Chunk-Metrics: server-ctx-chunk-0-forward;dur=4.200000 +``X-TRTLLM-Start-End-Time`` carries absolute timestamps. ``start``/``end`` are the +executor's arrival and last-token times; ``srv-start``/``srv-ttft`` are the HTTP +server's arrival and first-token times; ``kv-start``/``kv-end`` bracket the +KV-cache transfer on a disaggregated generation worker. A disaggregated server +needs all of them to reconstruct a request's full lifecycle from a worker +response -- see :func:`build_metrics_record_from_headers`. + Streaming responses carry the same fields in a named SSE event after ``[DONE]``:: data: [DONE] @@ -313,9 +321,19 @@ def build_metrics_headers(records: List[Dict[str, Any]]) -> Dict[str, str]: for record in records: for phase, phase_record in record.get("phases", {}).items(): timing = phase_record.get("timing_metrics", {}) + # Absolute timestamps forwarded verbatim. The four "srv-"/"kv-" names + # are what let a disagg server reconstruct the full request lifecycle + # from a worker response; without them the per-phase breakdown + # silently collapses to zero-width spans. Names must not contain a + # second "server-"/"server_" substring, because the receiving side + # rewrites the phase prefix with an unqualified str.replace(). for name, field in ( ("start", "arrival_time"), ("end", "last_token_time"), + ("srv-start", "server_arrival_time"), + ("srv-ttft", "server_first_token_time"), + ("kv-start", "kv_cache_transfer_start"), + ("kv-end", "kv_cache_transfer_end"), ): timestamp = timing.get(field) if timestamp is not None: @@ -392,6 +410,10 @@ def build_metrics_record_from_headers( fields = { f"{phase}-start": "arrival_time", f"{phase}-end": "last_token_time", + f"{phase}-srv-start": "server_arrival_time", + f"{phase}-srv-ttft": "server_first_token_time", + f"{phase}-kv-start": "kv_cache_transfer_start", + f"{phase}-kv-end": "kv_cache_transfer_end", } for item in metrics_headers.get(START_END_TIME_HEADER, "").split(","): name, separator, timestamp = item.strip().partition(";ts=") @@ -541,7 +563,19 @@ def _jsonl_perf_metrics(phase_record: Dict[str, Any]) -> PerfMetrics: timing_metrics = dict(perf_metrics.get("timing_metrics", {})) if not timing_metrics.get("kv_cache_size"): - for name in ("kv_cache_size", "kv_cache_transfer_start", "kv_cache_transfer_end"): + timing_metrics.pop("kv_cache_size", None) + # Drop the KV-transfer timestamps only when they were never populated. Keying + # this off kv_cache_size instead discards timestamps that the Server-Timing + # header transport carried successfully, because kv_cache_size is worker-local + # and never reaches a header-derived record -- which zeroed the KV-transfer + # span for every disaggregated request. + # + # Falsy rather than `is None` only for belt-and-braces: both producers already + # yield None for an absent timestamp (_as_seconds maps <= 0 to None, and the + # header path emits a field only when the header carried it), and a populated + # timestamp is a steady-clock reading, so it is never 0. + for name in ("kv_cache_transfer_start", "kv_cache_transfer_end"): + if not timing_metrics.get(name): timing_metrics.pop(name, None) perf_metrics["timing_metrics"] = timing_metrics diff --git a/tensorrt_llm/serve/scripts/benchmark_serving.py b/tensorrt_llm/serve/scripts/benchmark_serving.py index a0913c62d25d..f5018a24b469 100644 --- a/tensorrt_llm/serve/scripts/benchmark_serving.py +++ b/tensorrt_llm/serve/scripts/benchmark_serving.py @@ -1100,20 +1100,60 @@ def create_dataset_and_sample(dataset_name: str): f"{base_model_id}-{current_dt}-perf_metrics") if args.result_dir: output_stem = os.path.join(args.result_dir, output_stem) - perf_filename = f"{output_stem}.jsonl" - with open(perf_filename, "w", encoding="utf-8") as outfile: - for record in perf_metrics: - outfile.write(json.dumps(record, separators=(",", ":")) + "\n") - print(f"Request performance metrics saved to: {perf_filename}") - + # Reduce the records we already hold rather than writing them out and reading + # them back: the round trip made the whole breakdown depend on output_stem + # being writable, so a read-only working directory (no --result-dir) cost the + # measurement instead of just the artifact. analyzer = RequestTimeBreakdown() - timing_data = analyzer.parse_json_file(perf_filename) - if timing_data: - diagram_filename = f"{output_stem}-time_diagram.html" + timing_data = analyzer.parse_records(perf_metrics) + if not timing_data: + print("No time data found; skipping time breakdown report.") + return + + # Deliberately not printed as scrapeable "Time Breakdown ..." lines. The + # perf-sanity harness aggregates the same spans itself from the worker + # JSONLs, and a second producer of those lines is worse than none: this + # view is built from the client's copy of the file only, drops spans whose + # events overlapped (see compute_statistics), and models neither the + # per-step nor the per-chunk spans. Printing it made the harness's + # "no breakdown lines were parsed" check pass on the fallback, hiding the + # aggregation failure the check exists to surface. Written as an artifact + # instead, for whoever passed --save-request-time-breakdown by hand. + span_stats = analyzer.compute_statistics(timing_data) + + # Each artifact is written independently: an unwritable output_stem would + # otherwise raise out of main() and make the client exit non-zero, which the + # harness reads as a failed benchmark. output_stem is relative to the current + # directory unless --result-dir was given. Report and continue. span_stats is + # passed in so the reduction is not run a second time over every request. + perf_filename = f"{output_stem}.jsonl" + try: + with open(perf_filename, "w", encoding="utf-8") as outfile: + for record in perf_metrics: + outfile.write( + json.dumps(record, separators=(",", ":")) + "\n") + print(f"Request performance metrics saved to: {perf_filename}") + except OSError as exc: + print(f"Could not write {perf_filename}: {exc}") + + stats_filename = f"{output_stem}-time_breakdown_stats.json" + try: + analyzer.export_statistics_json(timing_data, + stats_filename, + span_stats=span_stats) + print(f"Span statistics saved to: {stats_filename}") + except OSError as exc: + print(f"Could not write {stats_filename}: {exc}") + + diagram_filename = f"{output_stem}-time_diagram.html" + try: analyzer.create_timing_diagram(timing_data, diagram_filename) print(f"Time diagram saved to: {diagram_filename}") - else: - print("No time data found; skipping time breakdown diagram.") + except (OSError, ValueError, TypeError) as exc: + # plotly is a module-scope import of time_breakdown, so ImportError cannot + # surface here -- it would already have failed this module's import. What can + # surface is plotly rejecting the figure it was handed (ValueError/TypeError). + print(f"Could not write {diagram_filename}: {exc}") if __name__ == "__main__": diff --git a/tensorrt_llm/serve/scripts/time_breakdown/time_breakdown.py b/tensorrt_llm/serve/scripts/time_breakdown/time_breakdown.py index 19c8fe3fd978..8007b7207158 100644 --- a/tensorrt_llm/serve/scripts/time_breakdown/time_breakdown.py +++ b/tensorrt_llm/serve/scripts/time_breakdown/time_breakdown.py @@ -28,7 +28,7 @@ import math import sys from dataclasses import dataclass -from typing import Any, Dict, List, Optional +from typing import Any, Dict, Iterable, List, Optional import numpy as np import plotly.graph_objects as go @@ -373,17 +373,26 @@ def iter_records(json_file): "Expected a JSON array, JSON object, or JSONL file: " f"{json_file_path}") - timing_data = [] with open(json_file_path, 'r') as json_file: - for i, request in enumerate(iter_records(json_file)): - parsed_data = self.parser.parse_request(request, i) + return self.parse_records(iter_records(json_file)) + + def parse_records(self, records: Iterable[Dict]) -> List[Dict]: + """Extract timing information from already-decoded perf-metrics records. + + Same reduction as :meth:`parse_json_file`, minus the file decoding, so a caller + that already holds the records in memory does not have to write them out and read + them back just to get the breakdown. + """ + timing_data = [] + for i, request in enumerate(records): + parsed_data = self.parser.parse_request(request, i) - # Calculate durations for each metric - for metric in self.config.metrics: - duration = metric.calculate_duration(parsed_data) - parsed_data[f'{metric.name}_time'] = duration + # Calculate durations for each metric + for metric in self.config.metrics: + duration = metric.calculate_duration(parsed_data) + parsed_data[f'{metric.name}_time'] = duration - timing_data.append(parsed_data) + timing_data.append(parsed_data) if timing_data: has_gen_metrics = any(not math.isnan( @@ -2163,6 +2172,67 @@ def show_statistics(self, timing_data: List[Dict]): ) print(f" Median: {np.median(valid_times):.3f}") + def compute_statistics( + self, timing_data: List[Dict]) -> Dict[str, Dict[str, float]]: + """Aggregate every span across all requests. + + Returns ``{span_name: {mean, median, p75, p99, count}}`` with durations in + **milliseconds** (the unit every other serving benchmark metric uses). + + A span that is zero for every request is omitted rather than reported as + ``0.0``: :meth:`TimingMetric.calculate_duration` returns 0 when an endpoint + timestamp is missing, so 0 means "not measured", not "took no time". + Reporting it as 0.0 would silently fabricate a data point. + + This is a *coarse* view, and deliberately so. ``calculate_duration`` also + returns 0 when ``start_time > end_time``, so a span whose two events + genuinely overlapped is indistinguishable here from one that was never + measured, and both are dropped -- which biases the surviving mean of such a + span towards its non-overlapped tail. Overlap is real for per-step spans + under the overlap scheduler, so anything needing an unbiased mean should + use the perf-sanity aggregator + (``tests/integration/defs/perf/time_breakdown_metrics.py``), which keeps + signed spans and covers per-step and per-chunk detail this config does not + model at all. + """ + stats: Dict[str, Dict[str, float]] = {} + for metric in self.config.metrics: + key = f'{metric.name}_time' + valid = [ + data[key] * 1000 for data in timing_data + if data.get(key) is not None and data[key] != 0 + ] + if not valid: + continue + stats[metric.name] = { + 'mean': float(np.mean(valid)), + 'median': float(np.median(valid)), + 'p75': float(np.percentile(valid, 75)), + 'p99': float(np.percentile(valid, 99)), + 'count': len(valid), + } + return stats + + def export_statistics_json( + self, + timing_data: List[Dict], + output_path: str, + span_stats: Optional[Dict[str, Any]] = None) -> Dict[str, Any]: + """Write :meth:`compute_statistics` output to ``output_path`` as JSON. + + Pass ``span_stats`` when the caller has already reduced ``timing_data``, + so the reduction is not repeated over every request. + """ + payload = { + 'total_requests': + len(timing_data), + 'spans': (self.compute_statistics(timing_data) + if span_stats is None else span_stats), + } + with open(output_path, 'w', encoding='utf-8') as out_file: + json.dump(payload, out_file, indent=2, sort_keys=True) + return payload + def main(): """Main CLI entry point.""" @@ -2176,6 +2246,7 @@ def main(): python time_breakdown.py perf_metrics.jsonl --stats-only python time_breakdown.py perf_metrics.jsonl --max-requests 50 --sort-by e2e python time_breakdown.py perf_metrics.jsonl --max-requests 100 --sort-by arrival + python time_breakdown.py perf_metrics.jsonl --stats-only --export-stats-json stats.json """) parser.add_argument( @@ -2193,6 +2264,13 @@ def main(): parser.add_argument('--show-stats', action='store_true', help='Show statistics with diagram') + parser.add_argument( + '--export-stats-json', + type=str, + default=None, + metavar='PATH', + help='Write per-span mean/median/P75/P99 (in milliseconds) to PATH as ' + 'JSON. Combine with --stats-only to skip rendering the HTML diagram') parser.add_argument( '--max-requests', type=int, @@ -2227,6 +2305,10 @@ def main(): if args.stats_only or args.show_stats: analyzer.show_statistics(timing_data) + if args.export_stats_json: + analyzer.export_statistics_json(timing_data, args.export_stats_json) + print(f"Span statistics saved to: {args.export_stats_json}") + if not args.stats_only: analyzer.create_timing_diagram(timing_data, args.output, diff --git a/tests/integration/defs/.test_durations b/tests/integration/defs/.test_durations index af008484de0c..abc0935e9a80 100644 --- a/tests/integration/defs/.test_durations +++ b/tests/integration/defs/.test_durations @@ -1576,7 +1576,6 @@ "unittest/tools/test_layer_wise_benchmarks.py::test_kimi_k3_gen_dep[1]": 105.24084607329843, "unittest/tools/test_layer_wise_benchmarks.py::test_nemotron_gen_dep[1]": 129.26791205533596, "unittest/tools/test_layer_wise_benchmarks.py::test_qwen3_next_gen_tep[1]": 737.5263775720165, - "unittest/tools/test_perf_sanity_matching.py": 23.070881556683588, "unittest/tools/test_unittest_culprits.py": 22.74008013937282, "unittest/usage": 29.950440784313727, "unittest/usage/test_e2e_capture.py": 20.434414677276745, diff --git a/tests/integration/defs/perf/README_test_perf_sanity.md b/tests/integration/defs/perf/README_test_perf_sanity.md index 7bd773bd28fc..bad756fbb5d4 100644 --- a/tests/integration/defs/perf/README_test_perf_sanity.md +++ b/tests/integration/defs/perf/README_test_perf_sanity.md @@ -24,14 +24,18 @@ 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` | 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` | +| `MINIMIZE_METRICS` | 14 + 108 | TTFT, ITL, E2EL latencies (mean/median/P99 for each) + the five `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` (every mode in `DEVICE_STEP_TIME_MODES`) + the 108 `d_tb_*` lifecycle spans of the `time_breakdown` modifier | | `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 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) +#### `d_{mean,median,std,p75,p99}_gen_worker_per_iter_device_step_time` (gen_only, e2e) + +Uploaded for every mode in `DEVICE_STEP_TIME_MODES`, but **gated only in `gen_only`** (see the override above). In `e2e` the gen workers do pure decode — the ctx workers do the prefill — so the statistic means the same thing it does in `gen_only`, and it is there to attribute an `e2e` throughput or TTFT regression to the device side rather than to declare one. `ctx_only` is excluded by construction: it runs the *aggregated* runtime from a disagg YAML with no gen worker, so there is no `gen_server_*.log` to read; TTFT is the prefill signal there. + +Because `s_test_case_name` is a match key and carries the benchmark mode as its prefix, `e2e` and `gen_only` values share a *column* but never a *baseline series*. 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: @@ -42,7 +46,7 @@ These metrics are parsed from each `gen_server_{i}.log` produced by the disagg r 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. +1. Immediately before launching each client, snapshot `os.path.getsize()` of every `gen_server_{i}.log`. That snapshot is the client's `start_offsets` **and** the previous client's `end_offsets`, so each client is parsed from a bounded byte window and gets its own segment of gen-worker iterations rather than sharing a single global average. The last client's window ends at EOF. Taking the end bound from the *next* client's launch rather than from the previous client's return is what makes it safe to defer the parse past teardown: the bound cannot exclude an iteration the previous client drove, however late the gen worker flushed it. A line straddling the bound is dropped. The window is read in binary and decoded per line, so the byte accounting matches the `getsize()` bounds exactly. 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). "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. @@ -57,9 +61,9 @@ The device value reported at iter `N` is the device step time of iter `N-1` (dev P75 Per Iter Device Step Time (ms): P99 Per Iter Device Step Time (ms): ``` - 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. + Downstream `parse_metrics_from_output` picks them up via `DEVICE_STEP_TIME_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 mean 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. Other modes omit the five columns instead of failing: there the family is diagnostic and throughput still gates, so hard-failing would make every `e2e` case on every cluster red on log-scrape plumbing rather than on performance. ### Match Keys @@ -69,7 +73,7 @@ build a baseline. They are the same for every deployment mode | Key | Why | |-----|-----| -| `s_test_case_name` | `-` for aggregated, `--` for disaggregated. Already encodes every fixed parameter of the case: model, parallelism, ISL/OSL, concurrency. | +| `s_test_case_name` | `-` for aggregated, `[-]--` for disaggregated. Already encodes every fixed parameter of the case: model, parallelism, ISL/OSL, concurrency. | | `s_gpu_type` | The same case name runs on more than one GPU type. | | `s_runtime` | The same case name runs on both `aggr_server` and `multi_node_aggr_server`. | | `s_branch` | Release branches keep their own baseline rather than blending into `main`'s. | @@ -103,9 +107,10 @@ a case silently costs it its history and its next pre-merge regression check, so `multi_round` should be treated as a workload parameter, not a knob to sweep. `s_benchmark_mode` is deliberately excluded: it is null on every aggregated record -and exactly equals the test case name's prefix on every disaggregated one, so it -adds no information while breaking matching against records written before the -field existed (`benchmark_data_matches` treats `None` and `"e2e"` as different). +and exactly equals the test case name's prefix on every disaggregated one +(modifier segment included), so it adds no information while breaking matching +against records written before the field existed (`benchmark_data_matches` treats +`None` and `"e2e"` as different). `match_mode: scenario` in the server yamls is now inert — not forking a case on a config change is the default for every case. @@ -288,6 +293,77 @@ perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-{disagg config file base na perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-deepseek-r1-fp4_1k1k_ctx1_gen1_dep8] ``` +### The optional instrumentation modifier + +The three shapes that read a disaggregated config (2, 3 and 4 above) take one +**optional** extra segment between the benchmark mode and the config stem: + +```text +perf/test_perf_sanity.py::test_e2e[-[-]-] +``` + +`` comes from a closed vocabulary (`TEST_ID_MODIFIERS` in +`test_perf_sanity.py`), and the only member today is `time_breakdown`. It is +generated for shapes 4 (`disagg-e2e`) and 2 (`aggr-ctx_only`): + +```text +perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-time_breakdown-deepseek-r1-fp4_1k1k_ctx1_gen1_dep8] +perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-time_breakdown-deepseek-r1-fp4_1k1k_ctx1_gen1_dep8] +``` + +Not for shape 3 (`disagg-gen_only`): its regression signal is the gen-worker +device step time, and the lifecycle spans describe request admission and prefill, +which a gen_only run does not perform. The grammar would accept it; the collector +does not mint it, and `local/submit.py` rejects `--time-breakdown` there rather +than queueing a job that ends in "no tests ran". + +A modifier is **orthogonal to the mode**. It selects extra instrumentation — for +`time_breakdown`, `return_perf_metrics` plus `num_postprocess_workers: 0` on every +request-serving process (the ctx and gen workers in `e2e`, the single aggregated +server in `ctx_only`), `--save-request-time-breakdown` on the client, and the +`d_tb_*` lifecycle-span fields on the uploaded document — while the mode continues +to decide *what workload runs*. Which of the 108 fields are populated follows from +the mode (`MODE_GROUPS` in `time_breakdown_metrics.py`): 108 for `e2e`, 44 for +`ctx_only`; the rest upload as `0.0` so the column exists on every row of the +series. Shape 1 has no modifier slot: there, the segment +after the prefix is the config stem itself and the remainder is the server-config +name. Anything downstream that needs a benchmark mode +(notably `run_precheck.py --benchmark-mode`) is handed the bare ``, which is +why the modifier does not have to be enumerated in those whitelists. + +Two consequences worth knowing: + +- **The stem is whatever follows the mode and the optional modifier**, not a fixed + segment count. Disagg stems routinely contain `-` (`..._ccb-NIXL`), so the + grammar is only decidable because no config file stem begins with a modifier + name. `get_disagg_test_cases` raises at import time if a stem collides, so a + future colliding filename fails collection loudly instead of resolving to the + wrong YAML. +- **A modified case is its own baseline series.** The modifier is part of + `s_test_case_name`, and for `time_breakdown` that is required rather than + incidental: `num_postprocess_workers: 0` measurably changes throughput, so its + aggregate numbers are deliberately not comparable to the sibling unmodified + case. + +### Reading the JSONLs without racing the writers + +Each request-serving process appends to its own `perf_metrics-*.jsonl` from a +background writer thread and flushes the tail when it exits, so the aggregation has +to run after the writers are done. Only the **gen** workers announce that +(`gen_server_{i}.done`, which the device-step-time path already waits for); the ctx +workers and the disaggregated server do not. `wait_for_perf_metrics_files` therefore +polls the discovered set until its total size holds still for +`PERF_METRICS_SETTLE_SECONDS`, bounded by `PERF_METRICS_SETTLE_TIMEOUT`, before +anything is read, and then compares the largest file's complete-record count against +the client's `--num-prompts`. Both a still-growing set at the timeout and a census +shortfall are logged as warnings, not failures — a nearly-complete file still yields +usable statistics, and the numbers are not regression-gated. This matters because a +truncated read is otherwise **invisible**: all 108 fields are still populated and the +row uploads green. For the same reason a malformed line (a partial write caught +mid-record) costs only that line, never the whole file: dropping the disagg server's +file would silently reroute the per-request groups to same-role worker fallbacks, +which produce plausible values for the wrong phase. + ## CI Test Database Test lists are defined in `tests/integration/test_lists/test-db/`. diff --git a/tests/integration/defs/perf/test_perf_sanity.py b/tests/integration/defs/perf/test_perf_sanity.py index 4d6e056fd63c..f57a881dfd84 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -44,6 +44,16 @@ from ..conftest import get_llm_root, llm_models_root from ._model_paths import MODEL_PATH_DICT from .perf_regression_utils import _percentile, get_job_info, process_and_upload_test_results +from .time_breakdown_metrics import ALL_METRICS as TIME_BREAKDOWN_METRIC_NAMES +from .time_breakdown_metrics import COMPLETION_STABLE_SECONDS as _TB_SETTLE_SECONDS +from .time_breakdown_metrics import COMPLETION_TIMEOUT_SECONDS as _TB_SETTLE_TIMEOUT +from .time_breakdown_metrics import MODE_GROUPS as TIME_BREAKDOWN_MODE_GROUPS +from .time_breakdown_metrics import STATS as TIME_BREAKDOWN_STATS +from .time_breakdown_metrics import ( + compute_time_breakdown_metrics, + format_metric_log_lines, + wait_for_perf_metrics_files, +) SUPPORTED_GPU_MAPPING = { "GB200": "gb200", @@ -125,6 +135,13 @@ def ensure_bench_serving_repo() -> str: # Keep this well below the whole-test timeout so a stuck multi-node srun cannot # turn the optional log-flush synchronization into a pytest/Slurm cancellation. GEN_LOG_SENTINEL_TIMEOUT = 120 +# How long the perf_metrics JSONLs must hold still before the time_breakdown +# aggregation reads them, and the backstop for a writer that never settles. Only +# the GEN workers have a completion sentinel, so this is the ctx workers' and the +# disagg server's equivalent; see wait_for_perf_metrics_files. Named constants +# rather than call-site literals so a test can shorten the window. +PERF_METRICS_SETTLE_SECONDS = _TB_SETTLE_SECONDS +PERF_METRICS_SETTLE_TIMEOUT = _TB_SETTLE_TIMEOUT def server_ready_timeout(default: int, mode: str) -> int: @@ -189,23 +206,24 @@ def server_ready_timeout(default: int, mode: str) -> int: "al": re.compile(r"Mean Avg Decoded Tokens per Iter:\s+(-?[\d\.]+)"), } -# 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. +# Gen-worker device-step-time metrics: appended to each trtllm-benchmark log by +# DisaggTestCmds.run_cmd after parsing gen_server_*.log, and forwarded to the +# database for every mode in DEVICE_STEP_TIME_MODES. # # 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. 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. +# tell that from a real regression is to see the spread next to it. In gen_only +# the mean and median are both regression-gated (see GEN_ONLY_REGRESSION_METRICS) +# because they fail on different shapes of slowdown; std/p75/p99 are uploaded for +# diagnosis only. In every other mode all five are diagnostic -- see +# DEVICE_STEP_TIME_MODES. # # 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 = { +DEVICE_STEP_TIME_LOG_QUERIES = { "mean_gen_worker_per_iter_device_step_time": re.compile( r"Average Per Iter Device Step Time \(ms\):\s+(-?[\d\.]+)" ), @@ -223,10 +241,14 @@ 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 one check_test_failure keys on; mean and median are both -# regression-gated, std/p75/p99 are diagnostic. -GEN_ONLY_DEVICE_STEP_TIME_METRICS = ( +# Every gen-worker device-step-time metric, in log-line order. The mean is first +# because it is the one check_test_failure keys on. +# +# The `gen_worker` in the uploaded names is deliberate and frozen: these are live +# OpenSearch columns with baseline history, and renaming one would fork every +# gen_only series and discard its baselines. They describe the *gen worker*, which +# is what emits them, not the gen_only *mode*, which no longer has them to itself. +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", @@ -244,11 +266,140 @@ def server_ready_timeout(default: int, mode: str) -> int: # 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 ONLY. The other modes in DEVICE_STEP_TIME_MODES upload the same five +# statistics but keep the default REGRESSION_METRICS (throughput), so for them +# these names get a baseline and an s_regression_info diff line and can never set +# b_is_regression. That asymmetry is the point: in gen_only the token-throughput +# numbers are dominated by KV-cache transfer and are not a useful signal, so +# device step time is all there is to gate on; in e2e throughput is meaningful and +# already gates, and device step time is there to attribute a regression rather +# than to declare one. GEN_ONLY_REGRESSION_METRICS = ( "d_mean_gen_worker_per_iter_device_step_time", "d_median_gen_worker_per_iter_device_step_time", ) +# Test-id modifier that additionally captures the per-request lifecycle +# breakdown. It is a segment of its own, between the benchmark mode and the +# config stem, so that instrumentation and mode stay orthogonal: +# "disagg-e2e-time_breakdown-" today, "disagg-gen_only-time_breakdown-.." +# or "aggr-ctx_only-time_breakdown-.." with no new grammar. +# +# The run is otherwise the same workload as the unmodified mode; the only +# differences are the three worker_config keys injected in +# _parse_disagg_config_file and the --save-request-time-breakdown flag on the +# client. One of those keys forces num_postprocess_workers to 0 to keep the +# per-step detail, which measurably changes throughput -- so the modifier is +# part of the composed test label (see format_test_label) and therefore of +# s_test_case_name, giving the case its own baseline series. Its aggregate +# numbers are deliberately not comparable to the unmodified sibling's. +TIME_BREAKDOWN_MODIFIER = "time_breakdown" + +# Every modifier the test-id grammar recognises, i.e. the closed vocabulary that +# makes "-[-]-" decidable: a third segment is a +# modifier if and only if it is in here, otherwise it is the first segment of the +# config stem. get_disagg_test_cases asserts no config stem can collide. +TEST_ID_MODIFIERS = (TIME_BREAKDOWN_MODIFIER,) + +# Benchmark modes whose gen workers produce a per-iter device step time worth +# uploading. +# +# Not ctx_only: it runs aggregated from a disagg yaml with no gen worker at all, +# so there is no gen_server_*.log to read. Not the aggregated lanes either -- +# they call add_perf_metric_value without a benchmark_mode, and None is not in +# this tuple. +# +# Orthogonal to the time_breakdown modifier by construction: a modified case +# runs the same mode, so it uploads (and gates) exactly as its unmodified +# sibling does. +# +# Only gen_only gates on these (GEN_ONLY_REGRESSION_METRICS); for e2e they are +# uploaded and baselined but cannot fail a build. In e2e the gen worker still +# does pure decode -- the ctx workers do the prefill -- so the statistic means +# the same thing it does in gen_only and is comparable within its own +# s_test_case_name series. +DEVICE_STEP_TIME_MODES = ("gen_only", "e2e") + +# Config stems that get a time_breakdown test id. Deliberately an allowlist +# rather than "every disagg yaml": get_disagg_test_cases is a cartesian product, +# so an unconditional entry would add one parametrised id per config (~90) that +# nothing ever runs, and every one of them would still have to be waived, +# durations-seeded, and mapped to a Jenkins stage. +# +# The four entries are every DeepSeek-V4-Pro fp4 8k1k shape perf sanity runs +# disaggregated, i.e. the whole concurrency sweep from single-user latency to max +# throughput: con8 (ctx1/gen4), con180 (ctx3/gen1 dep32), con666 (ctx6/gen1 +# dep16), con4301 (ctx12/gen1 dep8). e2e is one of the two modes whose +# regressions land in host overhead (the other is ctx_only), so the breakdown is +# worth its own lane on each shape rather than on one representative -- the host +# work per request is what changes with concurrency, and a single shape cannot +# show that. Each lives in a different multi-node lane list, so each costs one +# additional split in its own Jenkins stage and none of them lengthens another. +# +# Cost scales with requests x decode steps per request, not with nodes: a +# measured con666 run (6660 requests, 1.54M steps) wrote a 386 MB gen-worker +# JSONL that compute_time_breakdown_metrics reduced in 11 s at 1.2 GB peak RSS. +# con4301 is 43010 requests at mtp1 (~2x the steps per request), i.e. ~14x that +# -- order 5 GB on disk and 15-20 GB resident on the benchmark node for a couple +# of minutes. Fine on a GB300, but a config an order of magnitude larger again +# would need the reduction to stream instead of materialising every sample. +E2E_TIME_BREAKDOWN_CONFIGS = ( + "gb300_deepseek-v4-pro-fp4_8k1k_con8_ctx1_dep4_gen4_tep8_eplb0_mtp3_ccb-NIXL", + "gb300_deepseek-v4-pro-fp4_8k1k_con180_ctx3_dep4_gen1_dep32_eplb384_mtp3_ccb-NIXL", + "gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL", + "gb300_deepseek-v4-pro-fp4_8k1k_con4301_ctx12_dep4_gen1_dep8_eplb384_mtp1_ccb-NIXL", +) + +# Same allowlist discipline for ctx_only. Kept separate from +# E2E_TIME_BREAKDOWN_CONFIGS rather than reused: ctx_only runs on the aggregated +# runtime with a single server on a fraction of the nodes, so whether a config is +# worth a time_breakdown lane is a different question per mode -- and the two +# lists already differ. All four disagg shapes get an e2e lane (they are four +# separate Jenkins stages, so each is one extra split in its own stage), while +# ctx_only has one: every ctx_only case shares the single +# l0_gb300_multi_gpus_perf_sanity stage, where each addition lengthens the same +# serial lane, and a prefill-only run's per-chunk spans vary far less across the +# concurrency sweep than a full e2e run's request lifecycle does. +CTX_ONLY_TIME_BREAKDOWN_CONFIGS = ( + "gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL", +) + +# The names and statistics come from .time_breakdown_metrics, which is the single +# source of truth for both -- it computes them and formats the log lines this +# module parses back, so the producer and consumer cannot drift. +# +# 27 metrics x 4 statistics = 108 fields, uploaded as d_tb__: +# the per-request lifecycle spans (context, generation, disagg-server) plus the +# per-chunk prefill and per-step decode breakdowns. Which subset is populated +# depends on the case type; the rest upload as 0.0. See MODE_GROUPS there. +# +# .time_breakdown_metrics is deliberately stdlib-only, so importing it here +# never pulls in tensorrt_llm (and with it plotly and the compiled extension) +# during collection. + +# One regex with capture groups instead of 108 literal patterns, for two reasons. +# It cannot participate in the leading-word shadowing hazard described above +# parse_metrics_from_output -- it is matched outside that first-match-wins loop. +# And a span this file does not know about still reaches OpenSearch (just +# without a baseline line), so adding a span to the tool is not silently lossy. +TIME_BREAKDOWN_METRIC_LOG_QUERY = re.compile( + r"Time Breakdown ([A-Za-z_][A-Za-z0-9_]*) " + rf"({'|'.join(TIME_BREAKDOWN_STATS)}) \(ms\):\s+(-?[\d\.]+)" +) + + +def time_breakdown_metric_name(span: str, stat: str) -> str: + """Metric key for one span/statistic pair (uploaded as ``d_``).""" + return f"tb_{span}_{stat}" + + +TIME_BREAKDOWN_METRICS = tuple( + time_breakdown_metric_name(name, stat) + for name in TIME_BREAKDOWN_METRIC_NAMES + for stat in TIME_BREAKDOWN_STATS +) + # 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, ..., @@ -338,8 +489,9 @@ def gen_worker_log_sizes(output_dir: str, num_gen_servers: int) -> List[int]: """Current byte size of each gen_server_{i}.log (0 if missing). Used to delimit per-client segments in DisaggTestCmds.run_cmd: snapshot - sizes before launching a client, then pass the snapshot as start_offsets - to parse_gen_worker_device_step_time after the client exits. + sizes before launching a client, then pass the snapshot as that client's + start_offsets -- and as the *previous* client's end_offsets -- to + parse_gen_worker_device_step_time once the gen logs are flushed. """ sizes: List[int] = [] for i in range(num_gen_servers): @@ -352,9 +504,16 @@ def _scan_gen_worker_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: Optional[List[int]] = None, + end_offsets: Optional[List[int]] = None, ) -> List[List[_IterRow]]: """Single-pass scan of the gen logs. + start_offsets/end_offsets delimit a half-open byte window per file; either + may be None (start of file / end of file). Both bounds are needed, not just + the start: a mode that runs several clients against one gen worker appends + every client's iterations to the same log, so an unbounded window would + make the first client's stats describe the whole run. + 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 @@ -389,9 +548,15 @@ def _scan_gen_worker_device_step_time( 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. + The file is read in binary and decoded per line, for two reasons. It makes + the byte accounting for end_offsets exact and comparable to the + os.path.getsize snapshots that produce the bounds (a text stream cannot be + asked its position mid-iteration -- TextIOWrapper.tell raises "telling + position disabled by next() call" -- and re-encoding a decoded line does not + reliably recover its byte length). It also confines the errors="replace" + guard, still needed because tqdm progress bars during model load write + partial multibyte sequences that would otherwise raise UnicodeDecodeError + mid-scan, to the lines actually parsed. """ per_file_rows: List[List[_IterRow]] = [] for i in range(num_gen_servers): @@ -404,19 +569,30 @@ def _scan_gen_worker_device_step_time( if start_offsets is not None and i < len(start_offsets) and start_offsets[i] else 0 ) + stop_at = end_offsets[i] if end_offsets is not None and i < len(end_offsets) else None rows: List[_IterRow] = [] # 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: + with open(log_path, "rb") as f: if seek_to: f.seek(seek_to) - for line in f: + pos = seek_to + for raw_line in f: + pos += len(raw_line) + if stop_at is not None and pos > stop_at: + # This line ends past the window, so it either belongs to a + # later client or was still being flushed when the bound was + # taken. Dropping one boundary line is the safe direction: + # everything after it belongs to another client's segment. + break # 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: + # the num_scheduled_requests tracking below needs to see. Done on + # bytes so unparsed lines are never decoded. + if b"prev_device_step_time" not in raw_line: continue + line = raw_line.decode(errors="replace") # 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 @@ -507,6 +683,7 @@ def parse_gen_worker_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: Optional[List[int]] = None, + end_offsets: Optional[List[int]] = None, ) -> Optional[_DeviceStepTimeStats]: """Per-iter prev_device_step_time statistics (ms) across all gen workers. @@ -526,9 +703,12 @@ def parse_gen_worker_device_step_time( _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 - single client's iteration segment. + start_offsets[i] and end_offsets[i] delimit the byte window read from + gen_server_{i}.log, slicing out a single client's iteration segment; either + may be None for start-of-file / end-of-file. A mode with more than one + client appends every client's iterations to the same worker log, so an + open-ended window would silently attribute the whole run to the first + client. The log is read exactly once. The caller (DisaggTestCmds.run_cmd) normally waits for the gen_server_{i}.done sentinels first, so every gen srun has @@ -539,7 +719,9 @@ 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_rows = _scan_gen_worker_device_step_time(output_dir, num_gen_servers, start_offsets) + per_file_rows = _scan_gen_worker_device_step_time( + output_dir, num_gen_servers, start_offsets, end_offsets + ) return _stats_at_mode_ngen(per_file_rows) @@ -548,6 +730,7 @@ def add_perf_metric_value( metrics: dict, spec_decoding: bool, benchmark_mode: Optional[str] = None, + time_breakdown: bool = False, ) -> None: """Populate `new_data` with per-test perf metrics from `metrics`. @@ -556,10 +739,16 @@ def add_perf_metric_value( non-spec rows omit it so OpenSearch baselines don't blend the two populations, and spec rows exempted from reporting it (AgentX) omit it rather than failing the upload. - - 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 the mean - and the median are regression-gated (GEN_ONLY_REGRESSION_METRICS); the - rest are uploaded for diagnosis. + - Adds the `d_*_gen_worker_per_iter_device_step_time` family for every mode + in DEVICE_STEP_TIME_MODES. Of these the mean and the median are + regression-gated in gen_only (GEN_ONLY_REGRESSION_METRICS); the rest are + uploaded for diagnosis. + - Adds the `d_tb__` family only when time_breakdown=True. Every + parsed metric is forwarded, including one this module does not list in + TIME_BREAKDOWN_METRIC_NAMES: an unlisted metric loses its baseline + comparison but still reaches OpenSearch, which beats dropping it. A metric + the case type does not support arrives as 0.0 rather than absent, so the + column exists on every row of the series. A missing or non-numeric gen_only statistic is omitted rather than forwarded: typeCheckForOpenSearchDB rejects both None and int for a `d_` @@ -581,12 +770,17 @@ def add_perf_metric_value( al = metrics.get("al") if al is not None: new_data["d_al"] = al - if benchmark_mode == "gen_only": - for metric_name in GEN_ONLY_DEVICE_STEP_TIME_METRICS: + if benchmark_mode in DEVICE_STEP_TIME_MODES: + for metric_name in DEVICE_STEP_TIME_METRICS: value = metrics.get(metric_name) if value is None: continue new_data[f"d_{metric_name}"] = float(value) + if time_breakdown: + for metric_name, value in metrics.items(): + if not metric_name.startswith("tb_") or value is None: + continue + new_data[f"d_{metric_name}"] = float(value) # Metrics where larger is better @@ -612,16 +806,30 @@ def add_perf_metric_value( "d_mean_e2el", "d_median_e2el", "d_p99_e2el", - # gen_only-only: per-iter device step time across gen workers. Lower is + # Per-iter device step time across gen workers, uploaded for every mode in + # DEVICE_STEP_TIME_MODES (gen_only, e2e). Lower is # better for all five, including the spread statistics -- a tighter # distribution is a more trustworthy measurement as well as a steadier - # workload. Mean and median are listed in regression_metrics; std/p75/p99 - # get baselines but cannot fail a build (see check_regression). + # workload. Only in gen_only do mean and median reach regression_metrics + # (GEN_ONLY_REGRESSION_METRICS); in the other modes all five, and in gen_only + # 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", "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", + # time_breakdown-only: the lifecycle spans plus the per-chunk and + # per-step breakdowns. Every one is a duration, so lower is better for all + # 108 -- including tb_step_preprocessing_*, which is legitimately negative + # when the overlap scheduler is on (step N forwards before step N-1's token + # is emitted), and where more negative genuinely is more overlap. + # Registered here -- and NOT in + # REGRESSION_METRICS -- so each gets a baseline and a diff line in + # s_regression_info (that is what makes a TTFT regression attributable to a + # phase) without any of them being able to fail a build. check_regression + # skips a metric absent from new_data, so these names stay inert for every + # other mode and cannot perturb an existing case. + *(f"d_{name}" for name in TIME_BREAKDOWN_METRICS), ] # Default key metrics that determine regression (throughput metrics only). @@ -1728,6 +1936,10 @@ def __init__( self.benchmark_client = client_config_data.get("benchmark_client", "") run_agentx_mode = self.benchmark_client == AGENTX_BENCHMARK_CLIENT self.warmup = warmup and not (run_agentx_mode or self.use_nv_sa_benchmark) + # Directory the servers write per-request perf-metrics JSONLs to. When + # set, the client reads the combined disagg record back after the run and + # prints the per-span statistics; see PerfSanityTestConfig.time_breakdown_dir. + self.save_request_time_breakdown = client_config_data.get("save_request_time_breakdown", "") 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 @@ -1747,6 +1959,15 @@ def __init__( if not self.name: self.name = f"con{self.concurrency}_iter{self.iterations}_isl{self.isl}_osl{self.osl}" + @property + def num_requests(self) -> int: + """Measured requests the client issues (``--num-prompts``). + + Excludes the warmup request, which ``benchmark_serving`` sends before the measured + window when ``--no-test-input`` is omitted. + """ + return self.concurrency * self.iterations + def to_cmd(self) -> List[str]: """Generate benchmark command.""" model_dir = get_model_dir(self.model_name) @@ -1796,7 +2017,7 @@ def _to_sa_benchmark_cmd(self) -> List[str]: "--dataset-name", "random", "--num-prompts", - str(self.concurrency * self.iterations), + str(self.num_requests), "--max-concurrency", str(self.concurrency), "--random-input-len", @@ -1831,7 +2052,7 @@ def _to_default_benchmark_cmd(self) -> List[str]: "--tokenizer", self.model_path, "--num-prompts", - str(self.concurrency * self.iterations), + str(self.num_requests), "--max-concurrency", str(self.concurrency), "--percentile-metrics", @@ -1870,6 +2091,13 @@ def _to_default_benchmark_cmd(self) -> List[str]: benchmark_cmd.append("--non-streaming") if self.trust_remote_code: benchmark_cmd.append("--trust-remote-code") + if self.save_request_time_breakdown: + # Makes the servers write their per-request JSONLs to this directory. + # The client emits only artifacts from them; the "Time Breakdown + # (ms):" lines parse_metrics_from_output scrapes are + # produced solely by append_time_breakdown_metrics below. + benchmark_cmd.append("--save-request-time-breakdown") + benchmark_cmd.append(self.save_request_time_breakdown) return benchmark_cmd def to_env(self) -> Dict[str, str]: @@ -1953,6 +2181,92 @@ def __init__( self.num_gen_servers = hardware.get("num_gen_servers", 0) +def append_time_breakdown_metrics( + pending_time_breakdown: List[dict], + outputs: List[str], + breakdown_dir: str, +) -> None: + """Aggregate the workers' perf_metrics JSONLs into log lines the parser reads. + + Shared by both runtimes: the disaggregated path (ctx + gen workers each write + their own file) and the aggregated path used by ctx_only and plain aggr (a + single server writes one file). The reduction in time_breakdown_metrics is + mode-agnostic -- it classifies each file by content, not by filename -- so the + only difference between the two callers is which directory to scan. + + Must be called *after* benchmark_status is written, for the same reason the + gen_only device step time is (nvbugs 6487036 / 6487040): the workers keep + appending to their JSONLs until their process exits, and reading early would + silently aggregate a truncated run. Being last in the sequence is necessary but + not sufficient -- only the *generation* workers have a completion sentinel, so + wait_for_perf_metrics_files adds the positive gate for the context workers and + the disaggregated server before anything is read. + + Failures are reported and skipped rather than raised: the resulting absence of + parsed ``Time Breakdown ...`` lines is what check_test_failure hard-fails on, + which keeps the diagnosis in one place instead of tearing down the whole + session from inside a post-benchmark hook. + """ + if not pending_time_breakdown: + return + # The largest request count across this directory's clients: every client's + # records land in the same files, so the census check has to allow for all of them. + expected_requests = max( + (record.get("expected_requests") or 0 for record in pending_time_breakdown), + default=0, + ) + paths, wait_info = wait_for_perf_metrics_files( + breakdown_dir, + expected_requests=expected_requests or None, + stable_seconds=PERF_METRICS_SETTLE_SECONDS, + timeout_seconds=PERF_METRICS_SETTLE_TIMEOUT, + ) + for warning in wait_info["warnings"]: + print_info(f"Time breakdown: {warning}") + print_info( + f"Time breakdown: perf_metrics settled after {wait_info['waited_seconds']:.1f}s " + f"(stable={wait_info['stable']}, lines={wait_info['line_counts']})" + ) + if not paths: + print_info( + f"No perf_metrics-*.jsonl under {breakdown_dir}; skipping time breakdown aggregation" + ) + return + for record in pending_time_breakdown: + # The benchmark mode *is* the parser's case type now that the + # time_breakdown modifier is a separate id segment. Checked rather + # than assumed: an unsupported case type would otherwise upload 108 + # zeros and look exactly like a run that measured nothing. + case_type = record["benchmark_mode"] + if case_type not in TIME_BREAKDOWN_MODE_GROUPS: + print_info( + f"No time breakdown groups defined for benchmark mode {case_type!r}; " + "skipping aggregation" + ) + continue + try: + # The client's warmup request is un-measured and absent from every other + # metric on the row, so it is excluded here too -- see _drop_warmup_record. + metrics, info = compute_time_breakdown_metrics( + paths, case_type, drop_warmup_request=bool(record.get("warmup")) + ) + except (OSError, ValueError, KeyError) as exc: + print_info(f"Time breakdown aggregation failed for {breakdown_dir}: {exc}") + continue + + for warning in info["warnings"]: + print_info(f"Time breakdown: {warning}") + print_info(f"Time breakdown ({case_type}) from {len(paths)} file(s): {info['counts']}") + if info["warmup_dropped"]: + print_info(f"Time breakdown: excluded the warmup request from {info['warmup_dropped']}") + + summary_lines = "\n".join(format_metric_log_lines(metrics)) + with open(record["benchmark_file_path"], "a") as benchmark_ctx: + benchmark_ctx.write(f"\n{summary_lines}\n") + idx = record["output_index"] + outputs[idx] = f"{outputs[idx]}\n{summary_lines}\n" + + class AggrTestCmds(NamedTuple): """Commands for aggregated server perf sanity tests.""" @@ -1964,6 +2278,15 @@ class AggrTestCmds(NamedTuple): client_configs: Dict[int, List["ClientConfig"]] = {} model_name: str = "" server_configs: List["ServerConfig"] = [] + # Non-empty exactly when the time_breakdown modifier is on: it is + # PerfSanityTestConfig.time_breakdown_dir(), the single master switch. The + # aggregated runtime serves both plain `aggr*` cases and `ctx_only` (which is + # parsed by the disagg config parser but executed here), and in both the one + # server process writes the perf_metrics JSONL this directory collects. + perf_metrics_output_dir: str = "" + # Parser case type for the reduction (ctx_only / gen_only / e2e). Carried as a + # field because the aggregated path has no per-client config to read it from. + benchmark_mode: str = "" def get_server_logs(self, server_idx) -> List[str]: server_file_path = os.path.join(self.test_output_dir, f"trtllm-serve.{server_idx}.log") @@ -1984,6 +2307,12 @@ def run_cmd(self, server_idx: int) -> List[str]: server_proc = None server_cmd = self.server_cmds[server_idx] client_configs = self.client_configs.get(server_idx, []) + # Deferred for the same reason as on the disagg path (nvbugs 6487036 / + # 6487040): PerfMetricsJsonlWriter drains its queue on a background task + # and only flushes the tail in close(), so the JSONL is complete just + # after the server exits -- i.e. after the finally below, not before it. + pending_time_breakdown: List[dict] = [] + collect_time_breakdown = bool(self.perf_metrics_output_dir) try: server_hostname = "localhost" @@ -2053,6 +2382,18 @@ def run_cmd(self, server_idx: int) -> List[str]: client_file_path, ) outputs.append(output) + if collect_time_breakdown: + pending_time_breakdown.append( + { + "output_index": len(outputs) - 1, + "benchmark_file_path": client_file_path, + "benchmark_mode": self.benchmark_mode, + "warmup": bool(client_config and client_config.warmup), + "expected_requests": ( + client_config.num_requests if client_config else 0 + ), + } + ) else: print_info( f"Skipping perf benchmark for client {client_idx}: only_run_accuracy=True" @@ -2077,6 +2418,12 @@ def run_cmd(self, server_idx: int) -> List[str]: server_proc.terminate() server_proc.wait() + # The server has been reaped, so its perf_metrics JSONL is closed and + # complete. terminate() is SIGTERM, which trtllm-serve handles as a + # graceful shutdown, so PerfMetricsJsonlWriter.close() has run and the + # tail of the queue is on disk. + append_time_breakdown_metrics(pending_time_breakdown, outputs, self.perf_metrics_output_dir) + return outputs def get_cmd_str(self, server_idx: int) -> List[str]: @@ -2110,6 +2457,10 @@ class DisaggTestCmds(NamedTuple): ctx_router_config: Optional[dict] = None gen_router_config: Optional[dict] = None server_config_extra: Optional[dict] = None + # Non-empty only with the time_breakdown modifier: goes into the generated disagg + # server config so the disagg server writes the combined per-request record. + # That combined file is the only one the benchmark client reads. + perf_metrics_output_dir: str = "" def _hostnames_dir(self, server_idx: int) -> str: """Directory the disagg tasks exchange bound addresses through. @@ -2248,6 +2599,21 @@ def _generate_disagg_server_config(self, server_idx: int) -> str: ) server_config.update(copy.deepcopy(self.server_config_extra)) + if self.perf_metrics_output_dir: + # Also flips the disagg server's _collect_perf_metrics on, which is + # what makes it send X-TRTLLM-Return-Metrics: 1 to the workers. Both + # halves are required: without this the workers are never asked for + # their timings, and without the workers' return_perf_metrics they + # would not answer. + # + # Deliberately after the server_config_extra merge, which otherwise + # wins over everything above it: the harness owns this path because + # the client resolves the same directory independently + # (time_breakdown_dir) to find the combined record. A yaml that + # redirected it would not fail -- it would upload no breakdown at + # all, which looks exactly like a case that has none. Non-empty only + # with the time_breakdown modifier, so no other lane is affected. + server_config["perf_metrics_output_dir"] = self.perf_metrics_output_dir config_path = os.path.join(self.test_output_dir, f"server_config.{server_idx}.yaml") with open(config_path, "w") as f: yaml.dump(server_config, f) @@ -2414,10 +2780,12 @@ def _append_gen_worker_device_step_time( 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. + the gen_only run before results are uploaded. Other modes in + DEVICE_STEP_TIME_MODES treat the family as diagnostic, so a fallback + parse that finds nothing simply omits the columns there. Five lines are written, one statistic each -- see - GEN_ONLY_PERF_METRIC_LOG_QUERIES for why they must not share a leading + DEVICE_STEP_TIME_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 @@ -2432,6 +2800,7 @@ def _append_gen_worker_device_step_time( self.test_output_dir, self.num_gen_servers, start_offsets=record["start_offsets"], + end_offsets=record.get("end_offsets"), ) if stats is None: continue @@ -2449,6 +2818,25 @@ def _append_gen_worker_device_step_time( idx = record["output_index"] outputs[idx] = f"{outputs[idx]}\n{summary_lines}\n" + def _append_time_breakdown_metrics( + self, + pending_time_breakdown: List[dict], + outputs: List[str], + ) -> None: + """Disagg entry point for the shared aggregation; see the module function. + + Deferred to after benchmark_status is written, for the same reason the + gen_only device step time is (nvbugs 6487036 / 6487040): the ctx and gen + workers keep appending to their perf_metrics JSONLs until their srun + exits, and reading early would silently aggregate a truncated run. + + PerfSanityTestConfig.time_breakdown_dir() is what *computed* this path; it + is handed to DisaggTestCmds as a field (see the construction site) and is + not a method here. Calling the method on self would raise AttributeError + after the whole benchmark has already run. + """ + append_time_breakdown_metrics(pending_time_breakdown, outputs, self.perf_metrics_output_dir) + def get_server_logs(self, server_idx: int) -> List[str]: server_logs = [] for i in range(self.num_ctx_servers): @@ -2614,9 +3002,18 @@ def run_cmd(self, server_idx: int) -> List[str]: # the loop (as before) could read a truncated / not-yet-flushed log # and report a wrong mean (nvbugs 6487036 / 6487040). pending_device_step_time: List[dict] = [] - collect_device_step_time = ( - configs_for_idx is not None and configs_for_idx[2].benchmark_mode == "gen_only" + benchmark_mode_for_idx = ( + configs_for_idx[2].benchmark_mode if configs_for_idx is not None else None ) + collect_device_step_time = benchmark_mode_for_idx in DEVICE_STEP_TIME_MODES + # Same deferral, same reason: the worker perf_metrics JSONLs are + # still being written until the workers stop. + pending_time_breakdown: List[dict] = [] + # perf_metrics_output_dir is non-empty exactly when the + # time_breakdown modifier is on (PerfSanityTestConfig.time_breakdown_dir + # is the single master switch), so there is no second predicate to + # keep in sync with it. + collect_time_breakdown = bool(self.perf_metrics_output_dir) try: disagg_server_hostname, disagg_server_port = ( self._get_disagg_server_hostname_and_port(server_idx) @@ -2650,15 +3047,28 @@ def run_cmd(self, server_idx: int) -> List[str]: ) print_info(f"Starting benchmark. cmd is {client_cmd_with_port}") - # Snapshot gen_server log sizes so the gen_only - # per-client average covers only iterations driven by - # this client. Other modes do not emit this metric and - # must not wait for the GEN teardown sentinel. + # Snapshot gen_server log sizes so each client's stats + # cover only iterations driven by that client. This is + # also the *end* bound of the previous client's window + # (see the fixup below): taken here, it is necessarily + # after that client returned, so it absorbs whatever + # the gen workers flushed late. Modes outside + # DEVICE_STEP_TIME_MODES skip this and must not wait for + # the GEN teardown sentinel. gen_log_start_offsets = None if collect_device_step_time: gen_log_start_offsets = gen_worker_log_sizes( self.test_output_dir, self.num_gen_servers ) + if pending_device_step_time: + # Close the previous client's window here rather + # than at its own return: this snapshot is the + # first byte of the current client's segment, so + # it cannot exclude an iteration the previous + # client drove, however late it flushed. The + # final record keeps end_offsets None and reads + # to EOF. + pending_device_step_time[-1]["end_offsets"] = gen_log_start_offsets bench_env = copy.deepcopy(os.environ) if client_config: @@ -2685,6 +3095,19 @@ def run_cmd(self, server_idx: int) -> List[str]: "output_index": len(outputs) - 1, "benchmark_file_path": benchmark_file_path, "start_offsets": gen_log_start_offsets, + "end_offsets": None, + } + ) + if collect_time_breakdown: + pending_time_breakdown.append( + { + "output_index": len(outputs) - 1, + "benchmark_file_path": benchmark_file_path, + "benchmark_mode": benchmark_mode_for_idx, + "warmup": bool(client_config and client_config.warmup), + "expected_requests": ( + client_config.num_requests if client_config else 0 + ), } ) else: @@ -2725,9 +3148,16 @@ def run_cmd(self, server_idx: int) -> List[str]: # those sentinels (bounded independently of the whole-test timeout), # then parse each benchmark client's gen-worker device step time a # single time. A timeout falls back to the current log contents. - # Only gen_only runs populate this queue; other modes skip both the - # sentinel wait and device-step-time parsing. + # Every mode in DEVICE_STEP_TIME_MODES (gen_only, e2e) populates this + # queue, so e2e now pays the sentinel wait too. That is bounded and + # small: slurm_launch_draft.sh touches gen_server_{i}.done for every + # disagg mode (only the *ctx* server loop is gated on gen_only), so no + # mode waits out GEN_LOG_SENTINEL_TIMEOUT for a sentinel that is never + # written, and the parse itself seeks to this client's byte window + # instead of rescanning the log. Modes outside the tuple leave the + # queue empty and skip both steps. self._append_gen_worker_device_step_time(pending_device_step_time, outputs) + self._append_time_breakdown_metrics(pending_time_breakdown, outputs) return outputs @@ -2748,58 +3178,93 @@ def parse_select_pattern(select_pattern: str) -> list: return [name.strip() for name in select_pattern.split(",")] +def format_test_label(benchmark_mode: str, time_breakdown: bool = False) -> str: + """Compose the mode segments of a test id: "" or "-". + + The single formatter for both the parametrised test id (get_disagg_test_cases) + and the DisaggConfig/ServerConfig name that becomes s_test_case_name. Those + two are built in different places, and a dashboard name that no longer + reverses into a runnable pytest id is a silent break -- the number is still + uploaded, it just cannot be reproduced. + """ + if time_breakdown: + return f"{benchmark_mode}-{TIME_BREAKDOWN_MODIFIER}" + return benchmark_mode + + def parse_test_string(test_case_name: str): """Parse test case name to get config base name, select pattern, runtime, and benchmark_mode. Test name formats: - - Disagg e2e: disagg_upload-e2e-{config_base} - - Disagg gen_only: disagg_upload-gen_only-{config_base} - - ctx_only: aggr_upload-ctx_only-{config_base} (runs aggr mode but reads disagg config) + - Disagg: disagg_upload-{e2e|gen_only}[-{modifier}]-{config_base} + - ctx_only: aggr_upload-ctx_only[-{modifier}]-{config_base} (runs aggr mode + but reads disagg config) - Regular aggr: aggr_upload-{config}-{server_name} + The modifier segment is optional and drawn from the closed TEST_ID_MODIFIERS + vocabulary, so mode and instrumentation are orthogonal. It is unambiguous + against the config stem because no config stem's first "-"-segment is a + modifier -- get_disagg_test_cases enforces that at collection time. + Returns: - tuple: (config_base_name, select_pattern, runtime_mode, benchmark_mode) + tuple: (config_base_name, select_pattern, runtime_mode, benchmark_mode, + time_breakdown) - runtime_mode: "aggregated" or "disaggregated" - - benchmark_mode: "e2e", "gen_only", "ctx_only", or None (for normal aggr) + - benchmark_mode: "e2e", "gen_only", "ctx_only", or None (normal aggr) + - time_breakdown: True when the time_breakdown modifier is present """ labels = test_case_name.split("-") - assert len(labels) > 1, "perf_sanity test must have a config file!" + # ValueError rather than assert throughout: these are test-id grammar + # violations, and `python -O` (or a future PYTHONOPTIMIZE in a CI image) + # removes assert statements, which would turn a malformed id into a silent + # IndexError or a run against the wrong config instead of a clear rejection. + if len(labels) <= 1: + raise ValueError(f"perf_sanity test must have a config file: {test_case_name}") prefix = labels[0] is_disagg_prefix = "disagg" in prefix is_aggr_prefix = "aggr" in prefix + def split_modifiers(rest: List[str]) -> Tuple[bool, str]: + """Peel the optional modifier segment off the front of the stem.""" + time_breakdown = bool(rest) and rest[0] == TIME_BREAKDOWN_MODIFIER + if time_breakdown: + rest = rest[1:] + if not rest: + raise ValueError(f"Test name has a modifier but no config: {test_case_name}") + return time_breakdown, "-".join(rest) + if is_disagg_prefix: - # Disagg format: disagg_upload-{e2e|gen_only}-{config_base} - assert len(labels) > 2, "Disagg test must have benchmark_mode and config!" - benchmark_mode = labels[1] # e2e or gen_only - assert benchmark_mode in ("e2e", "gen_only"), ( - f"Invalid benchmark_mode for disagg: {benchmark_mode}" - ) + # disagg_upload-{e2e|gen_only}[-{modifier}]-{config_base} + if len(labels) <= 2: + raise ValueError(f"Disagg test must have benchmark_mode and config: {test_case_name}") + benchmark_mode = labels[1] + if benchmark_mode not in ("e2e", "gen_only"): + raise ValueError(f"Invalid benchmark_mode for disagg: {benchmark_mode}") runtime_mode = "disaggregated" - config_base_name = "-".join(labels[2:]) + time_breakdown, config_base_name = split_modifiers(labels[2:]) select_pattern = None elif is_aggr_prefix: - # Check if this is ctx_only (aggr_upload-ctx_only-{config_base}) + # Check if this is ctx_only (aggr_upload-ctx_only[-{modifier}]-{config_base}) if len(labels) > 2 and labels[1] == "ctx_only": - # ctx_only: aggr_upload-ctx_only-{config_base} # Runs in aggregated mode but reads disagg config benchmark_mode = "ctx_only" runtime_mode = "aggregated" - config_base_name = "-".join(labels[2:]) + time_breakdown, config_base_name = split_modifiers(labels[2:]) select_pattern = None else: # Regular aggr: aggr_upload-config_yml or aggr_upload-config_yml-server_config_name benchmark_mode = None runtime_mode = "aggregated" + time_breakdown = False config_base_name = labels[1] # select_pattern is server config name (e.g., "r1_fp8_dep8_mtp1_1k1k") select_pattern = "-".join(labels[2:]) if len(labels) > 2 else None else: raise ValueError(f"Invalid test name prefix: {prefix}") - return config_base_name, select_pattern, runtime_mode, benchmark_mode + return config_base_name, select_pattern, runtime_mode, benchmark_mode, time_breakdown def get_config_dir(benchmark_mode: Optional[str]) -> str: @@ -2857,10 +3322,15 @@ def get_gpu_type() -> str: ) self.gpu_type = get_gpu_type() - # Parse test case name to get config_base_name, select_pattern, runtime, benchmark_mode - config_base_name, self.select_pattern, runtime, self.benchmark_mode = parse_test_string( - test_case_name - ) + # Parse test case name to get config_base_name, select_pattern, runtime, + # benchmark_mode and the time_breakdown modifier + ( + config_base_name, + self.select_pattern, + runtime, + self.benchmark_mode, + self.time_breakdown, + ) = parse_test_string(test_case_name) # Set runtime based on parsed result if runtime == "disaggregated": @@ -2883,7 +3353,8 @@ def parse_config_file(self): config_file_path = os.path.join(self.config_dir, self.config_file) # benchmark_mode determines which parser to use: - # - e2e, gen_only, ctx_only: use _parse_disagg_config_file (reads disagg config) + # - e2e, gen_only, ctx_only: use _parse_disagg_config_file (reads disagg + # config) # - None (normal aggr): use _parse_aggr_config_file if self.benchmark_mode in ("e2e", "gen_only", "ctx_only"): self._parse_disagg_config_file(config_file_path, self.config_file) @@ -2985,6 +3456,9 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): # Use self.benchmark_mode instead of reading from config file benchmark_mode = self.benchmark_mode + # The mode segments of the test id, reused verbatim as the config name so + # s_test_case_name reverses back into a runnable pytest id. + test_label = format_test_label(benchmark_mode, self.time_breakdown) if benchmark_mode == "gen_only": # Check if it's gen_only_no_context from config config_mode = benchmark.get("mode", "e2e") @@ -3036,11 +3510,17 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): # Create server config for ctx_only (single ServerConfig, not tuple) ctx_server_config_data = { "concurrency": -1, # Same as aggr - "name": f"{benchmark_mode}-{config_file_base_name}", + "name": f"{test_label}-{config_file_base_name}", "model_name": model_name, "gpus_per_node": gpus_per_node, "disagg_run_type": "aggr", # Run as aggr **ctx_config, + # ctx_only is parsed here but *executed* on the aggregated path, + # so this lone server is the only process that can emit the + # per-request timing events. Applied last so the modifier wins + # over anything the yaml's ctx block happens to set: without it + # the case would run green and upload 44 zeros. + **self._time_breakdown_worker_overrides(), } checkpoint_io_experiment = assign_checkpoint_io_experiment( [ctx_server_config_data], telemetry_eligible=self.upload_to_db @@ -3058,21 +3538,23 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): ctx_server_config_data = { "internal_request_auth_key": internal_request_auth_key, "concurrency": concurrency_values[0], - "name": f"{benchmark_mode}-{config_file_base_name}", + "name": f"{test_label}-{config_file_base_name}", "model_name": model_name, "gpus_per_node": gpus_per_node, "disagg_run_type": "ctx", **worker_config.get("ctx", {}), + **self._time_breakdown_worker_overrides(), } gen_server_config_data = { "internal_request_auth_key": internal_request_auth_key, "concurrency": concurrency_values[0], - "name": f"{benchmark_mode}-{config_file_base_name}", + "name": f"{test_label}-{config_file_base_name}", "model_name": model_name, "gpus_per_node": gpus_per_node, "disagg_run_type": "gen", **worker_config.get("gen", {}), + **self._time_breakdown_worker_overrides(), } checkpoint_io_experiment = assign_checkpoint_io_experiment( @@ -3088,7 +3570,7 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): ) disagg_config = DisaggConfig( - name=f"{benchmark_mode}-{config_file_base_name}", + name=f"{test_label}-{config_file_base_name}", disagg_serving_type=disagg_serving_type, hostname=socket.gethostname(), numa_bind=numa_bind, @@ -3123,6 +3605,39 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): f"expected '' or {AGENTX_BENCHMARK_CLIENT!r}." ) + # Only benchmark_serving accepts --save-request-time-breakdown. The + # external bench_serving client and the AgentX trace-replay client are + # both different programs with no equivalent flag, so neither can produce + # the lifecycle spans. Fail here naming the reason rather than at upload + # time with a row of zeros, which reads as "this case has no breakdown". + save_request_time_breakdown = self.time_breakdown_dir() + if save_request_time_breakdown: + unsupported = "use_nv_sa_benchmark: true" if use_nv_sa_benchmark else "" + if benchmark_client: + unsupported = f"benchmark_client: {benchmark_client}" + if unsupported: + raise ValueError( + f"The {TIME_BREAKDOWN_MODIFIER} modifier is incompatible with " + f"benchmark.{unsupported}; " + "only tensorrt_llm.serve.scripts.benchmark_serving can emit the " + "per-request time breakdown" + ) + # One client only. Every client in a lane hits the same servers, which + # append every client's requests to one set of perf_metrics JSONLs, and + # the aggregation runs once after the whole lane. Two clients would + # therefore both receive the same whole-lane breakdown, so neither row + # would describe its own concurrency -- and the numbers look perfectly + # healthy, so nothing downstream could notice. The device-step-time + # family avoids this with per-client byte windows into the gen log; the + # JSONLs have no equivalent bound yet, so refuse the case instead. + if len(concurrency_values) > 1: + raise ValueError( + f"The {TIME_BREAKDOWN_MODIFIER} modifier supports exactly one client, " + f"but benchmark.concurrency_list has {len(concurrency_values)} values " + f"({concurrency_values}); every client would be uploaded the same " + "whole-lane breakdown. Split them into one case per concurrency." + ) + if benchmark_mode == "ctx_only": spec_decoding = bool(ctx_server_config.spec_decoding_type) else: @@ -3153,6 +3668,7 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): "benchmark_client": benchmark_client, "accuracy_config": accuracy_data, "only_run_accuracy": only_run_accuracy, + "save_request_time_breakdown": save_request_time_breakdown, } client_config = ClientConfig( client_config_data, @@ -3165,6 +3681,59 @@ def _parse_disagg_config_file(self, config_file_path: str, config_file: str): self.server_client_configs = {0: client_configs} + def time_breakdown_dir(self) -> str: + """Directory the per-request perf-metrics JSONLs are written to. + + Empty unless the time_breakdown modifier is present, which is what + switches the whole feature off elsewhere. A subdirectory of + test_output_dir rather + than test_output_dir itself so the ~8 JSONLs (one per HTTP-serving + worker plus the disagg server's combined file) do not clutter the + artifact listing. Computed the same way test_output_dir is, because + every srun role parses the config independently and they must agree. + """ + if not self.time_breakdown: + return "" + return os.path.join(self._output_dir, self._test_param_labels, "perf_metrics") + + def _time_breakdown_worker_overrides(self) -> dict: + """worker_config keys the time_breakdown modifier forces on each server. + + Applied to the ctx and gen workers of a disaggregated case and to the lone + aggregated server of a ctx_only case -- in every mode, to whichever + processes actually serve requests, since those are the only ones that can + observe a request's timestamps. + + Applied after the yaml's worker_config splat, so these win over the + shared config -- which is the point: the yaml is shared with the e2e, + gen_only and ctx_only ids and must not be edited for this mode's sake. + + - return_perf_metrics is what makes a worker attach its Server-Timing + headers at all (PerfMetricsMiddleware is installed with + expose_headers=return_perf_metrics), and those headers are the only + way worker-side timestamps reach the disagg server's combined JSONL, + which is the one file the benchmark client reads. In ctx_only there is + no disagg server, so this flag is what makes the single server record + its own requests at all. + - perf_metrics_output_dir makes each worker also keep its own record. + On the disagg path the client ignores these (_perf_metrics_files + prefers the "disagg" file) but they carry per-step and per-chunk detail + the header transport cannot express; in ctx_only they are the only + record, and _perf_metrics_files falls back to the "server" kind. + - num_postprocess_workers=0 preserves that detail: PostprocWorker.Output + forwards request_perf_metrics but not time_breakdown_metrics, so a + non-zero value silently flattens the per-step bars. This measurably + changes throughput, which is why the mode has its own baseline series. + """ + perf_metrics_dir = self.time_breakdown_dir() + if not perf_metrics_dir: + return {} + return { + "return_perf_metrics": True, + "perf_metrics_output_dir": perf_metrics_dir, + "num_postprocess_workers": 0, + } + def _resolve_internal_request_auth_key(self, config: dict) -> str: explicit_key = config.get("internal_request_auth_key") if explicit_key: @@ -3239,6 +3808,12 @@ def _get_aggr_commands(self, output_dir: str, test_output_dir: str): client_configs=self.server_client_configs, model_name=agg_model_name, server_configs=list(self.server_configs), + # Empty unless the time_breakdown modifier is on, which is what makes + # run_cmd skip the aggregation entirely. benchmark_mode is None for a + # plain aggr case; "" then fails the MODE_GROUPS membership check with + # a diagnostic instead of reducing against an arbitrary mode. + perf_metrics_output_dir=self.time_breakdown_dir(), + benchmark_mode=self.benchmark_mode or "", ) def _get_disagg_commands(self, output_dir: str, test_output_dir: str): @@ -3310,6 +3885,7 @@ def _get_disagg_commands(self, output_dir: str, test_output_dir: str): server_config_extra=disagg_config.server_config_extra, client_configs=self.server_client_configs, server_configs=list(self.server_configs), + perf_metrics_output_dir=self.time_breakdown_dir(), ) def _check_benchmark_errors(self, output: str) -> None: @@ -3381,9 +3957,25 @@ def parse_metrics_from_output(output: str) -> Optional[Dict[str, float]]: all_queries = { **PERF_METRIC_LOG_QUERIES, **SPEC_DECODING_PERF_METRIC_LOG_QUERIES, - **GEN_ONLY_PERF_METRIC_LOG_QUERIES, + **DEVICE_STEP_TIME_LOG_QUERIES, } for line in output.split("\n"): + # Handled outside the first-match-wins loop below on purpose: + # one regex covers every metric x statistic, so it cannot + # shadow (or be shadowed by) a fixed pattern, and a span this + # module does not know about is still captured. + tb_match = TIME_BREAKDOWN_METRIC_LOG_QUERY.search(line) + if tb_match: + span, stat, value = tb_match.groups() + # append_time_breakdown_metrics is the sole producer of these + # lines, so every uploaded field comes from one computation and + # the spans tile TTFT exactly on the dashboard. Nothing else may + # print them: a second producer would satisfy the + # "parsed no 'Time Breakdown ...' lines" check in + # check_test_failure and hide an aggregation failure behind a + # partial, differently-computed set of spans. + metrics[time_breakdown_metric_name(span, stat)] = float(value) + continue for metric_type, regex in all_queries.items(): if metric_type in metrics: continue @@ -3483,6 +4075,15 @@ def check_test_failure(self): # 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. + # + # Deliberately gen_only and not every mode in + # DEVICE_STEP_TIME_MODES. In gen_only this family is the only + # regression signal, so losing it makes the run pointless. In e2e + # it is diagnostic and throughput still gates, so an absent value + # costs five columns on one row; hard-failing there would turn a + # diagnostic addition into a new red-build mode for every e2e + # case on every cluster, gated on log-scrape plumbing rather than + # on performance. if ( self.runtime == "multi_node_disagg_server" and self.server_configs[server_idx][2].benchmark_mode == "gen_only" @@ -3496,6 +4097,28 @@ def check_test_failure(self): f"missing 'prev_device_step_time' in gen_server_*.log under " f"{self._output_dir}. " ) + # The time_breakdown modifier exists only to publish the + # lifecycle spans. If none were parsed the run measured nothing + # the modifier is for, yet its ordinary metrics are all present -- + # so without this check it would upload as an unremarkable green + # row and the dashboard would show a gap rather than a failure. + # Individual spans stay ungated (a span can legitimately be + # absent when its endpoints were never populated); total absence + # cannot be. + # + # Keyed on the modifier alone, not on the runtime: e2e runs + # disaggregated while ctx_only runs on the aggregated runtime, and + # both collect. A runtime predicate here would have silently + # exempted ctx_only -- the exact failure this check exists to + # catch. Ids that cannot collect never reach here, because only + # the two allowlists above mint a modified id. + if self.time_breakdown and not any(k.startswith("tb_") for k in (metrics or {})): + error_msg += ( + f"{TIME_BREAKDOWN_MODIFIER} test Server {server_idx} Client " + f"{client_idx} parsed no 'Time Breakdown ...' lines from the " + f"benchmark output. Check that the workers wrote " + f"perf_metrics-*.jsonl under {self.time_breakdown_dir()}. " + ) if error_msg: raise RuntimeError(error_msg) @@ -3552,6 +4175,12 @@ def add_dict_prefix(config_dict: dict, prefix_name: str) -> dict: new_data, server_perf_results[client_idx], spec_decoding=client_config.spec_decoding, + # ctx_only rides this runtime (see parse_test_string), so + # the modifier reaches the aggregated branch too. Both + # arguments stay falsy for a plain aggr lane, which is why + # they were previously omitted. + benchmark_mode=self.benchmark_mode, + time_breakdown=self.time_breakdown, ) add_checkpoint_io_experiment_values( new_data, @@ -3610,7 +4239,12 @@ def add_dict_prefix(config_dict: dict, prefix_name: str) -> dict: new_data = { "s_gpu_type": self.gpu_type, "s_runtime": "multi_node_disagg_server", - "s_benchmark_mode": disagg_config.benchmark_mode, + # The composed label, not the bare mode, so a + # time_breakdown run stays distinguishable by this field + # alone. It is reported, never matched on. + "s_benchmark_mode": format_test_label( + disagg_config.benchmark_mode, self.time_breakdown + ), "s_server_env_var": disagg_config.server_env_var, "l_num_ctx_servers": num_ctx_servers, "l_num_gen_servers": num_gen_servers, @@ -3628,6 +4262,7 @@ def add_dict_prefix(config_dict: dict, prefix_name: str) -> dict: server_perf_results[client_idx], spec_decoding=client_config.spec_decoding, benchmark_mode=disagg_config.benchmark_mode, + time_breakdown=self.time_breakdown, ) add_checkpoint_io_experiment_values( new_data, @@ -3684,6 +4319,13 @@ def add_dict_prefix(config_dict: dict, prefix_name: str) -> dict: # until enough runs accrue -- it cannot fail a build before then. regression_metrics = list(GEN_ONLY_REGRESSION_METRICS) else: + # e2e lands here and keeps the throughput + # metrics. They upload the same five device-step-time statistics, but + # no gen_worker name is in REGRESSION_METRICS, so there they can only + # ever earn a baseline and an s_regression_info diff line -- never set + # b_is_regression. That is deliberate: in e2e throughput is a + # meaningful signal and already gates, and device step time is there + # to attribute a regression rather than to declare one. regression_metrics = list(REGRESSION_METRICS) has_spec_decoding = any( cc.spec_decoding @@ -3763,16 +4405,38 @@ def get_disagg_test_cases() -> List[str]: yaml_files = glob.glob(os.path.join(disagg_config_dir, "*.yaml")) basenames = sorted([os.path.splitext(os.path.basename(f))[0] for f in yaml_files]) + # The modifier segment sits between the mode and the config stem, so a config + # whose stem started with a modifier word would parse as a modified case + # against a shorter, wrong filename. Nothing today comes close (every disagg + # stem starts with a GPU token), and this makes the day someone adds one a + # loud collection error instead of a run of the wrong config. + for config_yml in basenames: + first_segment = config_yml.split("-")[0] + if first_segment in TEST_ID_MODIFIERS: + raise ValueError( + f"Disagg config {config_yml}.yaml starts with the reserved test-id " + f"modifier {first_segment!r}; rename it or the generated test id is " + f"ambiguous (see parse_test_string)." + ) + test_cases = [] for config_yml in basenames: # Disagg e2e and gen_only test cases for test_type in DISAGG_TEST_TYPES: - test_cases.append(f"{test_type}-e2e-{config_yml}") - test_cases.append(f"{test_type}-gen_only-{config_yml}") + test_cases.append(f"{test_type}-{format_test_label('e2e')}-{config_yml}") + test_cases.append(f"{test_type}-{format_test_label('gen_only')}-{config_yml}") + # Allowlisted rather than universal; see E2E_TIME_BREAKDOWN_CONFIGS. + if config_yml in E2E_TIME_BREAKDOWN_CONFIGS: + label = format_test_label("e2e", time_breakdown=True) + test_cases.append(f"{test_type}-{label}-{config_yml}") # ctx_only test cases (uses aggr prefix) for test_type in AGG_TEST_TYPES: test_cases.append(f"{test_type}-ctx_only-{config_yml}") + # Allowlisted, for the same reason the e2e ids are. + if config_yml in CTX_ONLY_TIME_BREAKDOWN_CONFIGS: + label = format_test_label("ctx_only", time_breakdown=True) + test_cases.append(f"{test_type}-{label}-{config_yml}") return test_cases diff --git a/tests/integration/defs/perf/time_breakdown_metrics.py b/tests/integration/defs/perf/time_breakdown_metrics.py new file mode 100644 index 000000000000..29d2e06ccde1 --- /dev/null +++ b/tests/integration/defs/perf/time_breakdown_metrics.py @@ -0,0 +1,911 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""Aggregate ``time_breakdown`` per-request lifecycle metrics for perf-sanity upload. + +Reads the per-request ``perf_metrics-*.jsonl`` files produced by a disagg run (or a merged +JSONL) and reduces them to ``mean`` / ``median`` / ``p75`` / ``p99`` per metric, in +milliseconds, ready to be uploaded to OpenSearch as ``d_tb__``. + +Five metric groups, matching ``tensorrt_llm/serve/scripts/time_breakdown/README.md``: + +=== ====================================== ===================================== +# group supported in +=== ====================================== ===================================== +1 Context/Prefill stage (per request) ``ctx_only``, ``e2e`` +2 Per-chunk, prefill (per chunk) ``ctx_only``, ``e2e`` +3 Per-step, generation (per step) ``gen_only``, ``e2e`` +4 Generation/Decode stage (per request) ``gen_only``, ``e2e`` +5 Disaggregation server (per request) ``gen_only``, ``e2e`` +=== ====================================== ===================================== + +Aggregated (non-disagg) cases are not supported at all. Every metric key is always present in +the returned dict; a group that the mode does not support is reported as ``0.0`` so the +OpenSearch document has a stable schema across modes. + +Non-chunked prefill is treated as a single chunk, so group 2 is always populated for +``ctx_only``/``e2e`` -- the per-chunk numbers then simply describe the whole prefill. + +Two properties of the data are relied on, both measured rather than assumed (see +``docs`` in ``compute_time_breakdown_metrics`` for the verification identities): + +**Role is not in the filename.** Every worker writes ``perf_metrics-server---*`` +because ``openai_server.py`` falls back to ``"server"`` when ``server_role is None``. Files are +therefore classified by *content*: ``ctx_chunk_metrics`` => context worker, ``step_metrics`` +=> generation worker. Do not use ``kv_cache_transfer_start`` -- the context worker records it +too, as the send side. + +**Per-chunk / per-step timestamps use a different clock base than the request timestamps.** +``ctx_chunk_metrics`` / ``step_metrics`` timestamps come from a per-worker-process monotonic +clock whose origin differs from the ``timing_metrics`` base by a constant offset (measured on a +9-node GB300 run: ctx ``+294065.985 s``; the four gen workers ``+0.0003``, ``+377680.565``, +``+9.971``, ``+0.993 s`` -- each constant to ~10 us across 80 requests). Intra-instance spans +are offset-invariant, but the *first* chunk's / *first* step's preprocessing is anchored at +``first_scheduled_time`` and crosses the boundary. That offset is estimated per worker file and +removed; uncorrected, one worker's first-step preprocessing would read as ``+377680 s``. + +**The writers are still running when the client exits.** Reading early truncates the +population *silently* -- every field is still populated and the row still uploads. Only the +generation workers have a completion sentinel, so ``wait_for_perf_metrics_files`` supplies the +missing gate for the context workers and the disaggregated server (size stability plus a +record census against the client's request count), and ``_read_jsonl`` skips a partial final +line rather than discarding the file it appears in. +""" + +import argparse +import glob +import json +import math +import os +import statistics +import time +from collections import defaultdict +from typing import Any, Dict, Iterable, List, Optional, Sequence, Tuple + +STATS = ("mean", "median", "p75", "p99") +METRIC_PREFIX = "d_tb_" + +# --- group 1: context/prefill stage, one value per request ------------------------------- +CTX_STAGE_SPANS = ( + ("ctx_preprocessing", "server_arrival_time", "arrival_time"), + ("ctx_queue", "arrival_time", "first_scheduled_time"), + ("ctx_processing", "first_scheduled_time", "first_token_time"), + ("ctx_postprocessing", "first_token_time", "server_first_token_time"), +) + +# --- group 4: generation/decode stage, one value per request ----------------------------- +# ``gen_queue`` is the README-canonical span and *contains* the KV-cache transfer. The three +# sub-spans are the finer decomposition; they tile ``gen_queue`` exactly. +GEN_STAGE_SPANS = ( + ("gen_preprocessing", "server_arrival_time", "arrival_time"), + ("gen_queue", "arrival_time", "first_scheduled_time"), + ("gen_postprocessing", "first_scheduled_time", "server_first_token_time"), + ("gen_queue_wait", "arrival_time", "kv_cache_transfer_start"), + ("gen_kv_transfer", "kv_cache_transfer_start", "kv_cache_transfer_end"), + ("gen_post_transfer", "kv_cache_transfer_end", "first_scheduled_time"), +) + +# --- group 5: disagg server, one value per request --------------------------------------- +# Cross-role spans: (start side, start field, end side, end field). "disagg" means the field +# lives on the combined record itself. +DISAGG_STAGE_SPANS = ( + ("disagg_preprocessing", "disagg", "disagg_server_arrival_time", "ctx", "server_arrival_time"), + ("disagg_relay", "ctx", "server_first_token_time", "gen", "server_arrival_time"), + ( + "disagg_postprocessing", + "gen", + "server_first_token_time", + "disagg", + "disagg_server_first_token_time", + ), +) + +# --- groups 2 and 3: per-instance spans, many values per request ------------------------- +# ``preprocessing`` is special: instance N starts at instance N-1's anchor, and instance 0 +# starts at ``first_scheduled_time`` (which is why the clock offset matters). +_INSTANCE_SPANS = ( + ("forward", "forward_start_time", "forward_end_time"), + ("update", "forward_end_time", "sample_start_time"), + ("sample", "sample_start_time", "sample_end_time"), + ("postprocessing", "sample_end_time", "token_time"), +) +# GPU fields are already in milliseconds (CUDA-event deltas), so they are not scaled. +_INSTANCE_GPU = (("gpu_forward", "gpu_forward_time"), ("gpu_sample", "gpu_sample_time")) + +CHUNK_METRICS = ( + ("chunk_preprocessing",) + + tuple(f"chunk_{n}" for n, _, _ in _INSTANCE_SPANS) + + tuple(f"chunk_{n}" for n, _ in _INSTANCE_GPU) +) +STEP_METRICS = ( + ("step_preprocessing",) + + tuple(f"step_{n}" for n, _, _ in _INSTANCE_SPANS) + + tuple(f"step_{n}" for n, _ in _INSTANCE_GPU) +) + +GROUP_METRICS: Dict[int, Tuple[str, ...]] = { + 1: tuple(n for n, _, _ in CTX_STAGE_SPANS), + 2: CHUNK_METRICS, + 3: STEP_METRICS, + 4: tuple(n for n, _, _ in GEN_STAGE_SPANS), + 5: tuple(n for n, *_ in DISAGG_STAGE_SPANS), +} + +# Which groups each benchmark mode can produce. Aggregated cases support nothing. +MODE_GROUPS: Dict[str, Tuple[int, ...]] = { + "ctx_only": (1, 2), + "gen_only": (3, 4, 5), + "e2e": (1, 2, 3, 4, 5), +} + +ALL_METRICS: Tuple[str, ...] = tuple(m for g in sorted(GROUP_METRICS) for m in GROUP_METRICS[g]) + +# A per-instance "preprocessing" whose magnitude exceeds this is taken as evidence that the +# clock-base offset could not be removed, and is discarded rather than averaged in. Real +# values are sub-millisecond to seconds; a failed correction is tens of thousands of seconds. +_MAX_PLAUSIBLE_PREPROC_MS = 60_000.0 +# Minimum records needed before a per-worker clock offset is trusted. +_MIN_OFFSET_SAMPLES = 3 + + +def _percentile(sorted_vals: Sequence[float], q: float) -> float: + """Linear-interpolation percentile (same convention as ``numpy.percentile``).""" + if len(sorted_vals) == 1: + return float(sorted_vals[0]) + pos = (len(sorted_vals) - 1) * q + lo, hi = math.floor(pos), math.ceil(pos) + if lo == hi: + return float(sorted_vals[lo]) + return float(sorted_vals[lo] + (sorted_vals[hi] - sorted_vals[lo]) * (pos - lo)) + + +def _summarize(values: Iterable[float]) -> Optional[Dict[str, float]]: + vals = [v for v in values if v is not None and not math.isnan(v)] + if not vals: + return None + vals.sort() + return { + "mean": float(statistics.fmean(vals)), + "median": _percentile(vals, 0.50), + "p75": _percentile(vals, 0.75), + "p99": _percentile(vals, 0.99), + } + + +def _ts(container: Optional[Dict[str, Any]], field: str) -> Optional[float]: + """Read a timestamp, mapping the tool's 'missing' encodings to ``None``. + + ``0`` and ``NaN`` both mean "endpoint not recorded" in this data, and + ``TimingMetric.calculate_duration`` treats them as such. Returning ``None`` keeps them out + of the aggregate instead of contributing a bogus zero-width or huge span. + """ + if not container: + return None + val = container.get(field) + if val is None or not isinstance(val, (int, float)): + return None + val = float(val) + if val == 0.0 or math.isnan(val): + return None + return val + + +def _span_ms(start: Optional[float], end: Optional[float]) -> Optional[float]: + if start is None or end is None: + return None + return (end - start) * 1000.0 + + +def _timing(node: Optional[Dict[str, Any]]) -> Dict[str, Any]: + return ((node or {}).get("perf_metrics") or {}).get("timing_metrics") or {} + + +def _breakdown(node: Optional[Dict[str, Any]]) -> Dict[str, Any]: + return (node or {}).get("time_breakdown_metrics") or {} + + +class _RecordView: + """Uniform view over the three record shapes this tool may be handed. + + * **merged** -- ``ctx_perf_metrics`` / ``gen_perf_metrics`` / ``disagg_*`` (output of + ``merge_disagg_perf_metrics.py``); carries request timestamps *and* chunk/step detail. + * **disagg combined** -- same top-level shape, written by the disagg server itself; + carries request timestamps, and chunk/step detail only for fields the header transport + carries. + * **plain worker** -- ``perf_metrics`` / ``time_breakdown_metrics`` at top level, one role + only. Used directly for ``ctx_only`` (which runs the ctx worker in aggregated mode with + no disagg server at all) and as the chunk/step source for ``e2e`` / ``gen_only``. + """ + + def __init__(self, raw: Dict[str, Any]): + self.raw = raw + self.is_combined = "ctx_perf_metrics" in raw or "gen_perf_metrics" in raw + + @property + def ctx(self) -> Optional[Dict[str, Any]]: + return self.raw.get("ctx_perf_metrics") if self.is_combined else self.raw + + @property + def gen(self) -> Optional[Dict[str, Any]]: + return self.raw.get("gen_perf_metrics") if self.is_combined else self.raw + + +def _classify(path: str, records: List[Dict[str, Any]]) -> str: + """Return one of ``combined``, ``ctx_worker``, ``gen_worker``, ``empty``. + + Content-based on purpose: the filename's ```` field is ``server`` for *every* + worker, so it cannot distinguish ctx from gen. + """ + if not records: + return "empty" + if any("ctx_perf_metrics" in r or "gen_perf_metrics" in r for r in records[:200]): + return "combined" + ctx_hits = sum(1 for r in records[:200] if "ctx_chunk_metrics" in _breakdown(r)) + gen_hits = sum(1 for r in records[:200] if "step_metrics" in _breakdown(r)) + if ctx_hits > gen_hits: + return "ctx_worker" + if gen_hits > ctx_hits: + return "gen_worker" + # No structured detail at all (num_postprocess_workers > 0 drops it). Fall back to the + # only role-exclusive request field: kv_cache_transfer_end is written by gen only. + if any(_ts(_timing(r), "kv_cache_transfer_end") for r in records[:200]): + return "gen_worker" + return "ctx_worker" + + +def _read_jsonl(path: str) -> Tuple[List[Dict[str, Any]], int]: + """Parse a JSONL file, skipping unparsable lines. Returns ``(records, skipped)``. + + A malformed line is expected rather than exceptional: the client and every worker + append to these files while the run is live, so the final line can be a partial + write at the moment the aggregator reads (and, for a worker killed mid-flush, can + stay partial forever). Dropping the whole file on one bad line is the worst possible + response -- it zeroes the cross-role group and silently reroutes the per-request + groups to same-role fallbacks, which still upload plausible-looking values. Skip the + line and count it instead; the count is surfaced as a warning by the caller. This + mirrors ``benchmark_serving._read_new_perf_metrics``, which also skips. + """ + out: List[Dict[str, Any]] = [] + skipped = 0 + with open(path) as handle: + for line in handle: + line = line.strip() + if not line: + continue + try: + record = json.loads(line) + except json.JSONDecodeError: + skipped += 1 + continue + if isinstance(record, dict): + out.append(record) + else: + skipped += 1 + return out, skipped + + +def _request_window(raw: Dict[str, Any]) -> Tuple[Optional[float], Optional[float]]: + """``(first arrival, last completion)`` for one record, on that record's own clock. + + Only ever compared against other records from the *same* file, so no cross-worker + clock correction is needed (or valid). + """ + view = _RecordView(raw) + arrivals = [ + ts + for ts in (_ts(_timing(view.ctx), "arrival_time"), _ts(_timing(view.gen), "arrival_time")) + if ts is not None + ] + ends = [ + ts + for ts in ( + _ts(_timing(view.gen), "last_token_time"), + _ts(_timing(view.ctx), "last_token_time"), + ) + if ts is not None + ] + return (min(arrivals) if arrivals else None, max(ends) if ends else None) + + +def _drop_warmup_record( + records: List[Dict[str, Any]], +) -> Tuple[List[Dict[str, Any]], Optional[Dict[str, Any]]]: + """Remove ``benchmark_serving``'s warmup record. Returns ``(kept, dropped_or_None)``. + + perf-sanity omits ``--no-test-input`` for the modes in its ``WARMUP_BENCHMARK_MODES`` + (``e2e`` and ``ctx_only`` -- the same two the time_breakdown modifier supports), so the + client issues one un-measured request before the measured window: its "initial single + prompt test run". ``benchmark_serving`` awaits that request, checks it for success and + then discards it, so it is absent from ``completed`` and from every ``d_*`` client + metric on the row -- but the servers still append a perf-metrics record for it, which + is exactly why the client computes ``expected_count = completed + 1``. Left in, that + one cold request would make ``d_tb_*`` the only family on the row computed over a + different population than the rest. + + It is dropped per file because only the ctx worker and the gen worker that actually + served it hold a record for it; the run's other workers must be left alone. The test + is isolation, which is the one property no measured request has: the warmup request + completes before the measured window opens, whereas measured requests arrive in a + burst at the lane's concurrency and therefore always overlap. A file whose earliest + record is not isolated is returned unchanged. + + Only the mean is materially at risk (a percentile over thousands of requests cannot be + moved by one sample), and no ``d_tb_*`` metric is regression-gated, so this correction + buys accuracy in the diagnostics rather than protecting a build. + """ + if len(records) < 2: + # A lone record cannot be shown to be isolated, and dropping it would leave the + # file empty -- indistinguishable from a run that measured nothing. + return records, None + dated = [ + (window, raw) + for window, raw in ((_request_window(r), r) for r in records) + if window[0] is not None + ] + if len(dated) < 2: + return records, None + dated.sort(key=lambda item: item[0][0]) + (_, first_end), first_rec = dated[0] + second_start = dated[1][0][0] + if first_end is None or first_end >= second_start: + return records, None + return [r for r in records if r is not first_rec], first_rec + + +def _estimate_clock_offset( + records: List[Dict[str, Any]], instances_key: str, reference_field: str +) -> Optional[float]: + """Estimate ``instance clock base - timing_metrics clock base``, in seconds. + + The last instance's ``token_time`` and the request's ``reference_field`` denote the same + physical moment, so their difference is the constant offset between the two bases. The + median over requests is used so a single malformed record cannot move it. + """ + samples = [] + for raw in records: + view = _RecordView(raw) + node = view.ctx if instances_key == "ctx_chunk_metrics" else view.gen + instances = _breakdown(node).get(instances_key) or [] + ref = _ts(_timing(node), reference_field) + if not instances or ref is None: + continue + last = _ts(instances[-1], "token_time") + if last is not None: + samples.append(last - ref) + if len(samples) < _MIN_OFFSET_SAMPLES: + return None + return statistics.median(samples) + + +def _worker_key(raw: Dict[str, Any], role: str, fallback: str) -> str: + """Identify the worker *process* a record's instance array came from. + + The clock-base offset is per process, so records must be grouped by process before the + offset is estimated. A combined/merged record names its workers explicitly + (``ctx_server`` / ``gen_server``), which matters because a single merged file mixes every + worker together -- estimating one offset across N workers corrupts the first-instance + preprocessing for N-1 of them. A plain worker file is already one process, so the file + path is the key. + """ + return str(raw.get(f"{role}_server") or fallback) + + +def _collect_instance_metrics( + records: List[Dict[str, Any]], + instances_key: str, + reference_field: str, + name_prefix: str, + sink: Dict[str, List[float]], + warnings: List[str], + source: str, +) -> int: + """Accumulate group 2 (chunks) or group 3 (steps), grouping records per worker process. + + All spans except the first instance's preprocessing are differences *within* the instance + array and so are invariant to the clock base. The first instance's preprocessing is + ``first_scheduled_time -> forward_start_time``, which crosses bases and needs the offset -- + estimated separately for each worker process present in ``records``. + """ + role = "ctx" if instances_key == "ctx_chunk_metrics" else "gen" + by_worker: Dict[str, List[Dict[str, Any]]] = defaultdict(list) + for raw in records: + by_worker[_worker_key(raw, role, source)].append(raw) + + offsets: Dict[str, Optional[float]] = {} + for key, group in by_worker.items(): + offsets[key] = _estimate_clock_offset(group, instances_key, reference_field) + if offsets[key] is None: + warnings.append( + f"{key}: could not estimate the {name_prefix} clock-base offset " + f"(<{_MIN_OFFSET_SAMPLES} usable records); first-instance " + f"{name_prefix}_preprocessing is excluded" + ) + if len(by_worker) > 1: + spread = [o for o in offsets.values() if o is not None] + if spread and max(spread) - min(spread) > 1.0: + warnings.append( + f"{source}: {len(by_worker)} {role} worker processes with clock-base offsets " + f"spanning {max(spread) - min(spread):.3f}s; corrected per worker" + ) + + discarded = 0 + n_instances = 0 + for raw in records: + offset = offsets[_worker_key(raw, role, source)] + view = _RecordView(raw) + node = view.ctx if instances_key == "ctx_chunk_metrics" else view.gen + instances = _breakdown(node).get(instances_key) or [] + if not instances: + continue + n_instances += len(instances) + anchor = _ts(_timing(node), "first_scheduled_time") + for idx, inst in enumerate(instances): + if idx == 0: + if offset is not None and anchor is not None: + start = _ts(inst, "forward_start_time") + if start is not None: + val = (start - offset - anchor) * 1000.0 + if abs(val) <= _MAX_PLAUSIBLE_PREPROC_MS: + sink[f"{name_prefix}_preprocessing"].append(val) + else: + discarded += 1 + else: + val = _span_ms( + _ts(instances[idx - 1], "token_time"), _ts(inst, "forward_start_time") + ) + if val is not None: + sink[f"{name_prefix}_preprocessing"].append(val) + for name, start_f, end_f in _INSTANCE_SPANS: + val = _span_ms(_ts(inst, start_f), _ts(inst, end_f)) + if val is not None: + sink[f"{name_prefix}_{name}"].append(val) + for name, field in _INSTANCE_GPU: + val = inst.get(field) + if isinstance(val, (int, float)) and not math.isnan(float(val)): + sink[f"{name_prefix}_{name}"].append(float(val)) + if discarded: + warnings.append( + f"{source}: discarded {discarded} first-{name_prefix} preprocessing value(s) " + f"exceeding {_MAX_PLAUSIBLE_PREPROC_MS:.0f} ms -- clock-base offset looks wrong" + ) + return n_instances + + +def compute_time_breakdown_metrics( + paths: Sequence[str], + benchmark_mode: str, + drop_warmup_request: bool = False, +) -> Tuple[Dict[str, float], Dict[str, Any]]: + """Reduce per-request JSONLs to ``{d_tb__: value_ms}``. + + Args: + paths: ``perf_metrics-*.jsonl`` files -- any mix of the disagg combined file, a merged + file, and per-worker files. Multiple context and multiple generation workers are + expected and handled: each file is reduced independently (which is what makes the + per-worker clock-offset correction correct), and the resulting per-request / + per-instance samples are pooled into one case-level distribution. + benchmark_mode: ``ctx_only``, ``gen_only`` or ``e2e``. Anything else yields all-zero + metrics, since aggregated cases do not support the time_breakdown tool. + drop_warmup_request: set when the client ran with a warmup request (perf-sanity omits + ``--no-test-input`` for ``e2e`` and ``ctx_only``). Discards that request's record + so the breakdown covers the same population as every other metric on the row; see + :func:`_drop_warmup_record`. Reported as ``info["warmup_dropped"]``. + + Returns: + ``(metrics, info)``. ``metrics`` always has exactly ``len(ALL_METRICS) * 4`` keys; + unsupported groups and groups with no usable sample are ``0.0``. ``info`` carries + sample counts, per-file classification, warnings, and the verification identities. + + Verification identities held by construction; the caller may assert them: + * groups 1+4+5 minus the ``gen_queue`` sub-spans tile the disagg-observed TTFT exactly; + * the three ``gen_queue`` sub-spans sum to ``gen_queue`` exactly; + * the five per-step spans tile the inter-token period exactly (so under an enabled + overlap scheduler ``step_preprocessing`` is legitimately negative); + * the five per-chunk spans sum to ``ctx_processing``. + """ + groups = MODE_GROUPS.get(benchmark_mode, ()) + per_request: Dict[str, List[float]] = defaultdict(list) + per_instance: Dict[str, List[float]] = defaultdict(list) + warnings: List[str] = [] + classified: Dict[str, str] = {} + counts: Dict[str, int] = defaultdict(int) + warmup_dropped: Dict[str, int] = {} + + combined: List[Dict[str, Any]] = [] + ctx_workers: List[Tuple[str, List[Dict[str, Any]]]] = [] + gen_workers: List[Tuple[str, List[Dict[str, Any]]]] = [] + + skipped_lines: Dict[str, int] = {} + for path in paths: + try: + records, skipped = _read_jsonl(path) + except OSError as exc: + warnings.append(f"{os.path.basename(path)}: unreadable ({exc})") + continue + if skipped: + skipped_lines[os.path.basename(path)] = skipped + warnings.append( + f"{os.path.basename(path)}: skipped {skipped} unparsable line(s) " + f"(kept {len(records)}); a truncated final line is the usual cause" + ) + if drop_warmup_request: + records, dropped = _drop_warmup_record(records) + if dropped is not None: + warmup_dropped[os.path.basename(path)] = 1 + kind = _classify(path, records) + classified[os.path.basename(path)] = f"{kind} (n={len(records)})" + if kind == "combined": + combined.extend(records) + elif kind == "ctx_worker": + ctx_workers.append((path, records)) + elif kind == "gen_worker": + gen_workers.append((path, records)) + + # ---- groups 1, 4, 5: one value per request -------------------------------------- + # Prefer the combined record: group 5 spans are cross-role and need the join. Without + # it each stage falls back to the workers *of its own role* -- never to the other + # role's. _RecordView aliases both .ctx and .gen to the raw record for a single-role + # worker file, so driving group 4 off ctx workers would compute gen_preprocessing / + # gen_queue / gen_postprocessing from the context worker's timestamps and upload + # plausible millisecond values for the wrong phase. Resolving per role instead makes + # a missing combined file cost the affected group its samples (a visible zero) rather + # than silently mislabelling another role's. + ctx_stage_records = combined or [r for _, rs in ctx_workers for r in rs] + gen_stage_records = combined or [r for _, rs in gen_workers for r in rs] + if 1 in groups: + for raw in ctx_stage_records: + ctm = _timing(_RecordView(raw).ctx) + for name, start_f, end_f in CTX_STAGE_SPANS: + val = _span_ms(_ts(ctm, start_f), _ts(ctm, end_f)) + if val is not None: + per_request[name].append(val) + if 4 in groups: + for raw in gen_stage_records: + gtm = _timing(_RecordView(raw).gen) + for name, start_f, end_f in GEN_STAGE_SPANS: + val = _span_ms(_ts(gtm, start_f), _ts(gtm, end_f)) + if val is not None: + per_request[name].append(val) + if 5 in groups: + # Cross-role by construction, so only the combined record can carry it. + for raw in combined: + view = _RecordView(raw) + if not view.is_combined: + continue + sides = {"ctx": _timing(view.ctx), "gen": _timing(view.gen), "disagg": raw} + for name, s_side, s_field, e_side, e_field in DISAGG_STAGE_SPANS: + val = _span_ms(_ts(sides[s_side], s_field), _ts(sides[e_side], e_field)) + if val is not None: + per_request[name].append(val) + counts["ctx_stage_records"] = len(ctx_stage_records) + counts["gen_stage_records"] = len(gen_stage_records) + + # ---- group 2: per-chunk, from every context worker ------------------------------ + if 2 in groups: + sources = ctx_workers or ([("", combined)] if combined else []) + for path, records in sources: + counts["chunks"] += _collect_instance_metrics( + records, + "ctx_chunk_metrics", + "first_token_time", + "chunk", + per_instance, + warnings, + os.path.basename(path), + ) + counts["ctx_workers"] = len(sources) + + # ---- group 3: per-step, from every generation worker ---------------------------- + if 3 in groups: + sources = gen_workers or ([("", combined)] if combined else []) + for path, records in sources: + counts["steps"] += _collect_instance_metrics( + records, + "step_metrics", + "last_token_time", + "step", + per_instance, + warnings, + os.path.basename(path), + ) + counts["gen_workers"] = len(sources) + + # ---- reduce; always emit every key so the OpenSearch schema is mode-stable ------ + metrics: Dict[str, float] = {} + missing: List[str] = [] + for group, names in sorted(GROUP_METRICS.items()): + pool = per_instance if group in (2, 3) else per_request + for name in names: + summary = _summarize(pool.get(name, [])) if group in groups else None + if summary is None: + if group in groups: + missing.append(name) + summary = {stat: 0.0 for stat in STATS} + for stat in STATS: + metrics[f"{METRIC_PREFIX}{name}_{stat}"] = summary[stat] + if missing: + warnings.append( + "supported by mode but no usable sample (reported as 0.0): " + + ", ".join(sorted(missing)) + ) + + info = { + "benchmark_mode": benchmark_mode, + "groups": list(groups), + "files": classified, + "counts": dict(counts), + # Per file, so an unexpected pattern is visible: with a warmup request exactly one + # ctx worker and one gen worker (plus the disagg server) should report a drop. + "warmup_dropped": warmup_dropped, + # Per file, non-empty only when a line failed to parse (usually a partial write). + "skipped_lines": skipped_lines, + "sample_counts": { + name: len( + (per_instance if name in CHUNK_METRICS + STEP_METRICS else per_request).get( + name, [] + ) + ) + for name in ALL_METRICS + }, + "warnings": warnings, + } + return metrics, info + + +def discover_perf_metrics_files(output_dir: str) -> List[str]: + """Find the run's per-request JSONLs, newest-last, under ``output_dir``. + + Looks in ``output_dir`` and a ``perf_metrics/`` subdirectory, which is where + ``perf_metrics_output_dir`` puts them. + """ + patterns = ( + os.path.join(output_dir, "perf_metrics-*.jsonl"), + os.path.join(output_dir, "perf_metrics", "perf_metrics-*.jsonl"), + ) + found: List[str] = [] + for pattern in patterns: + found.extend(sorted(glob.glob(pattern))) + # Deduplicate while preserving order, and drop empties so _classify never sees them. + seen = set() + result = [] + for path in found: + real = os.path.realpath(path) + if real in seen: + continue + try: + size = os.path.getsize(path) + except OSError: + # Raced with a rename/removal between glob and stat. Treat it as absent + # rather than aborting the completion gate, which is meant to expire as a + # warning; snapshot() below tolerates the same race on the same syscall. + continue + if size > 0: + seen.add(real) + result.append(path) + return result + + +# Bounds for wait_for_perf_metrics_files. The gate exists to cover the *tail* of the +# writers' drain, not a hang: PerfMetricsJsonlWriter drains its queue continuously in a +# background thread (batch 64, no timer), so at the moment the client exits only the last +# handful of records are still in flight. Seconds is the right order of magnitude; the +# timeout is a backstop for a worker that is wedged, and expiring it is a warning rather +# than an error because reading a nearly-complete file still yields usable statistics. +COMPLETION_STABLE_SECONDS = 3.0 +COMPLETION_TIMEOUT_SECONDS = 60.0 +COMPLETION_POLL_SECONDS = 0.5 + + +def _count_lines(path: str) -> int: + """Number of newline-terminated lines in ``path``. + + Deliberately counts newlines, not records: a final line without a trailing newline is + a partial write, and excluding it is exactly the semantics the completion check wants. + """ + total = 0 + with open(path, "rb") as handle: + while True: + chunk = handle.read(1 << 20) + if not chunk: + return total + total += chunk.count(b"\n") + + +def wait_for_perf_metrics_files( + output_dir: str, + expected_requests: Optional[int] = None, + stable_seconds: float = COMPLETION_STABLE_SECONDS, + timeout_seconds: float = COMPLETION_TIMEOUT_SECONDS, + poll_seconds: float = COMPLETION_POLL_SECONDS, + sleep=time.sleep, + monotonic=time.monotonic, +) -> Tuple[List[str], Dict[str, Any]]: + """Wait for the perf_metrics JSONLs to stop growing, then return them. + + Positive completion gate for the aggregation. The harness has no completion signal for + the context workers or the disaggregated server -- unlike the generation workers, whose + ``gen_server_{i}.done`` sentinels the device-step-time path already waits on -- so + without this the aggregator races the writers' tail flush and silently reduces a + truncated population. Nothing downstream can notice: every metric is still populated + and the row uploads green. + + Poll the discovered set's total byte size until it holds still for ``stable_seconds`` + (new files appearing counts as growth), bounded by ``timeout_seconds``. Then, if + ``expected_requests`` is known, compare it against the largest file's complete-line + count -- the disagg server and the aggregated server each write one record per request, + so that file is the run's census -- and report a shortfall. + + ``sleep`` / ``monotonic`` are injected so the unit tests can drive this without wall + time. + + Returns ``(paths, info)``; ``info`` carries ``stable`` (bool), ``waited_seconds``, + ``total_bytes``, ``line_counts`` and ``warnings``. + """ + warnings: List[str] = [] + deadline = monotonic() + timeout_seconds + + def snapshot() -> Tuple[List[str], Tuple[Tuple[str, Optional[int]], ...]]: + paths = discover_perf_metrics_files(output_dir) + sizes = [] + for path in paths: + try: + sizes.append((os.path.basename(path), os.path.getsize(path))) + except OSError: + # Raced with a rename/removal; ``None`` differs from any size, so the + # next poll sees a change and the stability window restarts. + sizes.append((os.path.basename(path), None)) + return paths, tuple(sizes) + + started = monotonic() + paths, fingerprint = snapshot() + if not paths: + # Nothing was ever created, so there is nothing to wait for: the workers write + # their first record long before the client exits. The caller reports the empty + # discovery itself. + return [], { + "stable": True, + "waited_seconds": 0.0, + "total_bytes": 0, + "line_counts": {}, + "expected_requests": expected_requests, + "warnings": warnings, + } + unchanged_since = monotonic() + stable = False + while True: + now = monotonic() + if now - unchanged_since >= stable_seconds: + stable = True + break + if now >= deadline: + warnings.append( + f"perf_metrics files under {output_dir} were still growing after " + f"{timeout_seconds:.0f}s; aggregating what is on disk" + ) + break + sleep(min(poll_seconds, max(0.0, deadline - now))) + paths, new_fingerprint = snapshot() + if new_fingerprint != fingerprint: + fingerprint = new_fingerprint + unchanged_since = monotonic() + + line_counts: Dict[str, int] = {} + for path in paths: + try: + line_counts[os.path.basename(path)] = _count_lines(path) + except OSError as exc: + warnings.append(f"{os.path.basename(path)}: could not count lines ({exc})") + + if expected_requests and line_counts: + census = max(line_counts.values()) + if census < expected_requests: + warnings.append( + f"the largest perf_metrics file holds {census} complete record(s) but the " + f"client issued {expected_requests} request(s); the breakdown covers a " + "subset of the run" + ) + + info = { + "stable": stable, + "waited_seconds": monotonic() - started, + "total_bytes": sum(size for _, size in fingerprint if size is not None), + "line_counts": line_counts, + "expected_requests": expected_requests, + "warnings": warnings, + } + return paths, info + + +def format_metric_log_lines(metrics: Dict[str, float]) -> List[str]: + """Render metrics as ``Time Breakdown (ms): `` log lines. + + The harness re-parses these out of the benchmark log, the same way the ``gen_only`` + device-step-time statistics are transported. + """ + lines = [] + for name in ALL_METRICS: + for stat in STATS: + key = f"{METRIC_PREFIX}{name}_{stat}" + if key in metrics: + lines.append(f"Time Breakdown {name} {stat} (ms): {metrics[key]:.6f}") + return lines + + +def main() -> int: + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0]) + parser.add_argument( + "--mode", + required=True, + choices=sorted(MODE_GROUPS) + ["aggr"], + help="benchmark mode; 'aggr' yields all zeros (unsupported)", + ) + parser.add_argument( + "--input", + action="append", + default=[], + metavar="JSONL", + help="a perf_metrics/merged JSONL; repeatable for multiple workers", + ) + parser.add_argument("--output-dir", help="discover perf_metrics-*.jsonl under this dir") + parser.add_argument("--json-out", help="write the metric dict here") + parser.add_argument( + "--log-lines", + action="store_true", + help="print 'Time Breakdown ...' lines for the harness to re-parse", + ) + parser.add_argument( + "--drop-warmup-request", + action="store_true", + help="discard the client's un-measured warmup request (perf-sanity runs one for " + "e2e and ctx_only); pass this to match what the harness uploads", + ) + args = parser.parse_args() + + paths = list(args.input) + if args.output_dir: + paths.extend(discover_perf_metrics_files(args.output_dir)) + if not paths: + parser.error("no input: pass --input and/or --output-dir") + + metrics, info = compute_time_breakdown_metrics( + paths, args.mode, drop_warmup_request=args.drop_warmup_request + ) + + if args.log_lines: + for line in format_metric_log_lines(metrics): + print(line) + else: + print(f"mode={info['benchmark_mode']} groups={info['groups']} counts={info['counts']}") + for name, kind in sorted(info["files"].items()): + dropped = " (-1 warmup)" if info["warmup_dropped"].get(name) else "" + print(f" {name}: {kind}{dropped}") + header = f"{'metric':24s}" + "".join(f"{s:>12s}" for s in STATS) + f"{'n':>9s}" + print(header) + print("-" * len(header)) + for group, names in sorted(GROUP_METRICS.items()): + print(f"-- group {group} --") + for name in names: + vals = "".join(f"{metrics[f'{METRIC_PREFIX}{name}_{s}']:12.3f}" for s in STATS) + print(f"{name:24s}{vals}{info['sample_counts'][name]:9d}") + for warning in info["warnings"]: + print(f"WARNING: {warning}") + + if args.json_out: + with open(args.json_out, "w") as handle: + json.dump({"metrics": metrics, "info": info}, handle, indent=2, sort_keys=True) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tests/integration/test_lists/test-db/l0_a10.yml b/tests/integration/test_lists/test-db/l0_a10.yml index d4fdf3ddca7e..278cffebb840 100644 --- a/tests/integration/test_lists/test-db/l0_a10.yml +++ b/tests/integration/test_lists/test-db/l0_a10.yml @@ -71,7 +71,6 @@ l0_a10: - unittest/tools/test_host_profiler.py - unittest/tools/test_infra_dry_run_pipeline.py - unittest/tools/test_infra_dry_run_pytest.py - - unittest/tools/test_perf_sanity_matching.py - unittest/tools/test_unittest_culprits.py - unittest/usage/test_transport.py - unittest/usage/test_e2e_capture.py diff --git a/tests/integration/test_lists/test-db/l0_cpu.yml b/tests/integration/test_lists/test-db/l0_cpu.yml index 233430c6ba82..e865163cb361 100644 --- a/tests/integration/test_lists/test-db/l0_cpu.yml +++ b/tests/integration/test_lists/test-db/l0_cpu.yml @@ -105,6 +105,12 @@ l0_cpu: - unittest/llmapi/apps/test_harmony_parsing.py::TestStripIncompleteMessagesReporting - unittest/llmapi/apps/test_kimi_serve_extensions.py - unittest/llmapi/apps/test_reasoning_prompt_resolution.py + # test_request_metrics.py as a whole is not registered on any list, so only the + # two cases added with the KV-transfer fix are selected here. Registering the + # file would also enable a dozen pre-existing cases that have never run in CI, + # which belongs in its own change. + - unittest/llmapi/apps/test_request_metrics.py::test_header_derived_record_keeps_kv_transfer_without_kv_cache_size + - unittest/llmapi/apps/test_request_metrics.py::test_unpopulated_kv_transfer_timestamps_stay_absent - unittest/llmapi/apps/test_responses_custom_tools.py - unittest/llmapi/apps/test_responses_input_preprocess.py - unittest/llmapi/apps/test_responses_streaming_events.py diff --git a/tests/integration/test_lists/test-db/l0_gb300_multi_gpus_perf_sanity.yml b/tests/integration/test_lists/test-db/l0_gb300_multi_gpus_perf_sanity.yml index 4a6935a5ef68..89dbd4466b63 100644 --- a/tests/integration/test_lists/test-db/l0_gb300_multi_gpus_perf_sanity.yml +++ b/tests/integration/test_lists/test-db/l0_gb300_multi_gpus_perf_sanity.yml @@ -25,6 +25,7 @@ l0_gb300_multi_gpus_perf_sanity: - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_deepseek-v4-pro-fp4_8k1k_con8_ctx1_dep4_gen4_tep8_eplb0_mtp3_ccb-NIXL] TIMEOUT (90) - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_deepseek-v4-pro-fp4_8k1k_con180_ctx3_dep4_gen1_dep32_eplb384_mtp3_ccb-NIXL] TIMEOUT (90) - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL] TIMEOUT (90) + - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-time_breakdown-gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL] TIMEOUT (90) - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_deepseek-v4-pro-fp4_8k1k_con4301_ctx12_dep4_gen1_dep8_eplb384_mtp1_ccb-NIXL] TIMEOUT (120) # nemotron-ultra-v3-fp4 8k64k (ctx_only) - perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_nemotron-ultra-v3-fp4_8k64k_con1_ctx1_dep4_gen1_tep4_eplb0_mtp5_ccb-NIXL] TIMEOUT (90) diff --git a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8.yml b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8.yml index d4d0de7d1ea1..b04dca2b9f9c 100644 --- a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8.yml +++ b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8.yml @@ -17,3 +17,4 @@ l0_gb300_multi_nodes_perf_sanity_ctx12_node1_gpu4_gen1_node2_gpu8: # deepseek-v4-pro-fp4 8k1k con4301 (max throughput) - perf/test_perf_sanity.py::test_e2e[disagg_upload-gen_only-gb300_deepseek-v4-pro-fp4_8k1k_con4301_ctx12_dep4_gen1_dep8_eplb384_mtp1_ccb-NIXL] TIMEOUT (120) - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-gb300_deepseek-v4-pro-fp4_8k1k_con4301_ctx12_dep4_gen1_dep8_eplb384_mtp1_ccb-NIXL] TIMEOUT (120) + - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-time_breakdown-gb300_deepseek-v4-pro-fp4_8k1k_con4301_ctx12_dep4_gen1_dep8_eplb384_mtp1_ccb-NIXL] TIMEOUT (120) diff --git a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8.yml b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8.yml index 07ad83e0e1e4..68ff643ef21b 100644 --- a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8.yml +++ b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8.yml @@ -17,3 +17,4 @@ l0_gb300_multi_nodes_perf_sanity_ctx1_node1_gpu4_gen4_node2_gpu8: # deepseek-v4-pro-fp4 8k1k con8 (single-user latency) - perf/test_perf_sanity.py::test_e2e[disagg_upload-gen_only-gb300_deepseek-v4-pro-fp4_8k1k_con8_ctx1_dep4_gen4_tep8_eplb0_mtp3_ccb-NIXL] TIMEOUT (120) - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-gb300_deepseek-v4-pro-fp4_8k1k_con8_ctx1_dep4_gen4_tep8_eplb0_mtp3_ccb-NIXL] TIMEOUT (120) + - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-time_breakdown-gb300_deepseek-v4-pro-fp4_8k1k_con8_ctx1_dep4_gen4_tep8_eplb0_mtp3_ccb-NIXL] TIMEOUT (120) diff --git a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32.yml b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32.yml index a6cdb0d3430e..f39a1c258486 100644 --- a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32.yml +++ b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32.yml @@ -17,3 +17,4 @@ l0_gb300_multi_nodes_perf_sanity_ctx3_node1_gpu4_gen1_node8_gpu32: # deepseek-v4-pro-fp4 8k1k con180 - perf/test_perf_sanity.py::test_e2e[disagg_upload-gen_only-gb300_deepseek-v4-pro-fp4_8k1k_con180_ctx3_dep4_gen1_dep32_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-gb300_deepseek-v4-pro-fp4_8k1k_con180_ctx3_dep4_gen1_dep32_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) + - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-time_breakdown-gb300_deepseek-v4-pro-fp4_8k1k_con180_ctx3_dep4_gen1_dep32_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) diff --git a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16.yml b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16.yml index 76f981ff6acb..96bb2ba7a7bd 100644 --- a/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16.yml +++ b/tests/integration/test_lists/test-db/l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16.yml @@ -17,3 +17,4 @@ l0_gb300_multi_nodes_perf_sanity_ctx6_node1_gpu4_gen1_node4_gpu16: # deepseek-v4-pro-fp4 8k1k con666 - perf/test_perf_sanity.py::test_e2e[disagg_upload-gen_only-gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) + - perf/test_perf_sanity.py::test_e2e[disagg_upload-e2e-time_breakdown-gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL] TIMEOUT (120) diff --git a/tests/unittest/llmapi/apps/test_request_metrics.py b/tests/unittest/llmapi/apps/test_request_metrics.py index edf92613fe6e..dd0544d6f3fa 100644 --- a/tests/unittest/llmapi/apps/test_request_metrics.py +++ b/tests/unittest/llmapi/apps/test_request_metrics.py @@ -78,6 +78,35 @@ def _record(status="complete"): } +def _record_with_kv_transfer(): + # _record() carries None for both KV timestamps, which every revision drops, so + # it cannot tell a working KV-transfer span from a zeroed one. + record = _record() + timing = record["phases"]["server"]["timing_metrics"] + timing["kv_cache_transfer_start"] = 1.011 + timing["kv_cache_transfer_end"] = 1.013 + return record + + +def _disagg_record_from_headers(worker_record): + headers = build_metrics_headers([worker_record]) + return headers, combine_disagg_metrics( + "42", + { + "ctx_server": "ctx:8000", + "gen_server": "gen:8000", + "timing_metrics": { + "server_arrival_time": 0.99, + "ctx_dispatch_time": 1.0, + "server_first_token_time": 1.03, + }, + }, + build_metrics_record_from_headers(headers, "ctx", request_id="42"), + build_metrics_record_from_headers(headers, "gen", request_id="42"), + disagg_request_id=42, + ) + + def test_metrics_headers_use_metric_list_syntax(): headers = build_metrics_headers([_record()]) @@ -160,6 +189,34 @@ def test_time_breakdown_parser_accepts_header_derived_disagg_record(): assert combined_headers[SERVER_TIMING_HEADER].count("ctx_queue;") == 1 +def test_header_derived_record_keeps_kv_transfer_without_kv_cache_size(): + # kv_cache_size is worker-local and has no Server-Timing header, so a record + # reconstructed from headers never carries it. Gating the KV-transfer timestamps + # on kv_cache_size therefore discarded them for every disaggregated request, + # zeroing that span; they must be gated on the timestamps themselves. + headers, record = _disagg_record_from_headers(_record_with_kv_transfer()) + assert "server-kv-start;" in headers[START_END_TIME_HEADER] + + gen_timing = record["phases"]["gen"]["timing_metrics"] + assert gen_timing["kv_cache_transfer_start"] == pytest.approx(1.011) + assert "kv_cache_size" not in gen_timing + + timing = _jsonl_record(record)["gen_perf_metrics"]["perf_metrics"]["timing_metrics"] + assert timing["kv_cache_transfer_start"] == pytest.approx(1.011) + assert timing["kv_cache_transfer_end"] == pytest.approx(1.013) + assert "kv_cache_size" not in timing + + +def test_unpopulated_kv_transfer_timestamps_stay_absent(): + # The other half of the same gate: an unpopulated timestamp must not be written + # as 0.0, or a consumer testing presence reads a zero-width transfer as real. + _, record = _disagg_record_from_headers(_record()) + + timing = _jsonl_record(record)["gen_perf_metrics"]["perf_metrics"]["timing_metrics"] + assert "kv_cache_transfer_start" not in timing + assert "kv_cache_transfer_end" not in timing + + @pytest.mark.asyncio @pytest.mark.parametrize( ("expose_headers", "request_metrics", "expected"), diff --git a/tests/unittest/tools/test_perf_sanity_matching.py b/tests/unittest/tools/test_perf_sanity_matching.py deleted file mode 100644 index 76e8b680acb0..000000000000 --- a/tests/unittest/tools/test_perf_sanity_matching.py +++ /dev/null @@ -1,499 +0,0 @@ -# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. -# SPDX-License-Identifier: Apache-2.0 -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. - -import ast -import importlib.util -import pathlib -import sys -import types - -from test_common.perf_sanity_matching import benchmark_data_matches, get_test_case_match_keys - - -def _benchmark_data(**overrides: object) -> dict[str, object]: - data: dict[str, object] = { - "s_test_case_name": "example_model_fp8_tp8-con32_iter10_1k1k", - "s_gpu_type": "b200", - "s_runtime": "aggr_server", - "s_branch": "main", - "s_model_name": "example_model", - "l_gpus": 8, - "l_tp": 8, - "l_ep": 1, - "l_max_batch_size": 32, - "s_kv_cache_dtype": "fp8", - "l_concurrency": 32, - "l_iterations": 10, - "l_isl": 1024, - "l_osl": 1024, - } - data.update(overrides) - return data - - -def test_match_keys_are_name_and_environment_only() -> None: - assert get_test_case_match_keys() == [ - "s_test_case_name", - "s_gpu_type", - "s_runtime", - "s_branch", - ] - - -def test_matching_ignores_tuning_changes() -> None: - """Tunables do not fork a case *while the name is held constant*. - - That proviso is the whole story for l_iterations, which reaches the case name - on the disagg path -- see test_iterations_fork_a_case_through_the_derived_name. - """ - previous_data = _benchmark_data() - updated_data = _benchmark_data( - l_max_batch_size=64, - s_kv_cache_dtype="auto", - l_iterations=20, - l_force_num_accepted_tokens=3, - ) - - assert benchmark_data_matches(previous_data, updated_data, get_test_case_match_keys()) - - -def _load_module() -> types.ModuleType: - """Import test_perf_sanity.py without the integration-test packages. - - Rules under test are only worth asserting against the code that owns them; - re-implementing them here would assert nothing. test_perf_sanity.py reaches - torch and the OpenSearch client through its imports, so those are stubbed -- - ClientConfig.__init__ and wants_warmup touch none of them. - """ - repo_root = pathlib.Path(__file__).resolve().parents[3] - module_path = repo_root / "tests" / "integration" / "defs" / "perf" / "test_perf_sanity.py" - - def stub(name: str, **attrs: object) -> types.ModuleType: - module = types.ModuleType(name) - for key, value in attrs.items(): - setattr(module, key, value) - return module - - def noop(*args: object, **kwargs: object) -> None: - return None - - defs_pkg = stub("defs") - defs_pkg.__path__ = [] - perf_pkg = stub("defs.perf") - perf_pkg.__path__ = [] - stubs = { - "defs": defs_pkg, - "defs.perf": perf_pkg, - "defs.common": stub("defs.common", wait_for_reported_addr=noop), - "defs.trt_test_alternative": stub( - "defs.trt_test_alternative", print_info=noop, print_warning=noop - ), - "defs.conftest": stub( - "defs.conftest", - get_llm_root=lambda *a, **k: "/repo", - llm_models_root=lambda *a, **k: "/models", - ), - "defs.perf._model_paths": stub("defs.perf._model_paths", MODEL_PATH_DICT={}), - "defs.perf.open_search_db_utils": stub( - "defs.perf.open_search_db_utils", - add_id=noop, - get_history_data=noop, - post_new_perf_data=noop, - ), - "defs.perf.perf_regression_utils": stub( - "defs.perf.perf_regression_utils", - process_and_upload_test_results=noop, - get_job_info=noop, - _percentile=noop, - ), - } - - saved = {name: sys.modules.get(name) for name in stubs} - sys.modules.update(stubs) - try: - spec = importlib.util.spec_from_file_location("defs.perf.test_perf_sanity", module_path) - module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(module) - finally: - for name, previous in saved.items(): - if previous is None: - sys.modules.pop(name, None) - else: - sys.modules[name] = previous - return module - - -def _load_client_config() -> type: - """Return the real ClientConfig.""" - return _load_module().ClientConfig - - -def _disagg_client_data(multi_round: int) -> dict[str, object]: - """The client dict a disagg config builds (test_perf_sanity.py:2266-2277). - - Notably it carries no "name", so ClientConfig derives one. - """ - return { - "concurrency": 12, - "iterations": multi_round, - "isl": 50000, - "osl": 2048, - } - - -def test_disagg_iterations_come_from_multi_round() -> None: - """Pin the yaml key that feeds "iterations" on the disagg path. - - _parse_disagg_config_file cannot be called here -- PerfSanityTestConfig's - constructor shells out to nvidia-smi and raises without a GPU -- so the - mapping is asserted against its source instead of re-stated in a docstring. - Without this, renaming the yaml key would leave the tests below green while - the documented behaviour silently changed. - """ - repo_root = pathlib.Path(__file__).resolve().parents[3] - module_path = repo_root / "tests" / "integration" / "defs" / "perf" / "test_perf_sanity.py" - tree = ast.parse(module_path.read_text()) - - iterations_values = [ - value - for node in ast.walk(tree) - if isinstance(node, ast.Dict) - for key, value in zip(node.keys, node.values) - if isinstance(key, ast.Constant) and key.value == "iterations" - ] - - assert iterations_values, 'no dict literal builds an "iterations" entry' - assert any("multi_round" in ast.dump(value) for value in iterations_values), ( - '"iterations" is no longer derived from benchmark.multi_round; ' - "update README_test_perf_sanity.md and the tests below" - ) - - -def test_iterations_fork_a_case_through_the_derived_name() -> None: - """benchmark.multi_round renames a disagg case, so it still forks history. - - multi_round becomes the client's "iterations" (test_perf_sanity.py:2270), which - lands in the derived name (:1119) and hence in s_test_case_name. Dropping - l_iterations from the match key therefore does not make it fork-free on this - path. Intended -- iterations sets the measurement length, so iter10 and iter12 - do not measure the same quantity -- but it costs the renamed case its history, - so it is pinned here rather than left as an assumption. - """ - client_config = _load_client_config() - - ten = client_config(_disagg_client_data(10), "example_model") - twelve = client_config(_disagg_client_data(12), "example_model") - - assert ten.name == "con12_iter10_isl50000_osl2048" - assert twelve.name == "con12_iter12_isl50000_osl2048" - - stem = "e2e-gb300_example_model_50k2k_con12_ctx1_dep4_gen6_tep4-" - assert not benchmark_data_matches( - _benchmark_data(s_test_case_name=stem + ten.name, l_iterations=10), - _benchmark_data(s_test_case_name=stem + twelve.name, l_iterations=12), - get_test_case_match_keys(), - ) - - -def test_an_explicit_client_name_keeps_the_case_across_an_iterations_change() -> None: - """Aggregated configs all name their clients, so tuning keeps the history. - - This is the path where removing l_iterations from the key pays off: the name is - pinned by the yaml, so a changed iterations count stays on one curve. - """ - client_config = _load_client_config() - - ten = client_config({**_disagg_client_data(10), "name": "con1024_iter10_1k1k"}, "example_model") - twenty = client_config( - {**_disagg_client_data(20), "name": "con1024_iter10_1k1k"}, "example_model" - ) - - assert ten.name == twenty.name == "con1024_iter10_1k1k" - assert benchmark_data_matches( - _benchmark_data(s_test_case_name="example_model_fp8_tp8-" + ten.name, l_iterations=10), - _benchmark_data(s_test_case_name="example_model_fp8_tp8-" + twenty.name, l_iterations=20), - get_test_case_match_keys(), - ) - - -def test_matching_distinguishes_test_case_name() -> None: - previous_data = _benchmark_data() - updated_data = _benchmark_data(s_test_case_name="example_model_fp8_tp4-con32_iter10_1k1k") - - assert not benchmark_data_matches(previous_data, updated_data, get_test_case_match_keys()) - - -def test_matching_distinguishes_gpu_type() -> None: - previous_data = _benchmark_data() - updated_data = _benchmark_data(s_gpu_type="gb200") - - assert not benchmark_data_matches(previous_data, updated_data, get_test_case_match_keys()) - - -def test_matching_distinguishes_runtime() -> None: - previous_data = _benchmark_data() - updated_data = _benchmark_data(s_runtime="multi_node_aggr_server") - - assert not benchmark_data_matches(previous_data, updated_data, get_test_case_match_keys()) - - -def test_matching_distinguishes_branch() -> None: - previous_data = _benchmark_data() - updated_data = _benchmark_data(s_branch="release/1.3.0") - - assert not benchmark_data_matches(previous_data, updated_data, get_test_case_match_keys()) - - -def test_benchmark_mode_is_not_a_match_key() -> None: - assert "s_benchmark_mode" not in get_test_case_match_keys() - history = _benchmark_data( - s_test_case_name="e2e-example_disagg-con32_iter10_1k1k", - s_runtime="multi_node_disagg_server", - s_benchmark_mode=None, - ) - new = _benchmark_data( - s_test_case_name="e2e-example_disagg-con32_iter10_1k1k", - s_runtime="multi_node_disagg_server", - s_benchmark_mode="e2e", - ) - - assert benchmark_data_matches(history, new, get_test_case_match_keys()) - - -def test_a_pre_merge_branch_does_not_match_post_merge_history() -> None: - """Branch is identity, so a PR run cannot match main's history unaided. - - This is the precondition that makes the baseline-branch substitution in - process_and_upload_test_results necessary; the substitution itself is tested - against that function in - tests/unittest/others/test_perf_regression_branch.py. - """ - history = _benchmark_data(s_branch="main") - pre_merge_data = _benchmark_data(s_branch="github-pr-12345") - - assert not benchmark_data_matches(history, pre_merge_data, get_test_case_match_keys()) - - -def test_warmup_lets_the_initial_test_request_through() -> None: - """A warmup lane drops --no-test-input, which is what creates the warmup. - - benchmark_serving's initial test request is excluded from the reported - metrics, so it is the cheapest available warmup. It reuses - input_requests[0], hence carries the lane's own ISL and OSL: on a disagg e2e - lane it absorbs the KV cache transceiver's one-time lazy connection setup - (ZMQ mesh + NIXL metadata registration) that otherwise slows the first - measured ctx->gen handover, and on a ctx_only lane it is a full-ISL prefill - that absorbs the first cold prefill out of the reported TTFT. - """ - client_config = _load_client_config() - - cold = client_config(_disagg_client_data(10), "example_model") - warm = client_config(_disagg_client_data(10), "example_model", warmup=True) - - assert "--no-test-input" in cold._to_default_benchmark_cmd() - assert "--no-test-input" not in warm._to_default_benchmark_cmd() - - -def test_warmup_cannot_be_enabled_from_lane_config() -> None: - """A "warmup" key in a lane yaml must not reach ClientConfig.warmup. - - b_warmup is deliberately not a match key (see - test_match_keys_are_name_and_environment_only), so warmed results merge into - the same baseline history as their cold predecessors. That is only sound - while the value stays fully determined by benchmark_mode. Both config - parsers hand the raw yaml client dict straight to ClientConfig, so if warmup - were read from it, any lane -- including an aggregated one -- could enable - warmup for itself and silently fork its own baseline history with no visible - config difference. Hence the constructor argument. - """ - client_config = _load_client_config() - - from_yaml = client_config({**_disagg_client_data(10), "warmup": True}, "example_model") - - assert from_yaml.warmup is False - assert from_yaml.to_db_data()["b_warmup"] is False - assert "--no-test-input" in from_yaml._to_default_benchmark_cmd() - - -def test_warmup_is_suppressed_for_the_non_default_benchmark_clients() -> None: - """b_warmup records the EFFECTIVE value, not the requested one. - - to_cmd dispatches to three builders, and only the built-in - benchmark_serving one has an initial test request to suppress. The agentx - and nv_sa builders emit no equivalent flag, so a requested warmup would not - happen there -- and a b_warmup=True row for a run that never warmed up is - worse than no row at all: it invites a later investigator to rule warmup out - as a cause it never had. Same convention as b_disable_overlap_scheduler, - which also reports what the run actually did. - """ - client_config = _load_client_config() - - nv_sa = client_config( - {**_disagg_client_data(10), "use_nv_sa_benchmark": True}, "example_model", warmup=True - ) - agentx = client_config( - {**_disagg_client_data(10), "benchmark_client": "agentx"}, "example_model", warmup=True - ) - default = client_config(_disagg_client_data(10), "example_model", warmup=True) - - assert nv_sa.warmup is False - assert nv_sa.to_db_data()["b_warmup"] is False - assert agentx.warmup is False - assert agentx.to_db_data()["b_warmup"] is False - assert default.warmup is True - assert default.to_db_data()["b_warmup"] is True - - -def test_warmup_is_suppressed_by_the_same_condition_to_cmd_dispatches_on() -> None: - """Only the agentx value suppresses warmup -- not any non-empty string. - - Suppression exists because the agentx and nv_sa builders have no initial test - request to un-suppress. to_cmd selects them by `== AGENTX_BENCHMARK_CLIENT` - and `use_nv_sa_benchmark`, so warmup must be suppressed on exactly that - condition. Testing `not self.benchmark_client` (truthiness) instead looks - equivalent and is not: an unrecognised value is falsy-negative there, so - warmup gets suppressed while to_cmd still falls through to the default - builder -- a lane that asked to warm up, can warm up, and silently does not. - Unrecognised values do reach ClientConfig: only _parse_disagg_config_file - rejects them, and the aggregated parser passes its yaml dict through - unvalidated. - - Asserted on the emitted command, not on self.warmup: b_warmup and - --no-test-input are both driven by self.warmup, so comparing them to each - other is circular and holds under either condition. - """ - module = _load_module() - client_config = module.ClientConfig - - unrecognised = client_config( - {**_disagg_client_data(10), "benchmark_client": "some-future-client"}, - "example_model", - warmup=True, - ) - cmd = unrecognised.to_cmd() - - assert any("benchmark_serving" in arg for arg in cmd), ( - "an unrecognised benchmark_client no longer falls through to the default " - "builder; this test's premise needs rechecking" - ) - assert "--no-test-input" not in cmd, ( - "warmup was suppressed for a lane that runs the default benchmark_serving " - "client anyway -- suppression must test == AGENTX_BENCHMARK_CLIENT, not the " - "truthiness of benchmark_client" - ) - - -def test_warmup_defaults_off_and_is_reported() -> None: - """Every other lane keeps today's behaviour, and the DB records which warmed.""" - client_config = _load_client_config() - - cold = client_config(_disagg_client_data(10), "example_model") - warm = client_config(_disagg_client_data(10), "example_model", warmup=True) - - assert cold.warmup is False - assert cold.to_db_data()["b_warmup"] is False - assert warm.to_db_data()["b_warmup"] is True - - -def test_warmup_is_derived_from_exactly_the_e2e_and_ctx_only_modes() -> None: - """Pin warmup to benchmark_mode, the reason b_warmup can skip the match key. - - Asserted through wants_warmup rather than against the source text: the set - of warmed lanes is the contract, the expression that computes it is not, so - a behaviour-preserving refactor must not fail here. The tests above cover - what ClientConfig does with the value; only this one covers which lanes get - it. - - Every mode the disagg parser can see is checked explicitly, so adding a mode - without deciding whether it warms up fails here rather than silently - inheriting a default. gen_only in particular must stay excluded: #18011 - established that the extra handover leaves a stale mSenderFutures entry that - the CTX worker's blocking idle KV-transfer poll then waits on. - """ - module = _load_module() - - assert module.wants_warmup("e2e") is True - assert module.wants_warmup("ctx_only") is True - assert module.wants_warmup("gen_only") is False - assert module.wants_warmup("gen_only_no_context") is False - assert module.wants_warmup("") is False - - # Pinned as an exact set, not by substring: a membership test against a - # tuple still "contains e2e" after gen_only has been added to it. - assert set(module.WARMUP_BENCHMARK_MODES) == {"e2e", "ctx_only"}, ( - "the set of warmup lanes changed; e2e absorbs the KV transceiver's lazy " - "connection setup and ctx_only absorbs the first cold prefill, while " - "gen_only must stay excluded (#18011)" - ) - - -def test_warmup_reaches_client_config_only_from_the_disagg_parser() -> None: - """No second producer may hand ClientConfig a warmup value. - - Locality, not expression shape: b_warmup is not a baseline match key, which - is only sound while one code path decides warmup for every lane. A second - ClientConfig(warmup=...) call site elsewhere -- notably in the aggregated - parser, which forwards lane yaml keys through verbatim -- would reintroduce - exactly the lane-settable warmup that test_warmup_cannot_be_enabled_from_ - lane_config forbids by value. - - _parse_disagg_config_file cannot be called directly here (PerfSanityTest- - Config's constructor shells out to nvidia-smi and raises without a GPU), so - this one property is checked against the source, scoped to that function. - """ - repo_root = pathlib.Path(__file__).resolve().parents[3] - module_path = repo_root / "tests" / "integration" / "defs" / "perf" / "test_perf_sanity.py" - tree = ast.parse(module_path.read_text()) - - def warmup_call_sites(node: ast.AST) -> list[ast.AST]: - return [ - call - for call in ast.walk(node) - if isinstance(call, ast.Call) - and isinstance(call.func, ast.Name) - and call.func.id == "ClientConfig" - and any(keyword.arg == "warmup" for keyword in call.keywords) - ] - - disagg_parsers = [ - node - for node in ast.walk(tree) - if isinstance(node, ast.FunctionDef) and node.name == "_parse_disagg_config_file" - ] - assert len(disagg_parsers) == 1, "expected exactly one _parse_disagg_config_file" - - inside = warmup_call_sites(disagg_parsers[0]) - total = warmup_call_sites(tree) - assert len(inside) == 1, ( - f"expected exactly one ClientConfig(warmup=...) in _parse_disagg_config_file, " - f"found {len(inside)}" - ) - assert len(total) == len(inside), ( - f"ClientConfig(warmup=...) appears {len(total) - len(inside)} time(s) outside " - "_parse_disagg_config_file; warmup must be decided in exactly one place, or " - "b_warmup stops being fully determined by benchmark_mode" - ) - - -def test_warmup_is_not_a_match_key() -> None: - """Warmup is a measurement-quality knob, not part of case identity. - - Making b_warmup a match key would fork all ~26 warmed lanes into a second - tracked series and make the improvement invisible in its own history -- a - permanent cost to paper over a one-time step. The four match keys are - identity, hardware, runtime and branch; none of them describes how well the - run was set up. Same rationale as s_benchmark_client. - """ - assert "b_warmup" not in get_test_case_match_keys()