diff --git a/integration-tests/cli/_daemon-benchmark-helpers.ts b/integration-tests/cli/_daemon-benchmark-helpers.ts index 16cd95fc59..202d2d506e 100644 --- a/integration-tests/cli/_daemon-benchmark-helpers.ts +++ b/integration-tests/cli/_daemon-benchmark-helpers.ts @@ -30,6 +30,7 @@ import { sleep, DEFAULT_CLI_BIN, DEFAULT_TOKEN, + LISTENING_LINE_RE, type SpawnDaemonOptions, type SpawnedDaemon, } from './_daemon-harness.js'; @@ -336,7 +337,6 @@ export async function spawnDaemonWithTime( stderrBuf.value += chunk.toString(); }); - const LISTENING_RE = /listening on http:\/\/127\.0\.0\.1:(\d+)/; const port = await new Promise((resolve, reject) => { let settled = false; const cleanup = () => { @@ -361,12 +361,12 @@ export async function spawnDaemonWithTime( ); }, bootTimeoutMs); const onData = () => { - const m = stdoutBuf.value.match(LISTENING_RE); - if (m && !settled) { - settled = true; - cleanup(); - resolve(Number(m[1])); - } + const matchedPort = + stdoutBuf.value.match(LISTENING_LINE_RE)?.groups?.['port']; + if (!matchedPort || settled) return; + settled = true; + cleanup(); + resolve(Number(matchedPort)); }; const onExit = (code: number | null) => { fail( diff --git a/integration-tests/cli/_daemon-harness.ts b/integration-tests/cli/_daemon-harness.ts index 869c18f2af..5d8e4d85e7 100644 --- a/integration-tests/cli/_daemon-harness.ts +++ b/integration-tests/cli/_daemon-harness.ts @@ -89,7 +89,8 @@ export interface SpawnedDaemon { dispose: () => Promise; } -const LISTENING_RE = /listening on http:\/\/127\.0\.0\.1:(\d+)/; +export const LISTENING_LINE_RE = + /^(?.*listening on http:\/\/127\.0\.0\.1:(?\d+).*)$/m; const DISPOSE_GRACE_MS = 5_000; const MATCHED_DESCENDANT_DEPTH = 4; @@ -160,13 +161,11 @@ export async function spawnDaemon( ); }, bootTimeoutMs); const onData = (_chunk: Buffer) => { - const m = stdoutBuf.value.match(LISTENING_RE); - if (m) { - if (settled) return; - settled = true; - cleanup(); - resolve(Number(m[1])); - } + const port = stdoutBuf.value.match(LISTENING_LINE_RE)?.groups?.['port']; + if (!port || settled) return; + settled = true; + cleanup(); + resolve(Number(port)); }; const onExit = (code: number | null) => { fail( diff --git a/integration-tests/cli/qwen-daemon-startup-benchmark.test.ts b/integration-tests/cli/qwen-daemon-startup-benchmark.test.ts new file mode 100644 index 0000000000..afd7eb13f4 --- /dev/null +++ b/integration-tests/cli/qwen-daemon-startup-benchmark.test.ts @@ -0,0 +1,504 @@ +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * qwen serve daemon startup benchmark. + * + * Measures only the cold path from spawning the built CLI to the HTTP + * listener-ready stdout line. It intentionally does not create a session, so + * ACP/runtime preheat cost remains observed but not part of the primary + * listener-ready latency. + * + * Gated by QWEN_BENCHMARK_ENABLED=1 and writes JSON/Markdown artifacts to the + * integration test output directory. + */ + +import { spawn, type ChildProcess } from 'node:child_process'; +import * as fs from 'node:fs'; +import * as path from 'node:path'; +import { performance } from 'node:perf_hooks'; +import { afterAll, describe, expect, it } from 'vitest'; + +import type { + DaemonStartupPreheatStatus, + DaemonStartupSnapshot, +} from '../../packages/cli/src/serve/daemon-status.js'; +import { + DEFAULT_REPO_ROOT, + gitHead, + LISTENING_LINE_RE, + makeTempWorkspace, + percentiles, + sleep, + type Percentiles, +} from './_daemon-harness.js'; +import { + collectPlatformInfo, + formatPercentiles, + resolveOutputDir, + writeSnapshotArtifacts, +} from './_daemon-perf-report.js'; + +const SANDBOX_ENABLED = Boolean( + process.env['QWEN_SANDBOX'] && + process.env['QWEN_SANDBOX'].toLowerCase() !== 'false', +); +const SKIP = + process.env['QWEN_BENCHMARK_ENABLED'] !== '1' || + SANDBOX_ENABLED || + process.platform === 'win32'; + +const ITERATIONS = Number(process.env['BENCHMARK_ITERATIONS'] ?? 5); +const WARMUP_ITERATIONS = Number( + process.env['BENCHMARK_WARMUP_ITERATIONS'] ?? 1, +); +const BOOT_TIMEOUT_MS = Number( + process.env['BENCHMARK_BOOT_TIMEOUT_MS'] ?? 15_000, +); +const EXTERNAL_P99_MAX_MS = Number( + process.env['BENCHMARK_DAEMON_STARTUP_P99_MAX_MS'] ?? 15_000, +); +const PROCESS_P99_MAX_MS = Number( + process.env['BENCHMARK_PROCESS_P99_MAX_MS'] ?? 5_000, +); +const RUN_SERVE_P99_MAX_MS = Number( + process.env['BENCHMARK_RUN_SERVE_P99_MAX_MS'] ?? 5_000, +); +const STATUS_FETCH_TIMEOUT_MS = Number( + process.env['BENCHMARK_DAEMON_STATUS_TIMEOUT_MS'] ?? 5_000, +); +const STDERR_TIMING_TIMEOUT_MS = Number( + process.env['BENCHMARK_STDERR_TIMING_TIMEOUT_MS'] ?? + Math.max(2_000, Math.ceil(BOOT_TIMEOUT_MS / 5)), +); + +const OUTPUT_DIR = resolveOutputDir('daemon-startup'); +const TOKEN = 'daemon-startup-benchmark-token'; +// Prefer the bundled root CLI because this benchmark targets the packaged +// `qwen serve` entrypoint; TEST_CLI_PATH can still override it. +const CLI_BIN = + process.env['TEST_CLI_PATH'] ?? + path.resolve(DEFAULT_REPO_ROOT, 'dist/cli.js'); +const PREHEAT_STATUS_SET: Record = { + external_bridge: true, + not_scheduled: true, + scheduled: true, + running: true, + succeeded: true, + failed: true, +}; +const PREHEAT_STATUSES = Object.keys( + PREHEAT_STATUS_SET, +) as DaemonStartupPreheatStatus[]; + +interface DaemonStatusResponse { + daemon?: { + startup?: DaemonStartupSnapshot; + }; +} + +interface StartupRun { + iteration: number; + measured: boolean; + externalCommandToListeningMs: number; + processToListenMs: number; + runQwenServeToListenMs: number; + preheatStatus: DaemonStartupPreheatStatus; + port: number; + stdoutListeningLine: string; +} + +interface StartupBenchmarkSnapshot { + version: 1; + capturedAt: string; + gitCommit: string | null; + platform: { os: string; arch: string; nodeVersion: string }; + cliBin: string; + config: { + iterations: number; + warmupIterations: number; + bootTimeoutMs: number; + externalP99MaxMs: number; + processP99MaxMs: number; + runServeP99MaxMs: number; + statusFetchTimeoutMs: number; + stderrTimingTimeoutMs: number; + }; + notes: string[]; + runs: StartupRun[]; + externalCommandToListening?: Percentiles; + processToListen?: Percentiles; + runQwenServeToListen?: Percentiles; +} + +const snapshot: StartupBenchmarkSnapshot = { + version: 1, + capturedAt: new Date().toISOString(), + gitCommit: gitHead(), + platform: collectPlatformInfo(), + cliBin: CLI_BIN, + config: { + iterations: ITERATIONS, + warmupIterations: WARMUP_ITERATIONS, + bootTimeoutMs: BOOT_TIMEOUT_MS, + externalP99MaxMs: EXTERNAL_P99_MAX_MS, + processP99MaxMs: PROCESS_P99_MAX_MS, + runServeP99MaxMs: RUN_SERVE_P99_MAX_MS, + statusFetchTimeoutMs: STATUS_FETCH_TIMEOUT_MS, + stderrTimingTimeoutMs: STDERR_TIMING_TIMEOUT_MS, + }, + notes: [ + 'Measures built CLI `qwen serve` cold startup to the stdout listening line.', + 'Runs the default daemon path except for ephemeral port, loopback host, explicit workspace, and --no-open.', + 'Does not create a session; preheat state is recorded but not included in the primary listener-ready metric.', + 'Validates stderr startup timing and /daemon/status startup fields for each run.', + ], + runs: [], +}; + +const STDERR_TIMING_RE = + /qwen serve: startup timing: processToListenMs=(\d+) runQwenServeToListenMs=(\d+)/; + +function signalChildTree(child: ChildProcess, signal: NodeJS.Signals): void { + if (!child.pid) return; + try { + process.kill(process.platform === 'win32' ? child.pid : -child.pid, signal); + } catch { + try { + child.kill(signal); + } catch { + /* already gone */ + } + } +} + +function childHasExited(child: ChildProcess): boolean { + return child.exitCode !== null || child.signalCode !== null; +} + +async function terminate(child: ChildProcess): Promise { + const exited = new Promise((resolve) => { + if (childHasExited(child)) { + resolve(true); + return; + } + child.once('exit', () => resolve(true)); + }); + signalChildTree(child, 'SIGTERM'); + if (await Promise.race([exited, sleep(250).then(() => false)])) { + return; + } + signalChildTree(child, 'SIGKILL'); + await Promise.race([exited, sleep(750)]); +} + +async function waitForStderrTiming( + stderr: () => string, +): Promise { + const deadline = performance.now() + STDERR_TIMING_TIMEOUT_MS; + while (performance.now() < deadline) { + const match = stderr().match(STDERR_TIMING_RE); + if (match) return match; + await new Promise((resolve) => setTimeout(resolve, 10)); + } + const match = stderr().match(STDERR_TIMING_RE); + if (match) return match; + throw new Error( + `startup timing line missing from stderr after ` + + `${STDERR_TIMING_TIMEOUT_MS}ms:\n${stderr()}`, + ); +} + +async function runStartupIteration( + iteration: number, + measured: boolean, +): Promise { + const workspace = makeTempWorkspace( + `${iteration}`, + 'qwen-daemon-startup-benchmark', + ); + const startedAt = performance.now(); + let stdout = ''; + let stderr = ''; + let child: ChildProcess | undefined; + const { VITEST_WORKER_ID: _vitestWorkerId, ...childEnv } = process.env; + + try { + // Keep this separate from spawnDaemon(): the benchmark needs the wall + // clock to include Node process creation, raw stderr for the timing-line + // assertion, and tighter sample-to-sample teardown. + child = spawn( + process.execPath, + [ + CLI_BIN, + 'serve', + '--port', + '0', + '--hostname', + '127.0.0.1', + '--workspace', + workspace, + '--no-open', + ], + { + stdio: ['ignore', 'pipe', 'pipe'], + detached: process.platform !== 'win32', + env: { + ...childEnv, + CI: '1', + NO_COLOR: '1', + QWEN_CODE_PROFILE_STARTUP: '0', + QWEN_CODE_PROFILE_STARTUP_OUTER: '0', + QWEN_CODE_SUPPRESS_YOLO_WARNING: '1', + QWEN_SERVER_TOKEN: TOKEN, + }, + }, + ); + + child.stderr?.on('data', (chunk: Buffer) => { + stderr += chunk.toString(); + }); + + const listening = await new Promise<{ + line: string; + port: number; + externalCommandToListeningMs: number; + }>((resolve, reject) => { + let settled = false; + const cleanup = () => { + child?.stdout?.off('data', onStdout); + child?.off('exit', onExit); + clearTimeout(timer); + }; + const fail = (err: Error) => { + if (settled) return; + settled = true; + cleanup(); + reject(err); + }; + const onStdout = (chunk: Buffer) => { + stdout += chunk.toString(); + const match = stdout.match(LISTENING_LINE_RE); + const line = match?.groups?.['line']; + const port = match?.groups?.['port']; + if (!line || !port) return; + settled = true; + cleanup(); + resolve({ + line, + port: Number(port), + externalCommandToListeningMs: Math.round( + performance.now() - startedAt, + ), + }); + }; + const onExit = (code: number | null, signal: NodeJS.Signals | null) => { + fail( + new Error( + `daemon exited before listening: code=${code} signal=${signal}\n` + + `stdout=${stdout}\nstderr=${stderr}`, + ), + ); + }; + const timer = setTimeout(() => { + fail( + new Error( + `daemon startup timed out after ${BOOT_TIMEOUT_MS}ms\n` + + `stdout=${stdout}\nstderr=${stderr}`, + ), + ); + }, BOOT_TIMEOUT_MS); + child?.stdout?.on('data', onStdout); + child?.once('exit', onExit); + }); + + const timing = await waitForStderrTiming(() => stderr); + let status: DaemonStatusResponse; + try { + const statusUrl = `http://127.0.0.1:${listening.port}/daemon/status`; + const res = await fetch(statusUrl, { + headers: { authorization: `Bearer ${TOKEN}` }, + signal: AbortSignal.timeout(STATUS_FETCH_TIMEOUT_MS), + }); + if (!res.ok) { + throw new Error(`/daemon/status returned ${res.status}`); + } + status = (await res.json()) as DaemonStatusResponse; + } catch (err) { + throw new Error( + `/daemon/status fetch failed on iteration ${iteration} ` + + `(port ${listening.port}): ` + + `${err instanceof Error ? err.message : String(err)}`, + ); + } + + const startup = status.daemon?.startup; + const processToListenMs = startup?.processToListenMs; + const runQwenServeToListenMs = startup?.runQwenServeToListenMs; + const preheatStatus = startup?.preheat?.status; + + const validateStartupObservation = () => { + expect(startup?.processStartedAt).toEqual(expect.any(String)); + expect(startup?.listenerReadyAt).toEqual(expect.any(String)); + expect(processToListenMs).toEqual(Number(timing[1])); + expect(runQwenServeToListenMs).toEqual(Number(timing[2])); + expect(processToListenMs).toBeGreaterThanOrEqual(runQwenServeToListenMs!); + expect(startup?.preheat).toEqual(expect.any(Object)); + expect(preheatStatus).toEqual(expect.any(String)); + expect(PREHEAT_STATUSES).toContain(preheatStatus); + }; + if (measured) { + validateStartupObservation(); + } else { + try { + validateStartupObservation(); + } catch (err) { + console.warn( + `[daemon-startup] warmup ${iteration}: startup validation failed: ` + + `${err instanceof Error ? err.message : String(err)}`, + ); + } + } + + return { + iteration, + measured, + externalCommandToListeningMs: listening.externalCommandToListeningMs, + processToListenMs: processToListenMs ?? -1, + runQwenServeToListenMs: runQwenServeToListenMs ?? -1, + preheatStatus: preheatStatus ?? 'not_scheduled', + port: listening.port, + stdoutListeningLine: listening.line, + }; + } finally { + if (child) await terminate(child); + fs.rmSync(workspace, { recursive: true, force: true }); + } +} + +(SKIP ? describe.skip : describe)( + 'qwen serve daemon startup benchmark', + { retry: 0 }, + () => { + it( + 'measures built CLI startup to listener readiness', + async () => { + const total = WARMUP_ITERATIONS + ITERATIONS; + for (let i = 0; i < total; i++) { + const measured = i >= WARMUP_ITERATIONS; + const run = await runStartupIteration(i, measured); + snapshot.runs.push(run); + console.log( + `[daemon-startup] ${measured ? 'run' : 'warmup'} ${i}: ` + + `external=${run.externalCommandToListeningMs}ms ` + + `process=${run.processToListenMs}ms ` + + `runQwenServe=${run.runQwenServeToListenMs}ms ` + + `preheat=${run.preheatStatus}`, + ); + } + + const measuredRuns = snapshot.runs.filter((run) => run.measured); + snapshot.externalCommandToListening = percentiles( + measuredRuns.map((run) => run.externalCommandToListeningMs), + ); + snapshot.processToListen = percentiles( + measuredRuns.map((run) => run.processToListenMs), + ); + snapshot.runQwenServeToListen = percentiles( + measuredRuns.map((run) => run.runQwenServeToListenMs), + ); + + expect(snapshot.externalCommandToListening.count).toBe(ITERATIONS); + expect(snapshot.externalCommandToListening.p99).toBeLessThan( + EXTERNAL_P99_MAX_MS, + ); + expect(snapshot.processToListen.p99).toBeLessThan(PROCESS_P99_MAX_MS); + expect(snapshot.runQwenServeToListen.p99).toBeLessThan( + RUN_SERVE_P99_MAX_MS, + ); + }, + (WARMUP_ITERATIONS + ITERATIONS) * + (BOOT_TIMEOUT_MS + + STDERR_TIMING_TIMEOUT_MS + + STATUS_FETCH_TIMEOUT_MS + + 5_000), + ); + + afterAll(() => { + if (SKIP || snapshot.runs.length === 0) return; + + console.log('\n[daemon-startup] ---- summary ----'); + console.log( + ` External command -> listening: ${formatPercentiles( + snapshot.externalCommandToListening, + )}`, + ); + console.log( + ` process -> listening: ${formatPercentiles( + snapshot.processToListen, + )}`, + ); + console.log( + ` runQwenServe -> listening: ${formatPercentiles( + snapshot.runQwenServeToListen, + )}`, + ); + console.log('[daemon-startup] ---- end summary ----\n'); + + writeSnapshotArtifacts( + OUTPUT_DIR, + 'daemon-startup-benchmark', + snapshot, + renderMarkdown(snapshot), + 'daemon-startup', + ); + }); + }, +); + +function renderMarkdown(s: StartupBenchmarkSnapshot): string { + const lines = [ + '# qwen serve daemon startup benchmark', + '', + `Captured: ${s.capturedAt}`, + `Git: ${s.gitCommit ?? 'unknown'}`, + `Platform: ${s.platform.os}/${s.platform.arch} node=${s.platform.nodeVersion}`, + `CLI: ${s.cliBin}`, + `Iterations: ${s.config.iterations} Warmup: ${s.config.warmupIterations}`, + '', + `> ${s.notes.join(' ')}`, + '', + '## Summary', + '', + `- External command -> listening: ${formatPercentiles( + s.externalCommandToListening, + )}`, + `- process -> listening: ${formatPercentiles(s.processToListen)}`, + `- runQwenServe -> listening: ${formatPercentiles(s.runQwenServeToListen)}`, + '', + '## Runs', + '', + '| Iteration | Measured | External wall | processToListen | runQwenServeToListen | Preheat |', + '|---:|:---:|---:|---:|---:|---|', + ]; + + for (const run of s.runs) { + lines.push( + `| ${run.iteration} | ${run.measured ? 'yes' : 'warmup'} | ` + + `${run.externalCommandToListeningMs}ms | ${run.processToListenMs}ms | ` + + `${run.runQwenServeToListenMs}ms | ${run.preheatStatus} |`, + ); + } + + lines.push( + '', + '## Scope', + '', + 'This benchmark stops at the stdout listening line and does not create a daemon session. It records the preheat state visible at listen time, but preheat completion is not part of the primary metric. Use `qwen-daemon-vs-cli-benchmark.test.ts` for first-session, memory, and prompt metrics.', + '', + ); + return lines.join('\n'); +}