feat(cli): add startup performance profiler (#3232)

feat(cli): add startup performance profiler (#3219)

  Add a lightweight startup profiler activated via QWEN_CODE_PROFILE_STARTUP=1.
  When enabled, collects performance.now() timestamps at 7 key phases in main()
  and writes a JSON report to ~/.qwen/startup-perf/. Also records
  process.uptime() at T0 to capture module loading time not covered by
  checkpoint-based measurement.

  Key design decisions:
  - Only profiles inside sandbox child process to avoid duplicate reports
  - initStartupProfiler() is idempotent (resets state on each call)
  - Filename uses report.sessionId for consistency with JSON content
  - Zero overhead when disabled (single env var check)

  Initial measurement: module loading ~1342ms (94%), main() ~85ms (6%),
  confirming barrel exports and eager dependency loading as primary
  optimization targets for #3011.

  Co-authored-by: Qwen-Coder <qwen-coder@alibabacloud.com>

packages/cli/index.ts

@@ -6,6 +6,11 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
+import { initStartupProfiler } from './src/utils/startupProfiler.js';
+
+// Must run before any other imports to capture the earliest possible T0.
+initStartupProfiler();
+
 import './src/gemini.js';
 import { main } from './src/gemini.js';
 import { FatalError } from '@qwen-code/qwen-code-core';

packages/cli/src/gemini.test.tsx

@@ -179,6 +179,7 @@ describe('gemini.tsx main function', () => {
         getProjectRoot: () => '/',
         getOutputFormat: () => OutputFormat.TEXT,
         getWarnings: () => [],
+        getSessionId: () => 'test-session-id',
       } as unknown as Config;
     });
     vi.mocked(loadSettings).mockReturnValue({
@@ -448,6 +449,7 @@ describe('gemini.tsx main function kitty protocol', () => {
       getGeminiMdFileCount: () => 0,
       getWarnings: () => [],
       getUsageStatisticsEnabled: () => true,
+      getSessionId: () => 'test-session-id',
     } as unknown as Config);
     vi.mocked(loadSettings).mockReturnValue({
       errors: [],

packages/cli/src/gemini.tsx

@@ -48,6 +48,10 @@ import {
 import { AppEvent, appEvents } from './utils/events.js';
 import { handleAutoUpdate } from './utils/handleAutoUpdate.js';
 import { readStdin } from './utils/readStdin.js';
+import {
+  profileCheckpoint,
+  finalizeStartupProfile,
+} from './utils/startupProfiler.js';
 import {
   relaunchAppInChildProcess,
   relaunchOnExitCode,
@@ -210,11 +214,14 @@ export async function startInteractiveUI(
 }
 
 export async function main() {
+  profileCheckpoint('main_entry');
   setupUnhandledRejectionHandler();
   const settings = loadSettings();
   await cleanupCheckpoints();
+  profileCheckpoint('after_load_settings');
 
   let argv = await parseArguments();
+  profileCheckpoint('after_parse_arguments');
 
   // Check for invalid input combinations early to prevent crashes
   if (argv.promptInteractive && !process.stdin.isTTY) {
@@ -350,6 +357,7 @@ export async function main() {
   // We are now past the logic handling potentially launching a child process
   // to run Qwen Code. It is now safe to perform expensive initialization that
   // may have side effects.
+  profileCheckpoint('after_sandbox_check');
 
   // Initialize output language file before config loads to ensure it's included in context
   initializeLlmOutputLanguage(settings.merged.general?.outputLanguage);
@@ -361,6 +369,7 @@ export async function main() {
       process.cwd(),
       argv.extensions,
     );
+    profileCheckpoint('after_load_cli_config');
 
     // Register cleanup for MCP clients as early as possible
     // This ensures MCP server subprocesses are properly terminated on exit
@@ -407,6 +416,7 @@ export async function main() {
     // For stream-json mode, defer config.initialize() until after the initialize control request
     // For other modes, initialize normally
     const initializationResult = await initializeApp(config, settings);
+    profileCheckpoint('after_initialize_app');
 
     if (config.getExperimentalZedIntegration()) {
       await runAcpAgent(config, settings, argv);
@@ -430,6 +440,9 @@ export async function main() {
     ];
 
     // Render UI, passing necessary config values. Check that there is no command line question.
+    profileCheckpoint('before_render');
+    finalizeStartupProfile(config.getSessionId());
+
     if (config.isInteractive()) {
       // Need kitty detection to be complete before we can start the interactive UI.
       await kittyProtocolDetectionComplete;

packages/cli/src/utils/startupProfiler.test.ts

@@ -0,0 +1,225 @@
+import { vi, describe, it, expect, beforeEach, afterEach } from 'vitest';
+import * as fs from 'node:fs';
+import {
+  initStartupProfiler,
+  profileCheckpoint,
+  finalizeStartupProfile,
+  getStartupReport,
+  resetStartupProfiler,
+} from './startupProfiler.js';
+
+vi.mock('node:fs');
+
+describe('startupProfiler', () => {
+  const savedEnv: Record<string, string | undefined> = {};
+
+  function saveEnv(...keys: string[]) {
+    for (const k of keys) {
+      savedEnv[k] = process.env[k];
+    }
+  }
+
+  function restoreEnv() {
+    for (const [k, v] of Object.entries(savedEnv)) {
+      if (v !== undefined) {
+        process.env[k] = v;
+      } else {
+        delete process.env[k];
+      }
+    }
+  }
+
+  beforeEach(() => {
+    resetStartupProfiler();
+    vi.restoreAllMocks();
+    saveEnv('QWEN_CODE_PROFILE_STARTUP', 'SANDBOX');
+    delete process.env['QWEN_CODE_PROFILE_STARTUP'];
+    delete process.env['SANDBOX'];
+  });
+
+  afterEach(() => {
+    restoreEnv();
+  });
+
+  function enableProfiler() {
+    process.env['QWEN_CODE_PROFILE_STARTUP'] = '1';
+    process.env['SANDBOX'] = '1';
+  }
+
+  describe('when disabled (no env var)', () => {
+    it('should return null from getStartupReport', () => {
+      initStartupProfiler();
+      profileCheckpoint('test');
+      expect(getStartupReport()).toBeNull();
+    });
+
+    it('should not write any files on finalize', () => {
+      initStartupProfiler();
+      profileCheckpoint('test');
+      finalizeStartupProfile('session-1');
+      expect(fs.mkdirSync).not.toHaveBeenCalled();
+      expect(fs.writeFileSync).not.toHaveBeenCalled();
+    });
+  });
+
+  describe('when outside sandbox (SANDBOX not set)', () => {
+    it('should not enable profiler even with QWEN_CODE_PROFILE_STARTUP=1', () => {
+      process.env['QWEN_CODE_PROFILE_STARTUP'] = '1';
+      delete process.env['SANDBOX'];
+
+      initStartupProfiler();
+      profileCheckpoint('test');
+      expect(getStartupReport()).toBeNull();
+    });
+  });
+
+  describe('when enabled (QWEN_CODE_PROFILE_STARTUP=1 + SANDBOX)', () => {
+    beforeEach(() => {
+      enableProfiler();
+    });
+
+    it('should collect checkpoints and return a report', () => {
+      initStartupProfiler();
+      profileCheckpoint('phase_a');
+      profileCheckpoint('phase_b');
+      profileCheckpoint('phase_c');
+
+      const report = getStartupReport();
+      expect(report).not.toBeNull();
+      expect(report!.phases).toHaveLength(3);
+      expect(report!.phases[0]!.name).toBe('phase_a');
+      expect(report!.phases[1]!.name).toBe('phase_b');
+      expect(report!.phases[2]!.name).toBe('phase_c');
+      expect(report!.totalMs).toBeGreaterThanOrEqual(0);
+      expect(report!.processUptimeAtT0Ms).toBeGreaterThan(0);
+      expect(report!.nodeVersion).toBe(process.version);
+      expect(report!.platform).toBe(process.platform);
+      expect(report!.arch).toBe(process.arch);
+    });
+
+    it('should have non-negative durations for each phase', () => {
+      initStartupProfiler();
+      profileCheckpoint('a');
+      profileCheckpoint('b');
+
+      const report = getStartupReport();
+      for (const phase of report!.phases) {
+        expect(phase.durationMs).toBeGreaterThanOrEqual(0);
+        expect(phase.startMs).toBeGreaterThanOrEqual(0);
+      }
+    });
+
+    it('should write JSON file on finalize and print path to stderr', () => {
+      vi.mocked(fs.mkdirSync).mockReturnValue(undefined);
+      vi.mocked(fs.writeFileSync).mockReturnValue(undefined);
+      const stderrSpy = vi
+        .spyOn(process.stderr, 'write')
+        .mockReturnValue(true);
+
+      initStartupProfiler();
+      profileCheckpoint('main_entry');
+      profileCheckpoint('after_load_settings');
+      finalizeStartupProfile('test-session-123');
+
+      expect(fs.mkdirSync).toHaveBeenCalledWith(
+        expect.stringContaining('startup-perf'),
+        { recursive: true },
+      );
+      expect(fs.writeFileSync).toHaveBeenCalledTimes(1);
+
+      const writtenPath = vi.mocked(fs.writeFileSync).mock
+        .calls[0]![0] as string;
+      expect(writtenPath).toContain('startup-perf');
+      expect(writtenPath).toContain('test-session-123');
+      expect(writtenPath).toMatch(/\.json$/);
+
+      const writtenContent = JSON.parse(
+        vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string,
+      );
+      expect(writtenContent.sessionId).toBe('test-session-123');
+      expect(writtenContent.phases).toHaveLength(2);
+      expect(writtenContent.totalMs).toBeGreaterThanOrEqual(0);
+
+      expect(stderrSpy).toHaveBeenCalledWith(
+        expect.stringContaining('Startup profile written to:'),
+      );
+    });
+
+    it('should use report timestamp for filename (no double Date call)', () => {
+      vi.mocked(fs.mkdirSync).mockReturnValue(undefined);
+      vi.mocked(fs.writeFileSync).mockReturnValue(undefined);
+      vi.spyOn(process.stderr, 'write').mockReturnValue(true);
+
+      initStartupProfiler();
+      profileCheckpoint('test');
+      finalizeStartupProfile('s1');
+
+      const writtenPath = vi.mocked(fs.writeFileSync).mock
+        .calls[0]![0] as string;
+      const writtenContent = JSON.parse(
+        vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string,
+      );
+      // Filename should contain the same timestamp as the report (with colons/dots replaced)
+      const expectedTs = writtenContent.timestamp.replace(/[:.]/g, '-');
+      expect(writtenPath).toContain(expectedTs);
+    });
+
+    it('should not finalize twice', () => {
+      vi.mocked(fs.mkdirSync).mockReturnValue(undefined);
+      vi.mocked(fs.writeFileSync).mockReturnValue(undefined);
+      vi.spyOn(process.stderr, 'write').mockReturnValue(true);
+
+      initStartupProfiler();
+      profileCheckpoint('test');
+      finalizeStartupProfile('s1');
+      finalizeStartupProfile('s1');
+
+      expect(fs.writeFileSync).toHaveBeenCalledTimes(1);
+    });
+
+    it('should use "unknown" as sessionId in both filename and JSON when not provided', () => {
+      vi.mocked(fs.mkdirSync).mockReturnValue(undefined);
+      vi.mocked(fs.writeFileSync).mockReturnValue(undefined);
+      vi.spyOn(process.stderr, 'write').mockReturnValue(true);
+
+      initStartupProfiler();
+      profileCheckpoint('test');
+      finalizeStartupProfile();
+
+      const writtenPath = vi.mocked(fs.writeFileSync).mock
+        .calls[0]![0] as string;
+      expect(writtenPath).toContain('unknown');
+
+      const writtenContent = JSON.parse(
+        vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string,
+      );
+      expect(writtenContent.sessionId).toBe('unknown');
+    });
+
+    it('should not throw when file write fails', () => {
+      vi.mocked(fs.mkdirSync).mockImplementation(() => {
+        throw new Error('Permission denied');
+      });
+      const stderrSpy = vi
+        .spyOn(process.stderr, 'write')
+        .mockReturnValue(true);
+
+      initStartupProfiler();
+      profileCheckpoint('test');
+
+      expect(() => finalizeStartupProfile('s1')).not.toThrow();
+      expect(stderrSpy).toHaveBeenCalledWith(
+        expect.stringContaining('Warning'),
+      );
+    });
+
+    it('should return null after reset', () => {
+      initStartupProfiler();
+      profileCheckpoint('test');
+      expect(getStartupReport()).not.toBeNull();
+
+      resetStartupProfiler();
+      expect(getStartupReport()).toBeNull();
+    });
+  });
+});

packages/cli/src/utils/startupProfiler.ts

@@ -0,0 +1,137 @@
+/**
+ * Lightweight startup performance profiler.
+ *
+ * Activated by setting QWEN_CODE_PROFILE_STARTUP=1. When enabled, collects
+ * high-resolution timestamps at key phases of CLI startup and writes a JSON
+ * report to ~/.qwen/startup-perf/ on finalization.
+ *
+ * Usage (already wired in index.ts / gemini.tsx):
+ *   initStartupProfiler()        — call once at process start to record T0
+ *   profileCheckpoint('name')    — call at each phase boundary
+ *   finalizeStartupProfile(id)   — call after last checkpoint to write report
+ *
+ * Only profiles inside the sandbox child process to avoid duplicate reports.
+ * Zero overhead when disabled (single env var check).
+ */
+import * as fs from 'node:fs';
+import * as os from 'node:os';
+import * as path from 'node:path';
+import { performance } from 'node:perf_hooks';
+
+interface Checkpoint {
+  name: string;
+  timestamp: number;
+}
+
+export interface StartupPhase {
+  name: string;
+  startMs: number;
+  durationMs: number;
+}
+
+export interface StartupReport {
+  timestamp: string;
+  sessionId: string;
+  /** Time from Node.js process start to T0 (initStartupProfiler call), covers module loading. */
+  processUptimeAtT0Ms: number;
+  totalMs: number;
+  phases: StartupPhase[];
+  nodeVersion: string;
+  platform: string;
+  arch: string;
+}
+
+let enabled = false;
+let t0 = 0;
+let processUptimeAtT0Ms = 0;
+let checkpoints: Checkpoint[] = [];
+let finalized = false;
+
+export function initStartupProfiler(): void {
+  // Reset any prior state so the function is idempotent.
+  resetStartupProfiler();
+
+  if (process.env['QWEN_CODE_PROFILE_STARTUP'] !== '1') {
+    return;
+  }
+  // Skip profiling in the outer (pre-sandbox) process — the child will
+  // re-run index.ts inside the sandbox and collect its own profile.
+  if (!process.env['SANDBOX']) {
+    return;
+  }
+  enabled = true;
+  finalized = false;
+  processUptimeAtT0Ms = Math.round(process.uptime() * 1000 * 100) / 100;
+  t0 = performance.now();
+  checkpoints = [];
+}
+
+export function profileCheckpoint(name: string): void {
+  if (!enabled) return;
+  checkpoints.push({ name, timestamp: performance.now() });
+}
+
+export function getStartupReport(): StartupReport | null {
+  if (!enabled || checkpoints.length === 0) return null;
+
+  const phases: StartupPhase[] = [];
+  let prev = t0;
+
+  // Each phase's durationMs is the delta from the previous checkpoint (or T0
+  // for the first one). Checkpoints are assumed to be recorded sequentially.
+  for (const cp of checkpoints) {
+    phases.push({
+      name: cp.name,
+      startMs: Math.round((prev - t0) * 100) / 100,
+      durationMs: Math.round((cp.timestamp - prev) * 100) / 100,
+    });
+    prev = cp.timestamp;
+  }
+
+  const lastTimestamp = checkpoints[checkpoints.length - 1]!.timestamp;
+
+  return {
+    timestamp: new Date().toISOString(),
+    sessionId: 'unknown',
+    processUptimeAtT0Ms,
+    totalMs: Math.round((lastTimestamp - t0) * 100) / 100,
+    phases,
+    nodeVersion: process.version,
+    platform: process.platform,
+    arch: process.arch,
+  };
+}
+
+export function finalizeStartupProfile(sessionId?: string): void {
+  if (!enabled || finalized) return;
+  finalized = true;
+
+  const report = getStartupReport();
+  if (!report) return;
+
+  if (sessionId) {
+    report.sessionId = sessionId;
+  }
+
+  try {
+    const dir = path.join(os.homedir(), '.qwen', 'startup-perf');
+    fs.mkdirSync(dir, { recursive: true });
+
+    const filename = `${report.timestamp.replace(/[:.]/g, '-')}-${report.sessionId}.json`;
+    const filepath = path.join(dir, filename);
+    fs.writeFileSync(filepath, JSON.stringify(report, null, 2), 'utf-8');
+    process.stderr.write(`Startup profile written to: ${filepath}\n`);
+  } catch {
+    process.stderr.write(
+      'Warning: Failed to write startup profile report\n',
+    );
+  }
+}
+
+export function resetStartupProfiler(): void {
+  enabled = false;
+  t0 = 0;
+  processUptimeAtT0Ms = 0;
+  checkpoints = [];
+  finalized = false;
+}