From e9cbe41152b2b6bbddc301ede681e353a0f4d9a8 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Wed, 29 Jul 2026 07:36:22 -0700 Subject: [PATCH] test(terminal): attribute typing stalls under load --- .../artificial-opencode-terminal-load.spec.ts | 90 +++----- .../artificial-opencode-typing-measurement.ts | 206 ++++++++++++++++++ 2 files changed, 234 insertions(+), 62 deletions(-) create mode 100644 tests/e2e/artificial-opencode-typing-measurement.ts diff --git a/tests/e2e/artificial-opencode-terminal-load.spec.ts b/tests/e2e/artificial-opencode-terminal-load.spec.ts index 9b937775a84..ba94c7ff71d 100644 --- a/tests/e2e/artificial-opencode-terminal-load.spec.ts +++ b/tests/e2e/artificial-opencode-terminal-load.spec.ts @@ -16,27 +16,17 @@ import { waitForActivePanePtyId, waitForActiveTerminalManager } from './helpers/terminal' +import { ensureActiveWorktreePaneLoad, focusPane } from './artificial-opencode-pane-interactions' import { - ensureActiveWorktreePaneLoad, - focusActiveTerminalInput, - focusPane, - waitForMarkerLatency, - waitForTerminalOutputForPtyId -} from './artificial-opencode-pane-interactions' + measureTerminalTypingDuringLoad, + type TypingMeasurement +} from './artificial-opencode-typing-measurement' import { runHiddenRealPtyPressureScenario } from './artificial-opencode-hidden-pressure-scenario' import type { HiddenPressureOutputMode } from './artificial-opencode-hidden-pressure-script' import { runMainPressureScenario } from './artificial-opencode-main-pressure-scenario' import { runRendererBackpressureRevisitScenario } from './artificial-opencode-revisit-pressure-scenario' import { startSyntheticOpenCodeInjection } from './artificial-opencode-synthetic-injection' -type TypingMeasurement = { - latencies: number[] - medianLatencyMs: number - worstLatencyMs: number - maxTimerDriftMs: number - frameCount: number -} - type SyntheticOpenCodeWindow = Window & { __terminalPtyDataInjection?: { inject: (paneKey: string, data: string) => boolean @@ -108,7 +98,6 @@ type MainPtyPressureDebugSnapshot = { pendingDroppedChars: number } -const KEY_LATENCY_SAMPLES = 'abcdefghijklmnop' const DEFAULT_SAME_WORKSPACE_PANES = 5 const DEFAULT_CROSS_WORKSPACE_PANES_PER_WORKTREE = 3 const DEFAULT_PRESSURE_BACKGROUND_PANES = 17 @@ -117,7 +106,6 @@ const DEFAULT_HIDDEN_PRESSURE_PANES = 17 const HIDDEN_PRESSURE_START_DELAY_MS = 1200 const DEFAULT_FRAME_COUNT = 180 const DEFAULT_FRAME_INTERVAL_MS = 6 -const TIMER_SAMPLE_MS = 16 const MAIN_RENDERER_PRESSURE_TARGET_CHARS = 2 * 1024 * 1024 // Why: these are regression budgets, not observed baselines. Repeated local // 100-pane OpenCode-scale runs are below 50ms worst-key latency; keep enough @@ -233,57 +221,13 @@ function writeInteractivePromptScript(scriptPath: string, runId: string): void { writeFileSync(scriptPath, interactivePromptScript(runId)) } -function median(values: number[]): number { - const sorted = [...values].sort((a, b) => a - b) - return sorted[Math.floor(sorted.length / 2)] ?? 0 -} - async function measureTypingDuringLoad( page: Page, scriptPath: string, ptyId: string, runId: string ): Promise { - await sendToTerminal(page, ptyId, `node ${JSON.stringify(scriptPath)}\r`) - await waitForTerminalOutputForPtyId(page, ptyId, `OPENCODE_TYPING_READY_${runId}`, 10_000) - await focusActiveTerminalInput(page) - - const eventLoop = await page.evaluateHandle((sampleMs) => { - let maxTimerDriftMs = 0 - let lastTick = performance.now() - const timer = window.setInterval(() => { - const now = performance.now() - maxTimerDriftMs = Math.max(maxTimerDriftMs, now - lastTick - sampleMs) - lastTick = now - }, sampleMs) - return { - stop: () => { - window.clearInterval(timer) - return maxTimerDriftMs - } - } - }, TIMER_SAMPLE_MS) - - const latencies: number[] = [] - for (const [index, char] of [...KEY_LATENCY_SAMPLES].entries()) { - const marker = `OPENCODE_TYPING_KEY_${runId}_${index + 1}` - const start = performance.now() - await page.keyboard.type(char) - // Why: wait up to the under-load budget so a slow echo is measured and - // asserted per-scenario, not thrown as a confusing "did not contain". - await waitForMarkerLatency(page, marker, MAX_WORST_KEY_LATENCY_UNDER_LOAD_MS) - latencies.push(performance.now() - start) - } - - const maxTimerDriftMs = await eventLoop.evaluate((watcher) => watcher.stop()) - await eventLoop.dispose() - return { - latencies, - medianLatencyMs: median(latencies), - worstLatencyMs: Math.max(...latencies), - maxTimerDriftMs, - frameCount: FRAME_COUNT - } + return measureTerminalTypingDuringLoad(page, scriptPath, ptyId, runId, FRAME_COUNT) } async function resetTerminalPtyOutputDebug(page: Page): Promise { @@ -388,7 +332,29 @@ function annotateTypingMeasurement( 1 )}ms worst=${measurement.worstLatencyMs.toFixed( 1 - )}ms maxTimerDrift=${measurement.maxTimerDriftMs.toFixed(1)}ms samples=${measurement.latencies + )}ms maxTimerDrift=${measurement.maxTimerDriftMs.toFixed( + 1 + )}ms controllerDrift=${measurement.controllerMaxTimerDriftMs.toFixed( + 1 + )}ms rendererLongTask=${measurement.rendererMaxLongTaskMs.toFixed( + 1 + )}ms rendererLongTaskSupported=${ + measurement.rendererLongTaskSupported + } rendererKeydowns=${measurement.rendererKeydownCount} typingElapsed=${measurement.elapsedMs.toFixed( + 1 + )}ms dispatchSamples=${measurement.dispatchLatencies + .map((value) => value.toFixed(1)) + .join(',')} echoSamples=${measurement.echoLatencies + .map((value) => value.toFixed(1)) + .join(',')} hostCpuBusy=${ + measurement.hostCpuBusyPercent == null + ? 'na' + : `${measurement.hostCpuBusyPercent.toFixed(1)}%` + } hostCpuPressureWait=${ + measurement.hostCpuPressureWaitMs == null + ? 'na' + : `${measurement.hostCpuPressureWaitMs.toFixed(1)}ms` + } samples=${measurement.latencies .map((value) => value.toFixed(1)) .join(',')}${mode2031Summary}${schedulerSummary}${mainPressureSummary}${ackGateSummary}` }) diff --git a/tests/e2e/artificial-opencode-typing-measurement.ts b/tests/e2e/artificial-opencode-typing-measurement.ts new file mode 100644 index 00000000000..3cf630e6e68 --- /dev/null +++ b/tests/e2e/artificial-opencode-typing-measurement.ts @@ -0,0 +1,206 @@ +import type { Page } from '@stablyai/playwright-test' +import { readFileSync } from 'node:fs' +import { performance } from 'node:perf_hooks' +import { + focusActiveTerminalInput, + waitForMarkerLatency, + waitForTerminalOutputForPtyId +} from './artificial-opencode-pane-interactions' +import { sendToTerminal } from './helpers/terminal' + +export type TypingMeasurement = { + latencies: number[] + dispatchLatencies: number[] + echoLatencies: number[] + medianLatencyMs: number + worstLatencyMs: number + maxTimerDriftMs: number + controllerMaxTimerDriftMs: number + rendererMaxLongTaskMs: number + rendererLongTaskSupported: boolean + rendererKeydownCount: number + hostCpuBusyPercent: number | null + hostCpuPressureWaitMs: number | null + elapsedMs: number + frameCount: number +} + +type HostCpuSnapshot = { + idleTicks: number + pressureWaitMicros: number | null + totalTicks: number +} + +const KEY_LATENCY_SAMPLES = 'abcdefghijklmnop' +const MAX_KEY_ECHO_LATENCY_MS = 3_000 +const TIMER_SAMPLE_MS = 16 + +function median(values: number[]): number { + const sorted = [...values].sort((a, b) => a - b) + return sorted[Math.floor(sorted.length / 2)] ?? 0 +} + +function readHostCpuSnapshot(): HostCpuSnapshot | null { + if (process.platform !== 'linux') { + return null + } + try { + const cpuFields = readFileSync('/proc/stat', 'utf8') + .split('\n')[0] + ?.trim() + .split(/\s+/) + .slice(1) + .map(Number) + if (!cpuFields || cpuFields.length < 4 || cpuFields.some((value) => !Number.isFinite(value))) { + return null + } + const pressureMatch = readFileSync('/proc/pressure/cpu', 'utf8').match( + /^some\s+.*\btotal=(\d+)$/m + ) + return { + idleTicks: cpuFields[3] + (cpuFields[4] ?? 0), + pressureWaitMicros: pressureMatch ? Number(pressureMatch[1]) : null, + totalTicks: cpuFields.reduce((total, value) => total + value, 0) + } + } catch { + return null + } +} + +function hostCpuDelta( + start: HostCpuSnapshot | null, + end: HostCpuSnapshot | null +): { + busyPercent: number | null + pressureWaitMs: number | null +} { + if (!start || !end) { + return { busyPercent: null, pressureWaitMs: null } + } + const totalTicks = end.totalTicks - start.totalTicks + const idleTicks = end.idleTicks - start.idleTicks + const pressureWaitMicros = + start.pressureWaitMicros == null || end.pressureWaitMicros == null + ? null + : end.pressureWaitMicros - start.pressureWaitMicros + return { + busyPercent: totalTicks > 0 ? ((totalTicks - idleTicks) / totalTicks) * 100 : null, + pressureWaitMs: pressureWaitMicros == null ? null : pressureWaitMicros / 1_000 + } +} + +function startControllerTimerDrift(): () => number { + let maxTimerDriftMs = 0 + let lastTick = performance.now() + const timer = setInterval(() => { + const now = performance.now() + maxTimerDriftMs = Math.max(maxTimerDriftMs, now - lastTick - TIMER_SAMPLE_MS) + lastTick = now + }, TIMER_SAMPLE_MS) + return () => { + clearInterval(timer) + return maxTimerDriftMs + } +} + +export async function measureTerminalTypingDuringLoad( + page: Page, + scriptPath: string, + ptyId: string, + runId: string, + frameCount: number +): Promise { + await sendToTerminal(page, ptyId, `node ${JSON.stringify(scriptPath)}\r`) + await waitForTerminalOutputForPtyId(page, ptyId, `OPENCODE_TYPING_READY_${runId}`, 10_000) + await focusActiveTerminalInput(page) + + const rendererWatcher = await page.evaluateHandle((sampleMs) => { + let maxTimerDriftMs = 0 + let maxLongTaskMs = 0 + let keydownCount = 0 + let lastTick = window.performance.now() + const timer = window.setInterval(() => { + const now = window.performance.now() + maxTimerDriftMs = Math.max(maxTimerDriftMs, now - lastTick - sampleMs) + lastTick = now + }, sampleMs) + const onKeydown = (): void => { + keydownCount += 1 + } + window.addEventListener('keydown', onKeydown, true) + const longTaskSupported = PerformanceObserver.supportedEntryTypes.includes('longtask') + const observer = longTaskSupported + ? new PerformanceObserver((list) => { + for (const entry of list.getEntries()) { + maxLongTaskMs = Math.max(maxLongTaskMs, entry.duration) + } + }) + : null + observer?.observe({ type: 'longtask' }) + return { + stop: () => { + window.clearInterval(timer) + window.removeEventListener('keydown', onKeydown, true) + for (const entry of observer?.takeRecords() ?? []) { + maxLongTaskMs = Math.max(maxLongTaskMs, entry.duration) + } + observer?.disconnect() + return { keydownCount, longTaskSupported, maxLongTaskMs, maxTimerDriftMs } + } + } + }, TIMER_SAMPLE_MS) + const stopControllerTimer = startControllerTimerDrift() + const hostCpuStart = readHostCpuSnapshot() + const measurementStart = performance.now() + const latencies: number[] = [] + const dispatchLatencies: number[] = [] + const echoLatencies: number[] = [] + let controllerMaxTimerDriftMs = 0 + let elapsedMs = 0 + let hostCpuEnd: HostCpuSnapshot | null = null + let rendererTiming = { + keydownCount: 0, + longTaskSupported: false, + maxLongTaskMs: 0, + maxTimerDriftMs: 0 + } + try { + for (const [index, char] of KEY_LATENCY_SAMPLES.split('').entries()) { + const marker = `OPENCODE_TYPING_KEY_${runId}_${index + 1}` + const start = performance.now() + await page.keyboard.type(char) + const dispatched = performance.now() + await waitForMarkerLatency(page, marker, MAX_KEY_ECHO_LATENCY_MS) + const completed = performance.now() + dispatchLatencies.push(dispatched - start) + echoLatencies.push(completed - dispatched) + latencies.push(completed - start) + } + } finally { + try { + rendererTiming = await rendererWatcher.evaluate((watcher) => watcher.stop()) + } finally { + controllerMaxTimerDriftMs = stopControllerTimer() + hostCpuEnd = readHostCpuSnapshot() + elapsedMs = performance.now() - measurementStart + await rendererWatcher.dispose() + } + } + const hostCpu = hostCpuDelta(hostCpuStart, hostCpuEnd) + return { + latencies, + dispatchLatencies, + echoLatencies, + medianLatencyMs: median(latencies), + worstLatencyMs: Math.max(...latencies), + maxTimerDriftMs: rendererTiming.maxTimerDriftMs, + controllerMaxTimerDriftMs, + rendererMaxLongTaskMs: rendererTiming.maxLongTaskMs, + rendererLongTaskSupported: rendererTiming.longTaskSupported, + rendererKeydownCount: rendererTiming.keydownCount, + hostCpuBusyPercent: hostCpu.busyPercent, + hostCpuPressureWaitMs: hostCpu.pressureWaitMs, + elapsedMs, + frameCount + } +}