mirror of
https://github.com/stablyai/orca.git
synced 2026-09-22 16:02:32 +00:00
* 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
281 lines
11 KiB
TypeScript
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))
|
|
}))
|
|
}
|
|
}
|