mirror of
https://github.com/stablyai/orca.git
synced 2026-10-31 00:57:45 +00:00
test(perf): layout latency instruments and a main baseline (#27538)
* test(perf): in-app layout latency probe, event-loop delay on main and orcad, and a main baseline * test(perf): plain report comment * test(perf): name the latency report type * test(perf): add the Linux CI baseline; routine runs take 10 samples * test(perf): stamp close pane on the w key, keep probe work out of samples, label first drawn and Linux flood
This commit is contained in:
Jinwoo Hong
@@ -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)
|
||||
})
|
||||
})
|
||||
@@ -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?.()
|
||||
}
|
||||
@@ -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)
|
||||
|
||||
@@ -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
|
||||
)
|
||||
|
||||
@@ -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<EventLoopDelayWindow, 'process' | 't' | 'windowMs' | 'p99' | 'max'>
|
||||
|
||||
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<void> {
|
||||
await expect
|
||||
.poll(() => readWindows(userDataDir).some((entry) => entry.t >= epochMs), {
|
||||
timeout: 10_000,
|
||||
message: 'the event-loop delay probe wrote no window'
|
||||
})
|
||||
.toBe(true)
|
||||
}
|
||||
@@ -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<HTMLElement>('[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<void> {
|
||||
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
|
||||
}
|
||||
}
|
||||
@@ -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<void>
|
||||
}
|
||||
|
||||
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<void> {
|
||||
return page.evaluate(
|
||||
({ condition, startOn, confirmButton, tabSelector, timeoutMs }) => {
|
||||
const holds = (): boolean => {
|
||||
const tabs = (): HTMLElement[] =>
|
||||
Array.from(document.querySelectorAll<HTMLElement>(tabSelector))
|
||||
switch (condition.kind) {
|
||||
case 'panes': {
|
||||
const surface = Array.from(
|
||||
document.querySelectorAll<HTMLElement>('[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<void>((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<InAppSample | null> {
|
||||
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 }
|
||||
}
|
||||
@@ -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<string, number>
|
||||
report: {
|
||||
findings: OracleFinding[]
|
||||
viewCreations: Record<string, number>
|
||||
/** 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`)
|
||||
}
|
||||
|
||||
@@ -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`
|
||||
)
|
||||
}
|
||||
|
||||
|
||||
@@ -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."
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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<string, number[]>
|
||||
type Sample = { outerMs: number; inApp: InAppSample }
|
||||
type Samples = Record<string, Sample[]>
|
||||
|
||||
/** Reads can briefly fail while the window re-publishes its terminals; only reads are retried. */
|
||||
async function read<T>(client: RuntimeClient, method: string, params: unknown): Promise<T> {
|
||||
@@ -41,35 +73,44 @@ async function read<T>(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<unknown>,
|
||||
drawn: (page: Page) => Promise<unknown>
|
||||
): Promise<number> {
|
||||
const started = performance.now()
|
||||
await command()
|
||||
await drawn(page)
|
||||
return performance.now() - started
|
||||
condition: DrawnCondition,
|
||||
options: ArmOptions,
|
||||
send: () => Promise<unknown>
|
||||
): Promise<Sample | null> {
|
||||
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<HTMLElement>('[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<void> {
|
||||
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<void> {
|
||||
): Promise<number> {
|
||||
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<RuntimeTerminalListResult['terminals']> =>
|
||||
(await read<RuntimeTerminalListResult>(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<RuntimeMobileSessionTabsResult>(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<HTMLElement>(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<void> {
|
||||
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<void> }> {
|
||||
const shown = await client.call<{ worktree: { repoId: string } }>('worktree.show', {
|
||||
worktree: `id:${worktreeId}`
|
||||
})
|
||||
const created = await client.call<RuntimeWorktreeCreateResult>('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<typeof stats>
|
||||
type StartupSample = { firstDrawnMs: number; eventLoopDelayMax: number }
|
||||
type LatencyReport =
|
||||
| {
|
||||
scenario: 'latency'
|
||||
summary: Record<string, { n: number; inAppCommit: Stats; inAppDrawn: Stats; outer: Stats }>
|
||||
eventLoopDelay: Record<string, EventLoopDelaySummary>
|
||||
closeConfirms: Record<Condition, number>
|
||||
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<void>)[] = []
|
||||
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<Condition, { from: number; to: number; confirms: number }> = {
|
||||
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<RuntimeTerminalListResult>(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<void>)[] = []
|
||||
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<RuntimeTerminalListResult>(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()
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user