From bc06eef234fff598dd808359523d1685355d1094 Mon Sep 17 00:00:00 2001 From: Neil Date: Mon, 14 Sep 2026 13:10:34 -0700 Subject: [PATCH] feat(diagnostics): trace terminal startup delivery phases --- docs/reference/terminal-startup-timing.md | 30 ++++ src/main/ipc/pty-spawn-timing.test.ts | 69 +++++++++ src/main/ipc/pty-spawn-timing.ts | 21 ++- .../pty-connection/live-data-callback.ts | 2 +- .../session-reconcile-dispose.ts | 1 + .../transport-output-callbacks.ts | 15 ++ .../write-pty-output-to-xterm.ts | 12 +- .../terminal-startup-timing.test.ts | 141 ++++++++++++++++++ .../terminal-pane/terminal-startup-timing.ts | 112 ++++++++++++++ 9 files changed, 396 insertions(+), 7 deletions(-) create mode 100644 docs/reference/terminal-startup-timing.md create mode 100644 src/main/ipc/pty-spawn-timing.test.ts create mode 100644 src/renderer/src/components/terminal-pane/terminal-startup-timing.test.ts create mode 100644 src/renderer/src/components/terminal-pane/terminal-startup-timing.ts diff --git a/docs/reference/terminal-startup-timing.md b/docs/reference/terminal-startup-timing.md new file mode 100644 index 00000000000..bf79200fdfc --- /dev/null +++ b/docs/reference/terminal-startup-timing.md @@ -0,0 +1,30 @@ +# Terminal startup timing + +For #19333, enable the renderer's opt-in recorder in its DevTools console before opening a new terminal: + +```js +localStorage.setItem('orca:terminal-startup-timing', '1') +``` + +Remove the key to disable it. Existing sessions are unaffected. To capture the existing host spawn phases, start the host with `ORCA_PTY_SPAWN_TIMING=1`. Do not restart a host with active work just to enable diagnostics. + +The renderer emits one `terminal_startup_timing` breadcrumb per transport callback generation through the existing local diagnostic channel. In `main.trace.ndjson`, find the `renderer.breadcrumb` record whose `breadcrumb.name` matches. The host's existing console timing line also becomes a `pty.spawn.timing` trace record. Correlate available PTY IDs; renderer generation distinguishes retries. Compare elapsed durations within each process, not wall clocks across hosts. + +Renderer offsets are monotonic milliseconds from callback-generation creation immediately before a transport operation: + +| Field | Observation | +|---|---| +| connected | Transport connection callback accepted for the current generation | +| liveData | First nonempty live delivery, including control-only output | +| submitted | First live batch sent to the renderer output scheduler | +| writeStarted | Scheduler invokes the batch's pre-write callback | +| parsed | Xterm invokes that batch's completion callback | +| renderEvent | First public xterm render event after the batch starts writing | + +A render event can precede the parse callback. These observations do not establish the first printable glyph, physical screen presentation, React mount time or click-to-paint latency. Replay and synthetic reset writes do not claim the first live batch. A replay or resize can still contribute to a render event after a live write, so the event is temporal evidence rather than attribution to exact content. Hidden or restored panes may never submit a live batch; missing fields remain missing. A queue-cap warning can inherit the pre-write callback while discarding the original batch’s parse callback. In that case writeStarted/renderEvent describe incomplete pre-write activity, not successful delivery of the original batch; outcome cannot be observed without parsed. + +The recorder ends after connection, parse and render observations, or on replacement, disposal, error or a ten-second diagnostic deadline. It retains only phase numbers and identifiers, with one timer and at most one render listener while enabled. It does not retain terminal text, commands, credentials or transcript buffers. Disabled recording adds no listeners or timers. + +Host `phaseDurations` preserve the current phase boundaries: the timer starts after initial ownership lookups and logs before all commit/serializer work finishes. `totalMs` is that measured interval, not full IPC latency. `provider_spawn` includes provider call and surrounding reconciliation; it is not raw process creation time. The enclosing trace record is a diagnostic snapshot, not a span covering that interval. + +Reliability invariant: diagnostics must not change terminal output, delivery credits, provider ownership or spawn outcome. Failure source: Windows OMP first-paint report #19333. Oracle: opt-in recorder tests distinguish queued, parsed and render milestones; existing live-delivery and synchronized-output suites preserve output behavior. No matching startup diagnostic reliability gate exists; full click-to-physical-presentation remains an explicit validation gap. Native, daemon, WSL and SSH execution remain host-owned; this adds no wire fields or remote process queries. Mobile has no recorder change. macOS/Linux/Windows renderer timing uses the same public xterm events; physical-device timing requires a separate capture. diff --git a/src/main/ipc/pty-spawn-timing.test.ts b/src/main/ipc/pty-spawn-timing.test.ts new file mode 100644 index 00000000000..06485fd3bf7 --- /dev/null +++ b/src/main/ipc/pty-spawn-timing.test.ts @@ -0,0 +1,69 @@ +import { afterEach, beforeEach, expect, it, vi } from 'vitest' +import { setActiveSink } from '../observability/tracer' +import { createPtySpawnTiming } from './pty-spawn-timing' + +const records: unknown[] = [] +beforeEach(() => { + vi.useFakeTimers({ toFake: ['performance'] }) + records.length = 0 + setActiveSink({ + push: (r) => { + records.push(r) + }, + flush() {}, + close() {} + }) + vi.spyOn(console, 'log').mockImplementation(() => {}) +}) +afterEach(() => { + setActiveSink(null) + vi.restoreAllMocks() + vi.unstubAllEnvs() + vi.useRealTimers() +}) + +it('keeps disabled spawn timing silent', () => { + vi.stubEnv('ORCA_PTY_SPAWN_TIMING', '0') + const timing = createPtySpawnTiming() + timing.mark('provider_spawn') + timing.log('pty-1') + expect(records).toEqual([]) + expect(console.log).not.toHaveBeenCalled() +}) + +it('writes numeric monotonic phase durations through the existing local trace sink', () => { + vi.stubEnv('ORCA_PTY_SPAWN_TIMING', '1') + const timing = createPtySpawnTiming() + vi.advanceTimersByTime(25) + timing.mark('preflight') + vi.advanceTimersByTime(80) + timing.mark('provider_spawn') + timing.log('pty-1', { daemon: true, reattach: false }) + expect(records).toEqual([ + expect.objectContaining({ + name: 'pty.spawn.timing', + attributes: expect.objectContaining({ + ptyId: 'pty-1', + totalMs: 105, + phaseDurations: { preflight: 25, provider_spawn: 80 }, + daemon: true, + reattach: false + }) + }) + ]) + expect(console.log).toHaveBeenCalledWith( + expect.stringContaining('total=105ms preflight=25ms provider_spawn=80ms') + ) +}) + +it('does not fail a successful spawn when the diagnostic sink throws', () => { + vi.stubEnv('ORCA_PTY_SPAWN_TIMING', '1') + setActiveSink({ + push() { + throw new Error('disk unavailable') + }, + flush() {}, + close() {} + }) + expect(() => createPtySpawnTiming().log('pty-1')).not.toThrow() +}) diff --git a/src/main/ipc/pty-spawn-timing.ts b/src/main/ipc/pty-spawn-timing.ts index edf98412ab9..3fcc12a9639 100644 --- a/src/main/ipc/pty-spawn-timing.ts +++ b/src/main/ipc/pty-spawn-timing.ts @@ -1,3 +1,5 @@ +import { startSpan } from '../observability/tracer' + // Why: pty:spawn latency has several very different suspects (startup barrier, // Claude auth prep, Codex resume/hook prep, account resolution, buildPtyHostEnv // filesystem work, provider/daemon spawn). A single opt-in log line per spawn @@ -21,23 +23,34 @@ export function createPtySpawnTiming(): PtySpawnTiming { if (!flag || flag === '0' || flag.toLowerCase() === 'false') { return noopTiming } - const startedAt = Date.now() + const startedAt = performance.now() let lastAt = startedAt const phases: string[] = [] + const phaseDurations: Record = {} return { mark(phase: string): void { - const now = Date.now() - phases.push(`${phase}=${now - lastAt}ms`) + const now = performance.now() + const elapsed = now - lastAt + phases.push(`${phase}=${Math.round(elapsed)}ms`) + phaseDurations[phase] = elapsed lastAt = now }, log(id: string, extra?: Record): void { + const totalMs = performance.now() - startedAt const extras = extra ? ` ${Object.entries(extra) .map(([key, value]) => `${key}=${value}`) .join(' ')}` : '' + try { + startSpan('pty.spawn.timing', { + attributes: { ptyId: id, totalMs, phaseDurations, ...extra } + }).end() + } catch { + // Optional diagnostics must not reject a successful spawn. + } console.log( - `[pty-spawn-timing] id=${id} total=${Date.now() - startedAt}ms ${phases.join(' ')}${extras}` + `[pty-spawn-timing] id=${id} total=${Math.round(totalMs)}ms ${phases.join(' ')}${extras}` ) } } diff --git a/src/renderer/src/components/terminal-pane/pty-connection/live-data-callback.ts b/src/renderer/src/components/terminal-pane/pty-connection/live-data-callback.ts index ac50af346cd..e42423fa418 100644 --- a/src/renderer/src/components/terminal-pane/pty-connection/live-data-callback.ts +++ b/src/renderer/src/components/terminal-pane/pty-connection/live-data-callback.ts @@ -171,7 +171,7 @@ export function bindLiveDataCallback(session: ConnectPanePtySession): void { hiddenStartupRendererQuery: true }) } - session.writePtyOutputToXterm(orderedRendererData, foreground) + session.writePtyOutputToXterm(orderedRendererData, foreground, { liveStartupBatch: true }) if (foreground) { session.recordRendererOrderedSeq(rendererMeta) } diff --git a/src/renderer/src/components/terminal-pane/pty-connection/session-reconcile-dispose.ts b/src/renderer/src/components/terminal-pane/pty-connection/session-reconcile-dispose.ts index 88f7b7cad01..798131ca5ad 100644 --- a/src/renderer/src/components/terminal-pane/pty-connection/session-reconcile-dispose.ts +++ b/src/renderer/src/components/terminal-pane/pty-connection/session-reconcile-dispose.ts @@ -176,6 +176,7 @@ export function installSessionReconcileDispose(session: ConnectPanePtySession): session.spawnedFreshPtyId === ptyId && !Number.isFinite(session.lastTerminalInputAt), dispose() { session.disposed = true + session.startupTiming?.finish('disposed') // A successor can claim the numeric pane slot before this retired // binding's disposal callback runs; do not clear its pane-scoped error. const currentPaneTransport = session.deps.paneTransportsRef.current.get(session.pane.id) diff --git a/src/renderer/src/components/terminal-pane/pty-connection/transport-output-callbacks.ts b/src/renderer/src/components/terminal-pane/pty-connection/transport-output-callbacks.ts index a1e2e97e070..6b77a95c084 100644 --- a/src/renderer/src/components/terminal-pane/pty-connection/transport-output-callbacks.ts +++ b/src/renderer/src/components/terminal-pane/pty-connection/transport-output-callbacks.ts @@ -1,3 +1,4 @@ +import { createTerminalStartupTiming } from '../terminal-startup-timing' import type { PtyReplayDataMeta } from '../pty-transport' import type { PtyTransportRecoveryState } from '../pty-transport-types' import type { PtyDataMeta } from '../pty-dispatcher' @@ -27,6 +28,15 @@ export function bindCaptureTransportOutputCallbacks(session: ConnectPanePtySessi // stream's queued callback runs; only the registered transport may // mutate pane-scoped error/recovery state. session.deps.paneTransportsRef.current.get(session.pane.id) === session.transport + session.startupTiming?.finish('replaced') + session.startupTiming = createTerminalStartupTiming({ + paneKey: session.cacheKey, + generation, + getPtyId: () => session.transport.getPtyId(), + isCurrent, + isForeground: () => session.deps.isVisibleRef.current, + onRender: (callback) => session.pane.terminal.onRender(callback) + }) return { generation, callbacks: { @@ -37,6 +47,7 @@ export function bindCaptureTransportOutputCallbacks(session: ConnectPanePtySessi }, onConnect: (): void => { if (isCurrent()) { + session.startupTiming?.mark('connected') session.reportRemoteRendererSerializerReady() // Re-derive the pause bit after a rebind; visibility can change while no PTY is bound. session.syncHiddenRendererPtyDelivery() @@ -49,6 +60,9 @@ export function bindCaptureTransportOutputCallbacks(session: ConnectPanePtySessi }, onData: (data: string, meta?: PtyDataMeta): void => { if (isCurrent()) { + if (data.length > 0) { + session.startupTiming?.mark('liveData') + } processExitState.detector.observe(data) session.dataCallback(data, meta, generation) } @@ -60,6 +74,7 @@ export function bindCaptureTransportOutputCallbacks(session: ConnectPanePtySessi }, onError: (message: string): void => { if (isCurrent()) { + session.startupTiming?.finish('error') onError(message) } }, diff --git a/src/renderer/src/components/terminal-pane/pty-connection/write-pty-output-to-xterm.ts b/src/renderer/src/components/terminal-pane/pty-connection/write-pty-output-to-xterm.ts index 28498734a05..66c89154cbd 100644 --- a/src/renderer/src/components/terminal-pane/pty-connection/write-pty-output-to-xterm.ts +++ b/src/renderer/src/components/terminal-pane/pty-connection/write-pty-output-to-xterm.ts @@ -17,7 +17,7 @@ export function bindWritePtyOutputToXterm(session: ConnectPanePtySession): void session.writePtyOutputToXterm = function ( data: string, foreground: boolean, - opts?: { hiddenStartupRendererQuery?: boolean } + opts?: { hiddenStartupRendererQuery?: boolean; liveStartupBatch?: boolean } ): void { // Why: every application byte funnels through here, so it's the one place the kitty keyboard mirror observes the pane's protocol negotiation. session.kittyKeyboardModes.scan(data) @@ -77,9 +77,17 @@ export function bindWritePtyOutputToXterm(session: ConnectPanePtySession): void synchronizedForegroundOutput && session.synchronizedForegroundFrameInteractive session.synchronizedForegroundOutputActive = nextSynchronizedForegroundOutputActive session.synchronizedForegroundMarkerTail = synchronizedForegroundScan?.markerTail ?? '' + const startupWrite = + opts?.liveStartupBatch && data.length > 0 ? session.startupTiming?.firstWrite() : undefined writeTerminalOutput(session.pane.terminal, data, { foreground: foregroundOutput, - beforeWrite: session.beforeTerminalOutputWrite, + beforeWrite: startupWrite + ? (chunk) => { + session.beforeTerminalOutputWrite?.(chunk) + startupWrite.beforeWrite() + } + : session.beforeTerminalOutputWrite, + ...(startupWrite ? { onParsed: startupWrite.onParsed } : {}), // Why: every scheduler write claims one child so a split delivery is credited only after all children parse or discard. ackCredit: takeCurrentTerminalDeliveryCredit() ?? undefined, onBackgroundBacklogDropped: session.markHiddenOutputRestoreNeeded, diff --git a/src/renderer/src/components/terminal-pane/terminal-startup-timing.test.ts b/src/renderer/src/components/terminal-pane/terminal-startup-timing.test.ts new file mode 100644 index 00000000000..432db065891 --- /dev/null +++ b/src/renderer/src/components/terminal-pane/terminal-startup-timing.test.ts @@ -0,0 +1,141 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import { createTerminalStartupTiming } from './terminal-startup-timing' + +const record = vi.hoisted(() => vi.fn()) +vi.mock('@/lib/crash-breadcrumb-recorder', () => ({ recordRendererCrashBreadcrumb: record })) + +function fixture(enabled = true, failure?: 'subscribe' | 'dispose') { + vi.stubGlobal('localStorage', { getItem: () => (enabled ? '1' : null) }) + let current = true + let ptyId = 'pty-1' + let render: (() => void) | undefined + const dispose = vi.fn(() => { + if (failure === 'dispose') { + throw new Error('disposed terminal') + } + }) + const onRender = vi.fn((callback: () => void) => { + if (failure === 'subscribe') { + throw new Error('unavailable renderer') + } + render = callback + return { dispose } + }) + const timing = createTerminalStartupTiming({ + paneKey: 'tab:pane', + generation: 1, + getPtyId: () => ptyId, + isCurrent: () => current, + isForeground: () => true, + onRender + }) + return { + timing, + onRender, + dispose, + render: () => render?.(), + retire: () => { + current = false + ptyId = 'successor' + } + } +} + +beforeEach(() => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'performance'] }) + vi.stubGlobal('document', { visibilityState: 'hidden' }) + record.mockClear() +}) +afterEach(() => { + vi.useRealTimers() + vi.unstubAllGlobals() +}) + +describe('opt-in terminal startup diagnostics', () => { + it('allocates no timer or subscription while disabled', () => { + const f = fixture(false) + expect(f.timing).toBeUndefined() + expect(vi.getTimerCount()).toBe(0) + expect(f.onRender).not.toHaveBeenCalled() + }) + + it('separates early control data, queue delay, parsing and later connection', () => { + const f = fixture() + vi.advanceTimersByTime(10) + f.timing?.mark('liveData') + vi.advanceTimersByTime(20) + const write = f.timing?.firstWrite() + vi.advanceTimersByTime(1000) + expect(record).not.toHaveBeenCalled() + write?.beforeWrite() + f.render() + vi.advanceTimersByTime(5) + write?.onParsed() + expect(record).not.toHaveBeenCalled() + vi.advanceTimersByTime(5) + f.timing?.mark('connected') + expect(record).toHaveBeenCalledWith( + 'terminal_startup_timing', + expect.objectContaining({ + liveData: 10, + submitted: 30, + writeStarted: 1030, + renderEvent: 1030, + parsed: 1035, + connected: 1040, + outcome: 'observed', + documentVisible: false + }) + ) + expect(f.dispose).toHaveBeenCalledOnce() + expect(vi.getTimerCount()).toBe(0) + f.render() + f.timing?.finish('disposed') + expect(record).toHaveBeenCalledOnce() + }) + + it('does not subscribe from arrival alone or claim a render on timeout', () => { + const f = fixture() + f.timing?.mark('liveData') + f.timing?.mark('connected') + expect(f.onRender).not.toHaveBeenCalled() + vi.advanceTimersByTime(10_000) + expect(record.mock.calls[0][1]).toMatchObject({ outcome: 'timeout', liveData: 0 }) + expect(record.mock.calls[0][1]).not.toHaveProperty('renderEvent') + expect(vi.getTimerCount()).toBe(0) + }) + + it.each(['subscribe', 'dispose'] as const)( + 'contains a %s failure without interrupting writes or cleanup', + (failure) => { + const f = fixture(true, failure) + const write = f.timing?.firstWrite() + expect(() => write?.beforeWrite()).not.toThrow() + expect(() => f.timing?.finish('disposed')).not.toThrow() + expect(record).toHaveBeenCalledOnce() + expect(vi.getTimerCount()).toBe(0) + } + ) + + it.each(['disposed', 'replaced', 'error'] as const)( + 'cleans up %s and ignores late callbacks', + (reason) => { + const f = fixture() + f.timing?.mark('liveData') + const write = f.timing?.firstWrite() + write?.beforeWrite() + write?.beforeWrite() + expect(f.onRender).toHaveBeenCalledOnce() + expect(f.timing?.firstWrite()).toBeUndefined() + f.retire() + f.timing?.finish(reason) + write?.onParsed() + f.render() + expect(record).toHaveBeenCalledOnce() + expect(record.mock.calls[0][1]).not.toHaveProperty('parsed') + expect(record.mock.calls[0][1].ptyId).toBe('pty-1') + expect(f.dispose).toHaveBeenCalledOnce() + expect(vi.getTimerCount()).toBe(0) + } + ) +}) diff --git a/src/renderer/src/components/terminal-pane/terminal-startup-timing.ts b/src/renderer/src/components/terminal-pane/terminal-startup-timing.ts new file mode 100644 index 00000000000..4b27a998c54 --- /dev/null +++ b/src/renderer/src/components/terminal-pane/terminal-startup-timing.ts @@ -0,0 +1,112 @@ +import { recordRendererCrashBreadcrumb } from '@/lib/crash-breadcrumb-recorder' + +export const TERMINAL_STARTUP_TIMING_KEY = 'orca:terminal-startup-timing' +type Disposable = { dispose(): void } +type Phase = 'connected' | 'liveData' | 'submitted' | 'writeStarted' | 'parsed' | 'renderEvent' +type Finish = 'observed' | 'timeout' | 'disposed' | 'replaced' | 'error' +type WriteTiming = { beforeWrite(): void; onParsed(): void } + +export type TerminalStartupTiming = { + mark(phase: Phase): void + firstWrite(): WriteTiming | undefined + finish(outcome: Finish): void +} + +export function createTerminalStartupTiming(options: { + paneKey: string + generation: number + getPtyId(): string | null + isCurrent(): boolean + isForeground(): boolean + onRender(callback: () => void): Disposable +}): TerminalStartupTiming | undefined { + try { + if (localStorage.getItem(TERMINAL_STARTUP_TIMING_KEY) !== '1') { + return undefined + } + } catch { + return undefined + } + const started = performance.now() + const phases: Partial> = {} + let observedPtyId: string | null = null + let ended = false + let writeClaimed = false + let renderSubscription: Disposable | undefined + const timeout = setTimeout(() => finish('timeout'), 10_000) + + function finish(outcome: Finish): void { + if (ended) { + return + } + ended = true + clearTimeout(timeout) + try { + renderSubscription?.dispose() + } catch { + // Optional diagnostics cannot interrupt terminal cleanup. + } + try { + recordRendererCrashBreadcrumb('terminal_startup_timing', { + paneKey: options.paneKey, + generation: options.generation, + ptyId: observedPtyId, + outcome, + foreground: options.isForeground(), + documentVisible: document.visibilityState === 'visible', + elapsedMs: performance.now() - started, + ...phases + }) + } catch { + // A disappearing transport must not make diagnostic completion fail. + } + } + function mark(phase: Phase): void { + if (ended || !options.isCurrent() || phases[phase] !== undefined) { + return + } + if ((phase === 'connected' || phase === 'liveData') && observedPtyId === null) { + try { + observedPtyId = options.getPtyId() + } catch { + // Preserve an unknown identity when the current transport cannot report it. + } + } + phases[phase] = performance.now() - started + if ( + phases.connected !== undefined && + phases.parsed !== undefined && + phases.renderEvent !== undefined + ) { + finish('observed') + } + } + return { + mark, + finish, + firstWrite() { + if (ended || writeClaimed || !options.isCurrent()) { + return undefined + } + writeClaimed = true + mark('submitted') + return { + beforeWrite() { + if (ended || !options.isCurrent() || phases.writeStarted !== undefined) { + return + } + mark('writeStarted') + // The public event reports xterm activity, not physical display presentation. + try { + renderSubscription = options.onRender(() => mark('renderEvent')) + } catch { + finish('error') + } + }, + onParsed() { + mark('parsed') + } + } + } + } +}