Add opt-in pty:spawn phase timing

ORCA_PTY_SPAWN_TIMING=1 logs one line per spawn attributing latency to
startup barrier, Claude auth prep, buildPtyHostEnv, options assembly, and
provider spawn - the split that separated renderer-side cost from daemon
cost in the terminal perf investigation.
This commit is contained in:
Jinwoo Hong
2026-07-02 15:28:21 -04:00
parent 41e1c956d0
commit cd5fbe9fbf
2 changed files with 51 additions and 0 deletions
+40
View File
@@ -0,0 +1,40 @@
// Why: pty:spawn latency has four very different suspects (startup barrier,
// Claude auth prep, buildPtyHostEnv filesystem work, provider/daemon spawn).
// A single opt-in log line per spawn lets benchmarks attribute the cost
// without a tracing dependency. Enabled via ORCA_PTY_SPAWN_TIMING=1.
export type PtySpawnTiming = {
mark(phase: string): void
log(id: string, extra?: Record<string, string | number | boolean>): void
}
const noopTiming: PtySpawnTiming = {
mark: () => undefined,
log: () => undefined
}
export function createPtySpawnTiming(): PtySpawnTiming {
if (!process.env.ORCA_PTY_SPAWN_TIMING) {
return noopTiming
}
const startedAt = Date.now()
let lastAt = startedAt
const phases: string[] = []
return {
mark(phase: string): void {
const now = Date.now()
phases.push(`${phase}=${now - lastAt}ms`)
lastAt = now
},
log(id: string, extra?: Record<string, string | number | boolean>): void {
const extras = extra
? ` ${Object.entries(extra)
.map(([key, value]) => `${key}=${value}`)
.join(' ')}`
: ''
console.log(
`[pty-spawn-timing] id=${id} total=${Date.now() - startedAt}ms ${phases.join(' ')}${extras}`
)
}
}
}
+11
View File
@@ -39,6 +39,7 @@ import type { IPtyProvider, PtySpawnOptions, PtySpawnResult } from '../providers
import type { StartupCommandDelivery } from '../../shared/codex-startup-delivery'
import { SSH_SESSION_EXPIRED_ERROR, isSshPtyNotFoundError } from '../providers/ssh-pty-provider'
import { parseAppSshPtyId, toAppSshPtyId, toRelaySshPtyId } from '../providers/ssh-pty-id'
import { createPtySpawnTiming } from './pty-spawn-timing'
import { mintPtySessionId, isSafePtySessionId } from '../daemon/pty-session-id'
import { addNodePtyRecoveryHint } from '../daemon/node-pty-error-hints'
import type { ClaudeRuntimeAuthPreparation } from '../claude-accounts/runtime-auth-service'
@@ -2515,11 +2516,13 @@ export function registerPtyHandlers(
}
}
) => {
const spawnTiming = createPtySpawnTiming()
const startupPromise = getLocalPtyStartupPromise(args.connectionId)
if (startupPromise) {
await startupPromise
}
await assertFolderWorkspacePtyPathUsable(args.worktreeId)
spawnTiming.mark('preflight')
const provider = getProvider(args.connectionId)
const isClaudeLaunch = !args.connectionId && isClaudeLaunchCommand(args.command)
if (isClaudeLaunch && isClaudeAuthSwitchInProgress()) {
@@ -2542,6 +2545,7 @@ export function registerPtyHandlers(
)
const claudeAuth =
isClaudeLaunch && prepareClaudeAuth ? await prepareClaudeAuth(initialSelectionTarget) : null
spawnTiming.mark('auth')
if (isClaudeLaunch && isClaudeAuthSwitchInProgress()) {
throw new Error('A Claude account switch is in progress. Try again after it finishes.')
}
@@ -2767,6 +2771,7 @@ export function registerPtyHandlers(
throw err
}
}
spawnTiming.mark('host_env')
const spawnEnv = preAllocatedHandle
? { ...env, ORCA_TERMINAL_HANDLE: preAllocatedHandle }
: env
@@ -2861,7 +2866,9 @@ export function registerPtyHandlers(
startupTerminalColorQueryReplyColors
)
}
spawnTiming.mark('options')
result = await provider.spawn(spawnOptions)
spawnTiming.mark('provider_spawn')
} catch (err) {
const rawMessage = err instanceof Error ? err.message : String(err)
const spawnError = normalizeNodePtySpawnError(err)
@@ -2922,6 +2929,10 @@ export function registerPtyHandlers(
trustedTerminalHandleEnv.delete(preAllocatedHandle)
}
}
spawnTiming.log(result.id, {
daemon: isDaemonHostSpawn,
reattach: result.isReattach ?? false
})
ptyOwnership.set(result.id, args.connectionId ?? null)
if (startupTerminalColorQueryReplyColors) {
if (result.isReattach) {