diff --git a/packages/cli/src/gemini.tsx b/packages/cli/src/gemini.tsx index 331ec0c018..ded99b9639 100644 --- a/packages/cli/src/gemini.tsx +++ b/packages/cli/src/gemini.tsx @@ -328,6 +328,22 @@ export async function startInteractiveUI( export async function main() { const cliStartupHandle = startupProfiler.start('cli_startup'); + const parentStartTime = process.env['GEMINI_CLI_PARENT_START_TIME']; + if (parentStartTime) { + const startAbsMs = parseInt(parentStartTime, 10); + // Record how long the parent process(es) took before this child started. + startupProfiler.recordPhase( + 'parent_process_duration', + startAbsMs, + performance.timeOrigin, + ); + // Measure overall time from the very first process start + startupProfiler.start('overall_startup', {}, startAbsMs); + // Measure time from this child process launch + startupProfiler.start('child_process_to_ui_visible'); + startupProfiler.start('child_process_to_typing_ready'); + } + // Listen for admin controls from parent process (IPC) in non-sandbox mode. In // sandbox mode, we re-fetch the admin controls from the server once we enter // the sandbox. diff --git a/packages/cli/src/ui/AppContainer.tsx b/packages/cli/src/ui/AppContainer.tsx index 41cc5dec3d..8579850c74 100644 --- a/packages/cli/src/ui/AppContainer.tsx +++ b/packages/cli/src/ui/AppContainer.tsx @@ -429,7 +429,6 @@ export const AppContainer = (props: AppContainerProps) => { await config.initialize(); } setConfigInitialized(true); - startupProfiler.flush(config); const sessionStartSource = resumedSessionData ? SessionStartSource.Resume @@ -2578,6 +2577,23 @@ Logging in with Google... Restarting Gemini CLI to continue. ], ); + const hasFlushedStartupRef = useRef(false); + useEffect(() => { + if ( + authState === AuthState.Authenticated && + !hasFlushedStartupRef.current + ) { + startupProfiler.endPhase('child_process_to_typing_ready'); + startupProfiler.endPhase('overall_startup'); + startupProfiler.flush(config); + hasFlushedStartupRef.current = true; + } + }, [authState, config]); + + useLayoutEffect(() => { + startupProfiler.endPhase('child_process_to_ui_visible'); + }, []); + if (authState === AuthState.AwaitingGoogleLoginRestart) { return ( { const handle = profiler.start('test_phase'); expect(handle).toBeUndefined(); }); + + it('should support starting a phase at a specific absolute time', () => { + const startTimeMs = Date.now() - 1000; + profiler.start('custom_start_phase', {}, startTimeMs); + + const phase = profiler['phases'].get('custom_start_phase'); + expect(phase?.relativeStart).toBeDefined(); + expect(phase?.relativeStart).toBeCloseTo( + startTimeMs - performance.timeOrigin, + 0, + ); + }); }); describe('end', () => { @@ -121,6 +133,17 @@ describe('StartupProfiler', () => { expect(measure?.duration).toBeGreaterThan(0); }); + it('should handle ending a phase started at a specific absolute time', () => { + const startTimeMs = Date.now() - 1000; + const handle = profiler.start('custom_start_phase', {}, startTimeMs); + handle?.end(); + + const measures = performance.getEntriesByType('measure'); + const measure = measures.find((m) => m.name === 'custom_start_phase'); + expect(measure).toBeDefined(); + expect(measure?.duration).toBeGreaterThanOrEqual(1000); + }); + it('should merge details when ending a phase', () => { const handle = profiler.start('test_phase', { initial: 'value' }); handle?.end({ additional: 'data' }); @@ -141,6 +164,50 @@ describe('StartupProfiler', () => { }); }); + describe('endPhase', () => { + it('should end a phase by name', () => { + profiler.start('named_phase'); + profiler.endPhase('named_phase', { end: 'detail' }); + + const phase = profiler['phases'].get('named_phase'); + expect(phase?.ended).toBe(true); + expect(phase?.details).toEqual({ end: 'detail' }); + + const measures = performance.getEntriesByType('measure'); + expect(measures.some((m) => m.name === 'named_phase')).toBe(true); + }); + + it('should warn and do nothing if phase does not exist', () => { + const warnSpy = vi.spyOn(debugLogger, 'warn'); + profiler.endPhase('non_existent'); + expect(warnSpy).toHaveBeenCalledWith( + expect.stringContaining( + "Cannot end phase 'non_existent': phase not found.", + ), + ); + }); + }); + + describe('recordPhase', () => { + it('should record a completed phase with start and end times', () => { + const startAbsMs = Date.now() - 2000; + const endAbsMs = Date.now() - 1000; + + profiler.recordPhase('historical_phase', startAbsMs, endAbsMs, { + meta: 'data', + }); + + const phase = profiler['phases'].get('historical_phase'); + expect(phase?.ended).toBe(true); + expect(phase?.details).toEqual({ meta: 'data' }); + + const measures = performance.getEntriesByType('measure'); + const measure = measures.find((m) => m.name === 'historical_phase'); + expect(measure).toBeDefined(); + expect(measure?.duration).toBeCloseTo(1000, 0); + }); + }); + describe('flush', () => { it('should call recordStartupPerformance for each completed phase', () => { const handle1 = profiler.start('phase1'); @@ -269,6 +336,13 @@ describe('StartupProfiler', () => { expect(logSpy).not.toHaveBeenCalled(); expect(debugSpy).toHaveBeenCalled(); }); + + it('should suppress warnings for incomplete phases when skipWarnings is true', () => { + const warnSpy = vi.spyOn(debugLogger, 'warn'); + profiler.start('incomplete_phase'); + profiler.flush(mockConfig, { skipWarnings: true }); + expect(warnSpy).not.toHaveBeenCalled(); + }); }); describe('integration scenarios', () => { diff --git a/packages/core/src/telemetry/startupProfiler.ts b/packages/core/src/telemetry/startupProfiler.ts index 89421380b7..a1c26a41f4 100644 --- a/packages/core/src/telemetry/startupProfiler.ts +++ b/packages/core/src/telemetry/startupProfiler.ts @@ -19,6 +19,8 @@ interface StartupPhase { cpuUsage?: NodeJS.CpuUsage; details?: Record; ended: boolean; + relativeStart?: number; + durationMs?: number; } /** @@ -66,12 +68,17 @@ export class StartupProfiler { * idempotent calls in environments where initialization might happen multiple * times. * + * @param phaseName The name of the phase. + * @param details Optional additional details. + * @param startAbsMs Optional absolute start time in milliseconds. If not provided, performance.now() is used. + * * Callers should handle the potential `undefined` return value, typically * by using optional chaining: `handle?.end()`. */ start( phaseName: string, details?: Record, + startAbsMs?: number, ): StartupPhaseHandle | undefined { const existingPhase = this.phases.get(phaseName); @@ -83,14 +90,20 @@ export class StartupProfiler { return undefined; } - const startMarkName = this.getStartMarkName(phaseName); - performance.mark(startMarkName, { detail: details }); + let relativeStart: number | undefined = undefined; + if (startAbsMs !== undefined) { + relativeStart = startAbsMs - performance.timeOrigin; + } else { + const startMarkName = this.getStartMarkName(phaseName); + performance.mark(startMarkName, { detail: details }); + } const phase: StartupPhase = { name: phaseName, startCpuUsage: process.cpuUsage(), details, ended: false, + relativeStart, }; this.phases.set(phaseName, phase); @@ -103,6 +116,53 @@ export class StartupProfiler { }; } + /** + * Ends a phase by its name. + */ + endPhase( + phaseName: string, + details?: Record, + ): void { + const phase = this.phases.get(phaseName); + if (!phase) { + debugLogger.warn( + `[STARTUP] Cannot end phase '${phaseName}': phase not found.`, + ); + return; + } + this._end(phase, details); + } + + /** + * Records a phase that has already completed. + */ + recordPhase( + phaseName: string, + startAbsMs: number, + endAbsMs: number, + details?: Record, + ): void { + const relativeStart = startAbsMs - performance.timeOrigin; + const relativeEnd = endAbsMs - performance.timeOrigin; + const durationMs = endAbsMs - startAbsMs; + + // Node.js performance.measure throws if start or end are negative in the options object. + // We clamp to 0 for the local performance entry, but preserve the real duration in the phase. + performance.measure(phaseName, { + start: Math.max(0, relativeStart), + end: Math.max(0, relativeEnd), + }); + + this.phases.set(phaseName, { + name: phaseName, + startCpuUsage: { user: 0, system: 0 }, + cpuUsage: { user: 0, system: 0 }, + details, + ended: true, + durationMs, + }); + } + /** * Marks the end of a phase and calculates duration. * This is now a private method; callers should use the handle returned by start(). @@ -119,20 +179,30 @@ export class StartupProfiler { return; } - const startMarkName = this.getStartMarkName(phase.name); const endMarkName = this.getEndMarkName(phase.name); - - // Check if start mark exists before measuring - if (performance.getEntriesByName(startMarkName).length === 0) { - debugLogger.warn( - `[STARTUP] Cannot measure phase '${phase.name}': start mark '${startMarkName}' not found (likely cleared by reset).`, - ); - phase.ended = true; - return; - } - performance.mark(endMarkName, { detail: details }); - performance.measure(phase.name, startMarkName, endMarkName); + + if (phase.relativeStart !== undefined) { + const now = performance.now(); + phase.durationMs = now - phase.relativeStart; + // Clamp start to 0 for the performance measure to avoid ERR_PERFORMANCE_INVALID_TIMESTAMP, + // as relativeStart will be negative if it began before this process started. + performance.measure(phase.name, { + start: Math.max(0, phase.relativeStart), + end: now, + }); + } else { + const startMarkName = this.getStartMarkName(phase.name); + // Check if start mark exists before measuring + if (performance.getEntriesByName(startMarkName).length === 0) { + debugLogger.warn( + `[STARTUP] Cannot measure phase '${phase.name}': start mark '${startMarkName}' not found (likely cleared by reset).`, + ); + phase.ended = true; + return; + } + performance.measure(phase.name, startMarkName, endMarkName); + } phase.cpuUsage = process.cpuUsage(phase.startCpuUsage); phase.ended = true; @@ -144,7 +214,7 @@ export class StartupProfiler { /** * Flushes buffered metrics to the telemetry system. */ - flush(config: Config): void { + flush(config: Config, options: { skipWarnings?: boolean } = {}): void { debugLogger.debug( '[STARTUP] StartupProfiler.flush() called with', this.phases.size, @@ -160,13 +230,16 @@ export class StartupProfiler { // Get all performance measures. const measures = performance.getEntriesByType('measure'); + const flushedPhaseNames: string[] = []; for (const phase of this.phases.values()) { - // Warn about incomplete phases. + // Handle incomplete phases. if (!phase.ended) { - debugLogger.warn( - `[STARTUP] Phase '${phase.name}' was started but never ended. Skipping metrics.`, - ); + if (!options.skipWarnings) { + debugLogger.warn( + `[STARTUP] Phase '${phase.name}' was started but never ended. Skipping metrics.`, + ); + } continue; } @@ -174,6 +247,13 @@ export class StartupProfiler { const measure = measures.find((m) => m.name === phase.name); if (measure && phase.cpuUsage) { + const durationMs = phase.durationMs ?? measure.duration; + + // Skip metrics with non-positive duration. + if (durationMs <= 0) { + continue; + } + const details = { ...commonDetails, cpu_usage_user: phase.cpuUsage.user, @@ -185,12 +265,13 @@ export class StartupProfiler { '[STARTUP] Recording metric for phase:', phase.name, 'duration:', - measure.duration, + durationMs, ); - recordStartupPerformance(config, measure.duration, { + recordStartupPerformance(config, durationMs, { phase: phase.name, details, }); + flushedPhaseNames.push(phase.name); } else { debugLogger.debug( '[STARTUP] Skipping phase without measure:', @@ -205,9 +286,10 @@ export class StartupProfiler { if (!phase.ended) continue; const measure = measures.find((m) => m.name === phase.name); if (measure && phase.cpuUsage) { + const durationMs = phase.durationMs ?? measure.duration; startupPhases.push({ name: phase.name, - duration_ms: measure.duration, + duration_ms: durationMs, cpu_usage_user_usec: phase.cpuUsage.user, cpu_usage_system_usec: phase.cpuUsage.system, start_time_usec: (performance.timeOrigin + measure.startTime) * 1000, @@ -230,18 +312,18 @@ export class StartupProfiler { ); } - // Clear performance marks and measures for all tracked phases. - for (const phaseName of this.phases.keys()) { + // Clear performance marks and measures for the successfully flushed phases. + for (const phaseName of flushedPhaseNames) { const startMarkName = this.getStartMarkName(phaseName); const endMarkName = this.getEndMarkName(phaseName); performance.clearMarks(startMarkName); performance.clearMarks(endMarkName); performance.clearMeasures(phaseName); - } - // Clear all phases. - this.phases.clear(); + // Remove the successfully flushed phase from the tracking map. + this.phases.delete(phaseName); + } } }