Measure startup hydration phases

This commit is contained in:
Neil
2026-06-02 23:29:58 -07:00
parent 9bfceb934f
commit b240d5eee6
11 changed files with 692 additions and 193 deletions
+174 -108
View File
@@ -70,7 +70,12 @@ import {
logSingleInstanceLockFailure,
shouldBypassSingleInstanceLock
} from './startup/single-instance-lock'
import { isStartupDiagnosticsEnabled, logStartupDiagnostic } from './startup/startup-diagnostics'
import {
isStartupDiagnosticsEnabled,
logStartupDiagnostic,
logStartupTimingReport
} from './startup/startup-diagnostics'
import { createStartupPhaseTimer } from '../shared/startup-phase-timing'
import { RateLimitService } from './rate-limits/service'
import { getInitialClaudeRateLimitTarget } from './rate-limits/claude-rate-limit-target'
import { getInitialCodexRateLimitTarget } from './rate-limits/codex-rate-limit-target'
@@ -150,6 +155,8 @@ let runtimeRpc: OrcaRuntimeRpcServer | null = null
let starNag: StarNagService | null = null
let agentAwakeService: AgentAwakeService | null = null
let crashReports: CrashReportStore | null = null
let firstWindowVisibleRecorded = false
let firstWindowLoadRecorded = false
let unsubscribeAgentAwakeStatusChanges: (() => void) | null = null
let watcherShutdownPromise: Promise<void> | null = null
let watcherShutdownDone = false
@@ -244,6 +251,15 @@ if (app.isPackaged && process.platform !== 'win32') {
configureDevUserDataPath(is.dev)
configureOrcaUserDataPathEnv()
const startupDiagnosticsEnabled = isStartupDiagnosticsEnabled()
const mainStartupTiming = createStartupPhaseTimer({
origin: 'main',
details: {
packaged: app.isPackaged,
platform: process.platform,
serveMode: isServeMode
}
})
mainStartupTiming.markMilestone('process-entry')
if (startupDiagnosticsEnabled) {
logStartupDiagnostic('before-single-instance-lock', {
version: app.getVersion(),
@@ -255,6 +271,13 @@ if (startupDiagnosticsEnabled) {
})
}
function logMainStartupTiming(details: Record<string, unknown> = {}): void {
if (!startupDiagnosticsEnabled) {
return
}
logStartupTimingReport(mainStartupTiming.snapshot({ details }))
}
function focusExistingWindow(): void {
focusExistingMainWindow({
app,
@@ -447,6 +470,17 @@ function openMainWindow(): BrowserWindow {
if (!keybindings) {
throw new Error('Keybinding service must be initialized before opening the main window')
}
const currentStore = store
const currentRuntime = runtime
const currentStats = stats
const currentClaudeUsage = claudeUsage
const currentCodexUsage = codexUsage
const currentOpenCodeUsage = openCodeUsage
const currentRateLimits = rateLimits
const currentAutomations = automations
const currentCodexAccounts = codexAccounts
const currentClaudeAccounts = claudeAccounts
const currentKeybindings = keybindings
// Why: Chromium's BrowserWindow constructor resets the userData DACL to a
// Protected DACL. Grant explicit Full Control ACEs on all existing children
@@ -461,47 +495,49 @@ function openMainWindow(): BrowserWindow {
}
}
const window = createMainWindow(store, {
getIsQuitting: () => isQuitting,
onQuitAborted: () => {
isQuitting = false
clearExpectedRendererReload()
},
onRendererProcessGone: (details, webContentsId) => {
recordProcessGoneCrash(
'renderer',
'renderer',
details.reason,
details.exitCode ?? null,
{
processType: 'renderer'
},
webContentsId
)
},
shouldRecordRendererCrash: (details, webContentsId) =>
shouldRecordProcessGoneCrash({
source: 'renderer',
processType: 'renderer',
reason: details.reason,
exitCode: details.exitCode ?? null,
expectedTeardown: getExpectedTeardownScope(webContentsId)
}),
shouldRecoverRenderer: (details, webContentsId) =>
shouldRecoverRendererAfterProcessGone({
reason: details.reason,
expectedTeardown: getExpectedTeardownScope(webContentsId)
}),
deferLoad: true,
title: devInstanceIdentity.name,
getKeybindings: () => keybindings?.getOverrides(),
onBeforeReload: ({ ignoreCache, webContentsId }) => {
if (mainWindow?.webContents.id === webContentsId) {
markExpectedRendererReload(webContentsId)
const window = mainStartupTiming.measureSync('main-window.create', () =>
createMainWindow(currentStore, {
getIsQuitting: () => isQuitting,
onQuitAborted: () => {
isQuitting = false
clearExpectedRendererReload()
},
onRendererProcessGone: (details, webContentsId) => {
recordProcessGoneCrash(
'renderer',
'renderer',
details.reason,
details.exitCode ?? null,
{
processType: 'renderer'
},
webContentsId
)
},
shouldRecordRendererCrash: (details, webContentsId) =>
shouldRecordProcessGoneCrash({
source: 'renderer',
processType: 'renderer',
reason: details.reason,
exitCode: details.exitCode ?? null,
expectedTeardown: getExpectedTeardownScope(webContentsId)
}),
shouldRecoverRenderer: (details, webContentsId) =>
shouldRecoverRendererAfterProcessGone({
reason: details.reason,
expectedTeardown: getExpectedTeardownScope(webContentsId)
}),
deferLoad: true,
title: devInstanceIdentity.name,
getKeybindings: () => keybindings?.getOverrides(),
onBeforeReload: ({ ignoreCache, webContentsId }) => {
if (mainWindow?.webContents.id === webContentsId) {
markExpectedRendererReload(webContentsId)
}
recordCrashBreadcrumb('manual_reload_requested', { ignoreCache })
}
recordCrashBreadcrumb('manual_reload_requested', { ignoreCache })
}
})
})
)
recordCrashBreadcrumb('main_window_created')
// Why: telemetry-plan.md§First-launch experience anchors default-on
@@ -512,6 +548,11 @@ function openMainWindow(): BrowserWindow {
const onFirstWindowLoad = (): void => {
clearExpectedRendererReload(rendererWebContentsId)
recordCrashBreadcrumb('main_window_loaded')
if (!firstWindowLoadRecorded) {
firstWindowLoadRecorded = true
mainStartupTiming.markMilestone('main-window-did-finish-load', { rendererWebContentsId })
logMainStartupTiming({ stage: 'renderer-load' })
}
if (!store) {
return
}
@@ -522,33 +563,43 @@ function openMainWindow(): BrowserWindow {
trackAppOpenedOnce()
}
window.webContents.on('did-finish-load', onFirstWindowLoad)
registerCoreHandlers(
store,
runtime,
stats,
claudeUsage,
codexUsage,
openCodeUsage,
codexAccounts,
claudeAccounts,
rateLimits,
rendererWebContentsId,
automations,
{
prepareForCodexLaunch: prepareCodexRuntimeHomeForLaunch,
prepareForClaudeLaunch: () => claudeRuntimeAuth!.prepareForClaudeLaunch()
},
agentAwakeService ?? undefined,
crashReports ?? undefined,
keybindings,
{
onBeforeRelaunch: () => {
isQuitting = true
store?.flush()
}
window.once('show', () => {
if (firstWindowVisibleRecorded) {
return
}
)
firstWindowVisibleRecorded = true
mainStartupTiming.markMilestone('first-window-visible', { rendererWebContentsId })
logMainStartupTiming({ stage: 'first-window-visible' })
})
mainStartupTiming.measureSync('core-handlers.register', () => {
registerCoreHandlers(
currentStore,
currentRuntime,
currentStats,
currentClaudeUsage,
currentCodexUsage,
currentOpenCodeUsage,
currentCodexAccounts,
currentClaudeAccounts,
currentRateLimits,
rendererWebContentsId,
currentAutomations,
{
prepareForCodexLaunch: prepareCodexRuntimeHomeForLaunch,
prepareForClaudeLaunch: () => claudeRuntimeAuth!.prepareForClaudeLaunch()
},
agentAwakeService ?? undefined,
crashReports ?? undefined,
currentKeybindings,
{
onBeforeRelaunch: () => {
isQuitting = true
store?.flush()
}
}
)
})
automations.setWebContents(window.webContents)
automations.start()
attachMainWindowServices(
@@ -1033,6 +1084,7 @@ function driveSyntheticTitleFromHook(
}
app.whenReady().then(async () => {
mainStartupTiming.markMilestone('electron-ready')
electronApp.setAppUserModelId(devInstanceIdentity.appUserModelId)
app.setName(devInstanceIdentity.name)
@@ -1041,17 +1093,19 @@ app.whenReady().then(async () => {
app.dock?.setIcon(dockIcon)
}
store = new Store()
store = mainStartupTiming.measureSync('store.init', () => new Store())
if (shouldSuppressDevEducation({ isDev: is.dev })) {
suppressDevEducationForStore(store)
}
try {
// Why: Dock/Launchpad launches do not inherit shell proxy env vars, so the
// persisted proxy must be applied before any app-owned network fetchers run.
await applyElectronProxySettings(store.getSettings())
} catch {
console.warn('[proxy] Failed to apply network proxy settings')
}
await mainStartupTiming.measure('proxy.apply', async () => {
try {
// Why: Dock/Launchpad launches do not inherit shell proxy env vars, so the
// persisted proxy must be applied before any app-owned network fetchers run.
await applyElectronProxySettings(store!.getSettings())
} catch {
console.warn('[proxy] Failed to apply network proxy settings')
}
})
agentAwakeService = new AgentAwakeService()
agentAwakeService.setEnabled(store.getSettings().keepComputerAwakeWhileAgentsRun)
// Why: disk-hydrated status rows are UI continuity only. The service starts
@@ -1164,6 +1218,7 @@ app.whenReady().then(async () => {
onTabsChanged: (worktreeId) => runtimeService.notifyMobileSessionTabsChanged(worktreeId)
})
)
mainStartupTiming.markMilestone('main-services-ready')
nativeTheme.themeSource = store.getSettings().theme ?? 'system'
if (shouldInstallManagedHooks(is.dev)) {
// Why: the persisted off switch must run before any auto-install path so
@@ -1291,31 +1346,36 @@ app.whenReady().then(async () => {
registerMobileHandlers(runtimeRpc)
if (!isServeMode) {
await startFirstWindowStartupServices({
// Why: the persistent-terminal daemon is desktop-only. Headless
// `orca serve` registers its PTY runtime below and must not spawn the
// desktop daemon or hook loopback listener.
startDaemonPtyProvider: () => initDaemonPtyProvider(),
// Why: PTY spawn env reads ORCA_AGENT_HOOK_* from the live server state,
// so the hook server must start before restored terminals can mount.
startAgentHookServer: () =>
agentHookServer.start({
env: app.isPackaged ? 'production' : 'development',
// Why: hooks source this endpoint file at invocation time, so old PTY
// env still reaches the current Orca process after an app restart.
// Dev uses a namespace because all worktrees share `orca-dev`.
userDataPath: app.getPath('userData'),
endpointNamespace: devAgentHookEndpointNamespace
}),
onDaemonError: (error) => {
console.error('[daemon] Failed to start daemon PTY provider, falling back to local:', error)
},
onAgentHookServerError: (error) => {
// Why: Claude/Codex/Gemini/OpenCode/Cursor hook callbacks are sidebar
// enrichment only. Orca must still boot if the loopback receiver fails.
console.error('[agent-hooks] Failed to start local hook server:', error)
}
})
await mainStartupTiming.measure('first-window-services.start', () =>
startFirstWindowStartupServices({
// Why: the persistent-terminal daemon is desktop-only. Headless
// `orca serve` registers its PTY runtime below and must not spawn the
// desktop daemon or hook loopback listener.
startDaemonPtyProvider: () => initDaemonPtyProvider(),
// Why: PTY spawn env reads ORCA_AGENT_HOOK_* from the live server state,
// so the hook server must start before restored terminals can mount.
startAgentHookServer: () =>
agentHookServer.start({
env: app.isPackaged ? 'production' : 'development',
// Why: hooks source this endpoint file at invocation time, so old PTY
// env still reaches the current Orca process after an app restart.
// Dev uses a namespace because all worktrees share `orca-dev`.
userDataPath: app.getPath('userData'),
endpointNamespace: devAgentHookEndpointNamespace
}),
onDaemonError: (error) => {
console.error(
'[daemon] Failed to start daemon PTY provider, falling back to local:',
error
)
},
onAgentHookServerError: (error) => {
// Why: Claude/Codex/Gemini/OpenCode/Cursor hook callbacks are sidebar
// enrichment only. Orca must still boot if the loopback receiver fails.
console.error('[agent-hooks] Failed to start local hook server:', error)
}
})
)
}
if (serveOptions) {
@@ -1330,22 +1390,28 @@ app.whenReady().then(async () => {
// explicit empty graph so status clients see a ready server while
// renderer-only operations still fail at their own window boundary.
runtime.syncWindowGraph(0, { tabs: [], leaves: [] })
await runtimeRpc.start().catch((error) => {
console.error('[runtime] Failed to start headless RPC transport:', error)
throw error
})
await mainStartupTiming.measure('runtime-rpc.start', () =>
runtimeRpc!.start().catch((error) => {
console.error('[runtime] Failed to start headless RPC transport:', error)
throw error
})
)
installServeSignalHandlers()
await printServeReady(serveOptions)
mainStartupTiming.markMilestone('headless-server-ready')
logMainStartupTiming({ stage: 'headless-server-ready' })
return
}
// Why: once the hook server is ready (or has already failed open), window
// creation and runtime RPC startup are independent.
const [win] = await Promise.all([
Promise.resolve(openMainWindow()),
runtimeRpc.start().catch((error) => {
console.error('[runtime] Failed to start local RPC transport:', error)
})
Promise.resolve().then(() => mainStartupTiming.measureSync('main-window.open', openMainWindow)),
mainStartupTiming.measure('runtime-rpc.start', () =>
runtimeRpc!.start().catch((error) => {
console.error('[runtime] Failed to start local RPC transport:', error)
})
)
])
// Why: the macOS notification permission dialog must fire after the window
+2
View File
@@ -38,6 +38,7 @@ import { registerWorkspacePortHandlers } from './workspace-ports'
import { registerAutomationHandlers } from './automations'
import { registerKeybindingHandlers } from './keybindings'
import { registerTelemetryHandlers } from './telemetry'
import { registerStartupTimingHandlers } from './startup-timing'
import { registerBrowserHandlers } from './browser'
import { browserSessionRegistry } from '../browser/browser-session-registry'
import { registerShellHandlers } from './shell'
@@ -139,6 +140,7 @@ export function registerCoreHandlers(
registerKeybindingHandlers(keybindings)
}
registerTelemetryHandlers(store)
registerStartupTimingHandlers()
registerBrowserHandlers()
// Why: applyPendingCookieImport MUST run before restorePersistedUserAgent
// because the latter calls session.fromPartition() which initializes
+19
View File
@@ -0,0 +1,19 @@
import { ipcMain } from 'electron'
import { isStartupTimingReport, type StartupTimingReport } from '../../shared/startup-phase-timing'
import { isStartupDiagnosticsEnabled, logStartupTimingReport } from '../startup/startup-diagnostics'
let registered = false
export function registerStartupTimingHandlers(): void {
if (registered) {
return
}
registered = true
ipcMain.on('startup:timing-report', (_event, report: StartupTimingReport) => {
if (!isStartupDiagnosticsEnabled() || !isStartupTimingReport(report)) {
return
}
logStartupTimingReport(report)
})
}
@@ -2,6 +2,7 @@ import { describe, expect, it, vi } from 'vitest'
import {
isStartupDiagnosticsEnabled,
logStartupDiagnostic,
logStartupTimingReport,
STARTUP_DIAGNOSTICS_ENV,
writeStartupDiagnosticLine
} from './startup-diagnostics'
@@ -36,3 +37,40 @@ describe('logStartupDiagnostic', () => {
)
})
})
describe('logStartupTimingReport', () => {
it('formats structured startup timing records through the diagnostic sink', () => {
const write = vi.fn()
logStartupTimingReport(
{
origin: 'main',
startedAtMs: 1,
capturedAtMs: 5,
elapsedMs: 4,
phases: [
{
name: 'store.init',
status: 'ok',
startedAtMs: 1,
endedAtMs: 3,
durationMs: 2
}
],
milestones: [
{
name: 'first-window-visible',
atMs: 5,
elapsedMs: 4
}
]
},
write
)
expect(write).toHaveBeenCalledWith(
2,
'[startup] timing-report report={"origin":"main","startedAtMs":1,"capturedAtMs":5,"elapsedMs":4,"phases":[{"name":"store.init","status":"ok","startedAtMs":1,"endedAtMs":3,"durationMs":2}],"milestones":[{"name":"first-window-visible","atMs":5,"elapsedMs":4}]}\n'
)
})
})
+8
View File
@@ -1,4 +1,5 @@
import { writeSync } from 'node:fs'
import type { StartupTimingReport } from '../../shared/startup-phase-timing'
export const STARTUP_DIAGNOSTICS_ENV = 'ORCA_STARTUP_DIAGNOSTICS'
@@ -29,3 +30,10 @@ export function logStartupDiagnostic(
.join(' ')
writeStartupDiagnosticLine(`[startup] ${event}${detailText ? ` ${detailText}` : ''}`, write)
}
export function logStartupTimingReport(
report: StartupTimingReport,
write?: StartupDiagnosticSink
): void {
logStartupDiagnostic('timing-report', { report }, write)
}
+4
View File
@@ -10,6 +10,7 @@ import type {
import type { NativeFileDropPayload } from '../shared/native-file-drop'
import type { AppIdentity } from '../shared/app-identity'
import type { TerminalPaneSplitSource } from '../shared/feature-education-telemetry'
import type { StartupTimingReport } from '../shared/startup-phase-timing'
import type {
BaseRefDefaultResult,
BaseRefSearchResult,
@@ -1712,6 +1713,9 @@ export type PreloadApi = {
patch: (args: WorkspaceSessionPatch) => Promise<void>
setSync: (args: WorkspaceSessionState) => void
}
startupTiming: {
record: (report: StartupTimingReport) => void
}
remoteWorkspace: {
get: (args: { targetId: string }) => Promise<RemoteWorkspaceSnapshot | null>
setForConnectedTargets: (args: {
+7
View File
@@ -9,6 +9,7 @@ import type { AppIdentity } from '../shared/app-identity'
import type { CliInstallStatus } from '../shared/cli-install-types'
import type { AgentHookInstallStatus } from '../shared/agent-hook-types'
import type { TerminalPaneSplitSource } from '../shared/feature-education-telemetry'
import type { StartupTimingReport } from '../shared/startup-phase-timing'
import type {
BaseRefSearchResult,
BaseRefDefaultResult,
@@ -2081,6 +2082,12 @@ const api = {
}
} satisfies PreloadApi['session'],
startupTiming: {
record: (report: StartupTimingReport): void => {
ipcRenderer.send('startup:timing-report', report)
}
} satisfies PreloadApi['startupTiming'],
remoteWorkspace: {
get: (args) => ipcRenderer.invoke('remoteWorkspace:get', args),
setForConnectedTargets: (args) =>
+133 -85
View File
@@ -115,6 +115,7 @@ import {
} from '@/store/slices/worktree-nav-history'
import type { VirtualizedScrollAnchor } from './hooks/useVirtualizedScrollAnchor'
import type { RemoteWorkspacePatchResult } from '../../shared/remote-workspace-types'
import { createStartupPhaseTimer } from '../../shared/startup-phase-timing'
import type { OnboardingState } from '../../shared/types'
import { FLOATING_TERMINAL_WORKTREE_ID } from '../../shared/constants'
import { ContextualTourOverlay } from './components/contextual-tours/ContextualTourOverlay'
@@ -653,24 +654,54 @@ function App(): React.JSX.Element {
// workspaceSessionReady — so we still need to force the flag true so the
// UI mounts.
let reconnectStarted = false
const startupTiming = createStartupPhaseTimer({ origin: 'renderer' })
const recordStartupTiming = (details: Record<string, unknown>): void => {
window.api.startupTiming.record(startupTiming.snapshot({ details }))
}
const loadDeferredStartupReads = async (): Promise<void> => {
await Promise.allSettled([
startupTiming.measure('browser-profiles.fetch', () =>
actions.fetchBrowserSessionProfiles()
),
startupTiming.measure('onboarding.read', async () => {
const onboardingState = await window.api.onboarding.get()
if (!cancelled) {
setOnboarding(onboardingState)
setOnboardingLoaded(true)
}
})
])
}
void (async () => {
try {
startupTiming.markMilestone('hydration-effect-start')
// Why: repo/worktree hydration routes through settings.activeRuntimeEnvironmentId.
// Load settings first so a persisted remote runtime does not boot against
// the local filesystem and then hydrate stale local workspace state.
await actions.fetchSettings()
await actions.fetchRepos()
await actions.fetchProjectGroups()
await actions.fetchAllWorktrees()
await actions.fetchWorktreeLineage()
const persistedUI = await window.api.ui.get()
await startupTiming.measure('settings.fetch', () => actions.fetchSettings())
const persistedReads = Promise.all([
startupTiming.measure('persisted-ui.read', () => window.api.ui.get()),
startupTiming.measure('session.read', () => window.api.session.get())
])
const [[persistedUI, session]] = await Promise.all([
persistedReads,
(async () => {
await Promise.all([
startupTiming.measure('repos.fetch', () => actions.fetchRepos()),
startupTiming.measure('project-groups.fetch', () => actions.fetchProjectGroups()),
startupTiming.measure('keybindings.fetch', () => actions.fetchKeybindings())
])
await Promise.all([
startupTiming.measure('worktrees.fetch-all', () => actions.fetchAllWorktrees()),
startupTiming.measure('worktree-lineage.fetch', () => actions.fetchWorktreeLineage())
])
})()
])
uiHydrated = hydratePersistedUIAfterStartupRead({
persistedUI,
cancelled,
hydratePersistedUI: actions.hydratePersistedUI
})
const session = await window.api.session.get()
await actions.fetchKeybindings()
if (!cancelled) {
actions.hydrateWorkspaceSession(session)
actions.hydrateTabsSession(session)
@@ -686,12 +717,6 @@ function App(): React.JSX.Element {
// See docs/cmd-j-empty-query-ordering.md.
actions.pruneLastVisitedTimestamps()
actions.seedActiveWorktreeLastVisitedIfMissing()
await actions.fetchBrowserSessionProfiles()
const onboardingState = await window.api.onboarding.get()
if (!cancelled) {
setOnboarding(onboardingState)
setOnboardingLoaded(true)
}
// Why: SSH connections must be re-established BEFORE terminal
// reconnect so that reconnectPersistedTerminals can route SSH-backed
@@ -699,85 +724,94 @@ function App(): React.JSX.Element {
// are deferred to tab focus to avoid stacking credential dialogs at
// startup before the user has context.
const connectionIds = session.activeConnectionIdsAtShutdown ?? []
if (connectionIds.length > 0) {
try {
const SSH_RECONNECT_TIMEOUT_MS = 15_000
const allTargets = await window.api.ssh.listTargets()
const targetMap = new Map(allTargets.map((t) => [t.id, t]))
const targets = connectionIds.map((targetId) => ({
targetId,
needsPassphrase: targetMap.get(targetId)?.lastRequiredPassphrase ?? false
}))
const eagerTargets = targets.filter((t) => !t.needsPassphrase)
const deferredTargets = targets.filter((t) => t.needsPassphrase)
if (deferredTargets.length > 0) {
actions.setDeferredSshReconnectTargets(deferredTargets.map((t) => t.targetId))
await startupTiming.measure(
'ssh.reconnect',
async () => {
if (connectionIds.length === 0) {
return
}
try {
const SSH_RECONNECT_TIMEOUT_MS = 15_000
const allTargets = await window.api.ssh.listTargets()
const targetMap = new Map(allTargets.map((t) => [t.id, t]))
const targets = connectionIds.map((targetId) => ({
targetId,
needsPassphrase: targetMap.get(targetId)?.lastRequiredPassphrase ?? false
}))
// Why: track which eager targets timed out so we can treat them
// as deferred — the underlying ssh.connect() keeps running in the
// main process, but reconnectPersistedTerminals won't see them as
// connected. Adding them to the deferred list ensures PTYs get
// reattached when the user focuses the tab (by which time the
// slow connect will likely have succeeded).
const timedOutTargets: string[] = []
await Promise.allSettled(
eagerTargets.map(({ targetId }) =>
Promise.race([
window.api.ssh.connect({ targetId }),
new Promise((_, reject) =>
setTimeout(
() => reject(new Error('SSH reconnect timeout')),
SSH_RECONNECT_TIMEOUT_MS
const eagerTargets = targets.filter((t) => !t.needsPassphrase)
const deferredTargets = targets.filter((t) => t.needsPassphrase)
if (deferredTargets.length > 0) {
actions.setDeferredSshReconnectTargets(deferredTargets.map((t) => t.targetId))
}
// Why: track which eager targets timed out so we can treat them
// as deferred — the underlying ssh.connect() keeps running in the
// main process, but reconnectPersistedTerminals won't see them as
// connected. Adding them to the deferred list ensures PTYs get
// reattached when the user focuses the tab (by which time the
// slow connect will likely have succeeded).
const timedOutTargets: string[] = []
await Promise.allSettled(
eagerTargets.map(({ targetId }) =>
Promise.race([
window.api.ssh.connect({ targetId }),
new Promise((_, reject) =>
setTimeout(
() => reject(new Error('SSH reconnect timeout')),
SSH_RECONNECT_TIMEOUT_MS
)
)
)
]).catch((err) => {
const isTimeout =
err instanceof Error && err.message === 'SSH reconnect timeout'
if (isTimeout) {
timedOutTargets.push(targetId)
}
console.warn(`SSH auto-reconnect failed for ${targetId}:`, err)
})
)
)
if (timedOutTargets.length > 0) {
actions.setDeferredSshReconnectTargets([
...deferredTargets.map((t) => t.targetId),
...timedOutTargets
])
}
// Why: ssh.connect() resolves before the ssh:state-changed IPC
// event updates sshConnectionStates in the store. Without this,
// reconnectPersistedTerminals reads stale state and misclassifies
// successfully connected targets as disconnected, stranding their
// persisted PTYs. Polling getState ensures the store is current.
for (const { targetId } of eagerTargets) {
if (timedOutTargets.includes(targetId)) {
continue
}
try {
const state = await window.api.ssh.getState({ targetId })
console.warn(
`[ssh-restore] Polled state for ${targetId}: status=${state?.status}`
]).catch((err) => {
const isTimeout =
err instanceof Error && err.message === 'SSH reconnect timeout'
if (isTimeout) {
timedOutTargets.push(targetId)
}
console.warn(`SSH auto-reconnect failed for ${targetId}:`, err)
})
)
if (state?.status === 'connected') {
actions.setSshConnectionState(targetId, state)
}
} catch {
/* best-effort */
)
if (timedOutTargets.length > 0) {
actions.setDeferredSshReconnectTargets([
...deferredTargets.map((t) => t.targetId),
...timedOutTargets
])
}
// Why: ssh.connect() resolves before the ssh:state-changed IPC
// event updates sshConnectionStates in the store. Without this,
// reconnectPersistedTerminals reads stale state and misclassifies
// successfully connected targets as disconnected, stranding their
// persisted PTYs. Polling getState ensures the store is current.
for (const { targetId } of eagerTargets) {
if (timedOutTargets.includes(targetId)) {
continue
}
try {
const state = await window.api.ssh.getState({ targetId })
console.warn(
`[ssh-restore] Polled state for ${targetId}: status=${state?.status}`
)
if (state?.status === 'connected') {
actions.setSshConnectionState(targetId, state)
}
} catch {
/* best-effort */
}
}
} catch (err) {
console.warn('SSH startup reconnect failed:', err)
}
} catch (err) {
console.warn('SSH startup reconnect failed:', err)
}
}
},
{ details: { connectionCount: connectionIds.length } }
)
reconnectStarted = true
await actions.reconnectPersistedTerminals(abortController.signal)
await startupTiming.measure('terminal.reconnect', () =>
actions.reconnectPersistedTerminals(abortController.signal)
)
syncZoomCSSVar()
// Why (issue #1158): unlock the debounced session writer only after
// hydration AND all dependent startup steps (SSH reconnect, terminal
@@ -787,6 +821,14 @@ function App(): React.JSX.Element {
// and the writer would serialize a partially-mutated store back to
// disk — the exact data-loss mode this PR fixes.
actions.setHydrationSucceeded(true)
startupTiming.markMilestone('first-usable-workspace', {
sshConnectionCount: connectionIds.length
})
await loadDeferredStartupReads()
startupTiming.markMilestone('deferred-startup-complete')
if (!cancelled) {
recordStartupTiming({ outcome: 'ok' })
}
}
} catch (error) {
// Why (issue #1158): previously this catch called hydrateWorkspaceSession
@@ -797,6 +839,9 @@ function App(): React.JSX.Element {
// false so the writer stays gated. We still ensure persistedUIReady and
// workspaceSessionReady flip so the UI can mount without a session.
const stepLabel = error instanceof Error && error.message ? error.message : String(error)
startupTiming.markMilestone('workspace-session-hydration-failed', {
step: stepLabel
})
console.error(
'[startup] Workspace session hydration failed; leaving disk state untouched:',
stepLabel,
@@ -888,6 +933,9 @@ function App(): React.JSX.Element {
})
}
}
if (!cancelled) {
recordStartupTiming({ outcome: 'error', step: stepLabel })
}
}
void actions.initGitHubCache()
})()
+3
View File
@@ -488,6 +488,9 @@ function createWebPreloadApi(): Partial<PreloadApi> {
writeJson(SESSION_STORAGE_KEY, sanitizeWebRuntimeWorkspaceSession(session))
}
},
startupTiming: {
record: () => {}
},
onboarding: {
get: () => Promise.resolve(getStoredOnboarding()),
update: async (updates) => {
+98
View File
@@ -0,0 +1,98 @@
import { describe, expect, it } from 'vitest'
import { createStartupPhaseTimer, isStartupTimingReport } from './startup-phase-timing'
describe('startup phase timing', () => {
it('records structured phases and milestones with elapsed timings', async () => {
let now = 100
const timer = createStartupPhaseTimer({
origin: 'renderer',
now: () => now,
details: { runtime: 'local' }
})
timer.markMilestone('hydration-effect-start')
const value = timer.measureSync('settings.fetch', () => {
now += 12.3
return 'settings'
})
await timer.measure('session.read', async () => {
now += 8.1
})
timer.markMilestone('first-usable-workspace', { sshConnectionCount: 0 })
now += 4
const report = timer.snapshot({ details: { outcome: 'ok' } })
expect(value).toBe('settings')
expect(report).toMatchObject({
origin: 'renderer',
startedAtMs: 100,
capturedAtMs: 124.4,
elapsedMs: 24.4,
details: { runtime: 'local', outcome: 'ok' },
milestones: [
{ name: 'hydration-effect-start', atMs: 100, elapsedMs: 0 },
{
name: 'first-usable-workspace',
atMs: 120.4,
elapsedMs: 20.4,
details: { sshConnectionCount: 0 }
}
],
phases: [
{
name: 'settings.fetch',
status: 'ok',
startedAtMs: 100,
endedAtMs: 112.3,
durationMs: 12.3
},
{
name: 'session.read',
status: 'ok',
startedAtMs: 112.3,
endedAtMs: 120.4,
durationMs: 8.1
}
]
})
expect(isStartupTimingReport(report)).toBe(true)
})
it('records failed phases before rethrowing', () => {
let now = 20
const timer = createStartupPhaseTimer({ origin: 'main', now: () => now })
expect(() =>
timer.measureSync('store.init', () => {
now += 3
throw new Error('bad data')
})
).toThrow('bad data')
expect(timer.snapshot().phases).toEqual([
{
name: 'store.init',
status: 'error',
startedAtMs: 20,
endedAtMs: 23,
durationMs: 3,
details: { error: 'bad data', name: 'Error' }
}
])
})
it('rejects malformed timing reports', () => {
expect(isStartupTimingReport({ origin: 'renderer', phases: [], milestones: [] })).toBe(false)
expect(
isStartupTimingReport({
origin: 'renderer',
startedAtMs: 0,
capturedAtMs: 1,
elapsedMs: 1,
phases: [{ name: 'phase', status: 'ok', startedAtMs: 0, endedAtMs: 1 }],
milestones: []
})
).toBe(false)
})
})
+206
View File
@@ -0,0 +1,206 @@
export type StartupTimingOrigin = 'main' | 'renderer'
export type StartupTimingPhaseStatus = 'ok' | 'error'
export type StartupTimingDetails = Record<string, unknown>
export type StartupTimingPhase = {
name: string
status: StartupTimingPhaseStatus
startedAtMs: number
endedAtMs: number
durationMs: number
details?: StartupTimingDetails
}
export type StartupTimingMilestone = {
name: string
atMs: number
elapsedMs: number
details?: StartupTimingDetails
}
export type StartupTimingReport = {
origin: StartupTimingOrigin
startedAtMs: number
capturedAtMs: number
elapsedMs: number
phases: StartupTimingPhase[]
milestones: StartupTimingMilestone[]
details?: StartupTimingDetails
}
type StartupPhaseTimerOptions = {
origin: StartupTimingOrigin
now?: () => number
details?: StartupTimingDetails
}
type PhaseOptions = {
details?: StartupTimingDetails
}
type SnapshotOptions = {
details?: StartupTimingDetails
}
function defaultNow(): number {
return globalThis.performance?.now() ?? Date.now()
}
function roundedMs(value: number): number {
return Math.round(value * 100) / 100
}
function normalizeDetails(details?: StartupTimingDetails): StartupTimingDetails | undefined {
if (!details || Object.keys(details).length === 0) {
return undefined
}
return details
}
function errorDetails(error: unknown): StartupTimingDetails {
if (error instanceof Error) {
return { error: error.message, name: error.name }
}
return { error: String(error) }
}
export class StartupPhaseTimer {
private readonly origin: StartupTimingOrigin
private readonly now: () => number
private readonly startedAtMs: number
private readonly details?: StartupTimingDetails
private readonly phases: StartupTimingPhase[] = []
private readonly milestones: StartupTimingMilestone[] = []
constructor(options: StartupPhaseTimerOptions) {
this.origin = options.origin
this.now = options.now ?? defaultNow
this.startedAtMs = this.now()
this.details = normalizeDetails(options.details)
}
markMilestone(name: string, details?: StartupTimingDetails): void {
const atMs = this.now()
const normalizedDetails = normalizeDetails(details)
this.milestones.push({
name,
atMs: roundedMs(atMs),
elapsedMs: roundedMs(atMs - this.startedAtMs),
...(normalizedDetails ? { details: normalizedDetails } : {})
})
}
measureSync<T>(name: string, task: () => T, options: PhaseOptions = {}): T {
const startedAtMs = this.now()
try {
const result = task()
this.recordPhase(name, startedAtMs, this.now(), 'ok', options.details)
return result
} catch (error) {
this.recordPhase(name, startedAtMs, this.now(), 'error', {
...options.details,
...errorDetails(error)
})
throw error
}
}
async measure<T>(name: string, task: () => Promise<T>, options: PhaseOptions = {}): Promise<T> {
const startedAtMs = this.now()
try {
const result = await task()
this.recordPhase(name, startedAtMs, this.now(), 'ok', options.details)
return result
} catch (error) {
this.recordPhase(name, startedAtMs, this.now(), 'error', {
...options.details,
...errorDetails(error)
})
throw error
}
}
snapshot(options: SnapshotOptions = {}): StartupTimingReport {
const capturedAtMs = this.now()
const details = normalizeDetails({
...this.details,
...options.details
})
return {
origin: this.origin,
startedAtMs: roundedMs(this.startedAtMs),
capturedAtMs: roundedMs(capturedAtMs),
elapsedMs: roundedMs(capturedAtMs - this.startedAtMs),
phases: this.phases.map((phase) => ({ ...phase })),
milestones: this.milestones.map((milestone) => ({ ...milestone })),
...(details ? { details } : {})
}
}
private recordPhase(
name: string,
startedAtMs: number,
endedAtMs: number,
status: StartupTimingPhaseStatus,
details?: StartupTimingDetails
): void {
const normalizedDetails = normalizeDetails(details)
this.phases.push({
name,
status,
startedAtMs: roundedMs(startedAtMs),
endedAtMs: roundedMs(endedAtMs),
durationMs: roundedMs(endedAtMs - startedAtMs),
...(normalizedDetails ? { details: normalizedDetails } : {})
})
}
}
export function createStartupPhaseTimer(options: StartupPhaseTimerOptions): StartupPhaseTimer {
return new StartupPhaseTimer(options)
}
export function isStartupTimingReport(value: unknown): value is StartupTimingReport {
if (!value || typeof value !== 'object') {
return false
}
const report = value as Partial<StartupTimingReport>
return (
(report.origin === 'main' || report.origin === 'renderer') &&
typeof report.startedAtMs === 'number' &&
typeof report.capturedAtMs === 'number' &&
typeof report.elapsedMs === 'number' &&
Array.isArray(report.phases) &&
report.phases.every(isStartupTimingPhase) &&
Array.isArray(report.milestones) &&
report.milestones.every(isStartupTimingMilestone)
)
}
function isStartupTimingPhase(value: unknown): value is StartupTimingPhase {
if (!value || typeof value !== 'object') {
return false
}
const phase = value as Partial<StartupTimingPhase>
return (
typeof phase.name === 'string' &&
(phase.status === 'ok' || phase.status === 'error') &&
typeof phase.startedAtMs === 'number' &&
typeof phase.endedAtMs === 'number' &&
typeof phase.durationMs === 'number'
)
}
function isStartupTimingMilestone(value: unknown): value is StartupTimingMilestone {
if (!value || typeof value !== 'object') {
return false
}
const milestone = value as Partial<StartupTimingMilestone>
return (
typeof milestone.name === 'string' &&
typeof milestone.atMs === 'number' &&
typeof milestone.elapsedMs === 'number'
)
}