diff --git a/packages/a2a-server/src/config/config.ts b/packages/a2a-server/src/config/config.ts index 97a343eb8d..10f5a1b81c 100644 --- a/packages/a2a-server/src/config/config.ts +++ b/packages/a2a-server/src/config/config.ts @@ -21,6 +21,7 @@ import { DEFAULT_GEMINI_EMBEDDING_MODEL, DEFAULT_GEMINI_MODEL, type ExtensionLoader, + startupProfiler, } from '@google/gemini-cli-core'; import { logger } from '../utils/logger.js'; @@ -88,6 +89,7 @@ export async function loadConfig( }); // Needed to initialize ToolRegistry, and git checkpointing if enabled await config.initialize(); + startupProfiler.flush(config); if (process.env['USE_CCPA']) { logger.info('[Config] Using CCPA Auth:'); diff --git a/packages/cli/src/core/initializer.ts b/packages/cli/src/core/initializer.ts index b7b2c6be16..0ba76a989f 100644 --- a/packages/cli/src/core/initializer.ts +++ b/packages/cli/src/core/initializer.ts @@ -12,6 +12,7 @@ import { type Config, StartSessionEvent, logCliConfiguration, + startupProfiler, } from '@google/gemini-cli-core'; import { type LoadedSettings } from '../config/settings.js'; import { performInitialAuth } from './auth.js'; @@ -35,10 +36,12 @@ export async function initializeApp( config: Config, settings: LoadedSettings, ): Promise { + const authHandle = startupProfiler.start('authenticate'); const authError = await performInitialAuth( config, settings.merged.security?.auth?.selectedType, ); + authHandle?.end(); const themeError = validateTheme(settings); const shouldOpenAuthDialog = diff --git a/packages/cli/src/gemini.tsx b/packages/cli/src/gemini.tsx index e61f3ff364..e8c1ad185f 100644 --- a/packages/cli/src/gemini.tsx +++ b/packages/cli/src/gemini.tsx @@ -56,6 +56,7 @@ import { enterAlternateScreen, disableLineWrapping, shouldEnterAlternateScreen, + startupProfiler, ExitCodes, } from '@google/gemini-cli-core'; import { @@ -281,6 +282,7 @@ export async function startInteractiveUI( } export async function main() { + const cliStartupHandle = startupProfiler.start('cli_startup'); const cleanupStdio = patchStdio(); registerSyncCleanup(() => { // This is needed to ensure we don't lose any buffered output. @@ -289,7 +291,11 @@ export async function main() { }); setupUnhandledRejectionHandler(); + const loadSettingsHandle = startupProfiler.start('load_settings'); const settings = loadSettings(); + loadSettingsHandle?.end(); + + const migrateHandle = startupProfiler.start('migrate_settings'); migrateDeprecatedSettings( settings, // Temporary extension manager only used during this non-interactive UI phase. @@ -301,9 +307,12 @@ export async function main() { requestSetting: null, }), ); + migrateHandle?.end(); await cleanupCheckpoints(); + const parseArgsHandle = startupProfiler.start('parse_arguments'); const argv = await parseArguments(settings.merged); + parseArgsHandle?.end(); // Check for invalid input combinations early to prevent crashes if (argv.promptInteractive && !process.stdin.isTTY) { @@ -446,7 +455,9 @@ export async function main() { // to run Gemini CLI. It is now safe to perform expensive initialization that // may have side effects. { + const loadConfigHandle = startupProfiler.start('load_cli_config'); const config = await loadCliConfig(settings.merged, sessionId, argv); + loadConfigHandle?.end(); const policyEngine = config.getPolicyEngine(); const messageBus = config.getMessageBus(); @@ -514,7 +525,9 @@ export async function main() { } setMaxSizedBoxDebugging(isDebugMode); + const initAppHandle = startupProfiler.start('initialize_app'); const initializationResult = await initializeApp(config, settings); + initAppHandle?.end(); if ( settings.merged.security?.auth?.selectedType === @@ -556,6 +569,7 @@ export async function main() { } } + cliStartupHandle?.end(); // Render UI, passing necessary config values. Check that there is no command line question. if (config.isInteractive()) { await startInteractiveUI( @@ -570,6 +584,7 @@ export async function main() { } await config.initialize(); + startupProfiler.flush(config); // If not a TTY, read from stdin // This is for cases where the user pipes input directly into the command diff --git a/packages/cli/src/services/BuiltinCommandLoader.ts b/packages/cli/src/services/BuiltinCommandLoader.ts index d0bc8b4ff9..2bbb0d8824 100644 --- a/packages/cli/src/services/BuiltinCommandLoader.ts +++ b/packages/cli/src/services/BuiltinCommandLoader.ts @@ -8,6 +8,7 @@ import { isDevelopment } from '../utils/installationInfo.js'; import type { ICommandLoader } from './types.js'; import type { SlashCommand } from '../ui/commands/types.js'; import type { Config } from '@google/gemini-cli-core'; +import { startupProfiler } from '@google/gemini-cli-core'; import { aboutCommand } from '../ui/commands/aboutCommand.js'; import { authCommand } from '../ui/commands/authCommand.js'; import { bugCommand } from '../ui/commands/bugCommand.js'; @@ -56,6 +57,7 @@ export class BuiltinCommandLoader implements ICommandLoader { * @returns A promise that resolves to an array of `SlashCommand` objects. */ async loadCommands(_signal: AbortSignal): Promise { + const handle = startupProfiler.start('load_builtin_commands'); const allDefinitions: Array = [ aboutCommand, authCommand, @@ -92,7 +94,7 @@ export class BuiltinCommandLoader implements ICommandLoader { setupGithubCommand, terminalSetupCommand, ]; - + handle?.end(); return allDefinitions.filter((cmd): cmd is SlashCommand => cmd !== null); } } diff --git a/packages/cli/src/ui/AppContainer.tsx b/packages/cli/src/ui/AppContainer.tsx index 13d73a6336..95564f5db2 100644 --- a/packages/cli/src/ui/AppContainer.tsx +++ b/packages/cli/src/ui/AppContainer.tsx @@ -58,6 +58,7 @@ import { enableMouseEvents, disableLineWrapping, shouldEnterAlternateScreen, + startupProfiler, } from '@google/gemini-cli-core'; import { validateAuthMethod } from '../config/auth.js'; import process from 'node:process'; @@ -282,6 +283,7 @@ export const AppContainer = (props: AppContainerProps) => { // handled by the global catch. await config.initialize(); setConfigInitialized(true); + startupProfiler.flush(config); })(); registerCleanup(async () => { // Turn off mouse scroll. diff --git a/packages/cli/src/zed-integration/zedIntegration.ts b/packages/cli/src/zed-integration/zedIntegration.ts index 2f314c5349..e064f57977 100644 --- a/packages/cli/src/zed-integration/zedIntegration.ts +++ b/packages/cli/src/zed-integration/zedIntegration.ts @@ -30,6 +30,7 @@ import { debugLogger, ReadManyFilesTool, getEffectiveModel, + startupProfiler, } from '@google/gemini-cli-core'; import * as acp from './acp.js'; import { AcpFileSystemService } from './fileSystemService.js'; @@ -189,6 +190,7 @@ export class GeminiAgent { const config = await loadCliConfig(settings, sessionId, this.argv, cwd); await config.initialize(); + startupProfiler.flush(config); return config; } diff --git a/packages/core/src/config/config.ts b/packages/core/src/config/config.ts index 40696a4c25..4693810f0f 100644 --- a/packages/core/src/config/config.ts +++ b/packages/core/src/config/config.ts @@ -87,6 +87,7 @@ import { SubagentToolWrapper } from '../agents/subagent-tool-wrapper.js'; import { getExperiments } from '../code_assist/experiments/experiments.js'; import { ExperimentFlags } from '../code_assist/experiments/flagNames.js'; import { debugLogger } from '../utils/debugLogger.js'; +import { startupProfiler } from '../telemetry/startupProfiler.js'; import { ApprovalMode } from '../policy/types.js'; @@ -620,6 +621,7 @@ export class Config { this.initialized = true; // Initialize centralized FileDiscoveryService + const discoverToolsHandle = startupProfiler.start('discover_tools'); this.getFileService(); if (this.getCheckpointingEnabled()) { await this.getGitService(); @@ -630,15 +632,18 @@ export class Config { await this.agentRegistry.initialize(); this.toolRegistry = await this.createToolRegistry(); + discoverToolsHandle?.end(); this.mcpClientManager = new McpClientManager( this.toolRegistry, this, this.eventEmitter, ); + const initMcpHandle = startupProfiler.start('initialize_mcp_clients'); await Promise.all([ await this.mcpClientManager.startConfiguredMcpServers(), await this.getExtensionLoader().start(this), ]); + initMcpHandle?.end(); // Initialize hook system if enabled if (this.enableHooks) { diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index f9f520ae78..3e8cb53935 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -137,3 +137,4 @@ export { GenAiTokenType, } from './metrics.js'; export { runInDevTraceSpan, type SpanMetadata } from './trace.js'; +export { startupProfiler, StartupProfiler } from './startupProfiler.js'; diff --git a/packages/core/src/telemetry/startupProfiler.test.ts b/packages/core/src/telemetry/startupProfiler.test.ts new file mode 100644 index 0000000000..b0de573d35 --- /dev/null +++ b/packages/core/src/telemetry/startupProfiler.test.ts @@ -0,0 +1,343 @@ +/** + * @license + * Copyright 2025 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { StartupProfiler } from './startupProfiler.js'; +import type { Config } from '../config/config.js'; + +// Mock the metrics module +vi.mock('./metrics.js', () => ({ + recordStartupPerformance: vi.fn(), +})); + +// Mock os module +vi.mock('node:os', () => ({ + platform: vi.fn(() => 'darwin'), + arch: vi.fn(() => 'x64'), + release: vi.fn(() => '22.6.0'), +})); + +// Mock fs module +vi.mock('node:fs', () => ({ + existsSync: vi.fn(() => false), +})); + +describe('StartupProfiler', () => { + let profiler: StartupProfiler; + let mockConfig: Config; + let recordStartupPerformance: ReturnType; + + beforeEach(async () => { + vi.resetAllMocks(); + + // Get the mocked function + const metricsModule = await import('./metrics.js'); + recordStartupPerformance = + metricsModule.recordStartupPerformance as ReturnType; + + // Create a fresh profiler instance + profiler = StartupProfiler.getInstance(); + + // Clear any existing phases and performance entries + profiler['phases'].clear(); + performance.clearMarks(); + performance.clearMeasures(); + + mockConfig = { + getSessionId: () => 'test-session-id', + getTelemetryEnabled: () => true, + } as unknown as Config; + }); + + afterEach(() => { + vi.restoreAllMocks(); + }); + + describe('getInstance', () => { + it('should return a singleton instance', () => { + const instance1 = StartupProfiler.getInstance(); + const instance2 = StartupProfiler.getInstance(); + expect(instance1).toBe(instance2); + }); + }); + + describe('start', () => { + it('should create a performance mark for a phase', () => { + profiler.start('test_phase'); + + const phase = profiler['phases'].get('test_phase'); + expect(phase).toBeDefined(); + expect(phase?.name).toBe('test_phase'); + + // Verify performance mark was created + const marks = performance.getEntriesByType('mark'); + const startMark = marks.find( + (m) => m.name === 'startup:test_phase:start', + ); + expect(startMark).toBeDefined(); + }); + + it('should record start time with details', () => { + const details = { key: 'value', count: 42 }; + profiler.start('test_phase', details); + + const phase = profiler['phases'].get('test_phase'); + expect(phase?.details).toEqual(details); + }); + + it('should return undefined when starting a phase that is already active', () => { + profiler.start('test_phase'); + const handle = profiler.start('test_phase'); + expect(handle).toBeUndefined(); + }); + }); + + describe('end', () => { + it('should create a performance measure for a started phase', () => { + const handle = profiler.start('test_phase'); + handle?.end(); + + // Verify performance measure was created + const measures = performance.getEntriesByType('measure'); + const measure = measures.find((m) => m.name === 'test_phase'); + expect(measure).toBeDefined(); + expect(measure?.duration).toBeGreaterThan(0); + }); + + it('should merge details when ending a phase', () => { + const handle = profiler.start('test_phase', { initial: 'value' }); + handle?.end({ additional: 'data' }); + + const phase = profiler['phases'].get('test_phase'); + expect(phase?.details).toEqual({ + initial: 'value', + additional: 'data', + }); + }); + + it('should overwrite details with same key', () => { + const handle = profiler.start('test_phase', { key: 'original' }); + handle?.end({ key: 'updated' }); + + const phase = profiler['phases'].get('test_phase'); + expect(phase?.details).toEqual({ key: 'updated' }); + }); + }); + + describe('flush', () => { + it('should call recordStartupPerformance for each completed phase', () => { + const handle1 = profiler.start('phase1'); + handle1?.end(); + + const handle2 = profiler.start('phase2'); + handle2?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledTimes(2); + }); + + it('should not record phases without duration', () => { + profiler.start('incomplete_phase'); + profiler.flush(mockConfig); + + expect(recordStartupPerformance).not.toHaveBeenCalled(); + }); + + it('should include common details in all metrics', () => { + const handle = profiler.start('test_phase'); + handle?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ + phase: 'test_phase', + details: expect.objectContaining({ + os_platform: 'darwin', + os_arch: 'x64', + os_release: '22.6.0', + is_docker: false, + cpu_usage_user: expect.any(Number), + cpu_usage_system: expect.any(Number), + }), + }), + ); + }); + + it('should merge phase-specific details with common details', () => { + const handle = profiler.start('test_phase', { custom: 'value' }); + handle?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ + phase: 'test_phase', + details: expect.objectContaining({ + custom: 'value', + os_platform: 'darwin', + }), + }), + ); + }); + + it('should clear phases after flushing', () => { + const handle = profiler.start('test_phase'); + handle?.end(); + + profiler.flush(mockConfig); + + expect(profiler['phases'].size).toBe(0); + }); + + it('should detect Docker environment', async () => { + const fs = await import('node:fs'); + (fs.existsSync as ReturnType).mockReturnValue(true); + + const handle = profiler.start('test_phase'); + handle?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ + details: expect.objectContaining({ + is_docker: true, + }), + }), + ); + }); + + it('should calculate CPU usage correctly', () => { + const cpuUsageSpy = vi.spyOn(process, 'cpuUsage'); + // Mock start usage + cpuUsageSpy.mockReturnValueOnce({ user: 1000, system: 500 }); + // Mock diff usage (this is what process.cpuUsage(startUsage) returns) + cpuUsageSpy.mockReturnValueOnce({ user: 100, system: 50 }); + + const handle = profiler.start('cpu_test_phase'); + handle?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ + phase: 'cpu_test_phase', + details: expect.objectContaining({ + cpu_usage_user: 100, + cpu_usage_system: 50, + }), + }), + ); + }); + }); + + describe('integration scenarios', () => { + it('should handle a complete startup profiling workflow', () => { + // Simulate startup sequence + const totalHandle = profiler.start('total_startup'); + + const settingsHandle = profiler.start('load_settings'); + settingsHandle?.end(); + + const argsHandle = profiler.start('parse_arguments'); + argsHandle?.end(); + + const appHandle = profiler.start('initialize_app'); + appHandle?.end(); + + totalHandle?.end(); + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).toHaveBeenCalledTimes(4); + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ phase: 'total_startup' }), + ); + }); + + it('should handle nested timing correctly', () => { + const outerHandle = profiler.start('outer'); + const innerHandle = profiler.start('inner'); + innerHandle?.end(); + outerHandle?.end(); + + profiler.flush(mockConfig); + + const calls = (recordStartupPerformance as ReturnType).mock + .calls; + const outerCall = calls.find((call) => call[2].phase === 'outer'); + const innerCall = calls.find((call) => call[2].phase === 'inner'); + + expect(outerCall).toBeDefined(); + expect(innerCall).toBeDefined(); + // Outer duration should be >= inner duration + expect(outerCall![1]).toBeGreaterThanOrEqual(innerCall![1]); + }); + }); + + describe('sanity checking', () => { + it('should return undefined when starting a phase that is already active', () => { + profiler.start('test_phase'); + const handle = profiler.start('test_phase'); + expect(handle).toBeUndefined(); + }); + + it('should allow restarting a phase after it has ended', () => { + const handle1 = profiler.start('test_phase'); + handle1?.end(); + + // Should not throw + expect(() => profiler.start('test_phase')).not.toThrow(); + }); + + it('should not throw error when ending a phase that is already ended', () => { + const handle = profiler.start('test_phase'); + handle?.end(); + + // Calling end() again on the same handle should not throw + expect(() => handle?.end()).not.toThrow(); + }); + + it('should not record metrics for incomplete phases', () => { + profiler.start('incomplete_phase'); + // Never call end() + + profiler.flush(mockConfig); + + expect(recordStartupPerformance).not.toHaveBeenCalled(); + }); + + it('should handle mix of complete and incomplete phases', () => { + const completeHandle = profiler.start('complete_phase'); + completeHandle?.end(); + + profiler.start('incomplete_phase'); + // Never call end() + + profiler.flush(mockConfig); + + // Should only record the complete phase + expect(recordStartupPerformance).toHaveBeenCalledTimes(1); + expect(recordStartupPerformance).toHaveBeenCalledWith( + mockConfig, + expect.any(Number), + expect.objectContaining({ phase: 'complete_phase' }), + ); + }); + }); +}); diff --git a/packages/core/src/telemetry/startupProfiler.ts b/packages/core/src/telemetry/startupProfiler.ts new file mode 100644 index 0000000000..42c20e48e4 --- /dev/null +++ b/packages/core/src/telemetry/startupProfiler.ts @@ -0,0 +1,215 @@ +/** + * @license + * Copyright 2025 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { performance } from 'node:perf_hooks'; +import * as os from 'node:os'; +import * as fs from 'node:fs'; +import type { Config } from '../config/config.js'; +import { recordStartupPerformance } from './metrics.js'; +import { debugLogger } from '../utils/debugLogger.js'; + +interface StartupPhase { + name: string; + startCpuUsage: NodeJS.CpuUsage; + cpuUsage?: NodeJS.CpuUsage; + details?: Record; + ended: boolean; +} + +/** + * Handle returned by start() that allows ending the phase without repeating the phase name. + */ +export interface StartupPhaseHandle { + end(details?: Record): void; +} + +/** + * Buffers startup performance metrics until the telemetry system is fully initialized. + */ +export class StartupProfiler { + private phases: Map = new Map(); + private static instance: StartupProfiler; + + private constructor() {} + + static getInstance(): StartupProfiler { + if (!StartupProfiler.instance) { + StartupProfiler.instance = new StartupProfiler(); + } + return StartupProfiler.instance; + } + + /** + * Returns the mark name for the start of a phase. + */ + private getStartMarkName(phaseName: string): string { + return `startup:${phaseName}:start`; + } + + /** + * Returns the mark name for the end of a phase. + */ + private getEndMarkName(phaseName: string): string { + return `startup:${phaseName}:end`; + } + + /** + * Marks the start of a phase and returns a handle to end it. + * + * If a phase with the same name is already active (started but not ended), + * this method will log a warning and return `undefined`. This allows for + * idempotent calls in environments where initialization might happen multiple + * times. + * + * Callers should handle the potential `undefined` return value, typically + * by using optional chaining: `handle?.end()`. + */ + start( + phaseName: string, + details?: Record, + ): StartupPhaseHandle | undefined { + const existingPhase = this.phases.get(phaseName); + + // Error if starting a phase that's already active. + if (existingPhase && !existingPhase.ended) { + debugLogger.warn( + `[STARTUP] Cannot start phase '${phaseName}': phase is already active. Call end() before starting again.`, + ); + return undefined; + } + + const startMarkName = this.getStartMarkName(phaseName); + performance.mark(startMarkName, { detail: details }); + + const phase: StartupPhase = { + name: phaseName, + startCpuUsage: process.cpuUsage(), + details, + ended: false, + }; + + this.phases.set(phaseName, phase); + + // Return a handle that allows ending the phase without repeating the name + return { + end: (endDetails?: Record) => { + this._end(phase, endDetails); + }, + }; + } + + /** + * Marks the end of a phase and calculates duration. + * This is now a private method; callers should use the handle returned by start(). + */ + private _end( + phase: StartupPhase, + details?: Record, + ): void { + // Error if ending a phase that's already ended. + if (phase.ended) { + debugLogger.warn( + `[STARTUP] Cannot end phase '${phase.name}': phase was already ended.`, + ); + 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); + + phase.cpuUsage = process.cpuUsage(phase.startCpuUsage); + phase.ended = true; + if (details) { + phase.details = { ...phase.details, ...details }; + } + } + + /** + * Flushes buffered metrics to the telemetry system. + */ + flush(config: Config): void { + debugLogger.log( + '[STARTUP] StartupProfiler.flush() called with', + this.phases.size, + 'phases', + ); + + const commonDetails = { + os_platform: os.platform(), + os_arch: os.arch(), + os_release: os.release(), + is_docker: fs.existsSync('/.dockerenv'), + }; + + // Get all performance measures. + const measures = performance.getEntriesByType('measure'); + + for (const phase of this.phases.values()) { + // Warn about incomplete phases. + if (!phase.ended) { + debugLogger.warn( + `[STARTUP] Phase '${phase.name}' was started but never ended. Skipping metrics.`, + ); + continue; + } + + // Find the corresponding measure. + const measure = measures.find((m) => m.name === phase.name); + + if (measure && phase.cpuUsage) { + const details = { + ...commonDetails, + cpu_usage_user: phase.cpuUsage.user, + cpu_usage_system: phase.cpuUsage.system, + ...phase.details, + }; + + debugLogger.log( + '[STARTUP] Recording metric for phase:', + phase.name, + 'duration:', + measure.duration, + ); + recordStartupPerformance(config, measure.duration, { + phase: phase.name, + details, + }); + } else { + debugLogger.log( + '[STARTUP] Skipping phase without measure:', + phase.name, + ); + } + } + + // Clear performance marks and measures for all tracked phases. + for (const phaseName of this.phases.keys()) { + 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(); + } +} + +export const startupProfiler = StartupProfiler.getInstance();