diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index 4706a28218..8a2c08f2a5 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -50,6 +50,7 @@ import type { ExtensionUpdateEvent, LlmLoopCheckEvent, HookCallEvent, + StartupStatsEvent, } from './types.js'; import { recordApiErrorMetrics, @@ -688,3 +689,17 @@ export function logHookCall(config: Config, event: HookCallEvent): void { ); }); } + +export function logStartupStats( + config: Config, + event: StartupStatsEvent, +): void { + bufferTelemetryEvent(() => { + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: event.toLogBody(), + attributes: event.toOpenTelemetryAttributes(config), + }; + logger.emit(logRecord); + }); +} diff --git a/packages/core/src/telemetry/startupProfiler.test.ts b/packages/core/src/telemetry/startupProfiler.test.ts index 51c86ca89e..5a45974862 100644 --- a/packages/core/src/telemetry/startupProfiler.test.ts +++ b/packages/core/src/telemetry/startupProfiler.test.ts @@ -13,6 +13,11 @@ vi.mock('./metrics.js', () => ({ recordStartupPerformance: vi.fn(), })); +// Mock loggers module +vi.mock('./loggers.js', () => ({ + logStartupStats: vi.fn(), +})); + // Mock os module vi.mock('node:os', () => ({ platform: vi.fn(() => 'darwin'), @@ -33,6 +38,7 @@ describe('StartupProfiler', () => { let profiler: StartupProfiler; let mockConfig: Config; let recordStartupPerformance: ReturnType; + let logStartupStats: ReturnType; beforeEach(async () => { vi.resetAllMocks(); @@ -42,6 +48,9 @@ describe('StartupProfiler', () => { recordStartupPerformance = metricsModule.recordStartupPerformance as ReturnType; + const loggersModule = await import('./loggers.js'); + logStartupStats = loggersModule.logStartupStats as ReturnType; + // Create a fresh profiler instance profiler = StartupProfiler.getInstance(); @@ -343,5 +352,28 @@ describe('StartupProfiler', () => { expect.objectContaining({ phase: 'complete_phase' }), ); }); + it('should log startup stats event', () => { + const handle = profiler.start('test_phase'); + handle?.end(); + + profiler.flush(mockConfig); + + expect(logStartupStats).toHaveBeenCalledWith( + mockConfig, + expect.objectContaining({ + phases: expect.arrayContaining([ + expect.objectContaining({ + name: 'test_phase', + duration_ms: expect.any(Number), + start_time_usec: expect.any(Number), + end_time_usec: expect.any(Number), + }), + ]), + os_platform: 'darwin', + os_release: '22.6.0', + is_docker: false, + }), + ); + }); }); }); diff --git a/packages/core/src/telemetry/startupProfiler.ts b/packages/core/src/telemetry/startupProfiler.ts index 42c20e48e4..07776cfe36 100644 --- a/packages/core/src/telemetry/startupProfiler.ts +++ b/packages/core/src/telemetry/startupProfiler.ts @@ -10,6 +10,8 @@ import * as fs from 'node:fs'; import type { Config } from '../config/config.js'; import { recordStartupPerformance } from './metrics.js'; import { debugLogger } from '../utils/debugLogger.js'; +import { StartupStatsEvent, type StartupPhaseStats } from './types.js'; +import { logStartupStats } from './loggers.js'; interface StartupPhase { name: string; @@ -197,6 +199,37 @@ export class StartupProfiler { } } + // Emit StartupStats event + const startupPhases: StartupPhaseStats[] = []; + for (const phase of this.phases.values()) { + if (!phase.ended) continue; + const measure = measures.find((m) => m.name === phase.name); + if (measure && phase.cpuUsage) { + startupPhases.push({ + name: phase.name, + duration_ms: measure.duration, + cpu_usage_user_usec: phase.cpuUsage.user, + cpu_usage_system_usec: phase.cpuUsage.system, + start_time_usec: (performance.timeOrigin + measure.startTime) * 1000, + end_time_usec: + (performance.timeOrigin + measure.startTime + measure.duration) * + 1000, + }); + } + } + + if (startupPhases.length > 0) { + logStartupStats( + config, + new StartupStatsEvent( + startupPhases, + os.platform(), + os.release(), + fs.existsSync('/.dockerenv'), + ), + ); + } + // Clear performance marks and measures for all tracked phases. for (const phaseName of this.phases.keys()) { const startMarkName = this.getStartMarkName(phaseName); diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index 680b9cd6a1..1368967719 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -1538,6 +1538,7 @@ export type TelemetryEvent = | AgentFinishEvent | RecoveryAttemptEvent | LlmLoopCheckEvent + | StartupStatsEvent | WebFetchFallbackAttemptEvent; export const EVENT_EXTENSION_DISABLE = 'gemini_cli.extension_disable'; @@ -1627,6 +1628,55 @@ export class SmartEditCorrectionEvent implements BaseTelemetryEvent { } } +export interface StartupPhaseStats { + name: string; + duration_ms: number; + cpu_usage_user_usec: number; + cpu_usage_system_usec: number; + start_time_usec: number; + end_time_usec: number; +} + +export const EVENT_STARTUP_STATS = 'gemini_cli.startup_stats'; +export class StartupStatsEvent implements BaseTelemetryEvent { + 'event.name': 'startup_stats'; + 'event.timestamp': string; + phases: StartupPhaseStats[]; + os_platform: string; + os_release: string; + is_docker: boolean; + + constructor( + phases: StartupPhaseStats[], + os_platform: string, + os_release: string, + is_docker: boolean, + ) { + this['event.name'] = 'startup_stats'; + this['event.timestamp'] = new Date().toISOString(); + this.phases = phases; + this.os_platform = os_platform; + this.os_release = os_release; + this.is_docker = is_docker; + } + + toOpenTelemetryAttributes(config: Config): LogAttributes { + return { + ...getCommonAttributes(config), + 'event.name': EVENT_STARTUP_STATS, + 'event.timestamp': this['event.timestamp'], + phases: JSON.stringify(this.phases), + os_platform: this.os_platform, + os_release: this.os_release, + is_docker: this.is_docker, + }; + } + + toLogBody(): string { + return `Startup stats: ${this.phases.length} phases recorded.`; + } +} + abstract class BaseAgentEvent implements BaseTelemetryEvent { abstract 'event.name': | 'agent_start'