diff --git a/jenkins/L0_Test.groovy b/jenkins/L0_Test.groovy index 1b80c8beeb9b..3968257b14a5 100644 --- a/jenkins/L0_Test.groovy +++ b/jenkins/L0_Test.groovy @@ -6504,7 +6504,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 ) @@ -6513,7 +6513,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 ) @@ -6522,7 +6522,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 ) @@ -6531,7 +6531,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..cbd5006370ae 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,64 @@ 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): + """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) 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:]) 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:]) select_pattern = None else: # Regular aggr: aggr_upload-config_yml or aggr_upload-config_yml-server_config_name @@ -136,7 +183,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 +588,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 +706,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 +802,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 +828,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 +858,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 +943,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..4a1389f492ce 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,12 @@ 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,) + # --------------------------------------------------------------------------- # # Test list parsing @@ -316,11 +328,29 @@ 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) -> 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}") + 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 +362,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 +377,16 @@ 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) 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) config_yaml_path = os.path.join( llm_src, DISAGG_CONFIG_FOLDER, f"{config_base_name}.yaml" ) @@ -381,7 +413,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 +840,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 275ad005c3fd..c19193c53a7e 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] @@ -300,9 +308,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: @@ -378,6 +396,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=") @@ -484,7 +506,23 @@ 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, not `is None`: a request that never transferred KV reaches here with + # 0.0, not None, because the aggregated path reads these off a default- + # initialised C++ duration (`timing_metrics.kv_cache_transfer_start + # .total_seconds()` in executor/result.py). Testing only for None would write + # `kv_cache_transfer_start: 0.0` into the JSONL where the key used to be + # absent, and a consumer checking presence rather than truthiness would read a + # zero-width transfer as a real measurement. 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 f3ddffd21f6b..41e6b973d6d6 100644 --- a/tensorrt_llm/serve/scripts/benchmark_serving.py +++ b/tensorrt_llm/serve/scripts/benchmark_serving.py @@ -1099,20 +1099,62 @@ 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 + + # These "Time Breakdown ..." lines are the machine-readable output of the + # breakdown -- the perf-sanity harness scrapes them out of this process's + # stdout the same way it scrapes "Mean TTFT (ms)" -- whereas the JSONL, the + # JSON and the HTML diagram are human aids that need a writable path. Print + # first so that none of them failing can cost us the measurement: + # output_stem is relative to the current directory unless --result-dir was + # given. + span_stats = analyzer.compute_statistics(timing_data) + for span in sorted(span_stats): + for stat in ("mean", "median", "p75", "p99"): + print(f"Time Breakdown {span} {stat} (ms): " + f"{span_stats[span][stat]:.4f}") + + # Printing first is only half of it: 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 even though the lines above already carried the + # whole measurement. 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..c4e0a19f2bb1 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,64 @@ 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. + + Negative durations are kept. Only exactly-zero is the "not measured" + sentinel; a negative value is a real measurement of two events that + overlapped, which is normal for ``step_preprocessing`` when the overlap + scheduler is on (step N is prepared before step N-1's token is emitted). + Dropping those requests would bias the surviving mean towards the + non-overlapped tail -- worst of all silently, since the span would still + be reported with a plausible-looking positive value. + """ + 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 +2243,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 +2261,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 +2302,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/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 3dd5585a714e..08ef125f8405 100644 --- a/tests/integration/defs/perf/test_perf_sanity.py +++ b/tests/integration/defs/perf/test_perf_sanity.py @@ -40,6 +40,16 @@ from ..conftest import get_llm_root, llm_models_root from ._model_paths import MODEL_PATH_DICT from .perf_regression_utils import _percentile, 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", @@ -121,6 +131,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: @@ -185,23 +202,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\.]+)" ), @@ -219,10 +237,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", @@ -240,11 +262,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, ..., @@ -334,8 +485,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): @@ -348,9 +500,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 @@ -385,9 +544,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): @@ -400,19 +565,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 @@ -503,6 +679,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. @@ -522,9 +699,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 @@ -535,7 +715,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) @@ -544,6 +726,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`. @@ -552,10 +735,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_` @@ -577,12 +766,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 @@ -608,16 +802,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). @@ -1209,6 +1417,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 @@ -1228,6 +1440,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) @@ -1277,7 +1498,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", @@ -1312,7 +1533,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", @@ -1351,6 +1572,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 client read the servers' per-request JSONLs after the + # measured window and print one "Time Breakdown (ms):" + # line per aggregate, which parse_metrics_from_output scrapes back + # out of this command's stdout. + 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]: @@ -1430,6 +1658,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.""" @@ -1441,6 +1755,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") @@ -1461,6 +1784,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" @@ -1523,6 +1852,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" @@ -1547,6 +1888,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]: @@ -1580,6 +1927,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. @@ -1718,6 +2069,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) @@ -1828,10 +2194,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 @@ -1846,6 +2214,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 @@ -1863,6 +2232,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): @@ -2028,9 +2416,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) @@ -2062,15 +2459,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: @@ -2097,6 +2507,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: @@ -2137,9 +2560,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 @@ -2160,58 +2590,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: @@ -2269,10 +2734,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": @@ -2295,7 +2765,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) @@ -2392,6 +2863,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") @@ -2443,11 +2917,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(), } # ctx_only runs the ctx worker in aggregated mode; use the merged @@ -2460,28 +2940,30 @@ 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(), } ctx_server_config = ServerConfig(ctx_server_config_data, ctx_worker_env_var) gen_server_config = ServerConfig(gen_server_config_data, gen_worker_env_var) 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, @@ -2515,6 +2997,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: @@ -2545,6 +3060,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, @@ -2557,6 +3073,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: @@ -2631,6 +3200,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): @@ -2702,6 +3277,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: @@ -2773,9 +3349,28 @@ 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() + # Last match wins, unlike every other metric here. Two + # producers write these lines: benchmark_serving prints the + # lifecycle spans it can derive from the client's copy of the + # server-written file, and append_time_breakdown_metrics + # then appends the full set aggregated from the worker files. + # The two agree on the spans they share, but taking the + # appended set wholesale keeps every uploaded field from a + # single computation, so the spans still tile TTFT exactly on + # the dashboard. If that aggregation did not run, the + # client-derived lines remain as the fallback. + metrics[time_breakdown_metric_name(span, stat)] = float(value) + continue for metric_type, regex in all_queries.items(): if metric_type in metrics: continue @@ -2875,6 +3470,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" @@ -2888,6 +3492,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) @@ -2942,6 +3568,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, ) new_data_dict[cmd_idx] = new_data @@ -2985,7 +3617,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, @@ -3003,6 +3640,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, ) new_data_dict[cmd_idx] = new_data @@ -3038,6 +3676,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 @@ -3117,16 +3762,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..de429d592eab --- /dev/null +++ b/tests/integration/defs/perf/time_breakdown_metrics.py @@ -0,0 +1,902 @@ +# 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 not in seen and os.path.getsize(path) > 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_cpu.yml b/tests/integration/test_lists/test-db/l0_cpu.yml index 5808b6325769..62ec145db6a2 100644 --- a/tests/integration/test_lists/test-db/l0_cpu.yml +++ b/tests/integration/test_lists/test-db/l0_cpu.yml @@ -85,6 +85,7 @@ 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 + - unittest/llmapi/apps/test_request_metrics.py - 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 550754a1ee3e..2c7996b8d447 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 (90) # 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/integration/test_lists/waives.txt b/tests/integration/test_lists/waives.txt index 88768513f396..e30029d20d1c 100644 --- a/tests/integration/test_lists/waives.txt +++ b/tests/integration/test_lists/waives.txt @@ -308,6 +308,7 @@ perf/test_perf_sanity.py::test_e2e[aggr_upload-ctx_only-gb300_deepseek-v4-pro-fp 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] SKIP (https://nvbugs/6668776) perf/test_perf_sanity.py::test_e2e[aggr_upload-deepseek_r1_fp4_v2_2_nodes_grace_blackwell-r1_fp4_v2_tep8_mtp3] SKIP (https://nvbugs/6668776) 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] SKIP (https://nvbugs/6661856) +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] SKIP (https://nvbugs/6661856) 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] SKIP (https://nvbugs/6661856) test_e2e.py::test_ptp_quickstart_advanced[Nemotron-Nano-9B-v2-nvfp4-NVIDIA-Nemotron-Nano-9B-v2-NVFP4] SKIP (https://nvbugs/6624972) test_e2e.py::test_ptp_quickstart_advanced_deepseek_r1_w4afp8_8gpus[DeepSeek-R1-W4AFP8-DeepSeek-R1/DeepSeek-R1-W4AFP8] SKIP (https://nvbugs/5836830) diff --git a/tests/scripts/perf-sanity/cache_transceiver_precheck/run_precheck.py b/tests/scripts/perf-sanity/cache_transceiver_precheck/run_precheck.py index 9a2c7c5b131f..2ee3883d183b 100644 --- a/tests/scripts/perf-sanity/cache_transceiver_precheck/run_precheck.py +++ b/tests/scripts/perf-sanity/cache_transceiver_precheck/run_precheck.py @@ -1757,7 +1757,16 @@ def parse_args(argv=None): ap.add_argument("--server-idx", type=int, required=True) ap.add_argument("--config", required=True, help="disagg perf-sanity yaml path") ap.add_argument("--work-dir", required=True, help="shared dir for rendezvous/status") - ap.add_argument("--benchmark-mode", default="e2e", choices=["e2e", "gen_only"]) + # Only the benchmark mode is forwarded, never a test id's instrumentation + # modifier (e.g. `time_breakdown`): those change what the harness records, + # not the KV transfer being prechecked. submit.py pastes this value into + # shell text verbatim, so a mode missing from `choices` would kill the + # precheck srun before the workload started. + ap.add_argument( + "--benchmark-mode", + default="e2e", + choices=["e2e", "gen_only"], + ) ap.add_argument("--llm-src", default="", help="repo root (model path dict lookup)") ap.add_argument("--dry-run", action="store_true", help="print the resolved plan and exit") return ap.parse_args(argv) diff --git a/tests/unittest/llmapi/apps/test_request_metrics.py b/tests/unittest/llmapi/apps/test_request_metrics.py index 7429e50aaf47..2618923fd9db 100644 --- a/tests/unittest/llmapi/apps/test_request_metrics.py +++ b/tests/unittest/llmapi/apps/test_request_metrics.py @@ -13,6 +13,7 @@ # limitations under the License. import json +from typing import Optional import pytest @@ -25,12 +26,13 @@ STEP_METRICS_HEADER, PerfMetricsJsonlWriter, PerfMetricsMiddleware, + _jsonl_perf_metrics, _jsonl_record, build_metrics_headers, build_metrics_record_from_headers, combine_disagg_metrics, ) -from tensorrt_llm.serve.scripts.time_breakdown import RequestDataParser +from tensorrt_llm.serve.scripts.time_breakdown import RequestDataParser, RequestTimeBreakdown def _record(status="complete"): @@ -121,6 +123,18 @@ def test_combine_disagg_metrics_is_request_local(): def test_time_breakdown_parser_accepts_header_derived_disagg_record(): + """Backward compatibility: a peer that omits the srv-/kv- timestamps. + + ``_record()`` carries neither ``server_arrival_time`` nor + ``server_first_token_time``, and its KV timestamps are ``None`` -- i.e. what + a worker built before those tokens were added to the header transport, or a + non-disaggregated request, sends. The parser must still produce a record, + falling back to ``arrival_time`` / ``last_token_time``. The asserted values + below are therefore *fallbacks*, not measurements; the full-fidelity + contract is asserted by + ``test_header_transport_preserves_every_lifecycle_timestamp`` and + ``test_header_derived_record_yields_twelve_non_zero_spans``. + """ headers = build_metrics_headers([_record()]) ctx = build_metrics_record_from_headers(headers, "ctx", request_id="42") gen = build_metrics_record_from_headers(headers, "gen", request_id="42") @@ -158,6 +172,214 @@ def test_time_breakdown_parser_accepts_header_derived_disagg_record(): assert combined_headers[SERVER_TIMING_HEADER].count("ctx_queue;") == 1 +# One realistic disaggregated request whose 12 lifecycle spans are all distinct +# and non-zero: span k lasts exactly k ms. Distinct widths matter -- with equal +# widths a span attributed to the wrong pair of timestamps still reads correct. +_T0 = 1000.0 +_LIFECYCLE = { + "disagg_arrival": _T0 + 0.000, # span 1 start + "ctx_server_arrival": _T0 + 0.001, # span 1 end / span 2 start 1 ms + "ctx_arrival": _T0 + 0.003, # span 2 end / span 3 start 2 ms + "ctx_scheduled": _T0 + 0.006, # span 3 end / span 4 start 3 ms + "ctx_first_token": _T0 + 0.010, # span 4 end / span 5 start 4 ms + "ctx_server_first_token": _T0 + 0.015, # span 5 end / span 6 start 5 ms + "gen_server_arrival": _T0 + 0.021, # span 6 end / span 7 start 6 ms + "gen_arrival": _T0 + 0.028, # span 7 end / span 8 start 7 ms + "kv_start": _T0 + 0.036, # span 8 end / span 9 start 8 ms + "kv_end": _T0 + 0.045, # span 9 end / span 10 start 9 ms + "gen_scheduled": _T0 + 0.055, # span 10 end / span 11 start 10 ms + "gen_server_first_token": _T0 + 0.066, # span 11 end / span 12 start 11 ms + "disagg_first_token": _T0 + 0.078, # span 12 end 12 ms +} + +_EXPECTED_SPAN_MS = { + "disagg_preprocessing": 1.0, + "ctx_preprocessing": 2.0, + "ctx_queue": 3.0, + "ctx_processing": 4.0, + "ctx_postprocessing": 5.0, + "disagg_relay": 6.0, + "gen_preprocessing": 7.0, + "gen_queue_wait": 8.0, + "gen_kv_transfer": 9.0, + "gen_post_transfer": 10.0, + "gen_postprocessing": 11.0, + "disagg_postprocessing": 12.0, +} + + +def _ctx_worker_record(): + return { + "request_id": "ctx-1", + "phases": { + "server": { + "timing_metrics": { + "server_arrival_time": _LIFECYCLE["ctx_server_arrival"], + "arrival_time": _LIFECYCLE["ctx_arrival"], + "first_scheduled_time": _LIFECYCLE["ctx_scheduled"], + "first_token_time": _LIFECYCLE["ctx_first_token"], + "last_token_time": _LIFECYCLE["ctx_first_token"], + "server_first_token_time": _LIFECYCLE["ctx_server_first_token"], + "kv_cache_size": 2048, + } + } + }, + } + + +def _gen_worker_record(): + return { + "request_id": "gen-1", + "phases": { + "server": { + "timing_metrics": { + "server_arrival_time": _LIFECYCLE["gen_server_arrival"], + "arrival_time": _LIFECYCLE["gen_arrival"], + "kv_cache_transfer_start": _LIFECYCLE["kv_start"], + "kv_cache_transfer_end": _LIFECYCLE["kv_end"], + "first_scheduled_time": _LIFECYCLE["gen_scheduled"], + "first_token_time": _LIFECYCLE["gen_server_first_token"], + "last_token_time": _T0 + 0.200, + "server_first_token_time": _LIFECYCLE["gen_server_first_token"], + "kv_cache_size": 2048, + } + } + }, + } + + +def _combined_disagg_record(): + """Reproduce the worker -> header -> disagg-server -> JSONL chain.""" + ctx = build_metrics_record_from_headers( + build_metrics_headers([_ctx_worker_record()]), "ctx", request_id="ctx-1" + ) + gen = build_metrics_record_from_headers( + build_metrics_headers([_gen_worker_record()]), "gen", request_id="gen-1" + ) + return combine_disagg_metrics( + "req-1", + { + "ctx_server": "http://ctx0:8001", + "gen_server": "http://gen0:8002", + "timing_metrics": { + "server_arrival_time": _LIFECYCLE["disagg_arrival"], + "ctx_dispatch_time": _T0 + 0.0005, + "server_first_token_time": _LIFECYCLE["disagg_first_token"], + }, + }, + ctx, + gen, + disagg_request_id=1, + ) + + +@pytest.mark.parametrize("phase", ["ctx", "gen"]) +def test_header_transport_preserves_every_lifecycle_timestamp(phase): + """All six absolute timestamps must survive the Server-Timing round trip. + + Only ``arrival_time`` and ``last_token_time`` used to be forwarded, so a + disagg server reconstructed ``server_arrival_time``, + ``server_first_token_time`` and the two KV-transfer timestamps from + fallbacks. That is not detectable downstream: the affected spans come back as + 0 or as a plausible-looking wrong number, never as an error. + """ + worker = _ctx_worker_record() if phase == "ctx" else _gen_worker_record() + source = worker["phases"]["server"]["timing_metrics"] + + headers = build_metrics_headers([worker]) + derived = build_metrics_record_from_headers(headers, phase, request_id="x") + timing = derived["phases"][phase]["timing_metrics"] + + for field in ( + "arrival_time", + "last_token_time", + "server_arrival_time", + "server_first_token_time", + "kv_cache_transfer_start", + "kv_cache_transfer_end", + ): + if source.get(field) is None: + continue + assert timing[field] == pytest.approx(source[field]), field + + # The phase rewrite is an unqualified str.replace() of "server-"/"server_", + # so a token name containing a second occurrence would be substituted twice. + assert f"{phase}-{phase}-" not in headers[START_END_TIME_HEADER] + assert "server-" not in derived["metrics_headers"][START_END_TIME_HEADER] + + +def test_jsonl_record_keeps_header_derived_kv_transfer_timestamps(): + """kv_cache_size is worker-local; it must not gate the KV timestamps. + + ``kv_cache_size`` is set only when a worker builds its own record, so it + never reaches a header-derived one. Stripping the KV timestamps whenever it + is absent zeroed the KV-transfer span for every disaggregated request. + """ + gen = build_metrics_record_from_headers( + build_metrics_headers([_gen_worker_record()]), "gen", request_id="gen-1" + ) + timing = _jsonl_perf_metrics(gen["phases"]["gen"])["timing_metrics"] + + assert "kv_cache_size" not in timing + assert timing["kv_cache_transfer_start"] == pytest.approx(_LIFECYCLE["kv_start"]) + assert timing["kv_cache_transfer_end"] == pytest.approx(_LIFECYCLE["kv_end"]) + + +@pytest.mark.parametrize("absent", [None, 0, 0.0]) +def test_jsonl_record_still_strips_absent_kv_transfer_timestamps(absent: Optional[float]) -> None: + """A request that never transferred KV must not gain zero-width KV fields. + + ``0`` is not hypothetical: the aggregated path reads these off a default- + initialised C++ duration (``timing_metrics.kv_cache_transfer_start + .total_seconds()``), so a non-transferring request arrives as ``0.0`` rather + than ``None``. Both encodings must be stripped, or a consumer testing for + presence rather than truthiness reads a zero-width transfer as a measurement. + """ + record = _record() + phase = record["phases"]["server"] + phase["timing_metrics"]["kv_cache_transfer_start"] = absent + phase["timing_metrics"]["kv_cache_transfer_end"] = absent + timing = _jsonl_perf_metrics(phase)["timing_metrics"] + + assert "kv_cache_transfer_start" not in timing + assert "kv_cache_transfer_end" not in timing + + +def test_header_derived_record_yields_twelve_non_zero_spans(tmp_path): + """The acceptance test for the transport: 12/12 spans, each exactly right. + + This is what the ``time_breakdown`` perf-sanity modifier uploads. A span that + computes to 0 is reported by the tool as "0 ms", not as missing data, so + without this test a silently collapsed span would land in OpenSearch as a + real-looking measurement. + """ + record = _jsonl_record(_combined_disagg_record()) + jsonl = tmp_path / "perf_metrics-disagg.jsonl" + jsonl.write_text(json.dumps(record) + "\n") + + parsed = RequestTimeBreakdown().parse_json_file(str(jsonl)) + assert len(parsed) == 1 + + for span, expected_ms in _EXPECTED_SPAN_MS.items(): + assert parsed[0][f"{span}_time"] * 1000 == pytest.approx(expected_ms, abs=1e-3), span + + +def test_span_statistics_are_reported_in_milliseconds(tmp_path): + """compute_statistics feeds the perf-sanity metrics; check units and shape.""" + record = _jsonl_record(_combined_disagg_record()) + jsonl = tmp_path / "perf_metrics-disagg.jsonl" + jsonl.write_text("".join(json.dumps(record) + "\n" for _ in range(3))) + + analyzer = RequestTimeBreakdown() + stats = analyzer.compute_statistics(analyzer.parse_json_file(str(jsonl))) + + assert set(stats) == set(_EXPECTED_SPAN_MS) + for span, expected_ms in _EXPECTED_SPAN_MS.items(): + assert stats[span]["count"] == 3 + for statistic in ("mean", "median", "p75", "p99"): + assert stats[span][statistic] == pytest.approx(expected_ms, abs=1e-3) + + @pytest.mark.asyncio @pytest.mark.parametrize( ("expose_headers", "request_metrics", "expected"), diff --git a/tests/unittest/others/test_cache_transceiver_precheck_config.py b/tests/unittest/others/test_cache_transceiver_precheck_config.py index 00d224f5e6a6..7d9ea7a626b7 100644 --- a/tests/unittest/others/test_cache_transceiver_precheck_config.py +++ b/tests/unittest/others/test_cache_transceiver_precheck_config.py @@ -1386,3 +1386,70 @@ def test_python_transceiver_bandwidth_csv(tmp_path): assert abs(bw - 153600 * 1024 * 1024 / 1e9) < 1e-9 # no perf files -> None assert rp.parse_python_bandwidth_gbps(str(tmp_path / "empty")) is None + + +@pytest.mark.parametrize("mode", ["e2e", "gen_only"]) +def test_parse_args_accepts_every_forwarded_benchmark_mode(tmp_path, mode): + """--benchmark-mode must admit every mode submit.py can forward. + + jenkins/scripts/perf/submit.py builds pytestCommandCTXPrecheck / + pytestCommandGENPrecheck by pasting the test id's mode token in verbatim, so + a mode missing from these choices makes the precheck srun die in argparse -- + before the workload starts, and for a reason that reads as a launch failure + rather than an unsupported mode. resolve_plan only distinguishes gen_only; + e2e is accepted precisely because the KV transfer it prechecks is the same. + + An instrumentation modifier such as `time_breakdown` is a separate test-id + segment and is never forwarded here, which is what keeps this list closed. + """ + args = rp.parse_args( + [ + "--role", + "ctx", + "--server-idx", + "0", + "--config", + str(tmp_path / "cfg.yaml"), + "--work-dir", + str(tmp_path), + "--benchmark-mode", + mode, + ] + ) + assert args.benchmark_mode == mode + + +@pytest.mark.parametrize("mode", ["e2e_time_breakdown", "time_breakdown", "ctx_only"]) +def test_parse_args_still_rejects_an_unknown_benchmark_mode(tmp_path, mode): + """The choices list must stay a gate, not become a free-text field. + + A typo'd mode has to fail here, where the message names the argument, rather + than silently resolving to the e2e plan. The fused spelling + `e2e_time_breakdown` and a bare modifier are rejected for the same reason: a + caller passing either is a caller that has not split the axis. + + `ctx_only` is in this list rather than the accepted one, which looks odd next + to the harness where ctx_only is a real benchmark mode. It is deliberate and + not reachable in production: the precheck gate is spliced only into the + *disaggregated* launch draft (jenkins/scripts/perf/submit.py, and + slurm_ct_precheck_gate.sh's run_cache_transceiver_precheck), and ctx_only runs + on the aggregated runtime, so this script is never invoked with it. There is + also nothing for it to precheck -- a ctx_only lane has no gen server, so no KV + transfer. Rejecting it keeps that assumption falsifiable: the day someone + wires the gate into the aggregated path, this test fails and says so. + """ + with pytest.raises(SystemExit): + rp.parse_args( + [ + "--role", + "ctx", + "--server-idx", + "0", + "--config", + str(tmp_path / "cfg.yaml"), + "--work-dir", + str(tmp_path), + "--benchmark-mode", + mode, + ] + ) diff --git a/tests/unittest/others/test_perf_sanity_time_breakdown.py b/tests/unittest/others/test_perf_sanity_time_breakdown.py new file mode 100644 index 000000000000..1b821401fc33 --- /dev/null +++ b/tests/unittest/others/test_perf_sanity_time_breakdown.py @@ -0,0 +1,778 @@ +# 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. +"""Tests for the ``time_breakdown`` perf-sanity modifier's metric plumbing. + +The mode has a three-hop contract, and each hop fails *silently* if it drifts: + +1. ``benchmark_serving`` prints one ``Time Breakdown (ms): `` + line per span/statistic, ``test_perf_sanity`` scrapes those lines back out of + the captured stdout with a regex, and a mismatch between the two formats + yields zero parsed metrics -- an upload with no ``d_tb_*`` fields, which on a + dashboard is indistinguishable from a case that simply has no breakdown. +2. The metric names come from ``time_breakdown_metrics``, not from + ``TimingMetricsConfig``, because test collection must not import + ``tensorrt_llm``. Nothing at runtime notices if the two go stale relative to + each other: a span the tool emits but the harness does not know still + uploads, just with no baseline, so the drift is invisible until someone looks + for a missing history line. +3. Every uploaded name must be registered in ``MINIMIZE_METRICS`` (so it gets a + baseline) and must *not* be in ``REGRESSION_METRICS`` (so it cannot fail a + build). ``perf_regression_utils`` asserts the first relationship at import + time; nothing asserts the second. +""" + +import importlib.util +import json +import os +import pathlib +import sys +import types + +import pytest + +from tensorrt_llm.serve.scripts.time_breakdown import TimingMetricsConfig + +pytestmark = pytest.mark.cpu_only + +_REPO_ROOT = pathlib.Path(__file__).resolve().parents[3] +_MODULE_PATH = _REPO_ROOT / "tests" / "integration" / "defs" / "perf" / "test_perf_sanity.py" + + +def _load_test_perf_sanity(): + """Load the harness module without importing the integration-test packages. + + ``defs/__init__.py`` pre-imports ``torch._inductor`` and + ``perf_regression_utils`` pulls in the OpenSearch client. None of the module + level constants or the two pure functions under test reach either, and + requiring them would turn this into a GPU-image test. + """ + defs_pkg = types.ModuleType("defs") + defs_pkg.__path__ = [] + perf_pkg = types.ModuleType("defs.perf") + # Real path, so ``from .time_breakdown_metrics import ...`` resolves to the + # actual module -- it is stdlib-only, so loading it costs nothing and the + # metric names under test are the ones the harness really uses. The heavy + # siblings stay stubbed via sys.modules below, which wins over this path. + perf_pkg.__path__ = [str(_MODULE_PATH.parent)] + + conftest = types.ModuleType("defs.conftest") + conftest.get_llm_root = lambda *a, **k: "" + conftest.llm_models_root = lambda *a, **k: "" + + common = types.ModuleType("defs.common") + common.wait_for_reported_addr = lambda *a, **k: None + + alternative = types.ModuleType("defs.trt_test_alternative") + alternative.print_info = lambda *a, **k: None + alternative.print_warning = lambda *a, **k: None + + model_paths = types.ModuleType("defs.perf._model_paths") + model_paths.MODEL_PATH_DICT = {} + + regression = types.ModuleType("defs.perf.perf_regression_utils") + regression._percentile = lambda *a, **k: 0.0 + regression.process_and_upload_test_results = lambda *a, **k: None + + test_common = types.ModuleType("test_common") + test_common.__path__ = [] + error_utils = types.ModuleType("test_common.error_utils") + error_utils.report_error = lambda *a, **k: None + http_utils = types.ModuleType("test_common.http_utils") + http_utils.fail_if_proc_died = lambda *a, **k: None + http_utils.wait_for_endpoint_ready = lambda *a, **k: None + matching = types.ModuleType("test_common.perf_sanity_matching") + matching.get_test_case_match_keys = lambda *a, **k: {} + + stubs = { + "defs": defs_pkg, + "defs.conftest": conftest, + "defs.common": common, + "defs.trt_test_alternative": alternative, + "defs.perf": perf_pkg, + "defs.perf._model_paths": model_paths, + "defs.perf.perf_regression_utils": regression, + "test_common": test_common, + "test_common.error_utils": error_utils, + "test_common.http_utils": http_utils, + "test_common.perf_sanity_matching": matching, + } + 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) + sys.modules["defs.perf.test_perf_sanity"] = module + spec.loader.exec_module(module) + finally: + sys.modules.pop("defs.perf.test_perf_sanity", None) + for name, previous in saved.items(): + if previous is None: + sys.modules.pop(name, None) + else: + sys.modules[name] = previous + return module + + +_sanity = _load_test_perf_sanity() + + +@pytest.fixture(autouse=True) +def _no_settle_wait(monkeypatch): + """Collapse the perf_metrics settle window; these tests write their files up front. + + The window itself is covered directly in test_time_breakdown_metrics.py, with an + injected clock. Paying it here would only add wall time per call. + """ + monkeypatch.setattr(_sanity, "PERF_METRICS_SETTLE_SECONDS", 0.0) + + +def _format_line(span: str, stat: str, value: float) -> str: + """Reproduce exactly what ``benchmark_serving.main`` prints. + + Kept as a helper, and deliberately duplicated from the producer rather than + imported, so that a change on either side of the contract makes this test + fail rather than making both sides agree on something new. + """ + return f"Time Breakdown {span} {stat} (ms): {value:.4f}" + + +def test_every_tool_span_is_known_to_the_harness(): + """The tool's spans must all be metrics the harness has a baseline for. + + A subset rather than an equality: the harness also uploads the per-chunk and + per-step breakdowns, which the tool has no span for. What must not happen is + the tool emitting a span the harness cannot name -- that span would upload + with no baseline and no history line. + """ + tool_spans = tuple(m.name for m in TimingMetricsConfig().metrics) + unknown = set(tool_spans) - set(_sanity.TIME_BREAKDOWN_METRIC_NAMES) + assert not unknown, f"spans the tool emits but the harness does not know: {sorted(unknown)}" + + +def test_metric_names_cover_every_metric_and_statistic(): + assert len(_sanity.TIME_BREAKDOWN_METRICS) == ( + len(_sanity.TIME_BREAKDOWN_METRIC_NAMES) * len(_sanity.TIME_BREAKDOWN_STATS) + ) + assert len(set(_sanity.TIME_BREAKDOWN_METRICS)) == len(_sanity.TIME_BREAKDOWN_METRICS) + for name in _sanity.TIME_BREAKDOWN_METRICS: + assert name.startswith("tb_") + + +def test_every_benchmark_mode_is_one_the_parser_supports(): + """The case type IS the benchmark mode now -- no map in between. + + ``_append_time_breakdown_metrics`` feeds ``record["benchmark_mode"]`` + straight to the parser, so the two vocabularies have to be the same set. A + mode the parser did not know would silently skip aggregation instead of + uploading, and the run would fail only on the "parsed no lines" check. + """ + from defs.perf.time_breakdown_metrics import MODE_GROUPS + + assert set(MODE_GROUPS) == {"ctx_only", "gen_only", "e2e"} + + +@pytest.mark.parametrize("stat", ["mean", "median", "p75", "p99"]) +def test_regex_round_trips_every_printed_line(stat): + """Every metric/stat line the client prints must parse back to its metric.""" + for span in _sanity.TIME_BREAKDOWN_METRIC_NAMES: + line = _format_line(span, stat, 12.5) + match = _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search(line) + assert match is not None, line + parsed_span, parsed_stat, value = match.groups() + assert parsed_span == span + assert parsed_stat == stat + assert float(value) == pytest.approx(12.5) + assert ( + _sanity.time_breakdown_metric_name(parsed_span, parsed_stat) + in _sanity.TIME_BREAKDOWN_METRICS + ) + + +def test_regex_round_trips_the_harness_aggregator_output(): + """The second producer's lines must parse back too, negatives included. + + ``_append_time_breakdown_metrics`` appends ``format_metric_log_lines`` output + to the benchmark log and the harness scrapes it back with the same regex. The + format differs from ``benchmark_serving``'s (6 decimals, not 4), and + ``tb_step_preprocessing`` is negative whenever the overlap scheduler is on -- + a regex that only accepted unsigned values would drop exactly the metric that + proves overlap is working, on every row, forever. + """ + from defs.perf.time_breakdown_metrics import format_metric_log_lines + + values = { + f"d_{name}": (-11.718660 if name == "tb_step_preprocessing_mean" else 12.5) + for name in _sanity.TIME_BREAKDOWN_METRICS + } + # format_metric_log_lines keys off d_tb__, the upload name. + lines = format_metric_log_lines(values) + assert len(lines) == len(_sanity.TIME_BREAKDOWN_METRICS) + + parsed = {} + for line in lines: + match = _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search(line) + assert match is not None, line + span, stat, value = match.groups() + parsed[_sanity.time_breakdown_metric_name(span, stat)] = float(value) + + assert set(parsed) == set(_sanity.TIME_BREAKDOWN_METRICS) + assert parsed["tb_step_preprocessing_mean"] == pytest.approx(-11.718660) + assert parsed["tb_ctx_queue_median"] == pytest.approx(12.5) + + +def test_regex_tolerates_a_log_prefix_and_a_zero_value(): + """Real benchmark stdout is line-prefixed by the launcher and by srun.""" + line = "[2026-08-31 04:05:06] [Rank 0] " + _format_line("gen_kv_transfer", "p99", 0.0) + match = _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search(line) + assert match is not None + assert match.group(1) == "gen_kv_transfer" + assert float(match.group(3)) == 0.0 + + +def test_regex_ignores_an_unknown_statistic(): + """An unlisted statistic must not be uploaded under a mangled name.""" + assert ( + _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search(_format_line("ctx_queue", "stddev", 1.0)) + is None + ) + + +def test_regex_captures_a_span_the_harness_does_not_know_about(): + """A span added to the tool still reaches OpenSearch (without a baseline). + + This is why the query uses capture groups instead of one literal pattern + per metric/statistic pair: + extending TimingMetricsConfig should never silently drop data. + """ + match = _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search( + _format_line("some_future_span", "median", 3.25) + ) + assert match is not None + assert _sanity.time_breakdown_metric_name(*match.groups()[:2]) == ("tb_some_future_span_median") + + +def test_every_metric_is_a_minimize_metric_and_gates_nothing(): + for name in _sanity.TIME_BREAKDOWN_METRICS: + assert f"d_{name}" in _sanity.MINIMIZE_METRICS + assert f"d_{name}" not in _sanity.MAXIMIZE_METRICS + assert f"d_{name}" not in _sanity.REGRESSION_METRICS + + +def _parsed_metrics(**extra): + """A fully populated parse result plus whatever the caller adds. + + ``add_perf_metric_value`` indexes every ``PERF_METRIC_LOG_QUERIES`` key + unconditionally, so a partial dict would raise ``KeyError`` for reasons + unrelated to what these cases are checking. + """ + metrics = {name: 0.0 for name in _sanity.PERF_METRIC_LOG_QUERIES} + metrics.update(extra) + return metrics + + +def test_add_perf_metric_value_uploads_only_with_the_modifier(): + metrics = _parsed_metrics(tb_ctx_queue_median=4.5, tb_gen_kv_transfer_p99=41.25) + + new_data = {} + _sanity.add_perf_metric_value( + new_data, metrics, spec_decoding=False, benchmark_mode="e2e", time_breakdown=True + ) + assert new_data["d_tb_ctx_queue_median"] == pytest.approx(4.5) + assert new_data["d_tb_gen_kv_transfer_p99"] == pytest.approx(41.25) + + # The same parsed dict without the modifier must not grow any d_tb_* field: + # the two cases share every other metric name, and a plain e2e case that + # started uploading breakdown fields would fork its own history series. + e2e_data = {} + _sanity.add_perf_metric_value(e2e_data, metrics, spec_decoding=False, benchmark_mode="e2e") + assert not [key for key in e2e_data if key.startswith("d_tb_")] + + +def test_add_perf_metric_value_skips_a_missing_span(): + """A span with no measured requests is omitted, never uploaded as 0.0.""" + new_data = {} + _sanity.add_perf_metric_value( + new_data, + _parsed_metrics(tb_gen_kv_transfer_median=None), + spec_decoding=False, + benchmark_mode="e2e", + time_breakdown=True, + ) + assert "d_tb_gen_kv_transfer_median" not in new_data + + +# A disaggregated yaml reduced to what the parser actually reads. ctx_only runs +# only the `ctx:` worker, but `gen:` has to be present because the same file is +# what the e2e and gen_only ids read. +_DISAGG_YAML = """ +metadata: + model_name: deepseek-ai/DeepSeek-R1 +hardware: + gpus_per_node: 4 + num_ctx_servers: 1 + num_gen_servers: 1 + nodes_per_ctx_server: 1 + nodes_per_gen_server: 1 + gpus_per_node_per_ctx_server: 4 + gpus_per_node_per_gen_server: 4 +benchmark: + input_length: 8192 + output_length: 1024 + concurrency_list: "666" +worker_config: + ctx: + tensor_parallel_size: 4 + cache_transceiver_config: + backend: NIXL + gen: + tensor_parallel_size: 4 +""" + + +def _parsed_config(tmp_path, benchmark_mode: str, time_breakdown: bool): + """Drive the real parser without constructing a whole pytest fixture graph. + + ``PerfSanityTestConfig.__init__`` derives everything under test from the test + id; setting the four derived attributes directly keeps the case about the + parser instead of about id parsing, which the round-trip tests already cover. + """ + config_path = tmp_path / "gb300_stem-NIXL.yaml" + config_path.write_text(_DISAGG_YAML, encoding="utf-8") + config = object.__new__(_sanity.PerfSanityTestConfig) + config.benchmark_mode = benchmark_mode + config.time_breakdown = time_breakdown + config._output_dir = str(tmp_path) + config._test_param_labels = "case" + config._parse_disagg_config_file(str(config_path), config_path.name) + return config + + +def test_ctx_only_time_breakdown_instruments_its_one_server(tmp_path): + """The regression this guards: ctx_only runs on the *aggregated* runtime. + + ctx_only is parsed by the disagg parser but executed by AggrTestCmds, so it + takes the ``else`` branch's worker overrides nowhere -- it builds its own + single ServerConfig. Without the splat in that branch the case runs perfectly + green, the server is simply never asked to record any timings, and all 44 + ctx_only ``d_tb_*`` fields upload as 0.0. Nothing downstream can tell that + apart from a lane that genuinely measured nothing. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=True) + + assert len(config.server_configs) == 1 + extra = config.server_configs[0].extra_llm_api_config_data + assert extra["return_perf_metrics"] is True + assert extra["num_postprocess_workers"] == 0 + assert extra["perf_metrics_output_dir"] == config.time_breakdown_dir() + # The directory both halves have to agree on: the server writes here, and + # append_time_breakdown_metrics scans here. + assert config.time_breakdown_dir().endswith(os.path.join("case", "perf_metrics")) + + +def test_ctx_only_without_the_modifier_stays_untouched(tmp_path): + """The plain ctx_only lane must not acquire any of the three keys. + + num_postprocess_workers: 0 measurably changes throughput, so leaking it into + the unmodified lane would move that lane's baseline rather than fork a new + series -- a regression that looks like a real one. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=False) + + extra = config.server_configs[0].extra_llm_api_config_data + for key in ("return_perf_metrics", "perf_metrics_output_dir", "num_postprocess_workers"): + assert key not in extra + assert config.time_breakdown_dir() == "" + + +def test_ctx_only_client_records_the_breakdown(tmp_path): + """The other half of the contract: the client has to be told to read it back. + + The server writing a JSONL is useless on its own -- benchmark_serving is what + prints the ``Time Breakdown`` lines the harness scrapes, and it only does that + when handed --save-request-time-breakdown. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=True) + client_cmd = config.server_client_configs[0][0].to_cmd() + + assert "--save-request-time-breakdown" in client_cmd + assert client_cmd[client_cmd.index("--save-request-time-breakdown") + 1] == ( + config.time_breakdown_dir() + ) + + +def test_the_no_lines_guard_is_not_scoped_to_the_disagg_runtime(tmp_path): + """A runtime predicate on that guard would have exempted exactly ctx_only. + + check_test_failure's "parsed no Time Breakdown lines" check is the only thing + that turns a silently uninstrumented modified run into a red build. It used to + be gated on runtime == multi_node_disagg_server, which is false for ctx_only. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=True) + config.runtime = "aggr_server" + config.gpu_type = "gb300" + config._perf_results = {0: [_parsed_metrics()]} + + with pytest.raises(RuntimeError, match="parsed no 'Time Breakdown"): + config.check_test_failure() + + +def test_the_no_lines_guard_passes_once_a_span_is_present(tmp_path): + """Same lane, one parsed span: the guard must not fire. + + Individual spans stay ungated on purpose -- a span whose endpoints were never + populated is legitimately absent -- so presence of any one of them is the + whole condition. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=True) + config.runtime = "aggr_server" + config.gpu_type = "gb300" + config._perf_results = {0: [_parsed_metrics(tb_ctx_queue_mean=1.5)]} + + config.check_test_failure() + + +def test_get_commands_hands_the_breakdown_dir_to_the_aggregated_runner(tmp_path): + """ctx_only dispatches to _get_aggr_commands, so AggrTestCmds must carry the dir. + + DisaggTestCmds reads perf_metrics_output_dir off its disagg config; the + aggregated runner had no equivalent, so this is the hop that decides whether + run_cmd aggregates at all. An empty string here means every ctx_only + breakdown run silently skips the reduction. + """ + config = _parsed_config(tmp_path, "ctx_only", time_breakdown=True) + config.runtime = "aggr_server" + + cmds = config.get_commands() + + assert isinstance(cmds, _sanity.AggrTestCmds) + assert cmds.perf_metrics_output_dir == config.time_breakdown_dir() + assert cmds.benchmark_mode == "ctx_only" + + # And the plain ctx_only lane must leave it empty, which is what makes run_cmd + # skip the aggregation rather than reduce an empty directory every run. + plain = _parsed_config(tmp_path, "ctx_only", time_breakdown=False) + plain.runtime = "aggr_server" + assert plain.get_commands().perf_metrics_output_dir == "" + + +def _ctx_worker_jsonl(directory, count=3): + """A context worker's perf_metrics JSONL, in the shape the server really writes. + + Only the fields the reduction reads: the request-level timing metrics and one + prefill chunk per request. + """ + os.makedirs(directory, exist_ok=True) + lines = [] + for i in range(count): + t0 = 1000.0 + i + chunk_start = t0 + 0.010 + lines.append( + json.dumps( + { + "request_id": i, + "perf_metrics": { + "timing_metrics": { + "server_arrival_time": t0, + "arrival_time": t0 + 0.001, + "first_scheduled_time": t0 + 0.003, + "first_token_time": t0 + 0.130, + "server_first_token_time": t0 + 0.131, + "last_token_time": t0 + 0.130, + } + }, + "time_breakdown_metrics": { + "ctx_chunk_metrics": [ + { + "forward_start_time": chunk_start, + "forward_end_time": chunk_start + 0.100, + "sample_start_time": chunk_start + 0.102, + "sample_end_time": chunk_start + 0.103, + "token_time": t0 + 0.130, + "gpu_forward_time": 98.0, + "gpu_sample_time": 0.9, + } + ] + }, + } + ) + ) + path = os.path.join(directory, "perf_metrics-server-hostA-0-run.jsonl") + with open(path, "w", encoding="utf-8") as handle: + handle.write("\n".join(lines) + "\n") + return path + + +def test_append_time_breakdown_metrics_reduces_a_single_aggregated_worker(tmp_path): + """The aggregated path has one server file, not a ctx/gen pair. + + The reduction classifies files by content, so it needs no changes for this -- + but the caller does, and this is what proves the shared entry point works + with a lone ctx-role file and emits lines in the format the scraper matches. + """ + breakdown_dir = str(tmp_path / "perf_metrics") + _ctx_worker_jsonl(breakdown_dir) + benchmark_file = tmp_path / "benchmark.log" + benchmark_file.write_text("existing client output\n", encoding="utf-8") + outputs = ["existing client output\n"] + + _sanity.append_time_breakdown_metrics( + [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_file), + "benchmark_mode": "ctx_only", + } + ], + outputs, + breakdown_dir, + ) + + # Both sinks must be written: the parser reads the captured stdout, and the + # benchmark file is what a human reads afterwards. + assert "Time Breakdown ctx_processing mean (ms):" in outputs[0] + assert "Time Breakdown ctx_processing mean (ms):" in benchmark_file.read_text() + + # The whole point of the wiring: the real consumer regex now finds populated + # ctx spans in what the run captured. Scraped with the harness's own pattern + # rather than a copy, so a producer/consumer format drift fails here. + scraped = {} + for line in outputs[0].splitlines(): + match = _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.search(line) + if match: + span, stat, value = match.groups() + scraped[_sanity.time_breakdown_metric_name(span, stat)] = float(value) + + # Every field is emitted every run, so the OpenSearch doc schema never varies. + assert set(scraped) == set(_sanity.TIME_BREAKDOWN_METRICS) + assert scraped["tb_ctx_processing_mean"] > 0.0 + assert scraped["tb_chunk_forward_mean"] > 0.0 + # ctx_only populates 44 of the 108; the gen-side groups stay 0.0. + assert scraped["tb_gen_kv_transfer_mean"] == 0.0 + assert len([v for v in scraped.values() if v != 0.0]) <= 44 + + +def test_append_time_breakdown_metrics_is_a_no_op_without_files(tmp_path): + """A missing directory must not raise: it is diagnosed by the "no lines" check. + + Aggregation runs inside the test's teardown path. Raising here would replace a + clear "parsed no Time Breakdown lines" failure with a traceback from cleanup, + and on the disagg path it would mask whatever actually killed the workers. + """ + outputs = ["client output\n"] + benchmark_file = tmp_path / "benchmark.log" + benchmark_file.write_text("client output\n", encoding="utf-8") + + _sanity.append_time_breakdown_metrics( + [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_file), + "benchmark_mode": "ctx_only", + } + ], + outputs, + str(tmp_path / "absent"), + ) + + assert outputs == ["client output\n"] + + +def _listed_time_breakdown_ids(): + """Every ``time_breakdown`` perf-sanity id referenced by a CI lane list.""" + test_db = _REPO_ROOT / "tests" / "integration" / "test_lists" / "test-db" + found = [] + for path in sorted(test_db.glob("*.yml")): + for line in path.read_text(encoding="utf-8").splitlines(): + stripped = line.strip() + if not stripped.startswith("- perf/test_perf_sanity.py::"): + continue + if f"-{_sanity.TIME_BREAKDOWN_MODIFIER}-" not in stripped: + continue + found.append((path.name, stripped.split("[", 1)[1].split("]", 1)[0])) + return found + + +def test_every_listed_breakdown_lane_is_an_id_the_harness_generates(): + """A lane id the collector never produces is an error at collection, not a skip. + + The modified ids are allowlisted per config stem, so a lane list and an + allowlist can disagree in either direction: an id in a list but not in the + allowlist fails the whole stage, and an allowlisted stem no list references + is a case that is generated but never run. Both are invisible until CI runs, + which for a post_merge perf stage is a slow way to find out. + """ + listed = _listed_time_breakdown_ids() + assert listed, "no time_breakdown lane found; did the lists move?" + + allowlists = { + "e2e": _sanity.E2E_TIME_BREAKDOWN_CONFIGS, + "ctx_only": _sanity.CTX_ONLY_TIME_BREAKDOWN_CONFIGS, + } + seen = set() + for list_name, test_id in listed: + stem, _pattern, _runtime, mode, time_breakdown = _sanity.parse_test_string(test_id) + assert time_breakdown, f"{list_name}: {test_id} did not parse as a modified id" + assert mode in allowlists, f"{list_name}: {test_id} has unsupported mode {mode!r}" + assert stem in allowlists[mode], ( + f"{list_name}: {test_id} is not generated -- {stem!r} is missing from the " + f"{mode} allowlist" + ) + seen.add((mode, stem)) + + # And the reverse direction: nothing is allowlisted but unreferenced. + for mode, stems in allowlists.items(): + for stem in stems: + assert (mode, stem) in seen, f"{mode} breakdown case {stem!r} is in no lane list" + + +# Loading the harness imported this for real (test_perf_sanity does +# ``from .time_breakdown_metrics import ...``), and _load_test_perf_sanity only restores the +# names it stubbed -- which this is not -- so it is still registered. Taken from sys.modules +# rather than imported: ``from defs.perf import time_breakdown_metrics`` would need the +# ``defs.perf`` parent, and that stub *was* restored away. +_tbm = sys.modules["defs.perf.time_breakdown_metrics"] + + +def _burst_ctx_worker_jsonl(directory, count=4, warmup=False): + """A ctx worker's JSONL whose measured requests overlap, as a real lane's do. + + The measured requests arrive within 50 ms of each other and each takes 500 ms, so + every one of them overlaps its neighbour -- the property _drop_warmup_record relies + on to tell them apart from a warmup request. With ``warmup=True`` an additional + request is prepended that arrives 10 s earlier and completes 9.5 s before the burst + opens, which is what benchmark_serving's "initial single prompt test run" looks like. + + Returns the path written. + """ + os.makedirs(directory, exist_ok=True) + + def record(request_id, t0, forward_ms): + chunk_start = t0 + 0.010 + return { + "request_id": request_id, + "perf_metrics": { + "timing_metrics": { + "server_arrival_time": t0, + "arrival_time": t0 + 0.001, + "first_scheduled_time": t0 + 0.003, + "first_token_time": t0 + 0.500, + "server_first_token_time": t0 + 0.501, + "last_token_time": t0 + 0.500, + } + }, + "time_breakdown_metrics": { + "ctx_chunk_metrics": [ + { + "forward_start_time": chunk_start, + "forward_end_time": chunk_start + forward_ms / 1000.0, + "sample_start_time": chunk_start + 0.402, + "sample_end_time": chunk_start + 0.403, + "token_time": t0 + 0.500, + "gpu_forward_time": forward_ms, + "gpu_sample_time": 0.9, + } + ] + }, + } + + records = [] + if warmup: + # Deliberately pathological, the way a cold first request is: ~4x the forward + # time of a measured request. If it is not excluded it moves the mean. + records.append(record("warmup", 1000.0 - 10.0, forward_ms=1600.0)) + records.extend(record(i, 1000.0 + i * 0.05, forward_ms=400.0) for i in range(count)) + + path = os.path.join(directory, "perf_metrics-server-host-1-20260101T000000Z.jsonl") + with open(path, "w", encoding="utf-8") as handle: + for raw in records: + handle.write(json.dumps(raw) + "\n") + return path + + +def test_the_warmup_request_is_excluded_and_the_measured_population_recovered(tmp_path): + """Dropping the warmup record must reproduce the warmup-free run exactly.""" + clean = _burst_ctx_worker_jsonl(str(tmp_path / "clean"), warmup=False) + dirty = _burst_ctx_worker_jsonl(str(tmp_path / "dirty"), warmup=True) + + baseline, _ = _tbm.compute_time_breakdown_metrics([clean], "ctx_only") + left_in, _ = _tbm.compute_time_breakdown_metrics([dirty], "ctx_only") + dropped, info = _tbm.compute_time_breakdown_metrics( + [dirty], "ctx_only", drop_warmup_request=True + ) + + # The warmup request has to actually perturb the result, or this proves nothing. + assert left_in["d_tb_chunk_gpu_forward_mean"] != baseline["d_tb_chunk_gpu_forward_mean"] + assert dropped == baseline + assert sum(info["warmup_dropped"].values()) == 1 + + +def test_a_burst_of_measured_requests_is_never_mistaken_for_a_warmup_request(tmp_path): + """The guard is isolation: overlapping requests must all survive.""" + clean = _burst_ctx_worker_jsonl(str(tmp_path / "clean"), warmup=False) + + kept, info = _tbm.compute_time_breakdown_metrics([clean], "ctx_only", drop_warmup_request=True) + untouched, _ = _tbm.compute_time_breakdown_metrics([clean], "ctx_only") + + assert info["warmup_dropped"] == {} + assert kept == untouched + + +def test_a_single_record_file_is_never_emptied(tmp_path): + """One record cannot be shown to be isolated, and dropping it would erase the file.""" + path = _burst_ctx_worker_jsonl(str(tmp_path / "one"), count=1, warmup=False) + + metrics, info = _tbm.compute_time_breakdown_metrics( + [path], "ctx_only", drop_warmup_request=True + ) + + assert info["warmup_dropped"] == {} + assert metrics["d_tb_ctx_processing_mean"] > 0.0 + + +def test_the_harness_forwards_the_clients_warmup_flag(tmp_path): + """append_time_breakdown_metrics must honour the pending record's warmup flag.""" + breakdown_dir = str(tmp_path / "tb") + _burst_ctx_worker_jsonl(breakdown_dir, warmup=True) + + def scraped(warmup): + benchmark_file = tmp_path / f"benchmark-{warmup}.log" + benchmark_file.write_text("client output\n", encoding="utf-8") + outputs = ["client output\n"] + _sanity.append_time_breakdown_metrics( + [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_file), + "benchmark_mode": "ctx_only", + "warmup": warmup, + } + ], + outputs, + breakdown_dir, + ) + return { + match.group(1) + "_" + match.group(2): float(match.group(3)) + for match in _sanity.TIME_BREAKDOWN_METRIC_LOG_QUERY.finditer(outputs[0]) + } + + with_warmup = scraped(True) + without = scraped(False) + + assert with_warmup and without + # Same schema either way; only the values move. + assert set(with_warmup) == set(without) + assert with_warmup["chunk_gpu_forward_mean"] != without["chunk_gpu_forward_mean"] + # Excluding the cold request must lower the mean forward time, not raise it. + assert with_warmup["chunk_gpu_forward_mean"] < without["chunk_gpu_forward_mean"] diff --git a/tests/unittest/others/test_time_breakdown.py b/tests/unittest/others/test_time_breakdown.py index 132727f2326f..708505fa2d10 100644 --- a/tests/unittest/others/test_time_breakdown.py +++ b/tests/unittest/others/test_time_breakdown.py @@ -416,6 +416,29 @@ def test_parse_jsonl_file(self): finally: os.unlink(temp_file) + def test_parse_records_matches_parse_json_file(self): + """In-memory parsing must be the same reduction, not a second implementation. + + benchmark_serving reduces the records it already holds instead of writing them + out and reading them back, so that an unwritable output directory costs the + artifact rather than the measurement. That is only safe while the two paths + agree. + """ + with tempfile.NamedTemporaryFile(mode='w', + suffix='.jsonl', + delete=False) as f: + for record in self.test_data: + f.write(json.dumps(record) + '\n') + temp_file = f.name + + try: + from_file = self.analyzer.parse_json_file(temp_file) + finally: + os.unlink(temp_file) + + from_memory = self.analyzer.parse_records(self.test_data) + self.assertEqual(from_memory, from_file) + def test_read_new_disagg_metrics_for_benchmark(self): """Test reading only new combined records from a metrics directory.""" with tempfile.TemporaryDirectory() as output_dir: diff --git a/tests/unittest/others/test_time_breakdown_metrics.py b/tests/unittest/others/test_time_breakdown_metrics.py new file mode 100644 index 000000000000..19d6d86b1433 --- /dev/null +++ b/tests/unittest/others/test_time_breakdown_metrics.py @@ -0,0 +1,525 @@ +# 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. +"""Unit tests for perf-sanity time_breakdown metric aggregation.""" + +import importlib.util +import json +import os +from pathlib import Path +from types import ModuleType +from typing import Any, Dict, List + +import pytest + +pytestmark = pytest.mark.cpu_only + +# Loaded by path rather than via sys.path.insert: the perf defs directory holds modules +# whose names collide with top-level ones (_model_paths, perf_regression_utils), and a +# module-level insert is never undone, so it would shadow them for every test collected +# later in the same process. The sibling test_perf_sanity_time_breakdown.py does the same. +# No import stubs are needed here because time_breakdown_metrics is stdlib-only. +_MODULE_PATH = os.path.join( + os.path.dirname(__file__), + "..", + "..", + "integration", + "defs", + "perf", + "time_breakdown_metrics.py", +) + + +def _load_time_breakdown_metrics() -> ModuleType: + spec = importlib.util.spec_from_file_location("perf_time_breakdown_metrics", _MODULE_PATH) + module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(module) + return module + + +_tbm = _load_time_breakdown_metrics() + +ALL_METRICS = _tbm.ALL_METRICS +GROUP_METRICS = _tbm.GROUP_METRICS +MODE_GROUPS = _tbm.MODE_GROUPS +STATS = _tbm.STATS +compute_time_breakdown_metrics = _tbm.compute_time_breakdown_metrics +wait_for_perf_metrics_files = _tbm.wait_for_perf_metrics_files + + +def _chunk(base, *, fwd=0.100, upd=0.002, smp=0.001, post=0.010, gpu_fwd=110.0): + """One ctx_chunk_metrics entry starting at ``base`` (seconds).""" + fwd_end = base + fwd + smp_start = fwd_end + upd + smp_end = smp_start + smp + return { + "forward_start_time": base, + "forward_end_time": fwd_end, + "sample_start_time": smp_start, + "sample_end_time": smp_end, + "token_time": smp_end + post, + "gpu_forward_time": gpu_fwd, + "gpu_sample_time": 0.02, + } + + +def _step(base, idx, *, fwd=0.002, upd=0.009, smp=0.0002, post=0.012): + entry = _chunk(base, fwd=fwd, upd=upd, smp=smp, post=post, gpu_fwd=12.0) + entry["iter"] = idx + return entry + + +def _worker_record(rid, t0, *, chunks=None, steps=None, gen=False): + """A plain per-worker record, as ``perf_metrics-server-*.jsonl`` contains.""" + timing = { + "server_arrival_time": t0, + "arrival_time": t0 + 0.001, + "first_scheduled_time": t0 + 0.003, + "first_token_time": t0 + 0.500, + "server_first_token_time": t0 + 0.501, + "last_token_time": t0 + 1.500, + } + if gen: + timing["kv_cache_transfer_start"] = t0 + 0.010 + timing["kv_cache_transfer_end"] = t0 + 0.030 + breakdown = {} + if chunks is not None: + breakdown["ctx_chunk_metrics"] = chunks + if steps is not None: + breakdown["step_metrics"] = steps + return { + "request_id": rid, + "disagg_request_id": rid, + "perf_metrics": {"timing_metrics": timing}, + "time_breakdown_metrics": breakdown, + } + + +def _write(tmp_path, name, records): + path = tmp_path / name + path.write_text("".join(json.dumps(r) + "\n" for r in records)) + return str(path) + + +def _read(path: str) -> List[Dict[str, Any]]: + """Read a JSONL back without leaking the handle into the test's teardown.""" + with open(path, encoding="utf-8") as handle: + return [json.loads(line) for line in handle if line.strip()] + + +def _ctx_file(tmp_path, name="perf_metrics-server-hostA-1-t.jsonl", n=5, offset=0.0): + """A context worker whose chunk clock is ``offset`` seconds ahead of its request clock.""" + records = [] + for i in range(n): + t0 = 1000.0 + i + # The single chunk must end (token_time) exactly at first_token_time + offset. + chunk = _chunk(t0 + 0.003 + offset + 0.005) + shift = (t0 + 0.500 + offset) - chunk["token_time"] + chunk = {k: (v + shift if k.endswith("_time") else v) for k, v in chunk.items()} + records.append(_worker_record(i, t0, chunks=[chunk])) + return _write(tmp_path, name, records) + + +def _gen_file(tmp_path, name, n=4, nsteps=6, offset=0.0): + records = [] + for i in range(n): + t0 = 2000.0 + i + steps = [] + cursor = t0 + 0.100 + offset + for s in range(nsteps): + entry = _step(cursor, s + 1) + steps.append(entry) + cursor = entry["token_time"] + 0.0005 + shift = (t0 + 1.500 + offset) - steps[-1]["token_time"] + steps = [ + {k: (v + shift if k.endswith("_time") else v) for k, v in s.items()} for s in steps + ] + records.append(_worker_record(i, t0, steps=steps, gen=True)) + return _write(tmp_path, name, records) + + +def _combined(ctx_records, gen_records, ctx_server, gen_servers): + """Merge plain worker records into the disagg combined shape.""" + out = [] + for i, (c, g) in enumerate(zip(ctx_records, gen_records)): + ctm = c["perf_metrics"]["timing_metrics"] + gtm = g["perf_metrics"]["timing_metrics"] + out.append( + { + "disagg_request_id": i, + "disagg_server_arrival_time": ctm["server_arrival_time"] - 0.002, + "disagg_server_first_token_time": gtm["server_first_token_time"] + 0.0005, + "ctx_server": ctx_server, + "gen_server": gen_servers[i % len(gen_servers)], + "ctx_perf_metrics": c, + "gen_perf_metrics": g, + } + ) + return out + + +def test_schema_is_stable_and_complete(): + metrics, _ = compute_time_breakdown_metrics([], "e2e") + assert len(metrics) == len(ALL_METRICS) * len(STATS) + assert len(ALL_METRICS) == len(set(ALL_METRICS)), "duplicate metric name" + # Every mode yields the identical key set, so the OpenSearch doc schema never varies. + for mode in list(MODE_GROUPS) + ["aggr"]: + other, _ = compute_time_breakdown_metrics([], mode) + assert set(other) == set(metrics) + + +def test_aggregated_mode_is_all_zero(tmp_path): + paths = [_ctx_file(tmp_path), _gen_file(tmp_path, "perf_metrics-server-hostB-2-t.jsonl")] + metrics, info = compute_time_breakdown_metrics(paths, "aggr") + assert info["groups"] == [] + assert set(metrics.values()) == {0.0} + + +@pytest.mark.parametrize("mode", sorted(MODE_GROUPS)) +def test_mode_gating_zeroes_unsupported_groups(tmp_path, mode): + ctx = _ctx_file(tmp_path) + gen = _gen_file(tmp_path, "perf_metrics-server-hostB-2-t.jsonl") + metrics, info = compute_time_breakdown_metrics([ctx, gen], mode) + for group, names in GROUP_METRICS.items(): + supported = group in MODE_GROUPS[mode] + for name in names: + values = [metrics[f"d_tb_{name}_{s}"] for s in STATS] + if not supported: + assert values == [0.0] * len(STATS), f"{mode}/{name} should be zeroed" + assert info["groups"] == list(MODE_GROUPS[mode]) + + +def test_ctx_only_needs_no_disagg_server(tmp_path): + """ctx_only runs the ctx worker in aggregated mode, so there is no combined file.""" + metrics, info = compute_time_breakdown_metrics([_ctx_file(tmp_path)], "ctx_only") + assert info["counts"]["ctx_stage_records"] == 5 + assert metrics["d_tb_ctx_processing_mean"] == pytest.approx(497.0, abs=1.0) + # Non-chunked prefill is still reported as a single chunk (group 2 populated). + assert info["sample_counts"]["chunk_forward"] == 5 + assert metrics["d_tb_chunk_forward_mean"] > 0.0 + + +def test_stage_groups_never_borrow_the_other_roles_records(tmp_path: Path) -> None: + """Without a combined file each stage must fall back to its *own* role's workers. + + _RecordView aliases both .ctx and .gen to the raw record for a single-role worker + file, so a shared fallback list would compute the group 4 gen spans from the context + worker's timestamps and upload plausible values for the wrong phase. Losing the + samples is the correct failure: a zero is visible, a mislabelled span is not. + """ + ctx = _ctx_file(tmp_path) + gen = _gen_file(tmp_path, "perf_metrics-server-hostB-2-t.jsonl") + + # Both roles present, still no combined file: each group reads its own role. + metrics, info = compute_time_breakdown_metrics([ctx, gen], "e2e") + assert info["counts"]["ctx_stage_records"] == 5 + assert info["counts"]["gen_stage_records"] == 4 + assert metrics["d_tb_ctx_processing_mean"] == pytest.approx(497.0, abs=1.0) + # Only a gen record carries kv_cache_transfer_*, so a non-zero value here proves + # group 4 was computed from the gen worker and not from the ctx worker. + assert metrics["d_tb_gen_kv_transfer_mean"] == pytest.approx(20.0, abs=1e-6) + assert metrics["d_tb_gen_queue_wait_mean"] == pytest.approx(9.0, abs=1e-6) + # Group 5 is cross-role, so it stays empty without the join. + for name in GROUP_METRICS[5]: + assert metrics[f"d_tb_{name}_mean"] == 0.0 + + # Only a ctx worker: group 4 must be empty rather than a copy of group 1. + ctx_only_metrics, _ = compute_time_breakdown_metrics([ctx], "e2e") + for name in GROUP_METRICS[4]: + assert ctx_only_metrics[f"d_tb_{name}_mean"] == 0.0, f"{name} borrowed ctx timestamps" + assert ctx_only_metrics["d_tb_ctx_preprocessing_mean"] > 0.0 + + # Mirror image: only a gen worker, so group 1 must be empty. + gen_only_metrics, _ = compute_time_breakdown_metrics([gen], "e2e") + for name in GROUP_METRICS[1]: + assert gen_only_metrics[f"d_tb_{name}_mean"] == 0.0, f"{name} borrowed gen timestamps" + assert gen_only_metrics["d_tb_gen_kv_transfer_mean"] == pytest.approx(20.0, abs=1e-6) + + +def test_chunk_spans_tile_ctx_processing(tmp_path): + metrics, _ = compute_time_breakdown_metrics([_ctx_file(tmp_path)], "ctx_only") + total = sum( + metrics[f"d_tb_chunk_{n}_mean"] + for n in ("preprocessing", "forward", "update", "sample", "postprocessing") + ) + assert total == pytest.approx(metrics["d_tb_ctx_processing_mean"], abs=1e-6) + + +def test_gen_queue_sub_spans_sum_to_gen_queue(tmp_path): + gen = _gen_file(tmp_path, "perf_metrics-server-hostB-2-t.jsonl") + metrics, _ = compute_time_breakdown_metrics([gen], "gen_only") + subs = sum( + metrics[f"d_tb_{n}_mean"] + for n in ("gen_queue_wait", "gen_kv_transfer", "gen_post_transfer") + ) + assert subs == pytest.approx(metrics["d_tb_gen_queue_mean"], abs=1e-6) + + +def test_step_preprocessing_may_be_negative_under_overlap(tmp_path): + """With the overlap scheduler on, step N forwards before step N-1's token_time. + + The value is a legitimate signed term of a contiguous decomposition, so it must be + reported as-is rather than clamped. + """ + records = [] + for i in range(4): + t0 = 2000.0 + i + steps, cursor = [], t0 + 0.100 + for s in range(6): + entry = _step(cursor, s + 1) + steps.append(entry) + cursor = entry["token_time"] - 0.011 # next forward starts BEFORE this token + shift = (t0 + 1.500) - steps[-1]["token_time"] + steps = [ + {k: (v + shift if k.endswith("_time") else v) for k, v in s.items()} for s in steps + ] + records.append(_worker_record(i, t0, steps=steps, gen=True)) + path = _write(tmp_path, "perf_metrics-server-hostB-2-t.jsonl", records) + metrics, _ = compute_time_breakdown_metrics([path], "gen_only") + assert metrics["d_tb_step_preprocessing_median"] < 0.0 + total = sum( + metrics[f"d_tb_step_{n}_mean"] + for n in ("preprocessing", "forward", "update", "sample", "postprocessing") + ) + assert total > 0.0, "the five step spans must still tile a positive step period" + + +def test_multi_worker_clock_offsets_are_corrected_per_worker(tmp_path): + """Regression test for the bug this file exists to prevent. + + A merged/combined file mixes every worker together. Each worker process has its own + instance-clock origin, so estimating ONE offset across N workers corrupts the + first-instance preprocessing for N-1 of them. Here four gen workers sit at wildly + different offsets (one of them ~377680 s, as measured on real hardware); the result must + match the single-worker, zero-offset case. + """ + offsets = [0.0003, 377680.565, 9.9706, 0.9927] + per_worker = 4 + gen_records = [] + for widx, off in enumerate(offsets): + path = _gen_file( + tmp_path, f"perf_metrics-server-host{widx}-{widx}-t.jsonl", n=per_worker, offset=off + ) + gen_records.extend(_read(path)) + ctx_path = _ctx_file(tmp_path, n=len(gen_records)) + ctx_records = _read(ctx_path) + # Round-robin assignment, so consecutive records come from different workers -- exactly the + # interleaving that makes a single pooled offset estimate look plausible but be wrong. + gen_servers = [f"genhost{i}:1" for i in range(len(offsets))] + combined = _combined( + ctx_records, + [ + gen_records[(i % len(offsets)) * per_worker + i // len(offsets)] + for i in range(len(gen_records)) + ], + "ctxhost:1", + gen_servers, + ) + merged_path = _write(tmp_path, "perf_metrics-disagg-hostZ-9-t.jsonl", combined) + + metrics, info = compute_time_breakdown_metrics([merged_path], "e2e") + + # Every worker contributed a first-step preprocessing value; none was discarded. + assert info["sample_counts"]["step_preprocessing"] == info["sample_counts"]["step_forward"] + assert any("clock-base offsets spanning" in w for w in info["warnings"]) + + # The offsets are an artefact of the workers' clock bases. Removing them per worker must + # reproduce, stat for stat, what one worker at offset 0 yields -- the four workers are + # identical apart from their clock base, and each contributes the same share of samples. + solo, _ = compute_time_breakdown_metrics( + [_gen_file(tmp_path, "perf_metrics-server-solo-9-t.jsonl", n=per_worker, offset=0.0)], + "gen_only", + ) + for stat in STATS: + assert metrics[f"d_tb_step_preprocessing_{stat}"] == pytest.approx( + solo[f"d_tb_step_preprocessing_{stat}"], abs=1e-6 + ), stat + # A single pooled offset would leave residuals of seconds to days on 3 of the 4 workers. + assert metrics["d_tb_step_preprocessing_p99"] < 2000.0 + + +def test_unverifiable_clock_offset_drops_the_crossing_span_not_guesses(tmp_path): + """Too few requests to pin a worker's offset => omit that one value, never emit it raw. + + Only the FIRST instance's preprocessing crosses the clock-base boundary. If the offset + cannot be estimated, emitting it uncorrected would inject a multi-second (here multi-day) + outlier into an otherwise millisecond-scale distribution, which is far worse than a + slightly smaller sample. + """ + path = _gen_file(tmp_path, "perf_metrics-server-lonely-1-t.jsonl", n=1, offset=377680.565) + metrics, info = compute_time_breakdown_metrics([path], "gen_only") + # 6 steps: 5 intra-array preprocessing values survive, the boundary-crossing one is dropped. + assert info["sample_counts"]["step_forward"] == 6 + assert info["sample_counts"]["step_preprocessing"] == 5 + assert abs(metrics["d_tb_step_preprocessing_mean"]) < 1000.0 + + +def test_zero_and_nan_timestamps_are_excluded_not_counted_as_zero_spans(tmp_path): + """0 / NaN mean 'endpoint not recorded'; they must not become zero-width spans.""" + records = _read(_ctx_file(tmp_path, n=4)) + records[0]["perf_metrics"]["timing_metrics"]["server_arrival_time"] = 0 + records[1]["perf_metrics"]["timing_metrics"]["server_arrival_time"] = float("nan") + path = _write(tmp_path, "perf_metrics-server-hostC-3-t.jsonl", records) + metrics, info = compute_time_breakdown_metrics([path], "ctx_only") + assert info["sample_counts"]["ctx_preprocessing"] == 2 + assert metrics["d_tb_ctx_preprocessing_mean"] > 0.0 + + +def test_role_is_classified_by_content_not_filename(tmp_path): + """Every worker writes kind 'server', so only content can tell ctx from gen.""" + ctx = _ctx_file(tmp_path, "perf_metrics-server-aaa-1-t.jsonl") + gen = _gen_file(tmp_path, "perf_metrics-server-bbb-2-t.jsonl") + _, info = compute_time_breakdown_metrics([ctx, gen], "e2e") + kinds = {name.split("-")[2]: kind.split(" ")[0] for name, kind in info["files"].items()} + assert kinds == {"aaa": "ctx_worker", "bbb": "gen_worker"} + + +def test_a_truncated_final_line_costs_that_line_not_the_file(tmp_path): + """A partial write is the expected failure mode, so it must not discard the file. + + Discarding it is worse than it looks: with the disagg server's file gone the + per-request groups fall back to the workers of their own role and still upload + plausible values, so nothing downstream can notice. + """ + ctx = _ctx_file(tmp_path, n=5) + with open(ctx, "a", encoding="utf-8") as handle: + handle.write(json.dumps(_read(ctx)[0])[:40]) # writer killed mid-record + + metrics, info = compute_time_breakdown_metrics([ctx], "ctx_only") + assert info["skipped_lines"] == {os.path.basename(ctx): 1} + assert info["files"][os.path.basename(ctx)] == "ctx_worker (n=5)" + assert metrics["d_tb_ctx_processing_mean"] > 0.0 + assert any("skipped 1 unparsable line" in w for w in info["warnings"]) + + +def test_a_non_object_line_is_skipped_too(tmp_path): + """json.loads succeeds on a bare scalar; _classify would then raise on it.""" + ctx = _ctx_file(tmp_path, n=3) + with open(ctx, "a", encoding="utf-8") as handle: + handle.write("null\n") + metrics, info = compute_time_breakdown_metrics([ctx], "ctx_only") + assert info["skipped_lines"] == {os.path.basename(ctx): 1} + assert metrics["d_tb_ctx_processing_mean"] > 0.0 + + +class _FakeClock: + """Injected time source: ``sleep`` advances ``monotonic``, so no wall time passes.""" + + def __init__(self, on_sleep=None): + self.now = 0.0 + self.on_sleep = on_sleep or (lambda _: None) + + def monotonic(self): + return self.now + + def sleep(self, seconds): + self.now += seconds + self.on_sleep(self.now) + + +def test_completion_gate_waits_until_the_files_stop_growing(tmp_path): + """The context workers and the disagg server have no sentinel; size stability is it.""" + path = tmp_path / "perf_metrics-server-hostA-1-t.jsonl" + path.write_text("{}\n") + grew = [] + + def grow(now): + # Keep appending for the first 2 simulated seconds, then go quiet. + if now <= 2.0: + with open(path, "a", encoding="utf-8") as handle: + handle.write("{}\n") + grew.append(now) + + clock = _FakeClock(on_sleep=grow) + paths, info = wait_for_perf_metrics_files( + str(tmp_path), + stable_seconds=3.0, + timeout_seconds=60.0, + poll_seconds=0.5, + sleep=clock.sleep, + monotonic=clock.monotonic, + ) + assert paths == [str(path)] + assert info["stable"] is True + assert grew, "the fixture never grew the file, so the test proves nothing" + # Growth stopped at 2.0 and the window is 3.0, so it cannot have returned before 5.0. + assert info["waited_seconds"] >= 5.0 + assert info["warnings"] == [] + + +def test_completion_gate_gives_up_and_warns_instead_of_hanging(tmp_path): + """A wedged writer must cost a warning, not the run: what is on disk is still usable.""" + path = tmp_path / "perf_metrics-server-hostA-1-t.jsonl" + path.write_text("{}\n") + + def grow(_): + with open(path, "a", encoding="utf-8") as handle: + handle.write("{}\n") + + clock = _FakeClock(on_sleep=grow) + paths, info = wait_for_perf_metrics_files( + str(tmp_path), + stable_seconds=3.0, + timeout_seconds=10.0, + poll_seconds=0.5, + sleep=clock.sleep, + monotonic=clock.monotonic, + ) + assert paths == [str(path)] + assert info["stable"] is False + assert any("still growing after" in w for w in info["warnings"]) + + +def test_completion_gate_reports_a_record_census_shortfall(tmp_path): + """The census check is the only thing that can see a *silently* truncated run.""" + ctx = _ctx_file(tmp_path, n=5) + clock = _FakeClock() + _, info = wait_for_perf_metrics_files( + str(tmp_path), + expected_requests=10, + stable_seconds=1.0, + poll_seconds=0.5, + sleep=clock.sleep, + monotonic=clock.monotonic, + ) + assert info["line_counts"] == {os.path.basename(ctx): 5} + assert any("holds 5 complete record(s)" in w for w in info["warnings"]) + + clock = _FakeClock() + _, info = wait_for_perf_metrics_files( + str(tmp_path), + expected_requests=5, + stable_seconds=1.0, + poll_seconds=0.5, + sleep=clock.sleep, + monotonic=clock.monotonic, + ) + assert info["warnings"] == [] + + +def test_completion_gate_line_count_excludes_a_partial_final_line(tmp_path): + """A record without its trailing newline is in flight, so it must not count.""" + path = tmp_path / "perf_metrics-server-hostA-1-t.jsonl" + path.write_text('{"a": 1}\n{"b": 2}\n{"c": ') + clock = _FakeClock() + _, info = wait_for_perf_metrics_files( + str(tmp_path), + expected_requests=3, + stable_seconds=1.0, + poll_seconds=0.5, + sleep=clock.sleep, + monotonic=clock.monotonic, + ) + assert info["line_counts"] == {path.name: 2} + assert any("holds 2 complete record(s)" in w for w in info["warnings"]) diff --git a/tests/unittest/scripts/test_perf_sanity_helpers.py b/tests/unittest/scripts/test_perf_sanity_helpers.py index 21f6f7a721b1..0af2fccfabc4 100644 --- a/tests/unittest/scripts/test_perf_sanity_helpers.py +++ b/tests/unittest/scripts/test_perf_sanity_helpers.py @@ -97,6 +97,7 @@ def test_sentinel_timeout_falls_back_to_current_gen_logs( "output_index": 0, "benchmark_file_path": str(benchmark_log), "start_offsets": [10, 20], + "end_offsets": [110, 120], } ] commands = perf_sanity.DisaggTestCmds( @@ -116,14 +117,15 @@ def test_sentinel_timeout_falls_back_to_current_gen_logs( "wait_for_gen_log_sentinels", lambda self: False, ) - parse_calls: list[tuple[str, int, list[int]]] = [] + parse_calls: list[tuple[str, int, list[int], list[int]]] = [] def parse_device_step_time( output_dir: str, num_gen_servers: int, start_offsets: list[int], + end_offsets: list[int], ) -> perf_sanity._DeviceStepTimeStats: - parse_calls.append((output_dir, num_gen_servers, start_offsets)) + parse_calls.append((output_dir, num_gen_servers, start_offsets, end_offsets)) return perf_sanity._DeviceStepTimeStats(mean=7.25, median=7.2, std=0.115, p75=7.3, p99=7.42) monkeypatch.setattr( @@ -134,7 +136,10 @@ def parse_device_step_time( commands._append_gen_worker_device_step_time(pending, outputs) - assert parse_calls == [(str(tmp_path), 2, [10, 20])] + # Both window bounds must reach the parser: a record whose end_offsets were + # dropped on the way through would read to EOF and, in a multi-client mode, + # attribute every later client's iterations to this one. + assert parse_calls == [(str(tmp_path), 2, [10, 20], [110, 120])] expected = ( "Average Per Iter Device Step Time (ms): 7.25\n" "Median Per Iter Device Step Time (ms): 7.2000\n" @@ -193,6 +198,107 @@ def test_missing_device_step_time_appends_nothing( assert benchmark_log.read_text(encoding="utf-8") == "benchmark output" +def test_append_time_breakdown_metrics_reads_the_configured_dir( + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + """The breakdown directory is a DisaggTestCmds *field*, not a method. + + PerfSanityTestConfig.time_breakdown_dir() computes the path and hands it over + as perf_metrics_output_dir. Calling that method on DisaggTestCmds instead + raises AttributeError -- and this runs after benchmark_status is written, so + the whole measurement would be thrown away at the very last step. + """ + breakdown_dir = tmp_path / "perf_metrics" + breakdown_dir.mkdir() + benchmark_log = tmp_path / "trtllm-benchmark.0.0.log" + benchmark_log.write_text("benchmark output", encoding="utf-8") + outputs = ["benchmark output"] + pending = [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_log), + "benchmark_mode": "e2e", + } + ] + commands = perf_sanity.DisaggTestCmds( + server_cmds=[], + client_cmds={}, + timeout=1, + hostname="localhost", + disagg_serving_type="BENCHMARK", + num_ctx_servers=1, + num_gen_servers=2, + output_dir=str(tmp_path), + test_output_dir=str(tmp_path), + perf_metrics_output_dir=str(breakdown_dir), + ) + + discover_calls: list[str] = [] + + def wait_for_files(directory: str, **kwargs: object) -> tuple[list[str], dict]: + discover_calls.append(directory) + return ( + [str(breakdown_dir / "perf_metrics-server-0.jsonl")], + {"stable": True, "waited_seconds": 0.0, "line_counts": {}, "warnings": []}, + ) + + monkeypatch.setattr(perf_sanity, "wait_for_perf_metrics_files", wait_for_files) + monkeypatch.setattr( + perf_sanity, + "compute_time_breakdown_metrics", + lambda paths, case_type, **kwargs: ( + {"d_tb_ctx_queue_mean": 4.5}, + {"warnings": [], "counts": {"ctx": 1}, "warmup_dropped": {}}, + ), + ) + + commands._append_time_breakdown_metrics(pending, outputs) + + assert discover_calls == [str(breakdown_dir)] + assert "Time Breakdown ctx_queue mean (ms): 4.500000" in outputs[0] + assert "Time Breakdown ctx_queue mean (ms): 4.500000" in benchmark_log.read_text( + encoding="utf-8" + ) + + +def test_append_time_breakdown_metrics_without_any_jsonl_is_not_fatal(tmp_path: Path) -> None: + """The real discovery path over an empty directory, with no stubs. + + Deliberately unmonkeypatched so the attribute access on self is exercised for + real: a stubbed discover would still pass if the directory came from nowhere. + """ + benchmark_log = tmp_path / "trtllm-benchmark.0.0.log" + benchmark_log.write_text("benchmark output", encoding="utf-8") + outputs = ["benchmark output"] + commands = perf_sanity.DisaggTestCmds( + server_cmds=[], + client_cmds={}, + timeout=1, + hostname="localhost", + disagg_serving_type="BENCHMARK", + num_ctx_servers=1, + num_gen_servers=2, + output_dir=str(tmp_path), + test_output_dir=str(tmp_path), + perf_metrics_output_dir=str(tmp_path / "perf_metrics"), + ) + + commands._append_time_breakdown_metrics( + [ + { + "output_index": 0, + "benchmark_file_path": str(benchmark_log), + "benchmark_mode": "e2e", + } + ], + outputs, + ) + + assert outputs == ["benchmark output"] + assert benchmark_log.read_text(encoding="utf-8") == "benchmark output" + + # --------------------------------------------------------------------------- # Gen-worker per-iteration device step time # --------------------------------------------------------------------------- @@ -523,6 +629,123 @@ def test_parse_gen_worker_device_step_time_reports_none_with_no_logs( assert perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 2) is None +def _two_segment_gen_log(tmp_path: Path) -> int: + """One gen log holding two clients' iterations. Returns the split offset. + + Both segments use the same iter numbers and the same ngen, exactly as two + clients against one long-lived gen worker would: the only thing telling them + apart is the byte range, which is the whole point of the window. + """ + first = [_iter_line(n, 1, "7.0ms") for n in range(5, 15)] + second = [_iter_line(n, 1, "70.0ms") for n in range(5, 15)] + path = tmp_path / "gen_server_0.log" + first_text = "\n".join(first) + "\n" + path.write_text(first_text + "\n".join(second) + "\n", encoding="utf-8") + return len(first_text.encode()) + + +def test_invalid_utf8_in_the_log_does_not_abort_the_scan(tmp_path: Path) -> None: + """Tqdm progress bars write partial multibyte sequences during model load. + + The scan reads bytes and decodes per line (so end_offsets can be accounted + exactly), which moves where errors="replace" applies. Without it a single + malformed byte anywhere in a multi-hundred-MB worker log would raise + UnicodeDecodeError and lose the whole metric. + """ + path = tmp_path / "gen_server_0.log" + lines = [_iter_line(n, 1, "7.0ms").encode() for n in range(5, 15)] + # A truncated 3-byte UTF-8 sequence, mid-file, on its own line. + path.write_bytes(b"\n".join(lines[:5] + [b"loading \xe2\x96"] + lines[5:]) + b"\n") + + stats = perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 1) + + assert stats.mean == pytest.approx(7.0) + + +def test_crlf_line_endings_still_parse(tmp_path: Path) -> None: + r"""Binary reads keep the \r that text mode stripped. + + None of the iteration-line regexes are end-anchored, so this holds -- but it + holds by a property of those patterns rather than by construction, so it is + pinned here: adding a trailing anchor to any of them would silently zero the + metric on a log that ever carries CRLF. + """ + path = tmp_path / "gen_server_0.log" + path.write_bytes(b"".join(_iter_line(n, 1, "7.0ms").encode() + b"\r\n" for n in range(5, 15))) + + stats = perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 1) + + assert stats.mean == pytest.approx(7.0) + + +def test_end_offsets_confines_a_client_to_its_own_segment(tmp_path: Path) -> None: + """Without an end bound the first client would report the whole run. + + A multi-client mode appends every client's iterations to the same + gen_server_{i}.log, and the parse is deferred until after teardown, so at + parse time all segments are already on disk. An unbounded read would give + client 0 a mean averaged over client 1's iterations too -- silently wrong + rather than absent, which is why this is pinned. + """ + split = _two_segment_gen_log(tmp_path) + + first = perf_sanity.parse_gen_worker_device_step_time( + str(tmp_path), 1, start_offsets=[0], end_offsets=[split] + ) + second = perf_sanity.parse_gen_worker_device_step_time( + str(tmp_path), 1, start_offsets=[split], end_offsets=None + ) + + assert first.mean == pytest.approx(7.0) + assert second.mean == pytest.approx(70.0) + + +def test_no_end_offsets_reads_to_eof(tmp_path: Path) -> None: + """Backward compatibility: the single-client gen_only lane passes None. + + That lane must stay byte-identical to before the window existed, so this + asserts the unbounded read still spans both segments (mean of 7 and 70). + """ + _two_segment_gen_log(tmp_path) + + stats = perf_sanity.parse_gen_worker_device_step_time(str(tmp_path), 1) + + assert stats.mean == pytest.approx(38.5) + + +def test_an_end_offset_past_eof_is_harmless(tmp_path: Path) -> None: + """The bound comes from a getsize() snapshot of a file still being written. + + It can therefore sit past what a later reader sees only if the log were + truncated, but it must degrade to "read everything" rather than raise. + """ + _two_segment_gen_log(tmp_path) + + stats = perf_sanity.parse_gen_worker_device_step_time( + str(tmp_path), 1, start_offsets=[0], end_offsets=[10**9] + ) + + assert stats.mean == pytest.approx(38.5) + + +def test_a_line_straddling_the_end_offset_is_dropped(tmp_path: Path) -> None: + """A bound mid-line means the worker was flushing; drop that one row. + + The dropped row belongs to the earlier client, so failing this direction + costs one iteration out of hundreds. Reading on instead would pull in every + later client's rows, which is unbounded error. + """ + split = _two_segment_gen_log(tmp_path) + + stats = perf_sanity.parse_gen_worker_device_step_time( + str(tmp_path), 1, start_offsets=[0], end_offsets=[split - 20] + ) + + # 9 of the first segment's 10 rows, none of the second's. + assert stats.mean == pytest.approx(7.0) + assert stats.std == pytest.approx(0.0) + + def test_every_written_line_parses_and_none_shadows_another( monkeypatch: pytest.MonkeyPatch, tmp_path: Path, @@ -565,6 +788,7 @@ def test_every_written_line_parses_and_none_shadows_another( "output_index": 0, "benchmark_file_path": str(benchmark_log), "start_offsets": None, + "end_offsets": None, } ], outputs, @@ -572,7 +796,7 @@ def test_every_written_line_parses_and_none_shadows_another( metrics: dict[str, float] = {} for line in outputs[0].split("\n"): - for name, regex in perf_sanity.GEN_ONLY_PERF_METRIC_LOG_QUERIES.items(): + for name, regex in perf_sanity.DEVICE_STEP_TIME_LOG_QUERIES.items(): if name in metrics: continue match = regex.search(line) @@ -580,14 +804,14 @@ def test_every_written_line_parses_and_none_shadows_another( metrics[name] = float(match.group(1)) break - assert set(metrics) == set(perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS) + assert set(metrics) == set(perf_sanity.DEVICE_STEP_TIME_METRICS) assert metrics["mean_gen_worker_per_iter_device_step_time"] == pytest.approx(7.17, abs=0.01) assert metrics["std_gen_worker_per_iter_device_step_time"] > 0.0 def test_every_device_step_time_metric_is_a_minimize_metric() -> None: """A metric absent from both lists raises ValueError in check_regression.""" - for name in perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS: + for name in perf_sanity.DEVICE_STEP_TIME_METRICS: assert f"d_{name}" in perf_sanity.MINIMIZE_METRICS @@ -604,15 +828,54 @@ def test_add_perf_metric_value_skips_absent_statistics() -> None: assert "d_p99_gen_worker_per_iter_device_step_time" not in new_data -def test_add_perf_metric_value_omits_the_family_outside_gen_only() -> None: - """e2e and ctx_only never emit these lines, so they must not be uploaded.""" +@pytest.mark.parametrize("mode", ["gen_only", "e2e"]) +def test_add_perf_metric_value_uploads_the_family_for_every_gen_worker_mode( + mode: str, +) -> None: + """Every mode with a gen worker publishes all five statistics.""" + metrics = dict.fromkeys(perf_sanity.PERF_METRIC_LOG_QUERIES, 1.0) + for name in perf_sanity.DEVICE_STEP_TIME_METRICS: + metrics[name] = 7.0 + + new_data: dict = {} + perf_sanity.add_perf_metric_value(new_data, metrics, False, mode) + + for name in perf_sanity.DEVICE_STEP_TIME_METRICS: + assert new_data[f"d_{name}"] == pytest.approx(7.0) + + +def test_add_perf_metric_value_omits_the_family_without_a_benchmark_mode() -> None: + """ctx_only and the aggregated lanes call this with benchmark_mode=None. + + ctx_only runs the *aggregated* runtime from a disagg YAML, so it has no gen + worker and no gen_server_*.log; its call site passes no benchmark_mode at + all. Pinned because ``None in DEVICE_STEP_TIME_MODES`` being False is the + only thing keeping the family off those rows. + """ metrics = dict.fromkeys(perf_sanity.PERF_METRIC_LOG_QUERIES, 1.0) metrics["mean_gen_worker_per_iter_device_step_time"] = 7.0 new_data: dict = {} - perf_sanity.add_perf_metric_value(new_data, metrics, False, "e2e") + perf_sanity.add_perf_metric_value(new_data, metrics, False, None) assert not [key for key in new_data if "gen_worker_per_iter" in key] + assert "ctx_only" not in perf_sanity.DEVICE_STEP_TIME_MODES + + +def test_the_family_gates_only_in_gen_only() -> None: + """The executable form of "upload in e2e, but never gate on it there". + + Modes outside gen_only take the ``else`` branch in + get_regression_check_config and get REGRESSION_METRICS, so the only way a + device-step-time name could ever set b_is_regression for e2e is by leaking + into that default list. MINIMIZE_METRICS membership still buys each name a + baseline and an s_regression_info diff line, which is the diagnostic value -- + the two lists are independent. + """ + for name in perf_sanity.DEVICE_STEP_TIME_METRICS: + assert f"d_{name}" not in perf_sanity.REGRESSION_METRICS + assert f"d_{name}" in perf_sanity.MINIMIZE_METRICS + assert not set(perf_sanity.GEN_ONLY_REGRESSION_METRICS) & set(perf_sanity.REGRESSION_METRICS) def test_every_gated_metric_is_checkable() -> None: @@ -628,5 +891,5 @@ def test_every_gated_metric_is_checkable() -> None: def test_every_gated_metric_is_actually_emitted() -> None: """A gated metric the log never carries is skipped by 'not in new_data'.""" - emitted = {f"d_{name}" for name in perf_sanity.GEN_ONLY_DEVICE_STEP_TIME_METRICS} + emitted = {f"d_{name}" for name in perf_sanity.DEVICE_STEP_TIME_METRICS} assert set(perf_sanity.GEN_ONLY_REGRESSION_METRICS) <= emitted diff --git a/tests/unittest/scripts/test_perf_submit.py b/tests/unittest/scripts/test_perf_submit.py index 48e0922fb947..b1d96494e321 100644 --- a/tests/unittest/scripts/test_perf_submit.py +++ b/tests/unittest/scripts/test_perf_submit.py @@ -18,6 +18,7 @@ import json from pathlib import Path from types import ModuleType +from typing import Optional, Tuple import pytest from pytest_split.algorithms import LeastDurationAlgorithm @@ -499,3 +500,180 @@ def test_default_slurm_partition_empty_when_none_flagged( ): _fake_sinfo(monkeypatch, local_submit_module, "batch\ninteractive\n") assert local_submit_module.default_slurm_partition() == "" + + +# --------------------------------------------------------------------------- # +# Test-id grammar: -[-]- +# +# The modifier segment is what makes the grammar non-trivial: disagg stems +# routinely contain "-" (".._ccb-NIXL"), so the stem cannot be recovered by +# counting segments -- only by peeling a known modifier off the front. Three +# hand-duplicated parsers implement this (the two generators here plus +# test_perf_sanity.py:parse_test_string) and there is no shared module they can +# import, so the agreement test below is the only thing keeping them in step. +# --------------------------------------------------------------------------- # +_DISAGG_STEM = "gb300_deepseek-v4-pro-fp4_8k1k_con666_ctx6_dep4_gen1_dep16_eplb384_mtp3_ccb-NIXL" + +# (test id, config stem, benchmark_mode, runtime_mode, time_breakdown) +TEST_ID_GRAMMAR = ( + ("disagg-e2e-" + _DISAGG_STEM, _DISAGG_STEM, "e2e", "disaggregated", False), + ( + "disagg_upload-e2e-time_breakdown-" + _DISAGG_STEM, + _DISAGG_STEM, + "e2e", + "disaggregated", + True, + ), + ("disagg-gen_only-" + _DISAGG_STEM, _DISAGG_STEM, "gen_only", "disaggregated", False), + ( + "disagg_upload-gen_only-time_breakdown-" + _DISAGG_STEM, + _DISAGG_STEM, + "gen_only", + "disaggregated", + True, + ), + ("aggr-ctx_only-" + _DISAGG_STEM, _DISAGG_STEM, "ctx_only", "aggregated", False), + ( + "aggr_upload-ctx_only-time_breakdown-" + _DISAGG_STEM, + _DISAGG_STEM, + "ctx_only", + "aggregated", + True, + ), + # Plain aggregated: parts[1] alone is the stem, the remainder is the server + # name, and no modifier segment exists -- so a "-" in the stem is illegal + # there and this shape must stay untouched by the modifier logic. + ( + "aggr-deepseek_r1_fp4_v2-r1_fp4_v2_dep4_mtp1_8k1k", + "deepseek_r1_fp4_v2", + None, + "aggregated", + False, + ), +) + + +def _parse_with_module( + module: ModuleType, tmp_path: Path, test_id: str +) -> Tuple[str, Optional[str], str, bool]: + """Normalise the two generators' parsers to one tuple. + + The CI parser takes a test-list line and resolves the yaml on disk; the local + parser takes the bracket content alone. Both are fed the same id here. + """ + if Path(module.__file__).parent.name == "local": + stem, _select_pattern, runtime_mode, benchmark_mode, time_breakdown = ( + module.parse_test_string(test_id) + ) + return stem, benchmark_mode, runtime_mode, time_breakdown + + for folder in (module.AGG_CONFIG_FOLDER, module.DISAGG_CONFIG_FOLDER): + (tmp_path / folder).mkdir(parents=True, exist_ok=True) + for _id, stem, _mode, _runtime, _tb in TEST_ID_GRAMMAR: + for folder in (module.AGG_CONFIG_FOLDER, module.DISAGG_CONFIG_FOLDER): + (tmp_path / folder / f"{stem}.yaml").write_text("{}\n", encoding="utf-8") + config_yaml, _server_name, benchmark_mode, runtime_mode, time_breakdown = ( + module.parse_test_case_name( + str(tmp_path), f"perf/test_perf_sanity.py::test_e2e[{test_id}] TIMEOUT (90)" + ) + ) + return Path(config_yaml).stem, benchmark_mode, runtime_mode, time_breakdown + + +@pytest.mark.parametrize( + ("test_id", "stem", "benchmark_mode", "runtime_mode", "time_breakdown"), + TEST_ID_GRAMMAR, + ids=[entry[0][:40] for entry in TEST_ID_GRAMMAR], +) +def test_both_generators_parse_the_id_grammar( + submit_module: ModuleType, + tmp_path: Path, + test_id: str, + stem: str, + # None for a plain aggregated id, which has no mode segment. + benchmark_mode: Optional[str], + runtime_mode: str, + time_breakdown: bool, +) -> None: + assert _parse_with_module(submit_module, tmp_path, test_id) == ( + stem, + benchmark_mode, + runtime_mode, + time_breakdown, + ) + + +def test_all_three_parsers_agree_on_the_id_grammar( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """The runner and both generators must read every id identically. + + They are three hand-written copies of one grammar with no shared module. If + they drift, the launch script runs a different case than the one pytest + collects -- or writes its artifacts into a different directory -- and nothing + else in the tree notices. + """ + pytest.importorskip("torch._inductor") + # syspath_prepend rather than sys.path.insert: monkeypatch undoes it at + # teardown, so a later test in the same session cannot accidentally resolve + # `defs.*` through this entry. + monkeypatch.syspath_prepend(str(REPO_ROOT / "tests" / "integration")) + from defs.perf import test_perf_sanity as runner + + modules = [_load_module(path, monkeypatch) for path in SUBMIT_PATHS] + for index, (test_id, stem, benchmark_mode, runtime_mode, time_breakdown) in enumerate( + TEST_ID_GRAMMAR + ): + runner_stem, _select, runner_runtime, runner_mode, runner_tb = runner.parse_test_string( + test_id + ) + assert (runner_stem, runner_mode, runner_runtime, runner_tb) == ( + stem, + benchmark_mode, + runtime_mode, + time_breakdown, + ), test_id + for module in modules: + assert _parse_with_module(module, tmp_path / str(index), test_id) == ( + runner_stem, + runner_mode, + runner_runtime, + runner_tb, + ), f"{test_id} in {module.__file__}" + + +@pytest.mark.parametrize( + "test_id", + ( + "disagg-e2e-time_breakdown", + "aggr-ctx_only-time_breakdown", + ), +) +def test_a_modifier_with_no_config_is_rejected( + submit_module: ModuleType, tmp_path: Path, test_id: str +) -> None: + """An id ending at the modifier has no stem left to look up. + + Without this check the stem would come out empty and the failure would + surface as a FileNotFoundError for "/.yaml". + """ + with pytest.raises((AssertionError, ValueError)): + _parse_with_module(submit_module, tmp_path, test_id) + + +def test_format_test_label_round_trips_through_the_local_parser( + local_submit_module: ModuleType, +) -> None: + """The generator regenerates the id it was handed, modifier included. + + local/submit.py rebuilds the test id from the parsed components (see the + comment above its test_case_name reconstruction); if the formatter and the + parser disagree the run silently writes two divergent output folders. + """ + for test_id, stem, benchmark_mode, runtime_mode, time_breakdown in TEST_ID_GRAMMAR: + if benchmark_mode is None: + continue + prefix = "disagg" if runtime_mode == "disaggregated" else "aggr" + label = local_submit_module.format_test_label(benchmark_mode, time_breakdown) + rebuilt = f"{prefix}-{label}-{stem}" + assert rebuilt == test_id.replace("_upload", "", 1)