diff --git a/src/main/diagnostics/event-loop-delay-probe.test.ts b/src/main/diagnostics/event-loop-delay-probe.test.ts new file mode 100644 index 00000000000..e7e7e70eec3 --- /dev/null +++ b/src/main/diagnostics/event-loop-delay-probe.test.ts @@ -0,0 +1,56 @@ +import { existsSync, mkdtempSync, readFileSync, rmSync } from 'node:fs' +import os from 'node:os' +import { join } from 'node:path' +import { afterEach, describe, expect, it, vi } from 'vitest' +import { + EVENT_LOOP_DELAY_REPORT_FILE, + isEventLoopDelayProbeEnabled, + startEventLoopDelayProbe +} from './event-loop-delay-probe' + +describe('event-loop delay probe', () => { + const dirs: string[] = [] + afterEach(() => { + vi.useRealTimers() + dirs.splice(0).forEach((dir) => rmSync(dir, { recursive: true, force: true })) + }) + const userData = (): string => { + const dir = mkdtempSync(join(os.tmpdir(), 'event-loop-delay-')) + dirs.push(dir) + return dir + } + + it('runs only for e2e runs or the explicit opt-in', () => { + expect(isEventLoopDelayProbeEnabled({})).toBe(false) + expect(isEventLoopDelayProbeEnabled({ NODE_ENV: 'development' })).toBe(false) + expect(isEventLoopDelayProbeEnabled({ ORCA_E2E_USER_DATA_DIR: '/tmp/x' })).toBe(true) + expect(isEventLoopDelayProbeEnabled({ ORCA_EVENT_LOOP_DELAY_PROBE: '1' })).toBe(true) + }) + + it('writes nothing when disabled', () => { + vi.useFakeTimers() + const dir = userData() + startEventLoopDelayProbe('main', dir, {}) + vi.advanceTimersByTime(5_000) + expect(existsSync(join(dir, EVENT_LOOP_DELAY_REPORT_FILE))).toBe(false) + }) + + it('appends one window per second with the process and an epoch end time', async () => { + vi.useFakeTimers({ toFake: ['setInterval', 'Date'] }) + const dir = userData() + const started = Date.now() + startEventLoopDelayProbe('orcad', dir, { ORCA_EVENT_LOOP_DELAY_PROBE: '1' }) + vi.advanceTimersByTime(2_000) + const file = join(dir, EVENT_LOOP_DELAY_REPORT_FILE) + await vi.waitFor(() => expect(readFileSync(file, 'utf8').split('\n')).toHaveLength(3)) + // Appends are async, so lines may land out of order; readers match windows by `t`. + const [first] = readFileSync(file, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line)) + .toSorted((a, b) => a.t - b.t) + expect(first).toMatchObject({ process: 'orcad', pid: process.pid, windowMs: 1_000 }) + expect(first.t).toBe(started + 1_000) + expect(first.max).toBeGreaterThanOrEqual(0) + }) +}) diff --git a/src/main/diagnostics/event-loop-delay-probe.ts b/src/main/diagnostics/event-loop-delay-probe.ts new file mode 100644 index 00000000000..50950e184ea --- /dev/null +++ b/src/main/diagnostics/event-loop-delay-probe.ts @@ -0,0 +1,66 @@ +import { appendFile } from 'node:fs/promises' +import { join } from 'node:path' +import { monitorEventLoopDelay } from 'node:perf_hooks' + +export const EVENT_LOOP_DELAY_PROBE_ENV = 'ORCA_EVENT_LOOP_DELAY_PROBE' +/** Appended in the process's userData directory, one line per window. */ +export const EVENT_LOOP_DELAY_REPORT_FILE = 'event-loop-delay.ndjson' + +const RESOLUTION_MS = 10 +const REPORT_EVERY_MS = 1_000 + +export type EventLoopDelayWindow = { + process: 'main' | 'orcad' + pid: number + /** Epoch ms at the end of the window, so a test can match it to its own phases. */ + t: number + windowMs: number + /** Delay beyond the sampling interval, in ms. */ + p50: number + p99: number + max: number + samples: number +} + +/** E2E runs (local and CI) or an explicit dev opt-in; a packaged build sets neither. */ +export function isEventLoopDelayProbeEnabled(env: NodeJS.ProcessEnv = process.env): boolean { + return Boolean(env.ORCA_E2E_USER_DATA_DIR) || env[EVENT_LOOP_DELAY_PROBE_ENV] === '1' +} + +/** + * Latency instrument for main and orcad: every second appends the window's event-loop delay + * (perf_hooks histogram) to userData. Same windowed-report shape as event-loop-stall-probe, but + * runs for the whole session because flood and command latency are steady-state. + */ +export function startEventLoopDelayProbe( + processKind: EventLoopDelayWindow['process'], + userDataPath: string, + env: NodeJS.ProcessEnv = process.env +): void { + if (!isEventLoopDelayProbeEnabled(env)) { + return + } + const file = join(userDataPath, EVENT_LOOP_DELAY_REPORT_FILE) + const histogram = monitorEventLoopDelay({ resolution: RESOLUTION_MS }) + histogram.enable() + // The histogram records the whole interval between samples; subtract it to get the delay. + const delayMs = (ns: number): number => + Math.round(Math.max(0, ns / 1e6 - RESOLUTION_MS) * 100) / 100 + const timer = setInterval(() => { + const report: EventLoopDelayWindow = { + process: processKind, + pid: process.pid, + t: Date.now(), + windowMs: REPORT_EVERY_MS, + p50: delayMs(histogram.percentile(50)), + p99: delayMs(histogram.percentile(99)), + max: delayMs(histogram.max), + samples: histogram.count + } + histogram.reset() + appendFile(file, `${JSON.stringify(report)}\n`).catch((error: unknown) => { + console.warn('[event-loop-delay] could not append the report', error) + }) + }, REPORT_EVERY_MS) + timer.unref?.() +} diff --git a/src/main/orcad/orcad-entry.ts b/src/main/orcad/orcad-entry.ts index 8305ba4f1f5..307e1cb70b4 100644 --- a/src/main/orcad/orcad-entry.ts +++ b/src/main/orcad/orcad-entry.ts @@ -206,6 +206,8 @@ async function startOrcadRuntime( const { resolvePushGatewayOrigin } = await import('../runtime/push/push-gateway-origin') const runtimeUserDataPath = getAppEnvironment().getPath('userData') + const { startEventLoopDelayProbe } = await import('../diagnostics/event-loop-delay-probe') + startEventLoopDelayProbe('orcad', runtimeUserDataPath) // A missing `orca` command must never keep the server from starting. await prepareOrcadCliLauncher().catch((error: unknown) => { console.warn('[orcad] Could not prepare the profile CLI launcher', error) diff --git a/src/main/startup/main-process-preflight.ts b/src/main/startup/main-process-preflight.ts index 5443a2f5d4e..60367d2ee4e 100644 --- a/src/main/startup/main-process-preflight.ts +++ b/src/main/startup/main-process-preflight.ts @@ -38,6 +38,7 @@ import { enableRendererHeapHeadroom } from './renderer-heap-headroom' import { configureLinuxDevShmUsage } from './linux-dev-shm-policy' import { isStartupDiagnosticsEnabled, logStartupDiagnostic } from './startup-diagnostics' import { startEventLoopStallProbe } from './event-loop-stall-probe' +import { startEventLoopDelayProbe } from '../diagnostics/event-loop-delay-probe' import { isMainThreadDiagnosticsEnabled, recordSubprocessSpawn, @@ -219,6 +220,7 @@ function initializeMainProcessPreflight(options: MainProcessPreflightOptions): b // Why captured now: after the dev/E2E override above, and before app.setName('Orca') (whenReady) // changes how userData resolves on a case-sensitive filesystem. See persistence.ts:20-28. initDataPath() + startEventLoopDelayProbe('main', getCanonicalUserDataPath()) antigravityHookService.setWindowsRuntimePathProvider( () => getRelocatedDaemonHost()?.execPath ?? process.execPath ) diff --git a/tests/e2e/helpers/event-loop-delay-report.ts b/tests/e2e/helpers/event-loop-delay-report.ts new file mode 100644 index 00000000000..5680aee80d2 --- /dev/null +++ b/tests/e2e/helpers/event-loop-delay-report.ts @@ -0,0 +1,92 @@ +/** + * Reads the event-loop delay windows main or orcad append to their userData during e2e runs + * (src/main/diagnostics/event-loop-delay-probe.ts) and summarizes a time range of them. + */ + +import { existsSync, readFileSync } from 'node:fs' +import path from 'node:path' +import { expect } from '@stablyai/playwright-test' +import { + EVENT_LOOP_DELAY_REPORT_FILE, + type EventLoopDelayWindow +} from '../../../src/main/diagnostics/event-loop-delay-probe' + +export type EventLoopDelaySummary = { + process: EventLoopDelayWindow['process'] + /** One-second windows overlapping the range. */ + windows: number + /** Worst window's p99 and the largest single delay, in ms. */ + p99: number + max: number +} + +type ReadWindow = Pick + +function parseWindow(line: string): ReadWindow | null { + const value: unknown = JSON.parse(line) + if ( + !value || + typeof value !== 'object' || + !('t' in value) || + !('windowMs' in value) || + !('p99' in value) || + !('max' in value) || + !('process' in value) || + typeof value.t !== 'number' || + typeof value.windowMs !== 'number' || + typeof value.p99 !== 'number' || + typeof value.max !== 'number' || + (value.process !== 'main' && value.process !== 'orcad') + ) { + return null + } + return { + process: value.process, + t: value.t, + windowMs: value.windowMs, + p99: value.p99, + max: value.max + } +} + +function readWindows(userDataDir: string): ReadWindow[] { + const file = path.join(userDataDir, EVENT_LOOP_DELAY_REPORT_FILE) + return existsSync(file) + ? readFileSync(file, 'utf8') + .split('\n') + // The last element is '' or a line still being appended. + .slice(0, -1) + .flatMap((line) => parseWindow(line) ?? []) + : [] +} + +/** `processKind`'s windows overlapping [from, to] (epoch ms). */ +export function summarizeEventLoopDelay( + userDataDir: string, + processKind: EventLoopDelayWindow['process'], + from: number, + to: number +): EventLoopDelaySummary { + const windows = readWindows(userDataDir).filter( + (entry) => entry.process === processKind && entry.t > from && entry.t - entry.windowMs < to + ) + return { + process: processKind, + windows: windows.length, + p99: Math.max(0, ...windows.map((entry) => entry.p99)), + max: Math.max(0, ...windows.map((entry) => entry.max)) + } +} + +/** The probe writes a window once it closes; wait for the one holding `epochMs`. */ +export async function waitForEventLoopDelayWindow( + userDataDir: string, + epochMs: number +): Promise { + await expect + .poll(() => readWindows(userDataDir).some((entry) => entry.t >= epochMs), { + timeout: 10_000, + message: 'the event-loop delay probe wrote no window' + }) + .toBe(true) +} diff --git a/tests/e2e/helpers/first-drawn-watch.ts b/tests/e2e/helpers/first-drawn-watch.ts new file mode 100644 index 00000000000..c407d1c8fd4 --- /dev/null +++ b/tests/e2e/helpers/first-drawn-watch.ts @@ -0,0 +1,85 @@ +/** + * Time to first drawn after a relaunch: from the main process's start to the first animation + * frame in which the restored active tab shows all its panes with a terminal in each. The span + * includes the test harness attaching DevTools before the first window, and every relaunch keeps + * the PTY daemon warm, so compare it only with itself, not with a user's cold start. The watch is + * installed by main as soon as the window's DOM is ready and fails if the panes drew earlier. + */ + +import type { ElectronApplication, Page } from '@stablyai/playwright-test' +import type { WebContents } from 'electron' + +type FirstDrawnState = { drawnAtInstall: boolean; drawnAt: number | null } + +declare global { + // oxlint-disable-next-line typescript-eslint/consistent-type-definitions -- declaration merging requires interface + interface Window { + __layoutFirstDrawn?: FirstDrawnState + } +} + +/** Runs in the window, serialized: it can use nothing outside its own body. */ +function watchFirstDrawn(paneCount: number): void { + const drawn = (): boolean => { + const surface = Array.from( + document.querySelectorAll('[data-terminal-tab-id]') + ).find((element) => element.getBoundingClientRect().width > 0 && element.querySelector('.pane')) + const panes = Array.from(surface?.querySelectorAll('.pane[data-leaf-id]') ?? []) + return panes.length === paneCount && panes.every((pane) => pane.querySelector('.xterm')) + } + const state: FirstDrawnState = { drawnAtInstall: drawn(), drawnAt: null } + window.__layoutFirstDrawn = state + const tick = (): void => { + if (drawn()) { + state.drawnAt = Date.now() + return + } + requestAnimationFrame(tick) + } + requestAnimationFrame(tick) +} + +/** Call from `beforeFirstWindow`: covers a window that already exists and one created later. */ +export function installFirstDrawnWatch(app: ElectronApplication, paneCount: number): Promise { + const source = `(${watchFirstDrawn.toString()})(${paneCount})` + return app.evaluate(({ app, webContents }, script) => { + const install = (contents: WebContents): void => { + if (contents.getType() !== 'window') { + return + } + const run = (): void => { + void contents.executeJavaScript(script) + } + if (contents.isLoading() || !contents.getURL()) { + contents.once('dom-ready', run) + } else { + run() + } + } + webContents.getAllWebContents().forEach(install) + app.once('web-contents-created', (_event, contents) => install(contents)) + }, source) +} + +/** Epoch ms of the main process's start and of first drawn. */ +export async function readFirstDrawn( + app: ElectronApplication, + page: Page +): Promise<{ processStartedAt: number; drawnAt: number }> { + const handle = await page.waitForFunction( + () => { + const state = window.__layoutFirstDrawn + return state?.drawnAt ? state : null + }, + null, + { timeout: 120_000 } + ) + const state = await handle.jsonValue() + if (!state || state.drawnAtInstall || state.drawnAt === null) { + throw new Error('first-drawn watch was installed after the restored panes drew') + } + return { + processStartedAt: await app.evaluate(() => performance.timeOrigin), + drawnAt: state.drawnAt + } +} diff --git a/tests/e2e/helpers/layout-latency-probe.ts b/tests/e2e/helpers/layout-latency-probe.ts new file mode 100644 index 00000000000..004217fe4fd --- /dev/null +++ b/tests/e2e/helpers/layout-latency-probe.ts @@ -0,0 +1,168 @@ +/** + * In-app clock for command → drawn layout latency. The window stamps the moment React commits the + * expected DOM (the MutationObserver callback that first sees it) and the next animation frame, + * so no DevTools round trip lands inside a sample. The start is stamped in the window too for + * in-window commands (a keydown, or the call itself); RPC commands are stamped by the test just + * before sending. All stamps are Date.now() on one machine, so they compare across processes. + */ + +import type { Page } from '@stablyai/playwright-test' +import { SORTABLE_TAB } from './terminal-tab-menu' + +export type DrawnCondition = + | { kind: 'panes'; count: number } + | { kind: 'tabs'; count: number } + | { kind: 'tabTitle'; title: string } + | { kind: 'tabOrder'; order: string } + +type ProbeState = { + /** The command asked for confirmation and the probe clicked it: not a latency sample. */ + confirmed: boolean + startedAt: number | null + commitAt: number | null + drawnAt: number | null + done: Promise +} + +declare global { + // oxlint-disable-next-line typescript-eslint/consistent-type-definitions -- declaration merging requires interface + interface Window { + __layoutLatencyProbe?: ProbeState + } +} + +export type InAppSample = { commitMs: number; drawnMs: number } + +export type ArmOptions = { + /** `keydown` stamps the start on the next non-modifier key; otherwise the sender stamps it. */ + startOn: 'keydown' | 'sender' + /** A confirmation button the command may raise; the probe clicks it in the window. */ + confirmButton?: string +} + +const PROBE_TIMEOUT_MS = 30_000 + +/** Arms the watch; call right before the command. */ +export function armLayoutLatencyProbe( + page: Page, + condition: DrawnCondition, + { startOn, confirmButton }: ArmOptions +): Promise { + return page.evaluate( + ({ condition, startOn, confirmButton, tabSelector, timeoutMs }) => { + const holds = (): boolean => { + const tabs = (): HTMLElement[] => + Array.from(document.querySelectorAll(tabSelector)) + switch (condition.kind) { + case 'panes': { + const surface = Array.from( + document.querySelectorAll('[data-terminal-tab-id]') + ).find( + (element) => + element.getBoundingClientRect().width > 0 && element.querySelector('.pane') + ) + return ( + (surface?.querySelectorAll('.pane[data-leaf-id]').length ?? 0) === condition.count + ) + } + case 'tabs': + return tabs().length === condition.count + case 'tabTitle': + return tabs().some((tab) => tab.dataset.tabTitle === condition.title) + case 'tabOrder': + return ( + tabs() + .map((tab) => tab.dataset.tabId) + .join(',') === condition.order + ) + } + } + if (holds()) { + throw new Error( + `latency probe: ${JSON.stringify(condition)} already holds before the command` + ) + } + const probe: ProbeState = { + confirmed: false, + startedAt: null, + commitAt: null, + drawnAt: null, + done: new Promise((resolve, reject) => { + const timer = setTimeout(() => { + observer.disconnect() + reject(new Error(`latency probe: ${JSON.stringify(condition)} never drew`)) + }, timeoutMs) + const observer = new MutationObserver(() => { + // Stamped before the checks below, whose DOM reads would force layout inside the sample. + const seenAt = Date.now() + const confirm = confirmButton + ? Array.from(document.querySelectorAll('button')).find( + (button) => button.textContent?.trim() === confirmButton + ) + : undefined + if (confirm && !probe.confirmed) { + probe.confirmed = true + confirm.click() + } + if (!holds()) { + return + } + observer.disconnect() + clearTimeout(timer) + probe.commitAt = seenAt + requestAnimationFrame(() => { + probe.drawnAt = Date.now() + resolve() + }) + }) + observer.observe(document.body, { + childList: true, + subtree: true, + attributeFilter: ['data-tab-title'] + }) + }) + } + if (startOn === 'keydown') { + // A chord arrives as one keydown per key; the command's key is the first non-modifier. + const onKeydown = (event: KeyboardEvent): void => { + if (['Meta', 'Control', 'Shift', 'Alt'].includes(event.key)) { + return + } + probe.startedAt = Date.now() + window.removeEventListener('keydown', onKeydown, { capture: true }) + } + window.addEventListener('keydown', onKeydown, { capture: true }) + } + window.__layoutLatencyProbe = probe + }, + { condition, startOn, confirmButton, tabSelector: SORTABLE_TAB, timeoutMs: PROBE_TIMEOUT_MS } + ) +} + +/** + * Waits for the armed watch; `sentAt` is the test's stamp for a command it sent itself. Null when + * the command waited on a confirmation, which measures the click and not the layout. + */ +export async function readLayoutLatencyProbe( + page: Page, + sentAt: number +): Promise { + const stamps = await page.evaluate(async () => { + const probe = window.__layoutLatencyProbe + if (!probe) { + throw new Error('latency probe: not armed') + } + await probe.done + return { + confirmed: probe.confirmed, + startedAt: probe.startedAt, + commitAt: probe.commitAt!, + drawnAt: probe.drawnAt! + } + }) + if (stamps.confirmed) { + return null + } + const startedAt = stamps.startedAt ?? sentAt + return { commitMs: stamps.commitAt - startedAt, drawnMs: stamps.drawnAt - startedAt } +} diff --git a/tests/e2e/helpers/workspace-layout-oracle-session.ts b/tests/e2e/helpers/workspace-layout-oracle-session.ts index cc64ef21262..1ab69aa5d17 100644 --- a/tests/e2e/helpers/workspace-layout-oracle-session.ts +++ b/tests/e2e/helpers/workspace-layout-oracle-session.ts @@ -14,6 +14,7 @@ import { bootstrapRestoredLaunch } from './terminal-restart-persistence' import { waitForPaneCount } from './terminal' import { LayoutOracle, type OracleFinding } from './workspace-layout-oracle' import { readRuntimePartitions } from './workspace-layout-oracle-views' +import { summarizeEventLoopDelay, type EventLoopDelaySummary } from './event-loop-delay-report' export const ORACLE_REPORT_DIR_ENV = 'ORCA_LAYOUT_ORACLE_REPORT_DIR' @@ -72,6 +73,7 @@ export async function runOracleScenario( const session = createRestartSession(testInfo) let app: ElectronApplication | null = null const worktreeIds: string[] = [] + const started = Date.now() try { const first = await session.launch() app = first.app @@ -131,7 +133,11 @@ export async function runOracleScenario( } finally { await run.oracle.stop() } - writeReport(testInfo, scenarioId, run.oracle.findings, run.oracle.viewCreations.at(-1) ?? {}) + writeReport(testInfo, scenarioId, { + findings: run.oracle.findings, + viewCreations: run.oracle.viewCreations.at(-1) ?? {}, + eventLoopDelay: summarizeEventLoopDelay(session.userDataDir, 'main', started, Date.now()) + }) return run.oracle.findings } finally { if (app) { @@ -144,14 +150,15 @@ export async function runOracleScenario( function writeReport( testInfo: TestInfo, scenarioId: string, - findings: OracleFinding[], - viewCreations: Record + report: { + findings: OracleFinding[] + viewCreations: Record + /** Main's event-loop delay over the scenario. */ + eventLoopDelay: EventLoopDelaySummary + } ): void { const dir = process.env[ORACLE_REPORT_DIR_ENV] ?? testInfo.outputPath('layout-oracle') mkdirSync(dir, { recursive: true }) const file = path.join(dir, `${scenarioId}-${Date.now()}.json`) - writeFileSync( - file, - `${JSON.stringify({ scenario: scenarioId, findings, viewCreations }, null, 2)}\n` - ) + writeFileSync(file, `${JSON.stringify({ scenario: scenarioId, ...report }, null, 2)}\n`) } diff --git a/tests/e2e/workspace-layout-oracle-headless.spec.ts b/tests/e2e/workspace-layout-oracle-headless.spec.ts index 9d54de0a1c2..1350dc32145 100644 --- a/tests/e2e/workspace-layout-oracle-headless.spec.ts +++ b/tests/e2e/workspace-layout-oracle-headless.spec.ts @@ -37,6 +37,10 @@ import { import { LayoutOracle, type OracleFinding } from './helpers/workspace-layout-oracle' import type { OracleLayout } from './helpers/workspace-layout-oracle-model' import { ORACLE_REPORT_DIR_ENV } from './helpers/workspace-layout-oracle-session' +import { + summarizeEventLoopDelay, + type EventLoopDelaySummary +} from './helpers/event-loop-delay-report' import { unexpectedFindings } from './workspace-layout-oracle-known-on-main' type Run = { @@ -472,7 +476,18 @@ async function runHeadlessScenario( } return findings } finally { - writeReport(testInfo, `${kind}-${scenario.id}`, findings, Date.now() - started) + const ended = Date.now() + writeReport(testInfo, `${kind}-${scenario.id}`, { + durationMs: ended - started, + findings, + // orcad, or Electron serve's main process. + eventLoopDelay: summarizeEventLoopDelay( + host.userDataDir, + kind === 'orcad' ? 'orcad' : 'main', + started, + ended + ) + }) await host.dispose() } } @@ -480,15 +495,18 @@ async function runHeadlessScenario( function writeReport( testInfo: TestInfo, scenarioId: string, - findings: OracleFinding[], - durationMs: number + report: { + durationMs: number + findings: OracleFinding[] + eventLoopDelay: EventLoopDelaySummary + } ): void { const dir = process.env[ORACLE_REPORT_DIR_ENV] ?? testInfo.outputPath('layout-oracle') mkdirSync(dir, { recursive: true }) const file = path.join(dir, `headless-${scenarioId}-${Date.now()}.json`) writeFileSync( file, - `${JSON.stringify({ scenario: `headless-${scenarioId}`, durationMs, findings }, null, 2)}\n` + `${JSON.stringify({ scenario: `headless-${scenarioId}`, ...report }, null, 2)}\n` ) } diff --git a/tests/e2e/workspace-layout-oracle-latency-baseline.json b/tests/e2e/workspace-layout-oracle-latency-baseline.json new file mode 100644 index 00000000000..fe09ed5c6e9 --- /dev/null +++ b/tests/e2e/workspace-layout-oracle-latency-baseline.json @@ -0,0 +1,522 @@ +{ + "about": "Non-gating baseline from tests/e2e/workspace-layout-oracle-latency.spec.ts on main, with no layout subscriber. Milliseconds; inAppCommit/inAppDrawn are the in-window clock, outer includes one DevTools round trip. Event-loop delay is main's, beyond the 10 ms sampling interval. Taken with ORCA_LAYOUT_ORACLE_LATENCY_SAMPLES=100.", + "main": "73c53311dc03659f79375f79ac01dff1c9c66863", + "darwin": { + "machine": "Apple M5 Pro, macOS 27.0, hidden window (ORCA_BACKGROUND_LAUNCH=1)", + "latency": { + "split (idle)": { + "n": 100, + "inAppCommit": { + "p50": 22, + "p95": 24, + "max": 26 + }, + "inAppDrawn": { + "p50": 39, + "p95": 41, + "max": 44 + }, + "outer": { + "p50": 48, + "p95": 58, + "max": 67 + } + }, + "close pane (idle)": { + "n": 100, + "inAppCommit": { + "p50": 23, + "p95": 105, + "max": 174 + }, + "inAppDrawn": { + "p50": 24, + "p95": 106, + "max": 175 + }, + "outer": { + "p50": 26, + "p95": 108, + "max": 176 + } + }, + "new tab (idle)": { + "n": 100, + "inAppCommit": { + "p50": 43, + "p95": 87, + "max": 113 + }, + "inAppDrawn": { + "p50": 45, + "p95": 90, + "max": 115 + }, + "outer": { + "p50": 49, + "p95": 93, + "max": 132 + } + }, + "rename (idle)": { + "n": 100, + "inAppCommit": { + "p50": 8, + "p95": 16, + "max": 22 + }, + "inAppDrawn": { + "p50": 13, + "p95": 20, + "max": 22 + }, + "outer": { + "p50": 16, + "p95": 23, + "max": 49 + } + }, + "tab reorder (idle)": { + "n": 100, + "inAppCommit": { + "p50": 7, + "p95": 15, + "max": 19 + }, + "inAppDrawn": { + "p50": 10, + "p95": 17, + "max": 22 + }, + "outer": { + "p50": 11, + "p95": 18, + "max": 25 + } + }, + "close tab (idle)": { + "n": 100, + "inAppCommit": { + "p50": 12, + "p95": 15, + "max": 16 + }, + "inAppDrawn": { + "p50": 14, + "p95": 18, + "max": 20 + }, + "outer": { + "p50": 111, + "p95": 186, + "max": 245 + } + }, + "split (flood)": { + "n": 100, + "inAppCommit": { + "p50": 24, + "p95": 26, + "max": 27 + }, + "inAppDrawn": { + "p50": 42, + "p95": 45, + "max": 47 + }, + "outer": { + "p50": 53, + "p95": 65, + "max": 73 + } + }, + "close pane (flood)": { + "n": 100, + "inAppCommit": { + "p50": 30, + "p95": 87, + "max": 98 + }, + "inAppDrawn": { + "p50": 31, + "p95": 88, + "max": 98 + }, + "outer": { + "p50": 38, + "p95": 91, + "max": 99 + } + }, + "new tab (flood)": { + "n": 100, + "inAppCommit": { + "p50": 55, + "p95": 144, + "max": 192 + }, + "inAppDrawn": { + "p50": 58, + "p95": 147, + "max": 195 + }, + "outer": { + "p50": 62, + "p95": 149, + "max": 228 + } + }, + "rename (flood)": { + "n": 100, + "inAppCommit": { + "p50": 11, + "p95": 20, + "max": 20 + }, + "inAppDrawn": { + "p50": 17, + "p95": 24, + "max": 24 + }, + "outer": { + "p50": 19, + "p95": 26, + "max": 34 + } + }, + "tab reorder (flood)": { + "n": 100, + "inAppCommit": { + "p50": 9, + "p95": 15, + "max": 21 + }, + "inAppDrawn": { + "p50": 12, + "p95": 18, + "max": 24 + }, + "outer": { + "p50": 14, + "p95": 23, + "max": 48 + } + }, + "close tab (flood)": { + "n": 100, + "inAppCommit": { + "p50": 15, + "p95": 16, + "max": 18 + }, + "inAppDrawn": { + "p50": 17, + "p95": 20, + "max": 21 + }, + "outer": { + "p50": 89, + "p95": 183, + "max": 262 + } + } + }, + "eventLoopDelay": { + "idle": { + "process": "main", + "windows": 44, + "p99": 14.89, + "max": 17.8 + }, + "flood": { + "process": "main", + "windows": 48, + "p99": 14.94, + "max": 24.18 + } + }, + "closeConfirms": { + "idle": 0, + "flood": 0 + }, + "firstDrawn": { + "profile": { + "hiddenWorktrees": 12, + "tabsPerWorktree": 3, + "activePanes": 4 + }, + "firstDrawn": { + "n": 10, + "p50": 1334, + "p95": 2813, + "max": 2813 + }, + "eventLoopDelayMax": { + "p50": 73, + "p95": 96, + "max": 96 + }, + "caveat": "Measured from main process start, so it includes the test harness attaching DevTools before the first window; every relaunch keeps the PTY daemon warm. Compare only with itself, not with a user's cold start." + }, + "note": "close pane rows re-taken after the clock moved from the modifier keydown to the w keydown; other rows unchanged." + }, + "linux": { + "machine": "GitHub-hosted ubuntu-latest, Xvfb, hidden window; CI run 38165956663 job 114549487905", + "caveat": "Chromium runs a hidden window's animation frames at about 1 per second here, so inAppDrawn and outer are bounded by that throttle and only inAppCommit measures the app. Flood numbers are sensitive to runner CPU: three unthrottled `yes` panes compete with the app on a small runner, so Linux flood is not comparable with macOS or across runner types. The close pane rows were taken before the w-key fix, so their start includes one DevTools round trip (about 1 ms).", + "latency": { + "split (idle)": { + "n": 100, + "inAppCommit": { + "p50": 22, + "p95": 29, + "max": 32 + }, + "inAppDrawn": { + "p50": 1011, + "p95": 1013, + "max": 1018 + }, + "outer": { + "p50": 1014, + "p95": 1016, + "max": 1022 + } + }, + "close pane (idle)": { + "n": 100, + "inAppCommit": { + "p50": 30, + "p95": 51, + "max": 91 + }, + "inAppDrawn": { + "p50": 997, + "p95": 1000, + "max": 1002 + }, + "outer": { + "p50": 1001, + "p95": 1004, + "max": 1004 + } + }, + "new tab (idle)": { + "n": 100, + "inAppCommit": { + "p50": 49, + "p95": 62, + "max": 83 + }, + "inAppDrawn": { + "p50": 1008, + "p95": 1012, + "max": 1012 + }, + "outer": { + "p50": 1009, + "p95": 1013, + "max": 1014 + } + }, + "rename (idle)": { + "n": 100, + "inAppCommit": { + "p50": 13, + "p95": 16, + "max": 29 + }, + "inAppDrawn": { + "p50": 1010, + "p95": 1011, + "max": 1011 + }, + "outer": { + "p50": 1011, + "p95": 1012, + "max": 1014 + } + }, + "tab reorder (idle)": { + "n": 100, + "inAppCommit": { + "p50": 12, + "p95": 18, + "max": 19 + }, + "inAppDrawn": { + "p50": 1012, + "p95": 1013, + "max": 1013 + }, + "outer": { + "p50": 1013, + "p95": 1014, + "max": 1014 + } + }, + "close tab (idle)": { + "n": 100, + "inAppCommit": { + "p50": 21, + "p95": 25, + "max": 38 + }, + "inAppDrawn": { + "p50": 1014, + "p95": 1015, + "max": 1016 + }, + "outer": { + "p50": 1015, + "p95": 1016, + "max": 1017 + } + }, + "split (flood)": { + "n": 100, + "inAppCommit": { + "p50": 44, + "p95": 77, + "max": 119 + }, + "inAppDrawn": { + "p50": 367, + "p95": 706, + "max": 962 + }, + "outer": { + "p50": 642, + "p95": 887, + "max": 1063 + } + }, + "close pane (flood)": { + "n": 100, + "inAppCommit": { + "p50": 366, + "p95": 575, + "max": 2210 + }, + "inAppDrawn": { + "p50": 1014, + "p95": 1331, + "max": 3168 + }, + "outer": { + "p50": 1154, + "p95": 1493, + "max": 3344 + } + }, + "new tab (flood)": { + "n": 100, + "inAppCommit": { + "p50": 570, + "p95": 2209, + "max": 2969 + }, + "inAppDrawn": { + "p50": 1261, + "p95": 2585, + "max": 3394 + }, + "outer": { + "p50": 1322, + "p95": 2719, + "max": 3505 + } + }, + "rename (flood)": { + "n": 100, + "inAppCommit": { + "p50": 202, + "p95": 341, + "max": 377 + }, + "inAppDrawn": { + "p50": 539, + "p95": 1057, + "max": 1207 + }, + "outer": { + "p50": 587, + "p95": 1140, + "max": 1319 + } + }, + "tab reorder (flood)": { + "n": 100, + "inAppCommit": { + "p50": 176, + "p95": 361, + "max": 397 + }, + "inAppDrawn": { + "p50": 577, + "p95": 743, + "max": 1334 + }, + "outer": { + "p50": 627, + "p95": 838, + "max": 1385 + } + }, + "close tab (flood)": { + "n": 100, + "inAppCommit": { + "p50": 207, + "p95": 363, + "max": 445 + }, + "inAppDrawn": { + "p50": 838, + "p95": 932, + "max": 965 + }, + "outer": { + "p50": 931, + "p95": 1147, + "max": 1333 + } + } + }, + "eventLoopDelay": { + "idle": { + "process": "main", + "windows": 713, + "p99": 138.9, + "max": 197.88 + }, + "flood": { + "process": "main", + "windows": 742, + "p99": 355.69, + "max": 355.69 + } + }, + "closeConfirms": { + "idle": 0, + "flood": 0 + }, + "firstDrawn": { + "profile": { + "hiddenWorktrees": 12, + "tabsPerWorktree": 3, + "activePanes": 4 + }, + "firstDrawn": { + "n": 10, + "p50": 3026, + "p95": 3086, + "max": 3086 + }, + "eventLoopDelayMax": { + "p50": 91, + "p95": 106, + "max": 106 + }, + "caveat": "Measured from main process start, so it includes the test harness attaching DevTools before the first window; every relaunch keeps the PTY daemon warm. Compare only with itself, not with a user's cold start. Also read on an animation frame, so up to ~1 s late here." + } + } +} diff --git a/tests/e2e/workspace-layout-oracle-latency.spec.ts b/tests/e2e/workspace-layout-oracle-latency.spec.ts index 8fb5483fdd3..18fd201b0e7 100644 --- a/tests/e2e/workspace-layout-oracle-latency.spec.ts +++ b/tests/e2e/workspace-layout-oracle-latency.spec.ts @@ -1,30 +1,62 @@ /** - * Measures command → drawn update for layout commands, idle and with another tab's terminal - * flooding output (`yes`). Measuring only: it records p50/p95 per action in the oracle report and - * never fails on a number, so a later budget can gate on it. + * Measures command → drawn update for layout commands, idle and with three panes flooding output + * (`yes`), one of them in a hidden worktree, and time to first drawn after relaunching a large + * profile. Measuring only: it records each number in the oracle report and never fails on one, + * so a later budget can gate on it. Runs with no layout subscriber, so main is measured as users + * run it. The committed main baseline is workspace-layout-oracle-latency-baseline.json. * - * The clock runs from just before the command is sent until the window's DOM shows the result, - * polled every animation frame over CDP, so each sample includes one CDP round trip. + * Each command is timed twice. The in-app clock (helpers/layout-latency-probe.ts) stops in the + * window at React's commit and at the next frame. The outer clock stops when the test sees the + * drawn result over CDP, so it also holds one DevTools round trip. */ import { mkdirSync, writeFileSync } from 'node:fs' import path from 'node:path' -import type { Page } from '@stablyai/playwright-test' -import { test } from './helpers/orca-app' +import type { Page, TestInfo } from '@stablyai/playwright-test' +import { expect, test } from './helpers/orca-app' import { createRestartSession } from './helpers/orca-restart' import { bootstrapFirstLaunch, seededRepoPathOrSkip } from './helpers/terminal-restart-persistence' -import { splitActiveTerminalPane, waitForActiveTerminalManager } from './helpers/terminal' -import { closeActivePaneFromKeyboard, waitForBoundPanes } from './helpers/terminal-layout-journeys' +import { + focusActiveTerminalInput, + splitActiveTerminalPane, + waitForActiveTerminalManager +} from './helpers/terminal' +import { resolveActiveTabId } from './helpers/terminal-pane-identity' +import { waitForBoundPanes } from './helpers/terminal-layout-journeys' import { SORTABLE_TAB } from './helpers/terminal-tab-menu' import { ORACLE_REPORT_DIR_ENV } from './helpers/workspace-layout-oracle-session' +import { + armLayoutLatencyProbe, + readLayoutLatencyProbe, + type ArmOptions, + type DrawnCondition, + type InAppSample +} from './helpers/layout-latency-probe' +import { installFirstDrawnWatch, readFirstDrawn } from './helpers/first-drawn-watch' +import { + summarizeEventLoopDelay, + waitForEventLoopDelayWindow, + type EventLoopDelaySummary +} from './helpers/event-loop-delay-report' import { RuntimeClient } from '../../src/cli/runtime/client' -import type { RuntimeTerminalListResult } from '../../src/shared/runtime-types' +import type { + RuntimeTerminalCreate, + RuntimeTerminalListResult, + RuntimeTerminalRead, + RuntimeWorktreeCreateResult +} from '../../src/shared/runtime-types' import type { RuntimeMobileSessionTabsResult } from '../../src/shared/runtime-session-contracts' +// The baseline is taken with 100; routine runs keep 10, since a Linux CI sample waits ~1 s per frame. const SAMPLES = Number(process.env.ORCA_LAYOUT_ORACLE_LATENCY_SAMPLES ?? 10) +const STARTUP_SAMPLES = Number(process.env.ORCA_LAYOUT_ORACLE_STARTUP_SAMPLES ?? 10) +const FLOOD_COMMAND = 'yes orca-latency-flood' +const CLOSE_CONFIRM = 'Stop and Close' +const LARGE_PROFILE = { hiddenWorktrees: 12, tabsPerWorktree: 3, activePanes: 4 } type Condition = 'idle' | 'flood' -type Samples = Record +type Sample = { outerMs: number; inApp: InAppSample } +type Samples = Record /** Reads can briefly fail while the window re-publishes its terminals; only reads are retried. */ async function read(client: RuntimeClient, method: string, params: unknown): Promise { @@ -41,35 +73,44 @@ async function read(client: RuntimeClient, method: string, params: unknown): } } -function percentile(values: number[], p: number): number { +function stats(values: number[]): { p50: number; p95: number; max: number } { const sorted = values.toSorted((a, b) => a - b) - return sorted[Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length))] ?? Number.NaN + const at = (p: number): number => + sorted[Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length))] ?? Number.NaN + return { + p50: Math.round(at(50)), + p95: Math.round(at(95)), + max: Math.round(sorted.at(-1) ?? Number.NaN) + } } -async function timeUntil( +/** Times one command on both clocks; null when it stopped on a confirmation. */ +async function timeCommand( page: Page, - command: () => Promise, - drawn: (page: Page) => Promise -): Promise { - const started = performance.now() - await command() - await drawn(page) - return performance.now() - started + condition: DrawnCondition, + options: ArmOptions, + send: () => Promise +): Promise { + await armLayoutLatencyProbe(page, condition, options) + const sentAt = Date.now() + await send() + const inApp = await readLayoutLatencyProbe(page, sentAt) + return inApp ? { outerMs: Date.now() - sentAt, inApp } : null } -const paneCount = (page: Page, count: number) => - page.waitForFunction( - (expected) => { - const surface = Array.from( - document.querySelectorAll('[data-terminal-tab-id]') - ).find( - (element) => element.getBoundingClientRect().width > 0 && element.querySelector('.pane') - ) - return (surface?.querySelectorAll('.pane[data-leaf-id]').length ?? 0) === expected - }, - count, - { polling: 'raf', timeout: 30_000 } - ) +/** The split helper's call, stamped in the window right before it runs. */ +async function stampedSplit(page: Page): Promise { + const tabId = await resolveActiveTabId(page) + await page.evaluate((tabId) => { + const manager = tabId ? window.__paneManagers?.get(tabId) : null + const pane = manager?.getActivePane?.() ?? manager?.getPanes?.()[0] ?? null + if (!manager?.splitPane || !pane || !window.__layoutLatencyProbe) { + throw new Error('stampedSplit: active pane manager or probe not ready') + } + window.__layoutLatencyProbe.startedAt = Date.now() + manager.splitPane(pane.id, 'vertical') + }, tabId) +} async function measureCondition( page: Page, @@ -77,56 +118,56 @@ async function measureCondition( worktreeId: string, condition: Condition, samples: Samples -): Promise { +): Promise { const worktree = `id:${worktreeId}` - const add = (action: string, ms: number): void => { - ;(samples[`${action} (${condition})`] ??= []).push(ms) + const add = (action: string, sample: Sample | null): void => { + if (!sample) { + throw new Error(`${action} asked for confirmation`) + } + ;(samples[`${action} (${condition})`] ??= []).push(sample) } + const sender: ArmOptions = { startOn: 'sender' } + let confirms = 0 for (let index = 0; index < SAMPLES; index += 1) { add( 'split', - await timeUntil( - page, - () => splitActiveTerminalPane(page, 'vertical'), - (p) => paneCount(p, 2) - ) + await timeCommand(page, { kind: 'panes', count: 2 }, sender, () => stampedSplit(page)) ) await waitForBoundPanes(page, 2) - add( - 'close pane', - await timeUntil( + // A fresh shell can still read as busy and ask first; retry so close pane gets SAMPLES too. + for (;;) { + await focusActiveTerminalInput(page) + const closed = await timeCommand( page, - () => closeActivePaneFromKeyboard(page, 2), - (p) => paneCount(p, 1) + { kind: 'panes', count: 1 }, + { startOn: 'keydown', confirmButton: CLOSE_CONFIRM }, + () => page.keyboard.press(process.platform === 'darwin' ? 'Meta+w' : 'Control+w') ) - ) + if (closed) { + add('close pane', closed) + break + } + confirms += 1 + await splitActiveTerminalPane(page, 'vertical') + await waitForBoundPanes(page, 2) + } const tabsBefore = await page.locator(SORTABLE_TAB).count() - const strip = (count: number) => (p: Page) => - p.waitForFunction( - ({ selector, expected }) => document.querySelectorAll(selector).length === expected, - { selector: SORTABLE_TAB, expected: count }, - { polling: 'raf', timeout: 30_000 } - ) const handles = async (): Promise => (await read(client, 'terminal.list', { worktree })).terminals const existing = new Set((await handles()).map((terminal) => terminal.handle)) add( 'new tab', - await timeUntil( - page, - () => client.call('terminal.create', { worktree }), - strip(tabsBefore + 1) + await timeCommand(page, { kind: 'tabs', count: tabsBefore + 1 }, sender, () => + client.call('terminal.create', { worktree }) ) ) const created = (await handles()).find((terminal) => !existing.has(terminal.handle))! const title = `latency-${condition}-${index}` add( 'rename', - await timeUntil( - page, - () => client.call('terminal.rename', { terminal: created.handle, title }), - (p) => p.locator(`${SORTABLE_TAB}[data-tab-title="${title}"]`).waitFor({ timeout: 30_000 }) + await timeCommand(page, { kind: 'tabTitle', title }, sender, () => + client.call('terminal.rename', { terminal: created.handle, title }) ) ) const tabs = await read(client, 'session.tabs.list', { @@ -136,79 +177,231 @@ async function measureCondition( const reversed = group.tabOrder.toReversed() add( 'tab reorder', - await timeUntil( - page, - () => - client.call('session.tabs.move', { - worktree, - tabId: reversed[0], - targetGroupId: group.id, - kind: 'reorder', - tabOrder: reversed - }), - (p) => - p.waitForFunction( - ({ selector, order }) => - Array.from(document.querySelectorAll(selector)) - .map((tab) => tab.dataset.tabId) - .join(',') === order, - { selector: SORTABLE_TAB, order: reversed.join(',') }, - { polling: 'raf', timeout: 30_000 } - ) + await timeCommand(page, { kind: 'tabOrder', order: reversed.join(',') }, sender, () => + client.call('session.tabs.move', { + worktree, + tabId: reversed[0], + targetGroupId: group.id, + kind: 'reorder', + tabOrder: reversed + }) ) ) add( 'close tab', - await timeUntil( - page, - () => client.call('terminal.close', { terminal: created.handle }), - strip(tabsBefore) + await timeCommand(page, { kind: 'tabs', count: tabsBefore }, sender, () => + client.call('terminal.close', { terminal: created.handle }) ) ) await waitForActiveTerminalManager(page) } + return confirms +} + +/** The flood condition is only real if every flooding pane is producing output. */ +async function expectFlooding(client: RuntimeClient, handle: string): Promise { + await expect + .poll( + async () => { + const read = await client.call<{ terminal: RuntimeTerminalRead }>('terminal.read', { + terminal: handle, + limit: 20 + }) + return read.result.terminal.tail.join('\n') + }, + { timeout: 30_000, message: `flooding terminal ${handle} never produced output` } + ) + .toContain('orca-latency-flood') +} + +/** A worktree of the seeded repo that is never activated, removed by the returned cleanup. */ +async function createHiddenWorktree( + client: RuntimeClient, + worktreeId: string, + name: string +): Promise<{ id: string; remove: () => Promise }> { + const shown = await client.call<{ worktree: { repoId: string } }>('worktree.show', { + worktree: `id:${worktreeId}` + }) + const created = await client.call('worktree.create', { + repo: `id:${shown.result.worktree.repoId}`, + name: `${name}-${Date.now()}`, + noParent: true, + activate: false, + setupDecision: 'skip' + }) + const id = created.result.worktree.id + return { + id, + remove: async () => { + await client.call('worktree.rm', { worktree: `id:${id}`, force: true, runHooks: false }) + } + } +} + +type Stats = ReturnType +type StartupSample = { firstDrawnMs: number; eventLoopDelayMax: number } +type LatencyReport = + | { + scenario: 'latency' + summary: Record + eventLoopDelay: Record + closeConfirms: Record + samples: Samples + } + | { + scenario: 'first-drawn' + note: string + profile: typeof LARGE_PROFILE + firstDrawn: Stats & { n: number } + eventLoopDelayMax: Stats + samples: StartupSample[] + } + +/** All but the samples go to the log on one line, so a CI run's numbers can be read from it. */ +function writeLatencyReport(testInfo: TestInfo, { samples, ...summary }: LatencyReport): void { + const report = { ...summary, platform: process.platform } + console.log(`[layout-oracle] ${JSON.stringify(report)}`) + const scenario = summary.scenario + const dir = process.env[ORACLE_REPORT_DIR_ENV] ?? testInfo.outputPath('layout-oracle') + mkdirSync(dir, { recursive: true }) + writeFileSync( + path.join(dir, `${scenario}-${Date.now()}.json`), + `${JSON.stringify({ ...report, samples }, null, 2)}\n` + ) } // oxlint-disable-next-line no-empty-pattern -- The measurement owns its launch. test('layout oracle: command to drawn latency', async ({}, testInfo) => { - test.setTimeout(15 * 60_000) + test.setTimeout(90 * 60_000) const repoPath = seededRepoPathOrSkip() const session = createRestartSession(testInfo) const { app, page } = await session.launch() + const cleanups: (() => Promise)[] = [] try { const samples: Samples = {} const { worktreeId } = await bootstrapFirstLaunch(page, repoPath) const worktree = `id:${worktreeId}` const client = new RuntimeClient(session.userDataDir, 30_000) await waitForBoundPanes(page, 1) - await measureCondition(page, client, worktreeId, 'idle', samples) + const phases: Record = { + idle: { from: Date.now(), to: 0, confirms: 0 }, + flood: { from: 0, to: 0, confirms: 0 } + } + phases.idle.confirms = await measureCondition(page, client, worktreeId, 'idle', samples) + phases.idle.to = Date.now() - // A second tab floods output for the whole flood round; the measured tab stays active. + // Two flooding tabs beside the measured one and one in a worktree that is never shown. const list = await read(client, 'terminal.list', { worktree }) const measured = list.terminals[0]! - await client.call('terminal.create', { worktree, command: 'yes orca-latency-flood' }) + const hidden = await createHiddenWorktree(client, worktreeId, 'latency-flood') + cleanups.push(hidden.remove) + for (const target of [worktree, worktree, `id:${hidden.id}`]) { + const flood = await client.call<{ terminal: RuntimeTerminalCreate }>('terminal.create', { + worktree: target, + command: FLOOD_COMMAND + }) + await expectFlooding(client, flood.result.terminal.handle) + } await client.call('terminal.focus', { terminal: measured.handle, navigation: 'host' }) await waitForActiveTerminalManager(page) - await measureCondition(page, client, worktreeId, 'flood', samples) + phases.flood.from = Date.now() + phases.flood.confirms = await measureCondition(page, client, worktreeId, 'flood', samples) + phases.flood.to = Date.now() const summary = Object.fromEntries( Object.entries(samples).map(([action, values]) => [ action, { n: values.length, - p50: Math.round(percentile(values, 50)), - p95: Math.round(percentile(values, 95)) + inAppCommit: stats(values.map((sample) => sample.inApp.commitMs)), + inAppDrawn: stats(values.map((sample) => sample.inApp.drawnMs)), + outer: stats(values.map((sample) => sample.outerMs)) } ]) ) - console.log(`[layout-oracle] latency ms\n${JSON.stringify(summary, null, 2)}`) - const dir = process.env[ORACLE_REPORT_DIR_ENV] ?? testInfo.outputPath('layout-oracle') - mkdirSync(dir, { recursive: true }) - writeFileSync( - path.join(dir, `latency-${Date.now()}.json`), - `${JSON.stringify({ scenario: 'latency', summary, samples }, null, 2)}\n` + const eventLoopDelay = Object.fromEntries( + Object.entries(phases).map(([condition, phase]) => [ + condition, + summarizeEventLoopDelay(session.userDataDir, 'main', phase.from, phase.to) + ]) ) + const closeConfirms = { idle: phases.idle.confirms, flood: phases.flood.confirms } + writeLatencyReport(testInfo, { + scenario: 'latency', + summary, + eventLoopDelay, + closeConfirms, + samples + }) } finally { + for (const cleanup of cleanups) { + await cleanup().catch((error: unknown) => console.warn('[layout-oracle] cleanup', error)) + } + await session.close(app) + await session.dispose() + } +}) + +// oxlint-disable-next-line no-empty-pattern -- The measurement owns its launches. +test('layout oracle: time to first drawn on a large profile', async ({}, testInfo) => { + test.setTimeout(30 * 60_000) + const repoPath = seededRepoPathOrSkip() + const session = createRestartSession(testInfo) + let { app, page } = await session.launch() + const cleanups: (() => Promise)[] = [] + try { + const { worktreeId } = await bootstrapFirstLaunch(page, repoPath) + const worktree = `id:${worktreeId}` + const client = new RuntimeClient(session.userDataDir, 30_000) + for (let index = 0; index < LARGE_PROFILE.hiddenWorktrees; index += 1) { + const hidden = await createHiddenWorktree(client, worktreeId, `latency-profile-${index}`) + cleanups.push(hidden.remove) + for (let tab = 0; tab < LARGE_PROFILE.tabsPerWorktree; tab += 1) { + await client.call('terminal.create', { worktree: `id:${hidden.id}` }) + } + } + for (let tab = 1; tab < LARGE_PROFILE.tabsPerWorktree; tab += 1) { + await client.call('terminal.create', { worktree }) + } + const list = await read(client, 'terminal.list', { worktree }) + await client.call('terminal.focus', { terminal: list.terminals[0]!.handle, navigation: 'host' }) + await waitForActiveTerminalManager(page) + for (let panes = 2; panes <= LARGE_PROFILE.activePanes; panes += 1) { + await splitActiveTerminalPane(page, 'vertical') + await waitForBoundPanes(page, panes) + } + + const startup: StartupSample[] = [] + for (let index = 0; index < STARTUP_SAMPLES; index += 1) { + await session.close(app) + ;({ app, page } = await session.launch({ + beforeFirstWindow: (next) => installFirstDrawnWatch(next, LARGE_PROFILE.activePanes) + })) + const { processStartedAt, drawnAt } = await readFirstDrawn(app, page) + await waitForEventLoopDelayWindow(session.userDataDir, drawnAt) + startup.push({ + firstDrawnMs: Math.round(drawnAt - processStartedAt), + eventLoopDelayMax: summarizeEventLoopDelay( + session.userDataDir, + 'main', + processStartedAt, + drawnAt + ).max + }) + } + writeLatencyReport(testInfo, { + scenario: 'first-drawn', + note: 'from main process start, so includes DevTools attach; warm PTY daemon; relative use only', + profile: LARGE_PROFILE, + firstDrawn: { n: startup.length, ...stats(startup.map((sample) => sample.firstDrawnMs)) }, + eventLoopDelayMax: stats(startup.map((sample) => sample.eventLoopDelayMax)), + samples: startup + }) + } finally { + for (const cleanup of cleanups) { + await cleanup().catch((error: unknown) => console.warn('[layout-oracle] cleanup', error)) + } await session.close(app) await session.dispose() }