From c06bf64b4873a3040045aa0482be3ba85bf92559 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sat, 25 Jul 2026 20:06:19 -0700 Subject: [PATCH] test(e2e): make Codex typing-latency harness measure real echo latency (#10660) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * test(e2e): make Codex typing-latency harness measure real echo latency The local Codex typing-latency spec produced meaningless numbers. Four defects, all fixed here: 1. False-positive readiness. `/Ask Codex|OpenAI/i` matched "OpenAI's command-line coding agent" on the *sign-in* screen, so the test went "ready" against a login prompt and measured typing into a non-composer. Now gated on the composer status bar (`/Context \d+% used/i`), which only the live composer draws. Banner text is unusable: the serialized buffer interleaves ANSI escapes through those glyphs. 2. Missing auth. The E2E profile runs an isolated HOME with a managed CODEX_HOME that has no auth.json, guaranteeing the sign-in screen. The launch now pins the real ~/.codex, and skips with a clear message when auth.json is absent instead of silently measuring a login screen. 3. Measurement overhead swamped the signal. Per-key latency was measured by polling getTerminalContent() every 5ms, so each sample was real echo latency + full buffer serialize + CDP round-trip + poll granularity. Measurement now happens entirely in-renderer: an in-page hook stamps performance.now() on keydown (window capture phase, before xterm forwards to the PTY) and again in xterm's onWriteParsed once the glyph is in the viewport, with onRender giving a separate time-to-paint. Samples are drained in one page.evaluate after typing ends — zero CDP round-trips inside the measured window. 4. Thresholds were meaningless (median<150ms / worst<500ms). Replaced with p50<35 / p95<60 / max<120, based on 10 local runs. Also: 60 keystrokes instead of 24 with the first 10 discarded as warmup, p50/p95/max instead of a lone median, lowercase-only input so the slash and file-mention popups can't perturb later keys, an assertion that no keystroke went unechoed, and a terminal dump on readiness failure. Measured (10 local runs, headless, real Codex 0.145.0): echo (key->parse) p50 21.6-22.6ms, p95 23.2-41.5ms, max 23.4-58.7ms paint (key->render) p50 25.5-32.9ms, p95 34.3-49.7ms A plain-shell control on the same probe reads p50 2.0ms / p95 3.0ms, confirming the ~22ms is Codex composer redraw cost rather than a harness floor — the old harness reported ~29-30ms for everything. Co-authored-by: Orca * test(e2e): widen Codex latency tail budgets and assert terminal focus Follow-up calibration over ~20 local runs: the per-key distribution is unimodal at p50 21.3-22.7ms with rare isolated spikes to ~90-125ms that are not a steady-state shift. Tail budgets move to p95<80 / max<150 so only a sustained regression fails; p50<35 still gates the steady state. Also assert the xterm helper textarea actually took focus. One run typed all 60 keys with only 5 parse events because focus was lost, which previously surfaced as an opaque sample-count mismatch. Co-authored-by: Orca --------- Co-authored-by: Orca --- .../e2e/codex-composer-echo-latency-probe.ts | 203 ++++++++++++++++++ ...erminal-codex-local-typing-latency.spec.ts | 156 +++++++++----- 2 files changed, 309 insertions(+), 50 deletions(-) create mode 100644 tests/e2e/codex-composer-echo-latency-probe.ts diff --git a/tests/e2e/codex-composer-echo-latency-probe.ts b/tests/e2e/codex-composer-echo-latency-probe.ts new file mode 100644 index 000000000..9fc9cabf2 --- /dev/null +++ b/tests/e2e/codex-composer-echo-latency-probe.ts @@ -0,0 +1,203 @@ +import type { Page } from '@stablyai/playwright-test' + +export type CodexEchoLatencySample = { + index: number + char: string + /** keydown -> xterm finished parsing the echoed glyph (real echo latency). */ + keyToParseMs: number + /** keydown -> xterm renderer painted the row carrying that glyph. */ + keyToRenderMs: number | null +} + +export type CodexEchoProbeReport = { + samples: CodexEchoLatencySample[] + keysObserved: number + parseEvents: number + renderEvents: number + cols: number + rows: number +} + +declare global { + // oxlint-disable-next-line typescript-eslint/consistent-type-definitions -- declaration merging requires interface + interface Window { + __codexEchoProbe?: { + report(): CodexEchoProbeReport + dispose(): void + } + } +} + +/** + * Installs an in-renderer echo-latency recorder on the active terminal pane. + * + * Why in-page: polling a serialized buffer over CDP adds serialize + IPC + + * poll-granularity cost to every sample, which swamped the signal it measured. + * Timestamps here are taken inside the renderer with performance.now(), so the + * measured window contains no cross-process work at all. + */ +export async function installCodexEchoLatencyProbe(page: Page, target: string): Promise { + await page.evaluate((target) => { + type PendingSample = { + index: number + char: string + expected: string + startedAt: number + parsedAt: number | null + } + + const state = window.__store?.getState() + const worktreeId = state?.activeWorktreeId + const tabId = + state?.activeTabType === 'terminal' + ? state.activeTabId + : worktreeId + ? (state?.activeTabIdByWorktree?.[worktreeId] ?? null) + : null + const manager = tabId ? window.__paneManagers?.get(tabId) : null + const pane = manager?.getActivePane?.() ?? manager?.getPanes?.()[0] ?? null + if (!pane) { + throw new Error('Codex echo probe: no active terminal pane') + } + const terminal = pane.terminal + if (typeof terminal.onWriteParsed !== 'function') { + throw new Error('Codex echo probe: xterm build has no onWriteParsed') + } + + const samples: CodexEchoLatencySample[] = [] + const awaitingRender: { sample: CodexEchoLatencySample; startedAt: number }[] = [] + // Why a queue, not one slot: a slow echo can still be outstanding when the + // next key is pressed, and a single slot silently discards that sample. + const pending: PendingSample[] = [] + let keysObserved = 0 + let parseEvents = 0 + let renderEvents = 0 + + // Why concatenated without a separator: a composer line that wraps splits the + // token across rows, and trailing-trimmed rows rejoin exactly at the break. + const viewportText = (): string => { + const buffer = terminal.buffer.active + let text = '' + for (let row = 0; row < terminal.rows; row += 1) { + text += buffer.getLine(buffer.viewportY + row)?.translateToString(true) ?? '' + } + return text + } + + const observeParse = (): void => { + parseEvents += 1 + if (pending.length === 0) { + return + } + const text = viewportText() + // Why drain in order: one parse can land several queued keystrokes at + // once, and each still gets credited against its own keydown timestamp. + while (pending.length > 0 && text.includes(pending[0].expected)) { + const entry = pending.shift() + if (!entry) { + break + } + entry.parsedAt = performance.now() + const sample: CodexEchoLatencySample = { + index: entry.index, + char: entry.char, + keyToParseMs: entry.parsedAt - entry.startedAt, + keyToRenderMs: null + } + samples.push(sample) + awaitingRender.push({ sample, startedAt: entry.startedAt }) + } + } + + const observeRender = (): void => { + renderEvents += 1 + const paintedAt = performance.now() + for (const entry of awaitingRender.splice(0, awaitingRender.length)) { + entry.sample.keyToRenderMs = paintedAt - entry.startedAt + } + } + + // Why window capture: a listener on an ancestor in the capture phase is + // guaranteed to run before xterm's own keydown handler forwards to the PTY, + // so t0 is stamped before any of the work being measured starts. + const onKeyDown = (event: KeyboardEvent): void => { + if (event.key.length !== 1 || keysObserved >= target.length) { + return + } + const index = keysObserved + keysObserved += 1 + pending.push({ + index, + char: target[index], + expected: target.slice(0, index + 1), + startedAt: performance.now(), + parsedAt: null + }) + } + + window.addEventListener('keydown', onKeyDown, { capture: true }) + const parsedDisposable = terminal.onWriteParsed(observeParse) + const renderDisposable = terminal.onRender(observeRender) + + window.__codexEchoProbe = { + report: () => ({ + samples: [...samples], + keysObserved, + parseEvents, + renderEvents, + cols: terminal.cols, + rows: terminal.rows + }), + dispose: () => { + window.removeEventListener('keydown', onKeyDown, { capture: true }) + parsedDisposable.dispose() + renderDisposable.dispose() + } + } + }, target) +} + +/** Drains every recorded sample in a single round-trip once typing has finished. */ +export async function collectCodexEchoLatencyReport(page: Page): Promise { + return page.evaluate(() => { + const probe = window.__codexEchoProbe + if (!probe) { + throw new Error('Codex echo probe was never installed') + } + const report = probe.report() + probe.dispose() + return report + }) +} + +export type LatencyDistribution = { + count: number + p50: number + p95: number + max: number +} + +function percentile(sorted: number[], quantile: number): number { + if (sorted.length === 0) { + return 0 + } + const rank = Math.min(sorted.length - 1, Math.ceil(quantile * sorted.length) - 1) + return sorted[Math.max(0, rank)] +} + +export function summarizeLatencies(values: number[]): LatencyDistribution { + const sorted = [...values].sort((a, b) => a - b) + return { + count: sorted.length, + p50: percentile(sorted, 0.5), + p95: percentile(sorted, 0.95), + max: sorted.at(-1) ?? 0 + } +} + +export function formatDistribution(label: string, distribution: LatencyDistribution): string { + return ( + `${label} n=${distribution.count} p50=${distribution.p50.toFixed(1)}ms ` + + `p95=${distribution.p95.toFixed(1)}ms max=${distribution.max.toFixed(1)}ms` + ) +} diff --git a/tests/e2e/terminal-codex-local-typing-latency.spec.ts b/tests/e2e/terminal-codex-local-typing-latency.spec.ts index e0bb08eb3..e738e6070 100644 --- a/tests/e2e/terminal-codex-local-typing-latency.spec.ts +++ b/tests/e2e/terminal-codex-local-typing-latency.spec.ts @@ -1,5 +1,5 @@ import type { Page } from '@stablyai/playwright-test' -import { randomUUID } from 'node:crypto' +import { existsSync } from 'node:fs' import path from 'node:path' import { test, expect } from './helpers/orca-app' import { ensureTerminalVisible, waitForActiveWorktree, waitForSessionReady } from './helpers/store' @@ -13,18 +13,45 @@ import { analyzeRasterCursorCells, type TerminalRasterProbeTarget } from './terminal-cursor-raster-probe' +import { + collectCodexEchoLatencyReport, + formatDistribution, + installCodexEchoLatencyProbe, + summarizeLatencies +} from './codex-composer-echo-latency-probe' -const CODEX_READY_RE = /Ask Codex|OpenAI/i +// Why: only the live composer draws this status bar. Banner text like "OpenAI's +// command-line coding agent" also renders on the sign-in screen, and the +// serialized buffer interleaves ANSI codes through the banner glyphs. +const CODEX_COMPOSER_READY_RE = /Context \d+% used/i +const CODEX_SIGN_IN_RE = /Sign in with ChatGPT|Sign in to|press Enter to log in/i const CODEX_TRUST_PROMPT_RE = /Do you trust|trust this folder|Trust this/i const CODEX_UPDATE_PROMPT_RE = /update available|install update|Skip for now/i -const MAX_MEDIAN_KEY_LATENCY_MS = 150 -const MAX_WORST_KEY_LATENCY_MS = 500 +// Why lowercase ASCII only: digits/punctuation trigger the composer's slash and +// file-mention popups, which redraw the whole pane and skew later keystrokes. +const TYPING_ALPHABET = 'abcdefghijklmnopqrstuvwxyz' +const TOTAL_KEYSTROKES = 60 +// Why: the first keystrokes pay one-time costs (composer first-paint, WebGL +// atlas fill), so they measure startup rather than steady-state typing. +const WARMUP_KEYSTROKES = 10 +const KEYSTROKE_INTERVAL_MS = 60 +const TERMINAL_DUMP_CHARS = 4_000 +// Why these budgets: ~20 local runs put p50 in a tight 21.5-22.6ms band with a +// unimodal per-key distribution and rare isolated spikes to ~90ms. p50 gates the +// steady state at ~1.6x observed; the tail budgets absorb those spikes so only a +// sustained shift fails. A plain-shell control on this same probe reads p50 2ms, +// so the ~22ms is Codex composer redraw cost, not harness overhead. +const MAX_P50_ECHO_LATENCY_MS = 35 +const MAX_P95_ECHO_LATENCY_MS = 80 +const MAX_WORST_ECHO_LATENCY_MS = 150 type CodexCursorBlinkSample = { elapsedMs: number paintedCursorCellCount: number } +// Why the focus assert: a run that types into an unfocused pane records zero +// echoes and would otherwise fail as an opaque "sample count" mismatch. async function focusActiveTerminalInput(page: Page): Promise { await page.evaluate(() => { const state = window.__store?.getState() @@ -43,6 +70,11 @@ async function focusActiveTerminalInput(page: Page): Promise { } pane.terminal.focus() textarea.focus() + if (document.activeElement !== textarea) { + throw new Error( + 'Terminal helper textarea did not take focus; keystrokes would not reach Codex' + ) + } }) } @@ -121,10 +153,10 @@ async function sampleCursorBlink(page: Page): Promise } async function dismissCodexPromptsIfPresent(page: Page): Promise { - const deadline = Date.now() + 15_000 + const deadline = Date.now() + 20_000 while (Date.now() < deadline) { - const content = await getTerminalContent(page, 12_000) - if (CODEX_READY_RE.test(content) && !CODEX_TRUST_PROMPT_RE.test(content)) { + const content = await getTerminalContent(page, TERMINAL_DUMP_CHARS) + if (CODEX_COMPOSER_READY_RE.test(content)) { return } if (CODEX_TRUST_PROMPT_RE.test(content)) { @@ -142,29 +174,23 @@ async function dismissCodexPromptsIfPresent(page: Page): Promise { } } -async function waitForCodexReady(page: Page): Promise { - await expect - .poll(async () => CODEX_READY_RE.test(await getTerminalContent(page, 12_000)), { - timeout: 45_000, - message: 'Codex TUI did not render' - }) - .toBe(true) -} - -async function waitForPromptText(page: Page, text: string): Promise { - const start = performance.now() - while (performance.now() - start < MAX_WORST_KEY_LATENCY_MS) { - if ((await getTerminalContent(page, 12_000)).includes(text)) { - return performance.now() - start +// Why the dump: a run that "went ready" on the sign-in screen produced garbage +// numbers silently before; failures must show what the pane actually rendered. +async function waitForCodexComposer(page: Page): Promise { + const deadline = Date.now() + 60_000 + let lastContent = '' + while (Date.now() < deadline) { + lastContent = await getTerminalContent(page, TERMINAL_DUMP_CHARS) + const readyMarker = CODEX_COMPOSER_READY_RE.exec(lastContent) + if (readyMarker) { + return readyMarker[0] } - await page.waitForTimeout(5) + await page.waitForTimeout(250) } - throw new Error(`Codex prompt did not show ${text}`) -} - -function median(values: number[]): number { - const sorted = [...values].sort((a, b) => a - b) - return sorted[Math.floor(sorted.length / 2)] ?? 0 + const reason = CODEX_SIGN_IN_RE.test(lastContent) + ? 'Codex stopped on the sign-in screen — CODEX_HOME auth was not visible to the TUI' + : 'Codex never reached the composer' + throw new Error(`${reason}\n--- terminal tail ---\n${lastContent.slice(-1_500)}\n--- end ---`) } test.describe('local Codex terminal typing latency', () => { @@ -175,45 +201,71 @@ test.describe('local Codex terminal typing latency', () => { ) test.skip(process.platform === 'win32', 'local Codex command is POSIX-shell oriented') + const homeDir = process.env.HOME ?? '' + const codexSource = path.join(homeDir, 'projects', 'codex') + // Why: the E2E profile runs an isolated HOME with a managed CODEX_HOME that + // has no auth.json, so an unpinned launch lands on the sign-in screen. + const realCodexHome = path.join(homeDir, '.codex') + test.skip( + !existsSync(path.join(realCodexHome, 'auth.json')), + 'Codex auth.json is missing; the TUI would render the sign-in screen instead of a composer' + ) + test.skip(!existsSync(codexSource), 'local Codex checkout is missing') + await waitForSessionReady(orcaPage) await waitForActiveWorktree(orcaPage) await ensureTerminalVisible(orcaPage) await waitForActiveTerminalManager(orcaPage, 30_000) const ptyId = await waitForActivePanePtyId(orcaPage) - const codexSource = path.join(process.env.HOME ?? '', 'projects', 'codex') const launchCommand = - `cd ${JSON.stringify(codexSource)} && ` + + `cd ${JSON.stringify(codexSource)} && CODEX_HOME=${JSON.stringify(realCodexHome)} ` + 'codex --dangerously-bypass-approvals-and-sandbox --dangerously-bypass-hook-trust\r' try { await sendToTerminal(orcaPage, ptyId, launchCommand) await dismissCodexPromptsIfPresent(orcaPage) - await waitForCodexReady(orcaPage) + const composerMarker = await waitForCodexComposer(orcaPage) + testInfo.annotations.push({ + type: 'codex-composer-ready-marker', + description: composerMarker + }) await focusActiveTerminalInput(orcaPage) await forceCursorProbeTheme(orcaPage) const blinkSamples = await sampleCursorBlink(orcaPage) + await focusActiveTerminalInput(orcaPage) - const runId = randomUUID().replaceAll('-', '').slice(0, 8) - const prompt = `orca_codex_latency_${runId}` - const latencies: number[] = [] - let typed = '' - for (const char of prompt) { - typed += char - const start = performance.now() + const typed = Array.from( + { length: TOTAL_KEYSTROKES }, + (_value, index) => TYPING_ALPHABET[index % TYPING_ALPHABET.length] + ).join('') + await installCodexEchoLatencyProbe(orcaPage, typed) + for (const char of typed) { await orcaPage.keyboard.type(char) - await waitForPromptText(orcaPage, typed) - latencies.push(performance.now() - start) + // Why: spacing keys past one frame keeps each sample an isolated echo + // instead of measuring a burst the scheduler coalesced into one write. + await orcaPage.waitForTimeout(KEYSTROKE_INTERVAL_MS) } + // Why: the last keystroke's echo can still be in flight when typing ends. + await orcaPage.waitForTimeout(1_000) + const report = await collectCodexEchoLatencyReport(orcaPage) - const medianLatency = median(latencies) - const worstLatency = Math.max(...latencies) - testInfo.annotations.push({ - type: 'codex-local-typing-latency', - description: `median=${medianLatency.toFixed(1)}ms worst=${worstLatency.toFixed( - 1 - )}ms samples=${latencies.map((value) => value.toFixed(1)).join(',')}` - }) + const measured = report.samples.filter((sample) => sample.index >= WARMUP_KEYSTROKES) + const parseLatencies = measured.map((sample) => sample.keyToParseMs) + const renderLatencies = measured + .map((sample) => sample.keyToRenderMs) + .filter((value): value is number => value !== null) + const echo = summarizeLatencies(parseLatencies) + const painted = summarizeLatencies(renderLatencies) + + const summary = + `${formatDistribution('echo(key->parse)', echo)} | ` + + `${formatDistribution('paint(key->render)', painted)} | ` + + `keys=${report.keysObserved} parseEvents=${report.parseEvents}` + testInfo.annotations.push({ type: 'codex-local-typing-latency', description: summary }) + // Why stdout too: annotations are invisible in the default list reporter, + // and these numbers are the whole point of the run. + console.log(`[codex-typing-latency] ready="${composerMarker}" ${summary}`) testInfo.annotations.push({ type: 'codex-local-cursor-blink', description: blinkSamples @@ -223,8 +275,12 @@ test.describe('local Codex terminal typing latency', () => { expect(blinkSamples.some((sample) => sample.paintedCursorCellCount > 0)).toBe(true) expect(blinkSamples.some((sample) => sample.paintedCursorCellCount === 0)).toBe(true) - expect(medianLatency).toBeLessThan(MAX_MEDIAN_KEY_LATENCY_MS) - expect(worstLatency).toBeLessThan(MAX_WORST_KEY_LATENCY_MS) + // Why: a dropped keystroke means the composer stopped echoing, which the + // latency percentiles alone would silently hide. + expect(report.samples.length).toBe(TOTAL_KEYSTROKES) + expect(echo.p50).toBeLessThan(MAX_P50_ECHO_LATENCY_MS) + expect(echo.p95).toBeLessThan(MAX_P95_ECHO_LATENCY_MS) + expect(echo.max).toBeLessThan(MAX_WORST_ECHO_LATENCY_MS) } finally { await sendToTerminal(orcaPage, ptyId, '\x03').catch(() => undefined) }