mirror of
https://github.com/stablyai/orca.git
synced 2026-09-22 08:02:28 +00:00
feat(diagnostics): trace terminal startup delivery phases
Merge fully verified: all required CI checks pass. This lands bounded startup timing instrumentation for the open Windows OMP first-paint investigation in #19333; it does not claim the latency fix itself.
This commit is contained in:
@@ -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.
|
||||
@@ -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()
|
||||
})
|
||||
@@ -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<string, number> = {}
|
||||
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<string, string | number | boolean>): 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}`
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
|
||||
+15
@@ -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)
|
||||
}
|
||||
},
|
||||
|
||||
+10
-2
@@ -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,
|
||||
|
||||
@@ -0,0 +1,126 @@
|
||||
import { afterEach, beforeEach, expect, it, vi } from 'vitest'
|
||||
import {
|
||||
createTerminal,
|
||||
loadScheduler
|
||||
} from '@/lib/pane-manager/pane-terminal-output-scheduler-test-harness'
|
||||
import { createTerminalStartupTiming } from './terminal-startup-timing'
|
||||
|
||||
const record = vi.hoisted(() => vi.fn())
|
||||
vi.mock('@/lib/crash-breadcrumb-recorder', () => ({ recordRendererCrashBreadcrumb: record }))
|
||||
|
||||
beforeEach(() => {
|
||||
vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'performance'] })
|
||||
vi.stubGlobal('window', globalThis)
|
||||
vi.stubGlobal('document', { visibilityState: 'hidden' })
|
||||
vi.stubGlobal('localStorage', { getItem: () => '1' })
|
||||
record.mockClear()
|
||||
})
|
||||
|
||||
afterEach(() => {
|
||||
vi.useRealTimers()
|
||||
vi.unstubAllGlobals()
|
||||
})
|
||||
|
||||
function fixture() {
|
||||
let render: (() => void) | undefined
|
||||
const dispose = vi.fn()
|
||||
const timing = createTerminalStartupTiming({
|
||||
paneKey: 'tab:pane',
|
||||
generation: 1,
|
||||
getPtyId: () => 'pty-1',
|
||||
isCurrent: () => true,
|
||||
isForeground: () => false,
|
||||
onRender(callback) {
|
||||
render = callback
|
||||
return { dispose }
|
||||
}
|
||||
})
|
||||
timing?.mark('connected')
|
||||
timing?.mark('liveData')
|
||||
return { timing, dispose, render: () => render?.() }
|
||||
}
|
||||
|
||||
function summaries() {
|
||||
return record.mock.calls.filter(([name]) => name === 'terminal_startup_timing')
|
||||
}
|
||||
|
||||
it('waits for the final scheduled slice to parse and preserves delivery credit', async () => {
|
||||
const { writeTerminalOutput } = await loadScheduler()
|
||||
const f = fixture()
|
||||
const terminal = createTerminal()
|
||||
const callbacks: (() => void)[] = []
|
||||
terminal.write.mockImplementation((_data, callback) => {
|
||||
if (callback) {
|
||||
callbacks.push(callback)
|
||||
}
|
||||
})
|
||||
const credit = vi.fn()
|
||||
const payload = 'x'.repeat(20 * 1024)
|
||||
writeTerminalOutput(terminal, payload, {
|
||||
foreground: false,
|
||||
...f.timing?.firstWrite(),
|
||||
ackCredit: credit
|
||||
})
|
||||
vi.advanceTimersByTime(50)
|
||||
expect(terminal.write.mock.calls.map(([data]) => data).join('')).toBe(payload)
|
||||
expect(callbacks).toHaveLength(2)
|
||||
f.render()
|
||||
callbacks[0]()
|
||||
expect(summaries()).toHaveLength(0)
|
||||
expect(credit).not.toHaveBeenCalled()
|
||||
callbacks[1]()
|
||||
expect(summaries()).toHaveLength(1)
|
||||
expect(summaries()[0][1]).toMatchObject({ outcome: 'observed' })
|
||||
expect(credit).toHaveBeenCalledOnce()
|
||||
expect(f.dispose).toHaveBeenCalledOnce()
|
||||
expect(vi.getTimerCount()).toBe(0)
|
||||
})
|
||||
|
||||
it('does not report a dropped startup batch as parsed when the warning renders', async () => {
|
||||
const { writeTerminalOutput } = await loadScheduler()
|
||||
const f = fixture()
|
||||
const terminal = createTerminal()
|
||||
const credit = vi.fn()
|
||||
writeTerminalOutput(terminal, 'x'.repeat(512 * 1024), {
|
||||
foreground: false,
|
||||
...f.timing?.firstWrite(),
|
||||
ackCredit: credit
|
||||
})
|
||||
for (let i = 0; i < 4; i++) {
|
||||
writeTerminalOutput(terminal, 'x'.repeat(512 * 1024), { foreground: false })
|
||||
}
|
||||
vi.advanceTimersByTime(50)
|
||||
expect(terminal.write.mock.calls.map(([data]) => data).join('')).toContain(
|
||||
'Orca skipped hidden terminal output'
|
||||
)
|
||||
f.render()
|
||||
expect(summaries()).toHaveLength(0)
|
||||
expect(credit).toHaveBeenCalledOnce()
|
||||
vi.advanceTimersByTime(10_000)
|
||||
expect(summaries()).toHaveLength(1)
|
||||
expect(summaries()[0][1]).toMatchObject({ outcome: 'timeout' })
|
||||
expect(summaries()[0][1]).not.toHaveProperty('parsed')
|
||||
expect(f.dispose).toHaveBeenCalledOnce()
|
||||
expect(vi.getTimerCount()).toBe(0)
|
||||
})
|
||||
|
||||
it('discards a queued startup write without retaining diagnostics or delivery credit', async () => {
|
||||
const { discardTerminalOutput, writeTerminalOutput } = await loadScheduler()
|
||||
const f = fixture()
|
||||
const terminal = createTerminal()
|
||||
const credit = vi.fn()
|
||||
writeTerminalOutput(terminal, 'stale', {
|
||||
foreground: false,
|
||||
...f.timing?.firstWrite(),
|
||||
ackCredit: credit
|
||||
})
|
||||
f.timing?.finish('disposed')
|
||||
discardTerminalOutput(terminal)
|
||||
vi.advanceTimersByTime(10_000)
|
||||
expect(terminal.write).not.toHaveBeenCalled()
|
||||
expect(credit).toHaveBeenCalledOnce()
|
||||
expect(summaries()).toHaveLength(1)
|
||||
expect(summaries()[0][1]).toMatchObject({ outcome: 'disposed' })
|
||||
expect(summaries()[0][1]).not.toHaveProperty('parsed')
|
||||
expect(vi.getTimerCount()).toBe(0)
|
||||
})
|
||||
@@ -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)
|
||||
}
|
||||
)
|
||||
})
|
||||
@@ -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<Record<Phase, number>> = {}
|
||||
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')
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user