Files
orca/tests/e2e/runtime-graph-publication-probe.ts
Jinwoo Hong a634bf9b49 test(bench): runtime-graph publication probe and optional CDP CPU throttle (#21107)
* test(bench): count runtime-graph publications from main

The build-provided `__orcaBenchmarkInstrumentation` is gone from the tree, so
the typing bench could no longer report graph-publication counts at all. The
renderer cannot supply them either: `window.api` is frozen by contextBridge,
so `runtime.syncWindowGraph` is not wrappable.

Count them where they land instead — main's `runtime:syncWindowGraph` invoke
handler — behind ORCA_TYPING_BENCH_GRAPH_PROBE=1, and record the result in the
bench report. Measured on an 870-worktree fixture: 21 publications over a 50 s
metadata-only window versus ~1,205 with recurring OSC title/status traffic.

The long-task fields ship unproven: an injected 250 ms renderer busy-wait
produced zero entries even though `longtask` is in `supportedEntryTypes`, so
their zeros mean "oracle unverified", not "no long task". The self-test knob
exists to make that falsifiable, and the file says so; per-publication build
time still needs a separate --cpu-profile run.

* test(bench): optional CDP CPU throttle around the typing window

* test(bench): report the throttle that ran and the long task the self-test caused

Two ways the bench could misreport its own conditions.

`cpuThrottleRate` was the requested rate, written into every report, but only
two of the three scenarios wrapped their typing window in the throttle — a
`--cpu-throttle 4` visible-split run claimed a 4x throttle it never applied.
Recording the rate per scenario would have made the report honest; it would
also have left one scenario silently ignoring the flag, and a fourth scenario
would inherit the same omission. So both: every scenario now goes through one
`measureTypingWindow` helper, and the value it returns is the rate the throttle
actually applied. `writeBenchReport` takes that composite instead of a bare
measurement, so a scenario cannot produce a report without saying what it ran
under. Unthrottled runs are unchanged — rate 1 still opens no CDP session.

`selfTestLongTaskMs` took the *earliest* long task starting before a cutoff
captured after the busy-wait. The observer has been live since probe start, so
any unrelated long task from fixture setup satisfied it — the field whose whole
job is to prove the oracle is live was the easiest one to fake. The busy-wait
now reports its own renderer-clock bounds and the matching entry is the one
containing their midpoint: main-thread tasks never overlap, so at most one can,
and it is the task the busy-wait ran in. That entry is then withheld from
`longTasks`, `longestLongTasks`, and `longTasksAroundPublication`, which had
been counting the oracle's injected 250 ms as workload.

A zero still means "oracle unproven" — it now also means it honestly.

* test(bench): stop the graph probe when the typing run throws

* test(e2e): drain queued long-task records before the probe disconnects
2026-09-17 17:32:20 -04:00

281 lines
11 KiB
TypeScript

/**
* Diagnostic-only probe for renderer runtime-graph publication cost.
*
* `window.api` is frozen by contextBridge, so the renderer cannot wrap
* `runtime.syncWindowGraph`. Instead this counts publications where they land —
* main's `runtime:syncWindowGraph` invoke handler.
*
* `publications` and `mainHandler` are trustworthy. The long-task fields are NOT
* yet: on 2026-09-16 an injected 250 ms renderer busy-wait produced zero entries
* even though `longtask` is in `supportedEntryTypes`, so a zero there means
* "oracle unproven", not "no long task happened". Run with
* ORCA_TYPING_BENCH_GRAPH_PROBE_SELFTEST_MS and require a non-zero
* `selfTestLongTaskMs` before believing any long-task number. That number comes
* from the entry the busy-wait actually ran in (see `partitionSelfTestLongTask`),
* so unrelated work cannot satisfy it, and the same entry is withheld from every
* workload summary so the oracle does not measure itself.
*
* Renderer-side per-publication build time is unavailable here; attribute it
* with a separate --cpu-profile run instead.
*
* Keep this out of acceptance timing runs (gate: ORCA_TYPING_BENCH_GRAPH_PROBE=1).
*/
import type { ElectronApplication, Page } from '@stablyai/playwright-test'
const GRAPH_CHANNEL = 'runtime:syncWindowGraph'
export type DurationSummary = {
count: number
totalMs: number
maxMs: number
p50Ms: number
p90Ms: number
}
export type LongTaskSample = { startEpochMs: number; durationMs: number }
/** Renderer-clock bounds of the injected busy-wait, same base as long-task entries. */
export type RendererLongTaskSelfTestWindow = { startEpochMs: number; endEpochMs: number }
export type RuntimeGraphPublicationProbeSnapshot = {
mainCounterInstalled: boolean
mainCounterReason: string
rendererObserverInstalled: boolean
rendererObserverReason: string
/** Publications counted at main's invoke handler. */
publications: number
/** Main-side handler duration (excludes the renderer-side graph build). */
mainHandler: DurationSummary
/** Gaps between consecutive publications, epoch ms. */
publicationIntervalMs: DurationSummary
/** Workload long tasks; the self-test's own entry is excluded. */
longTasks: DurationSummary
/** Non-zero only when the self-test's own entry was observed; proves the oracle is live. */
selfTestLongTaskMs: number
/** Long tasks whose window contains a publication's main-side arrival. */
longTasksAroundPublication: DurationSummary
longestLongTasks: LongTaskSample[]
}
type MainProbeGlobals = {
__orcaGraphPublicationMainProbe?: {
stop: () => { count: number; handlerMs: number[]; atEpochMs: number[] }
}
}
type RendererProbeWindow = Window & {
__orcaGraphPublicationRendererProbe?: {
stop: () => { timeOrigin: number; longTasks: { start: number; duration: number }[] }
}
}
function summarize(values: number[]): DurationSummary {
if (values.length === 0) {
return { count: 0, totalMs: 0, maxMs: 0, p50Ms: 0, p90Ms: 0 }
}
const sorted = [...values].sort((a, b) => a - b)
const at = (fraction: number): number =>
sorted[Math.min(sorted.length - 1, Math.floor(fraction * sorted.length))] ?? 0
const round = (value: number): number => Number(value.toFixed(1))
return {
count: sorted.length,
totalMs: round(sorted.reduce((sum, value) => sum + value, 0)),
maxMs: round(sorted.at(-1) ?? 0),
p50Ms: round(at(0.5)),
p90Ms: round(at(0.9))
}
}
/**
* Presence precondition for the long-task oracle: burns a known span on the
* renderer thread so a run that reports zero long tasks has proved it could
* have seen one. Returns the busy-wait's own bounds — a cutoff timestamp would
* let any earlier unrelated long task stand in for it.
*/
export async function injectRendererLongTaskSelfTest(
page: Page,
busyMs: number
): Promise<RendererLongTaskSelfTestWindow> {
return page.evaluate((durationMs) => {
const startedAt = performance.now()
const deadline = startedAt + durationMs
while (performance.now() < deadline) {
// Intentional busy wait: setTimeout would not produce a long task.
}
return {
startEpochMs: performance.timeOrigin + startedAt,
endEpochMs: performance.timeOrigin + performance.now()
}
}, busyMs)
}
/**
* Main-thread tasks never overlap, so at most one long task can contain the
* busy-wait's midpoint and that one is the task the busy-wait ran in. Anything
* else — including a long task that merely started earlier — leaves the oracle
* unproven rather than falsely satisfied.
*/
export function partitionSelfTestLongTask(
longTasks: LongTaskSample[],
selfTest: RendererLongTaskSelfTestWindow | null
): { selfTestLongTaskMs: number; workloadLongTasks: LongTaskSample[] } {
if (!selfTest) {
return { selfTestLongTaskMs: 0, workloadLongTasks: longTasks }
}
const midpoint = (selfTest.startEpochMs + selfTest.endEpochMs) / 2
const selfTestTask = longTasks.find(
(task) => task.startEpochMs <= midpoint && midpoint <= task.startEpochMs + task.durationMs
)
if (!selfTestTask) {
return { selfTestLongTaskMs: 0, workloadLongTasks: longTasks }
}
return {
selfTestLongTaskMs: Number(selfTestTask.durationMs.toFixed(1)),
// Identity, not value: duplicate-looking entries must not be dropped too.
workloadLongTasks: longTasks.filter((task) => task !== selfTestTask)
}
}
export async function startRuntimeGraphPublicationProbe(
electronApp: ElectronApplication,
page: Page
): Promise<{ main: string; renderer: string }> {
const main = await electronApp.evaluate(({ ipcMain }, channel): string => {
// oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: diagnostic-only read of Electron's private invoke-handler map; every use is guarded by the shape checks below.
const registry = (ipcMain as unknown as { _invokeHandlers?: Map<string, unknown> })
._invokeHandlers
if (!(registry instanceof Map)) {
return 'no-invoke-handler-registry'
}
const original = registry.get(channel)
if (typeof original !== 'function') {
return `handler-missing typeof=${typeof original}`
}
// oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: Electron stores invoke handlers as callables; arguments are forwarded unchanged and never introspected.
const call = original as (...args: unknown[]) => unknown
const handlerMs: number[] = []
const atEpochMs: number[] = []
const publications = { count: 0, handlerMs, atEpochMs }
const wrapped = async (...args: unknown[]): Promise<unknown> => {
const startedAt = Date.now()
const startedHr = process.hrtime.bigint()
publications.count += 1
publications.atEpochMs.push(startedAt)
try {
return await call(...args)
} finally {
publications.handlerMs.push(Number(process.hrtime.bigint() - startedHr) / 1e6)
}
}
registry.set(channel, wrapped)
// oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: main-process bag read back only by the paired stop() call in this same run.
const globals = globalThis as unknown as MainProbeGlobals
globals.__orcaGraphPublicationMainProbe = {
stop: () => {
if (registry.get(channel) === wrapped) {
registry.set(channel, original)
}
delete globals.__orcaGraphPublicationMainProbe
return publications
}
}
return 'installed'
}, GRAPH_CHANNEL)
const renderer = await page.evaluate((): string => {
const probeWindow: RendererProbeWindow = window
if (probeWindow.__orcaGraphPublicationRendererProbe) {
return 'already-installed'
}
const supported = PerformanceObserver.supportedEntryTypes ?? []
if (!supported.includes('longtask')) {
return `longtask-unsupported supported=${supported.join('|')}`
}
const longTasks: { start: number; duration: number }[] = []
let observer: PerformanceObserver
try {
observer = new PerformanceObserver((list) => {
for (const entry of list.getEntries()) {
longTasks.push({ start: entry.startTime, duration: entry.duration })
}
})
observer.observe({ entryTypes: ['longtask'] })
} catch (error) {
return `longtask-observer-unavailable ${String(error)}`
}
probeWindow.__orcaGraphPublicationRendererProbe = {
stop: () => {
for (const entry of observer.takeRecords()) {
longTasks.push({ start: entry.startTime, duration: entry.duration })
}
observer.disconnect()
delete probeWindow.__orcaGraphPublicationRendererProbe
return { timeOrigin: performance.timeOrigin, longTasks }
}
}
return 'installed'
})
return { main, renderer }
}
export async function stopRuntimeGraphPublicationProbe(
electronApp: ElectronApplication,
page: Page,
start: { main: string; renderer: string },
selfTest: RendererLongTaskSelfTestWindow | null = null
): Promise<RuntimeGraphPublicationProbeSnapshot> {
const mainResult =
start.main === 'installed'
? await electronApp.evaluate(() => {
// oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: reads back the bag installed by startRuntimeGraphPublicationProbe in this run.
const globals = globalThis as unknown as MainProbeGlobals
return globals.__orcaGraphPublicationMainProbe?.stop() ?? null
})
: null
const rendererResult =
start.renderer === 'installed'
? await page.evaluate(() => {
const probeWindow: RendererProbeWindow = window
return probeWindow.__orcaGraphPublicationRendererProbe?.stop() ?? null
})
: null
const publicationEpochMs = mainResult?.atEpochMs ?? []
const intervals = publicationEpochMs
.slice(1)
.map((value, index) => value - (publicationEpochMs[index] ?? value))
const timeOrigin = rendererResult?.timeOrigin ?? 0
const longTasks: LongTaskSample[] = (rendererResult?.longTasks ?? []).map((task) => ({
startEpochMs: timeOrigin + task.start,
durationMs: task.duration
}))
const { selfTestLongTaskMs, workloadLongTasks } = partitionSelfTestLongTask(longTasks, selfTest)
// A renderer graph build ends at the invoke; allow slack for IPC transit either way.
const around = workloadLongTasks.filter((task) =>
publicationEpochMs.some(
(at) => at >= task.startEpochMs - 5 && at <= task.startEpochMs + task.durationMs + 50
)
)
return {
mainCounterInstalled: start.main === 'installed',
mainCounterReason: start.main,
rendererObserverInstalled: start.renderer === 'installed',
rendererObserverReason: start.renderer,
publications: mainResult?.count ?? 0,
mainHandler: summarize(mainResult?.handlerMs ?? []),
publicationIntervalMs: summarize(intervals),
longTasks: summarize(workloadLongTasks.map((task) => task.durationMs)),
selfTestLongTaskMs,
longTasksAroundPublication: summarize(around.map((task) => task.durationMs)),
longestLongTasks: [...workloadLongTasks]
.sort((a, b) => b.durationMs - a.durationMs)
.slice(0, 10)
.map((task) => ({
startEpochMs: task.startEpochMs,
durationMs: Number(task.durationMs.toFixed(1))
}))
}
}