[Bug]: test_cli_run_dispatches_main_run_before_audit is flaky in CI: 5-request QPS verdict gates it #554

Bug Description

test_cli_run_dispatches_main_run_before_audit (added in 85a9375, #332) is meant to check one thing: that cli._run calls run_benchmark before run_audit. To do that it runs a real output-caching (TEST04) audit against the echo server, with 5 requests per phase. When the audit verdict is FAIL, cli._run raises CLIError. So a few milliseconds of timing noise in one phase can fail this ordering test before its assertions run. Expected: the test passes every time on an unchanged tree.

Why it fails

1. Confirmed. cli._run raises CLIError when the verdict is FAIL (cli.py#L87-L95). The verdict is audit_qps < ref_qps * (1 + threshold) (output_caching_test.py#L178-L186). threshold must be < 1 (schema.py#L187-L196), so no allowed threshold accepts a ratio of 2.0x or more. 3 of the 4 failures were above 2.0x (2.10x, 2.23x, 2.26x).

2. Confirmed. For max_throughput, the QPS window runs from START_PERFORMANCE_TRACKING to the last completion (session.py#L566-L568, metrics_table.py#L109-L122, #L583-L590). QPS is n_completed / tracked_duration_ns (report.py#L360-L361, #L394-L396). The legacy LoadGen window applies only to poisson (pipeline.py#L219-L226). Computed as 5 / QPS from the verdict lines, the audit window in the failing jobs was 3.4 to 5.5 ms and the reference window 6.6 to 11.5 ms. At these lengths, 5 ms of extra time in a phase about halves its QPS.

3. Confirmed (CI logs). In all 4 CI failures the reference phase was the outlier. Its p50 latency was about 2x that of the main run and of the audit phase, and those two agreed with each other. The phases run in this order: main, then reference, then output_caching (cli.py#L88-L89, output_caching_test.py#L89-L100, audit.py#L137). Values are p50 sample_latency_ns from the aggregator log:

   Job	PR	audit/ref	p50 latency, main / reference / audit (ms)
   119629134046	chore(config): single-source CLI/YAML help text on Field(description=) #535 (main d3c57f2e)	2.10x	4.76 / 9.76 / 4.87
   122937510840	fix(deps): update msgpack for security fix #551	1.96x	2.85 / 6.14 / 2.90
   124114725336	feat: server-reported token counts for ISL/OSL/TPS/TPOT (#540) #552	2.26x	4.05 / 9.85 / 4.35
   124119198189	feat: server-reported token counts for ISL/OSL/TPS/TPOT (#540) #552 (re-run)	2.23x	4.97 / 10.28 / 4.26

   The main run is not compared, and a slow audit phase only lowers audit_qps. In these CI failures the extra time was in the reference phase. The one local failure (item 6) had a different pattern.

4. Confirmed (code + CI log). The runner has 2 physical cores (log: "2 total"). pin_loadgen (execute.py#L502-L507) gives the loadgen both cores with all their hyperthreads (cpu_affinity.py#L270-L273). It leaves none for the HTTP worker (log: "Workers will share cores"). The pytest process that calls it also runs the echo server as a thread (echo_server.py#L394-L399). The metrics-aggregator and event-logger subprocesses run on the same 2 cores.

5. Suspected. The extra time comes from CPU contention on those 2 cores, a GC pause, or GIL handoff between the echo-server thread and the benchmark loop in the same process. The cause has not been isolated.

6. Suspected, minor. Sample 0 has the shortest prompt. Its question (remapped to prompt, transforms.py#L351-L361) is 37 characters, against 134 to 804 for samples 1 to 4 (ds_samples.jsonl). In local macOS runs (6 each), the median audit/ref ratio was 1.28 with sample_index=0 and 0.95 with sample_index=3. In the CI failures, main and audit latencies match, so sample choice does not explain those failures. The one local failure did have a fast audit phase: the main / reference / audit windows were 7.9 / 7.2 / 3.1 ms.

7. Confirmed. The sibling test_audit_output_caching_two_phase_flow[offline|single-stream] uses the same audit config, and its [offline] variant uses the same settings (L184-L192). It asserts PASS (L258-L267), so it can fail the same way. In the same 22 jobs it passed 44 of 44 times. Why the target fails more often is unknown. The sibling's docstring attributes skew to "warm pools" (L224-L229). However, each phase creates a new HTTPEndpointClient (execute.py#L755-L756), and both tests set warmup_connections=0.

8. Confirmed. Unit tests already check the ordering with fixed results: call order and shared report_dir (test_benchmark.py#L3829-L3861), and FAIL raising CLIError (#L3863-L3880).

Steps to Reproduce

1. Run the Tests workflow's test job on main 4b385eb5. Among jobs that reach this test, it fails about 1 time in 5 (4 of 22). The failing jobs are linked in the table above.
2. Locally on Linux, run the loop below. On macOS, first add enable_cpu_affinity=False to the test's BenchmarkConfig, because pin_loadgen requires Linux.

   for i in $(seq 20); do
     uv run pytest -q --no-cov \
       "tests/integration/commands/test_benchmark_command.py::TestBenchmarkCommandIntegration::test_cli_run_dispatches_main_run_before_audit" || break
   done

3. To compare phases, read qps and duration_ns from performance/result_summary.json in three places: the test's tmp_path, audit/reference/ and audit/output_caching/.

Local macOS results, not from CI: with sample_index=0, 1 of 6 runs failed and the audit/ref ratio ranged from 0.73 to 2.29. With sample_index=3, 0 of 6 failed and the ratio ranged from 0.66 to 1.34.

Environment

Relevant Logs

From job 124114725336, with runner timestamps removed. The three latency lines are the main, reference and output_caching phases, in that order (values in ns).

tests/integration/commands/test_benchmark_command.py::TestBenchmarkCommandIntegration::test_audit_output_caching_two_phase_flow[offline] PASSED [  0%]
tests/integration/commands/test_benchmark_command.py::TestBenchmarkCommandIntegration::test_audit_output_caching_two_phase_flow[single-stream] PASSED [  0%]
tests/integration/commands/test_benchmark_command.py::TestBenchmarkCommandIntegration::test_cli_run_dispatches_main_run_before_audit FAILED [  0%]
[...]
        result = run_audit(config, report_dir / "audit")
        # main.run() maps CLIError -> exit 1; PASS returns 0.
        if not result.passed:
>           raise CLIError(
                f"Compliance audit {result.test_id} FAILED: "
                f"{result.details.get('reason', '')}"
            )
E           inference_endpoint.exceptions.CLIError: Compliance audit output_caching_test FAILED: audit_qps=1028.0197 >= ref_qps * (1 + 90%) = 866.0002
src/inference_endpoint/commands/benchmark/cli.py:92: CLIError
----------------------------- Captured stdout call -----------------------------
2026-10-30 14:22:26,246 - inference_endpoint.endpoint_client.cpu_affinity - WARNING - Primary NUMA 0 has only 2 cores, loadgen requested 5, using 2
2026-10-30 14:22:26,246 - inference_endpoint.endpoint_client.cpu_affinity - WARNING - Not enough physical cores for 1 workers (have 0, 2 total). Workers will share cores.
[...]
2026-10-30 14:22:30,695 - [...] sample_latency_ns early-stopping detail (confidence 0.99): p99.9: estimate=None empirical=4495848 n=5 [...] p50.0: estimate=None empirical=4052118 [...]
[...]
2026-10-30 14:22:35,710 - [...] sample_latency_ns early-stopping detail (confidence 0.99): p99.9: estimate=None empirical=10295943 n=5 [...] p50.0: estimate=None empirical=9850605 [...]
[...]
2026-10-30 14:22:40,855 - [...] sample_latency_ns early-stopping detail (confidence 0.99): p99.9: estimate=None empirical=4399140 n=5 [...] p50.0: estimate=None empirical=4346011 [...]
[...]
!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
==== 1 failed, 13 passed, 157 deselected, 20 warnings in 116.74s (0:01:56) =====

Impact

• Hidden test results. The job runs with -x, and integration tests are collected before unit tests. In job 124114725336, pytest stopped at 1 failed, 13 passed after 117 s. So 3,314 of the 3,328 selected tests never ran, including all unit tests. Any real failure in a PR stays hidden until someone re-runs the job.
• PRs affected. chore(config): single-source CLI/YAML help text on Field(description=) #535 (2026-10-22, main d3c57f2e), fix(deps): update msgpack for security fix #551 (2026-10-28) and feat: server-reported token counts for ISL/OSL/TPS/TPOT (#540) #552 (2026-10-30, failed on both attempts). chore(config): single-source CLI/YAML help text on Field(description=) #535 and fix(deps): update msgpack for security fix #551 failed with the same signature, so the flake existed before feat: server-reported token counts for ISL/OSL/TPS/TPOT (#540) #552.
• Combined with the other flake. A separate flake, test_run_timeout_during_metrics_drain_interrupts ([Bug]: test_run_timeout_during_metrics_drain_interrupts is flaky in CI: timeout hits service startup #553), aborts the same job. Together, the two flakes failed 12 of the 25 test job attempts from 2026-10-21 to 10-30.

Possible fixes

1. Stop the verdict from deciding the ordering test. Unit tests already cover the ordering (test_benchmark.py#L3829-L3880). One option is to delete this integration test. The other is to keep it for its real artifacts and change _spy_run_audit (L302-L304) to return dataclasses.replace(result, passed=True) after the real audit runs. AuditResult is a frozen dataclass (result.py#L27-L33). Either way, the assertions at L315-L318 would no longer depend on timing.
2. Run enough requests for a stable QPS comparison wherever the verdict is asserted. This covers the sibling's asserts at L260, L265 and L267, and this test if it keeps the verdict. Use at least 200 requests per phase, so 5 ms of noise shifts the ratio by a few percent rather than about 2x. validate() rejects a reference count larger than the dataset with SetupError (output_caching_test.py#L125-L133). The 5-row ds_samples.jsonl (conftest.py#L245-L249) would therefore need replacing, for example with dummy_1k.jsonl with its text_input column remapped to prompt.
3. Leave PASS/FAIL checks to unit tests. The verdict and its strict boundary are already unit-tested (test_output_caching.py#L56-L126). The integration tests could check only the plumbing: both phase directories exist, the result JSON matches the returned AuditResult, and the details keys are present. Those checks would replace the verdict asserts at L260, L265 and L267.