diff --git a/docs/design/daemon-first-output-latency.md b/docs/design/daemon-first-output-latency.md index cb62e760218..fb1d559c8d7 100644 --- a/docs/design/daemon-first-output-latency.md +++ b/docs/design/daemon-first-output-latency.md @@ -31,6 +31,15 @@ The runner is disabled unless `QWEN_FIRST_OUTPUT_BENCHMARK=1`. Its two input mod `BENCHMARK_POST_SESSION_DWELL_MS` is comparison-only, accepts exactly `0`, `100`, or `500`, and defaults to `0`. `BENCHMARK_MEASURED_PAIRS` is also comparison-only and accepts exactly `10` or `30`; it defaults to `10` for the 500 ms diagnostic and `30` otherwise. A 500 ms run requires 10 pairs and the 0/100 ms runs require 30, so a diagnostic cannot be mislabeled as decision-bearing. Formal Phase 2 runs invoke the runner separately for the three dwell scenarios; samples from different dwell values are never pooled. Missing or mixed modes, identical comparison bundles, unreadable paths, unsupported dwell or pair counts, and mismatched dwell/sample plans fail as `invalid_configuration` before sampling. +The dwell is anchored to SSE readiness rather than session readiness. The SSE connect sits between the two, so anchoring to `sessionReady` would let a slow connect consume the whole window and silently reduce a 100 ms scenario to an immediate-prompt run that still reported its configured dwell. `sseReadyToPromptMs` records the idle window each sample actually received. + +Millisecond-scale figures are only meaningful when nothing else competes for the host, so the runner is excluded from the shared integration config and has its own serial config at `integration-tests/vitest.firstoutput.config.ts` (`fileParallelism: false`, serial execution, `retry: 0`). The pure helper tests continue to run in the shared suite. Run the benchmark with: + +```text +QWEN_FIRST_OUTPUT_BENCHMARK=1 QWEN_SANDBOX=false BENCHMARK_CLI_PATH=... \ + npx vitest run --config integration-tests/vitest.firstoutput.config.ts +``` + Artifacts are written below `.qwen/investigations/daemon-first-output-benchmark/`, outside the integration harness's disposable run directory. This keeps successful, failed, and negative-result runs after global teardown without requiring `KEEP_OUTPUT`. ## Measurement contract @@ -43,6 +52,7 @@ All latency timestamps use `performance.now()` in the parent harness. No duratio | -------------------------- | ---------------------------------------------------------------------------------- | | `processSpawnAt` | Immediately before daemon `spawn` | | `sessionReadyAt` | Successful session response fully read and validated | +| `sseReadyAt` | First SSE epoch callback observed; the dwell anchor | | `promptStartedAt` | Immediately before starting the non-blocking prompt request | | `promptAcceptedAt` | HTTP `202` body validated, including top-level `promptId` and replay cursor | | `providerRequestArrivalAt` | Fake Provider accepts the measured request, before its fixed delay | @@ -56,6 +66,7 @@ The raw timestamps produce these exact metrics: | Metric | Calculation | | ----------------------------------- | ----------------------------------------------- | | `processToSessionReadyMs` | `sessionReadyAt - processSpawnAt` | +| `sseReadyToPromptMs` | `promptStartedAt - sseReadyAt`, diagnostic | | `promptToProviderRequestArrivalMs` | `providerRequestArrivalAt - promptStartedAt` | | `promptToFirstModelOutputMs` | `firstModelOutputAt - promptStartedAt` | | `promptToFirstAnswerTextMs` | `firstAnswerTextAt - promptStartedAt`, nullable | @@ -67,7 +78,7 @@ The raw timestamps produce these exact metrics: ### Prompt and event correlation -The SSE collector is active before the prompt, or resumes from the cursor preceding it, and buffers a fixed number of events until the `202` yields the accepted top-level `promptId`. The acceptance envelope must contain a non-empty `promptId` and a non-negative integer `lastEventId`; a legacy synchronous result is recognized only by its `stopReason`, while any other malformed response is rejected. A prompt acceptance timeout aborts the underlying request before sample teardown. The collector then evaluates buffered and live events in original arrival order and accepts only an exact top-level ID match. Earlier, absent-ID, and unrelated prompt events are ignored; buffer overflow fails rather than dropping events. +The SSE collector is active before the prompt, or resumes from the cursor preceding it, and buffers a fixed number of events until the `202` yields the accepted top-level `promptId`. The acceptance envelope must contain a non-empty `promptId` and a non-negative integer `lastEventId`; a legacy synchronous result is recognized only by its `stopReason`, while any other malformed response is rejected. A prompt acceptance timeout aborts the underlying request before sample teardown. The collector then evaluates buffered and live events in original arrival order and accepts only an exact top-level ID match. Earlier, absent-ID, and unrelated prompt events are ignored; on buffer overflow the tracker latches the failure and stops buffering, so the sample is invalidated and the excess events are dropped. Provider requests do not carry the daemon `promptId`. Each isolated fake Provider therefore permits only one expected measured request at a time and matches its unique fixed-length prompt sentinel. Its timestamp can be buffered before the `202`; an extra, missing, early, or concurrent request fails the sample. @@ -87,7 +98,7 @@ The loopback-only OpenAI-compatible fake Provider records request arrival, valid Every baseline process and every comparison arm gets a fresh daemon/ACP process tree, workspace, home and `QWEN_HOME`, ephemeral daemon/Provider ports, event collector, and request ledger. Samples run serially. -Node compile caches are empty at formal-run start, isolated by bundle and mode, populated only by excluded warmups, and then reused only by that same bundle. Control and candidate never share them. Warmup observations remain in the artifact with `measured: false`. +Node compile caches are empty at formal-run start, isolated by bundle and mode, populated only by excluded warmups, and then reused only by that same bundle. The artifact records each cache directory for provenance, but a clean run removes it during teardown, so the recorded path is not expected to exist afterwards. Control and candidate never share them. Warmup observations remain in the artifact with `measured: false`. The child starts from a minimal environment allowlist. It uses fixed locale/timezone, isolated writable paths, disabled telemetry/update checks, dummy Provider configuration, and cleared real credentials and proxy variables. The artifact records only deliberately supplied non-secret values. @@ -102,28 +113,32 @@ Run 2 excluded warmup processes, then 50 measured processes. Each measured proce 3. keeps the first session open, creates a distinct `sessionScope: thread` session on the same ACP child process; and 4. sends one same-length prompt with a distinct sentinel (`warm`). -The runner records the ACP child PID after both turns and invalidates the sample unless exactly one unchanged child served them. Only after the second turn does it close both sessions. The second session therefore has a fresh per-session lazy Provider wrapper but warm ACP process-wide ESM/runtime caches. The pair estimates cold process-level Provider loading without conversation-history confounding. Both sessions still construct their own Provider on prompt, so work the prototype may move into the dwell is not credited; the gate is conservative. Second-session process-to metrics are diagnostic. +The runner records the ACP child PID after both turns and invalidates the sample unless exactly one unchanged child served them. Only after the second turn does it close both sessions. The second session therefore has a fresh per-session lazy Provider wrapper but warm ACP process-wide ESM/runtime caches. The pair bounds the one-time local cost of a process's first trip through the prompt path, without conversation-history confounding. Provider construction is one component of that cost; the first prompt also pays for the first daemon route hit, the first ACP IPC round trip, JIT warm-up, and any unrelated lazy import. The delta is therefore an upper bound on what preloading the Provider could recover, not an estimate of Provider loading, and a passing gate does not establish that the Provider accounts for any particular share of it. Attribution is what the Phase 2 paired comparison tests. Both sessions still construct their own Provider on prompt, so work the prototype may move into the dwell is not credited; the gate is conservative. Second-session process-to metrics are diagnostic. -The baseline expects exactly two Provider requests per process. All 50 cold/warm pairs must be valid. With: +The baseline expects exactly two Provider requests per process. All 50 cold/warm pairs must be valid. Cold and warm share a process, so their deltas are paired rather than independent samples, and the gate is decided on the paired median with its seeded bootstrap 95% interval: ```text -providerDelta = - P50(cold promptToProviderRequestArrivalMs) - - P50(warm promptToProviderRequestArrivalMs) +providerDelta[i] = + cold promptToProviderRequestArrivalMs[i] - + warm promptToProviderRequestArrivalMs[i] + +providerDeltaCiLow = lower bound of the 95% CI of median(providerDelta) ``` Phase 1 passes when either: ```text -providerDelta >= 25 ms +providerDeltaCiLow >= 25 ms ``` or: ```text -providerDelta >= 10% * P50(cold promptToFirstModelOutputMs) +providerDeltaCiLow >= 10% * P50(cold promptToFirstModelOutputMs) ``` +The lower bound rather than the point estimate must clear the threshold, so a delta that only just exceeds it cannot authorize a prototype on the strength of noise. The difference of the two P50s is still recorded for continuity but no longer decides anything. Cold is always the first session, so the pair cannot be order-balanced the way a Phase 2 comparison is; this is a known limitation of the construct, not an omission. + Otherwise the artifact is retained and production work stops. ## Comparison and statistics @@ -134,7 +149,9 @@ Failed arms remain in raw output and invalidate their pairs. They are not replac For each metric, report nearest-rank P50/P90/P99 and mean for each arm, paired median delta, wins/ties, and AB/BA subgroup medians. P90/P99 are descriptive only at 30 pairs; no P95 or tail-latency conclusion is made without at least 100 pairs. -The paired-median 95% confidence interval uses 10,000 seeded bootstrap resamples of valid pair deltas with replacement; seed and iteration count are stored. Its bounds are the nearest-rank 2.5th and 97.5th percentiles. `orderSensitive` is true when AB and BA median deltas have opposite signs and either absolute median is at least 10 ms. Order sensitivity makes the run inconclusive rather than being averaged away. +Two definitions of median coexist deliberately and a reader comparing columns should expect them to differ on an even number of samples. The per-arm `p50` is nearest-rank, so it is always an observed value. The paired `median delta`, and the medians resampled inside the bootstrap, average the two middle values on even counts. A Markdown row can therefore show a `p50` and a `median delta` that do not reconcile arithmetically without either being wrong. + +The paired-median 95% confidence interval uses 10,000 seeded bootstrap resamples of valid pair deltas with replacement; seed and iteration count are stored. Its bounds are the nearest-rank 2.5th and 97.5th percentiles. Each metric's seed is offset by its position in the metric list, so inserting or reordering a metric shifts the bootstrap bounds of every later metric and makes artifacts on either side of the change incomparable even for identical raw samples; the per-metric stored `seed` keeps this auditable. `orderSensitive` is true when AB and BA median deltas have opposite signs and either absolute median is at least 10 ms. Order sensitivity makes the run inconclusive rather than being averaged away. A paired artifact's top-level outcome describes only its primary metric in that one scenario. It does not evaluate the cross-scenario, resource, functional, or publication gates and cannot by itself authorize a Phase 2 pull request. diff --git a/integration-tests/cli/_first-output-benchmark.test.ts b/integration-tests/cli/_first-output-benchmark.test.ts index fd06c25259b..b9464dd0551 100644 --- a/integration-tests/cli/_first-output-benchmark.test.ts +++ b/integration-tests/cli/_first-output-benchmark.test.ts @@ -11,6 +11,7 @@ import { FirstOutputTracker, classifyFirstOutputEvent, evaluateSingleBundlePrototypeGate, + findInvalidTimings, measuredPairCountForDwell, nullablePercentiles, parseBenchmarkPostSessionDwell, @@ -20,7 +21,8 @@ import { validateExpectedFinalText, validatePromptAcceptance, type BenchmarkDaemonEvent, - type FirstOutputBenchmarkArtifactV1, + type FirstOutputBenchmarkArtifactV2, + type FirstOutputSessionTimings, type PairedMetricSample, } from './_first-output-benchmark.js'; @@ -418,6 +420,50 @@ describe('FirstOutputTracker', () => { }); }); +describe('findInvalidTimings', () => { + function makeTimings( + overrides: Partial = {}, + ): FirstOutputSessionTimings { + return { + processToSessionReadyMs: 10, + sseReadyToPromptMs: 5, + promptToProviderRequestArrivalMs: 20, + promptToFirstModelOutputMs: 30, + promptToFirstAnswerTextMs: 35, + providerReadyToFirstModelOutputMs: 8, + processToFirstModelOutputMs: 40, + promptToTerminalMs: 50, + ...overrides, + }; + } + + it('treats finite non-negative and null timings as valid', () => { + expect(findInvalidTimings(makeTimings())).toEqual([]); + expect( + findInvalidTimings( + makeTimings({ + promptToFirstAnswerTextMs: null, + promptToTerminalMs: 0, + }), + ), + ).toEqual([]); + }); + + it('collects every invalid timing instead of stopping at the first', () => { + const invalid = findInvalidTimings( + makeTimings({ + sseReadyToPromptMs: -1, + promptToFirstModelOutputMs: Number.NaN, + }), + ); + expect(invalid).toHaveLength(2); + expect(invalid).toEqual([ + ['sseReadyToPromptMs', -1], + ['promptToFirstModelOutputMs', Number.NaN], + ]); + }); +}); + describe('statistics', () => { it('calculates predictable nearest-rank percentiles', () => { expect(percentiles([5, 1, 4, 2, 3])).toEqual({ @@ -622,33 +668,62 @@ describe('runner decision contracts', () => { }); it('applies the absolute and relative prototype gates only to complete baselines', () => { + const tightAround = (centre: number) => + Array.from({ length: 30 }, (_, index) => centre - 1 + (index % 3)); + expect( evaluateSingleBundlePrototypeGate({ complete: true, - coldPromptToProviderRequestP50Ms: 125, + coldWarmPairedDeltasMs: [], + seed: 7264, + coldPromptToProviderRequestP50Ms: 200, warmPromptToProviderRequestP50Ms: 100, coldPromptToFirstModelOutputP50Ms: 400, }), - ).toMatchObject({ passed: true, providerDeltaMs: 25 }); + ).toMatchObject({ + passed: false, + pairedMedianDeltaMs: null, + bootstrapMedianCi95: null, + }); expect( evaluateSingleBundlePrototypeGate({ complete: true, - coldPromptToProviderRequestP50Ms: 110, + coldWarmPairedDeltasMs: tightAround(30), + seed: 7264, + coldPromptToProviderRequestP50Ms: 200, + warmPromptToProviderRequestP50Ms: 100, + coldPromptToFirstModelOutputP50Ms: 400, + }), + ).toMatchObject({ + passed: true, + providerDeltaMs: 100, + pairedMedianDeltaMs: 30, + }); + expect( + evaluateSingleBundlePrototypeGate({ + complete: true, + coldWarmPairedDeltasMs: tightAround(12), + seed: 7264, + coldPromptToProviderRequestP50Ms: 112, warmPromptToProviderRequestP50Ms: 100, coldPromptToFirstModelOutputP50Ms: 100, }), - ).toMatchObject({ passed: true, providerDeltaMs: 10 }); + ).toMatchObject({ passed: true, pairedMedianDeltaMs: 12 }); expect( evaluateSingleBundlePrototypeGate({ complete: true, + coldWarmPairedDeltasMs: tightAround(9), + seed: 7264, coldPromptToProviderRequestP50Ms: 109, warmPromptToProviderRequestP50Ms: 100, coldPromptToFirstModelOutputP50Ms: 100, }), - ).toMatchObject({ passed: false, providerDeltaMs: 9 }); + ).toMatchObject({ passed: false, pairedMedianDeltaMs: 9 }); expect( evaluateSingleBundlePrototypeGate({ complete: false, + coldWarmPairedDeltasMs: tightAround(30), + seed: 7264, coldPromptToProviderRequestP50Ms: 130, warmPromptToProviderRequestP50Ms: 100, coldPromptToFirstModelOutputP50Ms: 100, @@ -656,6 +731,83 @@ describe('runner decision contracts', () => { ).toMatchObject({ passed: false }); }); + it('fails the prototype gate when a passing point estimate has a CI that crosses the threshold', () => { + // Median 30 ms, but the samples are bimodal at -40 and 100 ms. + const noisy = Array.from({ length: 30 }, (_, index) => + index % 2 === 0 ? -40 : 100, + ); + const gate = evaluateSingleBundlePrototypeGate({ + complete: true, + coldWarmPairedDeltasMs: noisy, + seed: 7264, + coldPromptToProviderRequestP50Ms: 130, + warmPromptToProviderRequestP50Ms: 100, + coldPromptToFirstModelOutputP50Ms: 400, + }); + + expect(gate.providerDeltaMs).toBe(30); + expect(gate.pairedMedianDeltaMs).toBe(30); + expect(gate.bootstrapMedianCi95?.lowMs).toBeLessThan(25); + expect(gate.passed).toBe(false); + }); + + it('produces a deterministic prototype-gate interval for a fixed seed', () => { + const deltas = Array.from({ length: 30 }, (_, index) => index); + const input = { + complete: true, + coldWarmPairedDeltasMs: deltas, + seed: 7264, + bootstrapIterations: 200, + coldPromptToProviderRequestP50Ms: 130, + warmPromptToProviderRequestP50Ms: 100, + coldPromptToFirstModelOutputP50Ms: 400, + }; + + const first = evaluateSingleBundlePrototypeGate(input); + const second = evaluateSingleBundlePrototypeGate(input); + expect(first).toEqual(second); + expect(first.bootstrapMedianCi95).toMatchObject({ + lowMs: 9, + highMs: 19.5, + iterations: 200, + seed: 7264, + }); + + const differentSeed = evaluateSingleBundlePrototypeGate({ + ...input, + seed: 99, + }); + expect(differentSeed.bootstrapMedianCi95).not.toEqual( + first.bootstrapMedianCi95, + ); + }); + + it('rejects invalid prototype-gate inputs before sampling', () => { + const validInput = { + complete: true, + coldWarmPairedDeltasMs: [30, 31, 29], + seed: 7264, + coldPromptToProviderRequestP50Ms: 200, + warmPromptToProviderRequestP50Ms: 100, + coldPromptToFirstModelOutputP50Ms: 400, + }; + expect(() => + evaluateSingleBundlePrototypeGate({ + ...validInput, + bootstrapIterations: 0, + }), + ).toThrow('bootstrapIterations must be a positive integer'); + expect(() => + evaluateSingleBundlePrototypeGate({ ...validInput, seed: Number.NaN }), + ).toThrow('seed must be finite'); + expect(() => + evaluateSingleBundlePrototypeGate({ + ...validInput, + coldWarmPairedDeltasMs: [Number.NaN], + }), + ).toThrow('coldWarmPairedDeltasMs must all be finite'); + }); + it('maps a mismatched final answer to the stable failure code', () => { expect(validateExpectedFinalText('expected', 'expected')).toBeNull(); expect(validateExpectedFinalText('actual', 'expected')).toEqual({ @@ -704,7 +856,7 @@ describe('artifact rendering', () => { providerDelayMs: 50, providerConnection: 'close-per-response', postSessionDwellMs: 0, - prompt: 'reply', + promptShape: 'reply', expectedAnswer: 'ok', maxBufferedEvents: 256, providerRequestsPerSession: 1, @@ -714,7 +866,6 @@ describe('artifact rendering', () => { cliPath: '/control', realpath: '/control', sha256: 'control-hash', - gitCommit: null, compileCache: { policy: 'fixed-private-per-variant-warmed', directory: '/cache/control', @@ -724,7 +875,6 @@ describe('artifact rendering', () => { cliPath: '/candidate', realpath: '/candidate', sha256: 'candidate-hash', - gitCommit: null, compileCache: { policy: 'fixed-private-per-variant-warmed', directory: '/cache/candidate', @@ -754,7 +904,7 @@ describe('artifact rendering', () => { reasons: ['Candidate is faster'], }, }, - } satisfies FirstOutputBenchmarkArtifactV1; + } satisfies FirstOutputBenchmarkArtifactV2; const before = JSON.stringify(artifact); const markdown = renderFirstOutputBenchmarkMarkdown(artifact); @@ -797,7 +947,7 @@ describe('artifact rendering', () => { reasons: ['bundle path is missing'], }, }, - } satisfies FirstOutputBenchmarkArtifactV1; + } satisfies FirstOutputBenchmarkArtifactV2; expect(renderFirstOutputBenchmarkMarkdown(artifact)).toContain( 'Failure: invalid_configuration', diff --git a/integration-tests/cli/_first-output-benchmark.ts b/integration-tests/cli/_first-output-benchmark.ts index 34b6499c97b..af740251b3b 100644 --- a/integration-tests/cli/_first-output-benchmark.ts +++ b/integration-tests/cli/_first-output-benchmark.ts @@ -4,7 +4,7 @@ * SPDX-License-Identifier: Apache-2.0 */ -export const FIRST_OUTPUT_BENCHMARK_VERSION = 1 as const; +export const FIRST_OUTPUT_BENCHMARK_VERSION = 2 as const; export const DEFAULT_BOOTSTRAP_ITERATIONS = 10_000; export const DEFAULT_MATERIAL_THRESHOLD_MS = 10; export const DEFAULT_ORDER_SENSITIVITY_THRESHOLD_MS = 10; @@ -813,9 +813,15 @@ export function validateExpectedFinalText( export interface SingleBundlePrototypeGateInput { complete: boolean; + /** Per-process cold-minus-warm deltas. Cold and warm share a process, so + * they are paired; the gate is decided on their median, not on a difference + * of two independent P50s. */ + coldWarmPairedDeltasMs: readonly number[]; + seed: number; coldPromptToProviderRequestP50Ms: number | null; warmPromptToProviderRequestP50Ms: number | null; coldPromptToFirstModelOutputP50Ms: number | null; + bootstrapIterations?: number; absoluteThresholdMs?: number; relativeThresholdRatio?: number; } @@ -823,6 +829,8 @@ export interface SingleBundlePrototypeGateInput { export interface SingleBundlePrototypeGateResult { passed: boolean; providerDeltaMs: number | null; + pairedMedianDeltaMs: number | null; + bootstrapMedianCi95: BootstrapMedianConfidenceInterval | null; absoluteThresholdMs: number; relativeThresholdRatio: number; } @@ -832,6 +840,7 @@ export function evaluateSingleBundlePrototypeGate( ): SingleBundlePrototypeGateResult { const absoluteThresholdMs = input.absoluteThresholdMs ?? 25; const relativeThresholdRatio = input.relativeThresholdRatio ?? 0.1; + const iterations = input.bootstrapIterations ?? DEFAULT_BOOTSTRAP_ITERATIONS; if ( !Number.isFinite(absoluteThresholdMs) || absoluteThresholdMs < 0 || @@ -840,22 +849,41 @@ export function evaluateSingleBundlePrototypeGate( ) { throw new TypeError('gate thresholds must be finite and non-negative'); } + if (!Number.isInteger(iterations) || iterations < 1) { + throw new TypeError('bootstrapIterations must be a positive integer'); + } + if (!Number.isFinite(input.seed)) { + throw new TypeError('seed must be finite'); + } + if (input.coldWarmPairedDeltasMs.some((value) => !Number.isFinite(value))) { + throw new TypeError('coldWarmPairedDeltasMs must all be finite'); + } const providerDeltaMs = input.coldPromptToProviderRequestP50Ms === null || input.warmPromptToProviderRequestP50Ms === null ? null : input.coldPromptToProviderRequestP50Ms - input.warmPromptToProviderRequestP50Ms; + const pairedMedianDeltaMs = median(input.coldWarmPairedDeltasMs); + const ci = bootstrapMedianCi95( + input.coldWarmPairedDeltasMs, + iterations, + input.seed, + ); + // The lower CI bound, not the point estimate, must clear the threshold: a + // delta that only just exceeds it is not distinguishable from noise. const passed = input.complete && - providerDeltaMs !== null && + ci !== null && input.coldPromptToFirstModelOutputP50Ms !== null && - (providerDeltaMs >= absoluteThresholdMs || - providerDeltaMs >= + (ci.lowMs >= absoluteThresholdMs || + ci.lowMs >= relativeThresholdRatio * input.coldPromptToFirstModelOutputP50Ms); return { passed, providerDeltaMs, + pairedMedianDeltaMs, + bootstrapMedianCi95: ci, absoluteThresholdMs, relativeThresholdRatio, }; @@ -876,6 +904,8 @@ export interface FirstOutputSessionTimestamps { export interface FirstOutputSessionTimings { processToSessionReadyMs: number | null; + /** Idle window actually granted by the configured post-session dwell. */ + sseReadyToPromptMs: number | null; promptToProviderRequestArrivalMs: number | null; promptToFirstModelOutputMs: number | null; promptToFirstAnswerTextMs: number | null; @@ -884,6 +914,21 @@ export interface FirstOutputSessionTimings { promptToTerminalMs: number | null; } +export function findInvalidTimings( + timings: FirstOutputSessionTimings, +): Array<[keyof FirstOutputSessionTimings, number]> { + const invalid: Array<[keyof FirstOutputSessionTimings, number]> = []; + for (const key of Object.keys(timings) as Array< + keyof FirstOutputSessionTimings + >) { + const value = timings[key]; + if (value !== null && (!Number.isFinite(value) || value < 0)) { + invalid.push([key, value]); + } + } + return invalid; +} + export interface FirstOutputSessionRunResult { ordinal: number; sessionId: string | null; @@ -942,7 +987,6 @@ export interface FirstOutputVariantDescriptor { cliPath: string; realpath: string; sha256: string; - gitCommit: string | null; compileCache: { policy: 'fixed-private-per-variant-warmed'; directory: string; @@ -952,6 +996,7 @@ export interface FirstOutputVariantDescriptor { export type FirstOutputMetricName = | 'processToListenMs' | 'processToSessionReadyMs' + | 'sseReadyToPromptMs' | 'promptToProviderRequestArrivalMs' | 'promptToFirstModelOutputMs' | 'promptToFirstAnswerTextMs' @@ -969,7 +1014,7 @@ export interface FirstOutputPairedMetricSummary { bySession: Record; } -interface FirstOutputBenchmarkArtifactBaseV1 { +interface FirstOutputBenchmarkArtifactBaseV2 { version: typeof FIRST_OUTPUT_BENCHMARK_VERSION; benchmark: 'daemon-first-output'; capturedAt: string; @@ -991,15 +1036,15 @@ interface FirstOutputBenchmarkCommonConfig { providerDelayMs: number; providerConnection: 'close-per-response'; postSessionDwellMs: number; - prompt: string; + promptShape: string; expectedAnswer: string; maxBufferedEvents: number; providerRequestsPerSession: number; timeoutsMs: Record; } -export interface FirstOutputSingleBenchmarkArtifactV1 - extends FirstOutputBenchmarkArtifactBaseV1 { +export interface FirstOutputSingleBenchmarkArtifactV2 + extends FirstOutputBenchmarkArtifactBaseV2 { mode: 'single'; config: FirstOutputBenchmarkCommonConfig & { warmupRuns: number; @@ -1023,6 +1068,8 @@ export interface FirstOutputSingleBenchmarkArtifactV1 coldPromptToProviderRequestP50Ms: number | null; warmPromptToProviderRequestP50Ms: number | null; providerDeltaMs: number | null; + pairedMedianDeltaMs: number | null; + bootstrapMedianCi95: BootstrapMedianConfidenceInterval | null; coldPromptToFirstModelOutputP50Ms: number | null; absoluteThresholdMs: number; relativeThresholdRatio: number; @@ -1032,8 +1079,8 @@ export interface FirstOutputSingleBenchmarkArtifactV1 }; } -export interface FirstOutputPairedBenchmarkArtifactV1 - extends FirstOutputBenchmarkArtifactBaseV1 { +export interface FirstOutputPairedBenchmarkArtifactV2 + extends FirstOutputBenchmarkArtifactBaseV2 { mode: 'paired'; config: FirstOutputBenchmarkCommonConfig & { warmupPairs: number; @@ -1067,8 +1114,8 @@ export interface FirstOutputPairedBenchmarkArtifactV1 }; } -export interface FirstOutputFailedBenchmarkArtifactV1 - extends FirstOutputBenchmarkArtifactBaseV1 { +export interface FirstOutputFailedBenchmarkArtifactV2 + extends FirstOutputBenchmarkArtifactBaseV2 { mode: 'failed'; config: { requestedMode: 'single' | 'paired' | 'unknown'; @@ -1083,10 +1130,10 @@ export interface FirstOutputFailedBenchmarkArtifactV1 }; } -export type FirstOutputBenchmarkArtifactV1 = - | FirstOutputSingleBenchmarkArtifactV1 - | FirstOutputPairedBenchmarkArtifactV1 - | FirstOutputFailedBenchmarkArtifactV1; +export type FirstOutputBenchmarkArtifactV2 = + | FirstOutputSingleBenchmarkArtifactV2 + | FirstOutputPairedBenchmarkArtifactV2 + | FirstOutputFailedBenchmarkArtifactV2; function formatMilliseconds(value: number | null): string { return value === null ? 'n/a' : value.toFixed(1); @@ -1109,7 +1156,7 @@ function formatDistribution(distribution: PercentileSummary | null): string { } export function renderFirstOutputBenchmarkMarkdown( - artifact: FirstOutputBenchmarkArtifactV1, + artifact: FirstOutputBenchmarkArtifactV2, ): string { const decisionLabel = artifact.mode === 'paired' ? 'Primary metric decision' : 'Decision'; diff --git a/integration-tests/cli/qwen-daemon-first-output-benchmark.test.ts b/integration-tests/cli/qwen-daemon-first-output-benchmark.test.ts index cc9794232fc..7539fa42e3c 100644 --- a/integration-tests/cli/qwen-daemon-first-output-benchmark.test.ts +++ b/integration-tests/cli/qwen-daemon-first-output-benchmark.test.ts @@ -11,8 +11,13 @@ * comparison mode runs paired control/candidate processes in balanced AB/BA * order. Every process, workspace, home, qwen home, and listener is isolated. * - * Enable with QWEN_FIRST_OUTPUT_BENCHMARK=1. See readBenchmarkConfig() for the - * intentionally strict bundle-path contract. + * Latency figures are only meaningful when nothing else competes for the host, + * so this file is excluded from the shared integration config and must run + * under its own serial config: + * QWEN_FIRST_OUTPUT_BENCHMARK=1 QWEN_SANDBOX=false BENCHMARK_CLI_PATH=... \ + * npx vitest run --config integration-tests/vitest.firstoutput.config.ts + * + * See readBenchmarkConfig() for the intentionally strict bundle-path contract. */ import { execFileSync, spawn, type ChildProcess } from 'node:child_process'; @@ -34,8 +39,10 @@ import { DEFAULT_FIRST_OUTPUT_EVENT_BUFFER_LIMIT, DEFAULT_MATERIAL_THRESHOLD_MS, DEFAULT_ORDER_SENSITIVITY_THRESHOLD_MS, + FIRST_OUTPUT_BENCHMARK_VERSION, FirstOutputTracker, evaluateSingleBundlePrototypeGate, + findInvalidTimings, measuredPairCountForDwell, nullablePercentiles, pairedCandidateControlStats, @@ -43,7 +50,7 @@ import { renderFirstOutputBenchmarkMarkdown, validateExpectedFinalText, validatePromptAcceptance, - type FirstOutputBenchmarkArtifactV1, + type FirstOutputBenchmarkArtifactV2, type FirstOutputFailure, type FirstOutputFailureCode, type FirstOutputMetricName, @@ -131,7 +138,6 @@ interface ResolvedBundle { configuredPath: string; realPath: string; sha256: string; - gitCommit: string | null; compileCacheDir: string; } @@ -301,9 +307,6 @@ function readBenchmarkConfig(): BenchmarkConfig { ); } - const dwell = parseBenchmarkPostSessionDwell( - process.env['BENCHMARK_POST_SESSION_DWELL_MS'], - ); if (hasSingle) { if (process.env['BENCHMARK_POST_SESSION_DWELL_MS'] !== undefined) { throw new Error( @@ -324,6 +327,12 @@ function readBenchmarkConfig(): BenchmarkConfig { }; } + // Parsed only after the compare-only rejections above, so an unsupported + // value in single mode reports that the variable is compare-only rather than + // listing the dwell values compare mode would have accepted. + const dwell = parseBenchmarkPostSessionDwell( + process.env['BENCHMARK_POST_SESSION_DWELL_MS'], + ); const control = resolveBundle(controlPath!, 'control'); const candidate = resolveBundle(candidatePath!, 'candidate'); if (control.realPath === candidate.realPath) { @@ -377,7 +386,6 @@ function resolveBundle(input: string, role: BundleRole): ResolvedBundle { sha256: createHash('sha256') .update(fs.readFileSync(realPath)) .digest('hex'), - gitCommit: gitCommitForPath(realPath), compileCacheDir, }; } @@ -386,22 +394,6 @@ function errorMessage(error: unknown): string { return error instanceof Error ? error.message : String(error); } -function gitCommitForPath(filePath: string): string | null { - try { - return execFileSync( - 'git', - ['-C', path.dirname(filePath), 'rev-parse', 'HEAD'], - { - encoding: 'utf8', - timeout: 5_000, - stdio: ['ignore', 'pipe', 'ignore'], - }, - ).trim(); - } catch { - return null; - } -} - async function spawnBenchmarkDaemon( bundle: ResolvedBundle, workspace: string, @@ -982,7 +974,18 @@ async function runSession( { cause: error }, ); } - const promptNotBefore = timestamps.sessionReady + postSessionDwellMs; + // The dwell exists to give a candidate genuinely idle time before the + // prompt, so it is anchored to SSE readiness rather than session readiness. + // The SSE connect sits between the two: anchoring to sessionReady lets a + // slow connect consume the whole window, silently degrading the scenario + // into an immediate-prompt run that still reports its configured dwell. + if (timestamps.sseReady === null) { + throw new BenchmarkFailure( + 'harness_error', + 'SSE readiness resolved without recording a timestamp.', + ); + } + const promptNotBefore = timestamps.sseReady + postSessionDwellMs; if (performance.now() < promptNotBefore) { await sleep(promptNotBefore - performance.now()); } @@ -1119,13 +1122,15 @@ async function runSession( timestamps.firstAnswerText = tracked.firstAnswer?.receivedAtMs ?? null; timestamps.terminal = tracked.terminal?.receivedAtMs ?? null; const timings = computeSessionTimings(timestamps, daemon.processStartedAtMs); - const invalidMetric = findInvalidTiming(timings); - if (invalidMetric) { + const invalidMetrics = findInvalidTimings(timings); + if (invalidMetrics.length > 0) { failure ??= { code: 'harness_error', - message: `Invalid ${invalidMetric[0]} duration: ${invalidMetric[1]}`, + message: `Invalid durations: ${invalidMetrics + .map(([key, value]) => `${key}=${value}`) + .join(', ')}`, }; - timings[invalidMetric[0]] = null; + for (const [key] of invalidMetrics) timings[key] = null; } return { @@ -1161,20 +1166,6 @@ async function runSession( }; } -function findInvalidTiming( - timings: FirstOutputSessionRunResult['timings'], -): [keyof FirstOutputSessionRunResult['timings'], number] | null { - for (const key of Object.keys(timings) as Array< - keyof FirstOutputSessionRunResult['timings'] - >) { - const value = timings[key]; - if (value !== null && (!Number.isFinite(value) || value < 0)) { - return [key, value]; - } - } - return null; -} - function computeSessionTimings( timestamps: FirstOutputSessionRunResult['timestamps'], processStartedAtMs: number, @@ -1184,6 +1175,7 @@ function computeSessionTimings( timestamps.sessionReady, processStartedAtMs, ), + sseReadyToPromptMs: duration(timestamps.promptStart, timestamps.sseReady), promptToProviderRequestArrivalMs: duration( timestamps.providerRequestArrival, timestamps.promptStart, @@ -1548,15 +1540,6 @@ async function runComparisonPairs( measured.push(pair); if (!isSuccessfulRawPair(pair)) return { warmups, measured }; } - const abCount = measured.filter((pair) => pair.order === 'AB').length; - const baCount = measured.filter((pair) => pair.order === 'BA').length; - const expectedPerOrder = config.measuredPairs / 2; - if (abCount !== expectedPerOrder || baCount !== expectedPerOrder) { - throw new Error( - 'Internal AB/BA balance error: expected ' + - `${expectedPerOrder}/${expectedPerOrder}, received ${abCount}/${baCount}.`, - ); - } return { warmups, measured }; } @@ -1615,7 +1598,11 @@ async function runComparisonPair( } function isSuccessfulProcessSample( - sample: ProcessSample, + sample: { + failure: FirstOutputFailure | null; + cleanup: { failure: FirstOutputFailure | null }; + sessions: readonly FirstOutputSessionRunResult[]; + }, expectedSessions: 1 | 2, ): boolean { return ( @@ -1680,6 +1667,7 @@ function logProgress(message: string): void { const METRICS: readonly FirstOutputMetricName[] = [ 'processToListenMs', 'processToSessionReadyMs', + 'sseReadyToPromptMs', 'promptToProviderRequestArrivalMs', 'promptToFirstModelOutputMs', 'promptToFirstAnswerTextMs', @@ -1765,6 +1753,8 @@ function sessionMetric( switch (metric) { case 'processToSessionReadyMs': return session.timings.processToSessionReadyMs; + case 'sseReadyToPromptMs': + return session.timings.sseReadyToPromptMs; case 'promptToProviderRequestArrivalMs': return session.timings.promptToProviderRequestArrivalMs; case 'promptToFirstModelOutputMs': @@ -1875,13 +1865,13 @@ function pairedOptions(seedOffset: number): { } function commonArtifactFields(): Pick< - FirstOutputBenchmarkArtifactV1, + FirstOutputBenchmarkArtifactV2, 'version' | 'benchmark' | 'capturedAt' | 'harnessGitCommit' | 'platform' > { const cpus = os.cpus(); const loadAverage = os.loadavg() as [number, number, number]; return { - version: 1, + version: FIRST_OUTPUT_BENCHMARK_VERSION, benchmark: 'daemon-first-output', capturedAt: new Date().toISOString(), harnessGitCommit: gitHead(), @@ -1903,7 +1893,7 @@ function commonConfig(postSessionDwellMs: number): { providerDelayMs: number; providerConnection: 'close-per-response'; postSessionDwellMs: number; - prompt: string; + promptShape: string; expectedAnswer: string; maxBufferedEvents: number; providerRequestsPerSession: number; @@ -1914,7 +1904,7 @@ function commonConfig(postSessionDwellMs: number): { providerDelayMs: PROVIDER_DELAY_MS, providerConnection: 'close-per-response', postSessionDwellMs, - prompt: + promptShape: `Unique fixed-width ${PROMPT_LENGTH}-character prompt with a ` + 'zero-padded per-session marker', expectedAnswer: EXPECTED_ANSWER, @@ -1938,7 +1928,6 @@ function variantDescriptor(bundle: ResolvedBundle): { cliPath: string; realpath: string; sha256: string; - gitCommit: string | null; compileCache: { policy: 'fixed-private-per-variant-warmed'; directory: string; @@ -1948,7 +1937,6 @@ function variantDescriptor(bundle: ResolvedBundle): { cliPath: bundle.configuredPath, realpath: bundle.realPath, sha256: bundle.sha256, - gitCommit: bundle.gitCommit, compileCache: { policy: 'fixed-private-per-variant-warmed', directory: bundle.compileCacheDir, @@ -1959,7 +1947,7 @@ function variantDescriptor(bundle: ResolvedBundle): { function buildSingleArtifact( config: SingleBenchmarkConfig, raw: Awaited>, -): FirstOutputBenchmarkArtifactV1 { +): FirstOutputBenchmarkArtifactV2 { const warmupRuns = raw.warmups.map((sample, index) => toProcessRun(sample, index + 1, null), ); @@ -1990,6 +1978,8 @@ function buildSingleArtifact( const complete = warmupsValid && measuredValid; const gate = evaluateSingleBundlePrototypeGate({ complete, + coldWarmPairedDeltasMs: coldWarmProviderDeltas(runs), + seed: BOOTSTRAP_SEED, coldPromptToProviderRequestP50Ms: coldProviderP50, warmPromptToProviderRequestP50Ms: warmProviderP50, coldPromptToFirstModelOutputP50Ms: coldFirstOutputP50, @@ -2025,10 +2015,14 @@ function buildSingleArtifact( ? `All ${SINGLE_MEASURED} measured processes ran.` : `Only ${runs.length}/${SINGLE_MEASURED} measured processes ran before the first invalid process stopped sampling.`, measuredValid - ? `Cold-minus-warm Provider-arrival P50: ${ - providerDeltaMs === null + ? `Paired cold-minus-warm Provider-arrival median: ${ + gate.pairedMedianDeltaMs === null ? 'n/a' - : `${providerDeltaMs.toFixed(1)}ms` + : `${gate.pairedMedianDeltaMs.toFixed(1)}ms` + }, 95% CI ${ + gate.bootstrapMedianCi95 === null + ? 'n/a' + : `[${gate.bootstrapMedianCi95.lowMs.toFixed(1)}, ${gate.bootstrapMedianCi95.highMs.toFixed(1)}]` }.` : `Only ${successfulRuns}/${SINGLE_MEASURED} measured processes were valid.`, warmupsComplete @@ -2046,6 +2040,8 @@ function buildSingleArtifact( coldPromptToProviderRequestP50Ms: coldProviderP50, warmPromptToProviderRequestP50Ms: warmProviderP50, providerDeltaMs, + pairedMedianDeltaMs: gate.pairedMedianDeltaMs, + bootstrapMedianCi95: gate.bootstrapMedianCi95, coldPromptToFirstModelOutputP50Ms: coldFirstOutputP50, absoluteThresholdMs: gate.absoluteThresholdMs, relativeThresholdRatio: gate.relativeThresholdRatio, @@ -2059,7 +2055,7 @@ function buildSingleArtifact( function buildPairedArtifact( config: CompareBenchmarkConfig, raw: Awaited>, -): FirstOutputBenchmarkArtifactV1 { +): FirstOutputBenchmarkArtifactV2 { const warmups = raw.warmups.map((pair, index) => toPairResult(pair, index + 1), ); @@ -2148,13 +2144,20 @@ function buildPairedArtifact( }; } +function coldWarmProviderDeltas( + runs: readonly FirstOutputProcessRunResult[], +): number[] { + const deltas: number[] = []; + for (const run of runs.filter(isSuccessfulRun)) { + const coldMs = metricForOrdinal(run, 1, 'promptToProviderRequestArrivalMs'); + const warmMs = metricForOrdinal(run, 2, 'promptToProviderRequestArrivalMs'); + if (coldMs !== null && warmMs !== null) deltas.push(coldMs - warmMs); + } + return deltas; +} + function isSuccessfulRun(run: FirstOutputProcessRunResult): boolean { - return ( - run.failure === null && - run.cleanup.failure === null && - run.sessions.length === SINGLE_SESSIONS_PER_PROCESS && - run.sessions.every((session) => session.runEligible) - ); + return isSuccessfulProcessSample(run, SINGLE_SESSIONS_PER_PROCESS); } function countRunFailures( @@ -2180,7 +2183,7 @@ function countPairFailures( function buildFatalArtifact( failure: FirstOutputFailure, -): FirstOutputBenchmarkArtifactV1 { +): FirstOutputBenchmarkArtifactV2 { const hasSingle = Boolean(process.env['BENCHMARK_CLI_PATH']?.trim()); const hasPaired = Boolean( process.env['BENCHMARK_CONTROL_CLI_PATH']?.trim() || @@ -2278,7 +2281,7 @@ async function cleanupActiveResources(): Promise { it( 'records a single baseline or balanced paired comparison', async () => { - let artifact: FirstOutputBenchmarkArtifactV1 | undefined; + let artifact: FirstOutputBenchmarkArtifactV2 | undefined; let runError: unknown; let configResolved = false; try { @@ -2300,7 +2303,7 @@ async function cleanupActiveResources(): Promise { if (artifact) { writeSnapshotArtifacts( OUTPUT_DIR, - 'daemon-first-output-benchmark-v1', + 'daemon-first-output-benchmark-v2', artifact, renderFirstOutputBenchmarkMarkdown(artifact), 'first-output-benchmark', diff --git a/integration-tests/fake-openai-server.test.ts b/integration-tests/fake-openai-server.test.ts index bbc15e3a73a..495705f6c77 100644 --- a/integration-tests/fake-openai-server.test.ts +++ b/integration-tests/fake-openai-server.test.ts @@ -110,6 +110,26 @@ describe('fake OpenAI server', () => { await response.text(); }); + it('closes non-streaming response connections when keepAlive is disabled', async () => { + server = await startFakeOpenAIServer(() => ({ content: 'no reuse' }), { + keepAlive: false, + }); + + const response = await fetch(`${server.baseUrl}/chat/completions`, { + method: 'POST', + headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ + model: 'fake-model', + stream: false, + messages: [{ role: 'user', content: 'hi' }], + }), + }); + + expect(response.status).toBe(200); + expect(response.headers.get('connection')).toBe('close'); + await response.text(); + }); + it('preserves a caller-requested close for default non-streaming responses', async () => { server = await startFakeOpenAIServer(() => ({ content: 'closed' })); diff --git a/integration-tests/vitest.config.ts b/integration-tests/vitest.config.ts index e7b0e0e5ce6..00a99473415 100644 --- a/integration-tests/vitest.config.ts +++ b/integration-tests/vitest.config.ts @@ -22,6 +22,7 @@ export default defineConfig({ '**/terminal-bench/*.test.ts', '**/hook-integration/**', '**/qwen-daemon-loadtest*', + '**/qwen-daemon-first-output-benchmark*', '**/node_modules/**', ], retry: 2, diff --git a/integration-tests/vitest.firstoutput.config.ts b/integration-tests/vitest.firstoutput.config.ts new file mode 100644 index 00000000000..2731ece8c2c --- /dev/null +++ b/integration-tests/vitest.firstoutput.config.ts @@ -0,0 +1,32 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { defineConfig } from 'vitest/config'; +import { dirname, resolve } from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const __dirname = dirname(fileURLToPath(import.meta.url)); + +export default defineConfig({ + test: { + // The benchmark supplies its own per-test timeout, which overrides this. + testTimeout: 10 * 60 * 1000, + root: __dirname, + globalSetup: './globalSetup.ts', + reporters: ['default'], + include: ['**/qwen-daemon-first-output-benchmark.test.ts'], + retry: 0, + fileParallelism: false, + }, + resolve: { + alias: { + '@qwen-code/sdk': resolve( + __dirname, + '../packages/sdk-typescript/dist/index.mjs', + ), + }, + }, +});