diff --git a/src/main/ipc/pty-spawn-timing.ts b/src/main/ipc/pty-spawn-timing.ts new file mode 100644 index 00000000000..99c829f80ce --- /dev/null +++ b/src/main/ipc/pty-spawn-timing.ts @@ -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): 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): 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}` + ) + } + } +} diff --git a/src/main/ipc/pty.ts b/src/main/ipc/pty.ts index 596c9c27012..25a8f557e19 100644 --- a/src/main/ipc/pty.ts +++ b/src/main/ipc/pty.ts @@ -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) {