diff --git a/src/main/index.ts b/src/main/index.ts index e9347aba382..f0093e67d42 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -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 | 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 = {}): 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 diff --git a/src/main/ipc/register-core-handlers.ts b/src/main/ipc/register-core-handlers.ts index 262f53ceeaf..23e73300cd1 100644 --- a/src/main/ipc/register-core-handlers.ts +++ b/src/main/ipc/register-core-handlers.ts @@ -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 diff --git a/src/main/ipc/startup-timing.ts b/src/main/ipc/startup-timing.ts new file mode 100644 index 00000000000..e0f02209406 --- /dev/null +++ b/src/main/ipc/startup-timing.ts @@ -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) + }) +} diff --git a/src/main/startup/startup-diagnostics.test.ts b/src/main/startup/startup-diagnostics.test.ts index dcf7a4237b3..f2d263ba622 100644 --- a/src/main/startup/startup-diagnostics.test.ts +++ b/src/main/startup/startup-diagnostics.test.ts @@ -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' + ) + }) +}) diff --git a/src/main/startup/startup-diagnostics.ts b/src/main/startup/startup-diagnostics.ts index 3e4114d6b8e..15a69e22a48 100644 --- a/src/main/startup/startup-diagnostics.ts +++ b/src/main/startup/startup-diagnostics.ts @@ -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) +} diff --git a/src/preload/api-types.ts b/src/preload/api-types.ts index 198fd9c4f2c..c96e7ecb83d 100644 --- a/src/preload/api-types.ts +++ b/src/preload/api-types.ts @@ -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 setSync: (args: WorkspaceSessionState) => void } + startupTiming: { + record: (report: StartupTimingReport) => void + } remoteWorkspace: { get: (args: { targetId: string }) => Promise setForConnectedTargets: (args: { diff --git a/src/preload/index.ts b/src/preload/index.ts index 0f9fb0a4b53..421a44c8678 100644 --- a/src/preload/index.ts +++ b/src/preload/index.ts @@ -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) => diff --git a/src/renderer/src/App.tsx b/src/renderer/src/App.tsx index f5ed6f79c92..96c3746bd57 100644 --- a/src/renderer/src/App.tsx +++ b/src/renderer/src/App.tsx @@ -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): void => { + window.api.startupTiming.record(startupTiming.snapshot({ details })) + } + const loadDeferredStartupReads = async (): Promise => { + 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() })() diff --git a/src/renderer/src/web/web-preload-api.ts b/src/renderer/src/web/web-preload-api.ts index aab7c3b1349..f203969c71c 100644 --- a/src/renderer/src/web/web-preload-api.ts +++ b/src/renderer/src/web/web-preload-api.ts @@ -488,6 +488,9 @@ function createWebPreloadApi(): Partial { writeJson(SESSION_STORAGE_KEY, sanitizeWebRuntimeWorkspaceSession(session)) } }, + startupTiming: { + record: () => {} + }, onboarding: { get: () => Promise.resolve(getStoredOnboarding()), update: async (updates) => { diff --git a/src/shared/startup-phase-timing.test.ts b/src/shared/startup-phase-timing.test.ts new file mode 100644 index 00000000000..5892a3c2e11 --- /dev/null +++ b/src/shared/startup-phase-timing.test.ts @@ -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) + }) +}) diff --git a/src/shared/startup-phase-timing.ts b/src/shared/startup-phase-timing.ts new file mode 100644 index 00000000000..1ce38e4c964 --- /dev/null +++ b/src/shared/startup-phase-timing.ts @@ -0,0 +1,206 @@ +export type StartupTimingOrigin = 'main' | 'renderer' + +export type StartupTimingPhaseStatus = 'ok' | 'error' + +export type StartupTimingDetails = Record + +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(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(name: string, task: () => Promise, options: PhaseOptions = {}): Promise { + 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 + 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 + 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 + return ( + typeof milestone.name === 'string' && + typeof milestone.atMs === 'number' && + typeof milestone.elapsedMs === 'number' + ) +}