test(e2e): make Codex typing-latency harness measure real echo latency (#10660)

* 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 <help@stably.ai>

* 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 <help@stably.ai>

---------

Co-authored-by: Orca <help@stably.ai>
This commit is contained in:
Neil 2026-07-25 20:06:19 -07:00 committed by GitHub
parent ae614443b4
commit c06bf64b48
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 309 additions and 50 deletions

View File

@ -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<void> {
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<CodexEchoProbeReport> {
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`
)
}

View File

@ -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<void> {
await page.evaluate(() => {
const state = window.__store?.getState()
@ -43,6 +70,11 @@ async function focusActiveTerminalInput(page: Page): Promise<void> {
}
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<CodexCursorBlinkSample[]>
}
async function dismissCodexPromptsIfPresent(page: Page): Promise<void> {
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<void> {
}
}
async function waitForCodexReady(page: Page): Promise<void> {
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<number> {
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<string> {
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)
}