perf(core): Add session start profiler

.qwen/design/2026-07-06-session-start-profiler.md

@@ -0,0 +1,31 @@
+# Session Start Profiler
+
+## Summary
+
+This change adds an internal, opt-in profiler for `GeminiClient.startChat()` so #6312 follow-up work can identify the remaining per-session initialization hotspot before choosing an optimization.
+
+It does not change session behavior, public protocol fields, SDK behavior, CLI flags, config schema, telemetry schema, or startup profiler semantics.
+
+## Measurement Shape
+
+The profiler is enabled only when `QWEN_CODE_PROFILE_SESSION_START=1`.
+
+When enabled, core writes JSONL records under `Storage.getRuntimeBaseDir()/session-start-perf/`. Each record includes a timestamp, `SessionStartSource`, success flag, total duration, bounded stage durations, and small aggregate counts such as history length and rendered snapshot count.
+
+The measured stages follow the existing `startChat()` sequence: tool registry warm, resumed deferred-tool reveal scan, deferred reminder resolution, initial chat history build, reminder dedup seeding, system instruction build, `GeminiChat` construction, orphan tool-use repair, SessionStart hook, optional SessionStart context apply, and `setTools()`.
+
+## Safety Boundaries
+
+The output intentionally excludes session IDs, prompts, model responses, hook output, tool names, file paths, and working directories. Stage names are static code-owned strings.
+
+All profiler writes are best-effort. File-system failures are swallowed so profiling cannot break or slow a session through error handling.
+
+When disabled, the helper performs no file writes and does not read the high-resolution clock.
+
+## Non-Goals
+
+This change does not optimize `GeminiClient.initialize()` or `startChat()`.
+
+It does not implement Part B extension caching, Part C skill body lazy-loading, command snapshot caching, or any daemon protocol changes.
+
+The next optimization should be chosen only after collecting stage breakdowns from this profiler and comparing them with extension-heavy or skill-heavy fixtures where relevant.

packages/core/src/core/client.test.ts

@@ -51,6 +51,22 @@ import {
 } from './turn.js';
 import { LoopType } from '../telemetry/types.js';
 
+type MockSessionStartProfiler = {
+  time: Mock;
+  timeSync: Mock;
+  finish: Mock;
+};
+
+const sessionStartProfilerMocks = vi.hoisted(() => ({
+  createSessionStartProfiler: vi.fn(),
+  profilers: [] as MockSessionStartProfiler[],
+}));
+
+vi.mock('./session-start-profiler.js', () => ({
+  createSessionStartProfiler:
+    sessionStartProfilerMocks.createSessionStartProfiler,
+}));
+
 vi.mock('../utils/retry.js', () => ({
   retryWithBackoff: vi.fn(async (fn) => await fn()),
   isUnattendedMode: vi.fn(() => false),
@@ -414,6 +430,20 @@ describe('Gemini Client (client.ts)', () => {
   };
   beforeEach(async () => {
     vi.resetAllMocks();
+    sessionStartProfilerMocks.profilers.length = 0;
+    sessionStartProfilerMocks.createSessionStartProfiler.mockImplementation(
+      () => {
+        const profiler: MockSessionStartProfiler = {
+          time: vi.fn(async (_stage: string, fn: () => Promise<unknown>) =>
+            fn(),
+          ),
+          timeSync: vi.fn((_stage: string, fn: () => unknown) => fn()),
+          finish: vi.fn(),
+        };
+        sessionStartProfilerMocks.profilers.push(profiler);
+        return profiler;
+      },
+    );
     vi.mocked(uiTelemetryService.setLastPromptTokenCount).mockClear();
 
     // Default: createContentGenerator rejects (simulates test env without auth).
@@ -900,6 +930,153 @@ describe('Gemini Client (client.ts)', () => {
     });
   });
 
+  describe('startChat — session start profiling', () => {
+    beforeEach(() => {
+      sessionStartProfilerMocks.createSessionStartProfiler.mockClear();
+      sessionStartProfilerMocks.profilers.length = 0;
+    });
+
+    it('passes startup, resume, and clear sources to the profiler', async () => {
+      await client.startChat();
+      await client.startChat([{ role: 'user', parts: [{ text: 'hi' }] }]);
+      await client.startChat(undefined, SessionStartSource.Clear);
+
+      expect(
+        sessionStartProfilerMocks.createSessionStartProfiler.mock.calls.map(
+          ([source]) => source,
+        ),
+      ).toEqual([
+        SessionStartSource.Startup,
+        SessionStartSource.Resume,
+        SessionStartSource.Clear,
+      ]);
+      for (const profiler of sessionStartProfilerMocks.profilers) {
+        expect(profiler.finish).toHaveBeenCalledTimes(1);
+      }
+    });
+
+    it('finalizes successful startChat profiles with bounded counts', async () => {
+      const hookSystem = {
+        fireSessionStartEvent: vi.fn().mockResolvedValue(
+          createHookOutput('SessionStart', {
+            hookSpecificOutput: {
+              additionalContext: 'hook output',
+            },
+          }),
+        ),
+      };
+      vi.mocked(mockConfig.getDisableAllHooks).mockReturnValue(false);
+      vi.mocked(mockConfig.hasHooksForEvent).mockReturnValue(true);
+      vi.mocked(mockConfig.getHookSystem).mockReturnValue(
+        hookSystem as unknown as ReturnType<Config['getHookSystem']>,
+      );
+
+      await client.startChat(undefined, SessionStartSource.Clear);
+
+      const profiler = sessionStartProfilerMocks.profilers.at(-1)!;
+      expect(profiler.finish).toHaveBeenCalledWith(
+        expect.objectContaining({
+          ok: true,
+          extraHistoryLength: 0,
+          historyLength: 1,
+          snapshotEntryCount: 0,
+          deferredReminderCount: 0,
+        }),
+      );
+      expect(profiler.time.mock.calls.map(([stage]) => stage)).toEqual([
+        'tool_registry_warm',
+        'initial_chat_history',
+        'agent_reminder_seed',
+        'session_start_hook',
+        'set_tools',
+      ]);
+      expect(profiler.timeSync.mock.calls.map(([stage]) => stage)).toEqual([
+        'resume_deferred_tool_reveal',
+        'deferred_reminder_resolution',
+        'skill_reminder_seed',
+        'system_instruction',
+        'gemini_chat_construct',
+        'orphan_tool_use_repair',
+        'session_start_context_apply',
+      ]);
+    });
+
+    it('finalizes failed startChat profiles without changing the thrown error', async () => {
+      vi.mocked(getInitialChatHistory).mockRejectedValueOnce(
+        new Error('history failed'),
+      );
+
+      await expect(client.startChat()).rejects.toThrow(
+        'Failed to initialize chat: history failed',
+      );
+
+      const profiler = sessionStartProfilerMocks.profilers.at(-1)!;
+      expect(profiler.finish).toHaveBeenCalledWith(
+        expect.objectContaining({
+          ok: false,
+          extraHistoryLength: 0,
+          historyLength: 0,
+          snapshotEntryCount: 0,
+          deferredReminderCount: 0,
+        }),
+      );
+    });
+
+    it('finalizes failed startChat profiles for first-stage warm errors', async () => {
+      const toolRegistry = vi.mocked(
+        mockConfig.getToolRegistry,
+      )() as unknown as {
+        warmAll: ReturnType<typeof vi.fn>;
+      };
+      toolRegistry.warmAll.mockRejectedValueOnce(new Error('warm failed'));
+
+      await expect(client.startChat()).rejects.toThrow(
+        'Failed to initialize chat: warm failed',
+      );
+
+      const profiler = sessionStartProfilerMocks.profilers.at(-1)!;
+      expect(profiler.time.mock.calls.map(([stage]) => stage)).toContain(
+        'tool_registry_warm',
+      );
+      expect(profiler.finish).toHaveBeenCalledWith(
+        expect.objectContaining({
+          ok: false,
+          extraHistoryLength: 0,
+          historyLength: 0,
+          snapshotEntryCount: 0,
+          deferredReminderCount: 0,
+        }),
+      );
+    });
+
+    it('finalizes failed startChat profiles for sync stage errors', async () => {
+      vi.spyOn(
+        client as unknown as { getMainSessionSystemInstruction: () => string },
+        'getMainSessionSystemInstruction',
+      ).mockImplementationOnce(() => {
+        throw new Error('system instruction failed');
+      });
+
+      await expect(client.startChat()).rejects.toThrow(
+        'Failed to initialize chat: system instruction failed',
+      );
+
+      const profiler = sessionStartProfilerMocks.profilers.at(-1)!;
+      expect(profiler.timeSync.mock.calls.map(([stage]) => stage)).toContain(
+        'system_instruction',
+      );
+      expect(profiler.finish).toHaveBeenCalledWith(
+        expect.objectContaining({
+          ok: false,
+          extraHistoryLength: 0,
+          historyLength: 1,
+          snapshotEntryCount: 0,
+          deferredReminderCount: 0,
+        }),
+      );
+    });
+  });
+
   describe('startChat — deferred tools', () => {
     // Pulls the registry mock used by the surrounding suite so each test
     // can stub the deferred-summary + ToolSearch availability per case.

packages/core/src/core/client.ts

@@ -39,6 +39,7 @@ import {
   escalatedOutputTokenLimit,
   parsePositiveIntegerEnvValue,
 } from './tokenLimits.js';
+import { createSessionStartProfiler } from './session-start-profiler.js';
 
 const debugLogger = createDebugLogger('CLIENT');
 
@@ -1231,7 +1232,19 @@ export class GeminiClient {
     // Clear stale cache params on session reset to prevent cross-session leakage
     clearCacheSafeParams();
 
+    const profiler = createSessionStartProfiler(sessionStartSource);
     let history: Content[] = [];
+    let snapshotEntries: AvailableSkillEntry[] = [];
+    let deferredReminderCount = 0;
+    const finishProfile = (ok: boolean) => {
+      profiler.finish({
+        ok,
+        extraHistoryLength: extraHistory?.length ?? 0,
+        historyLength: history.length,
+        snapshotEntryCount: snapshotEntries.length,
+        deferredReminderCount,
+      });
+    };
 
     try {
       // Warm the tool registry before building startup reminders and tool
@@ -1240,49 +1253,68 @@ export class GeminiClient {
       // session); `/clear` clears the revealed set via resetChat() before
       // calling us.
       const toolRegistry = this.config.getToolRegistry();
-      await toolRegistry.warmAll();
+      await profiler.time('tool_registry_warm', () => toolRegistry.warmAll());
       // Resume support: when a transcript contains prior calls to a deferred
       // tool, re-reveal that tool so `setTools()` below sends its schema in
       // the declaration list. Without this, the model sees history like
       // "I called foo_tool, got result" but the API rejects a follow-up
       // call to foo_tool because the schema is absent. This must happen
       // BEFORE `resolveDeferredToolsForReminder()` runs so the resumed tools
       // are correctly filtered out of the startup reminder built below.
-      if (extraHistory && extraHistory.length > 0) {
-        const deferredNames = new Set(
-          toolRegistry.getDeferredToolSummary().map((t) => t.name),
-        );
-        if (deferredNames.size > 0) {
-          for (const entry of extraHistory) {
-            for (const part of entry.parts ?? []) {
-              const callName = part.functionCall?.name;
-              if (callName && deferredNames.has(callName)) {
-                toolRegistry.revealDeferredTool(callName);
+      profiler.timeSync('resume_deferred_tool_reveal', () => {
+        if (extraHistory && extraHistory.length > 0) {
+          const deferredNames = new Set(
+            toolRegistry.getDeferredToolSummary().map((t) => t.name),
+          );
+          if (deferredNames.size > 0) {
+            for (const entry of extraHistory) {
+              for (const part of entry.parts ?? []) {
+                const callName = part.functionCall?.name;
+                if (callName && deferredNames.has(callName)) {
+                  toolRegistry.revealDeferredTool(callName);
+                }
               }
             }
           }
         }
-      }
-      const deferredTools = this.resolveDeferredToolsForReminder();
-      this.rememberAnnouncedDeferredTools(deferredTools);
-      let snapshotEntries: AvailableSkillEntry[];
-      [history, snapshotEntries] = await getInitialChatHistory(
-        this.config,
-        extraHistory,
+      });
+      const deferredTools = profiler.timeSync(
+        'deferred_reminder_resolution',
+        () => {
+          const resolved = this.resolveDeferredToolsForReminder();
+          this.rememberAnnouncedDeferredTools(resolved);
+          return resolved;
+        },
+      );
+      deferredReminderCount = deferredTools?.length ?? 0;
+      [history, snapshotEntries] = await profiler.time(
+        'initial_chat_history',
+        () => getInitialChatHistory(this.config, extraHistory),
+      );
+      profiler.timeSync('skill_reminder_seed', () => {
+        this.seedSkillReminderDedupFromSnapshot(snapshotEntries);
+      });
+      await profiler.time('agent_reminder_seed', () =>
+        this.seedAgentReminderDedupFromCurrent(),
+      );
+      const systemInstruction = profiler.timeSync('system_instruction', () =>
+        this.getMainSessionSystemInstruction(),
       );
-      this.seedSkillReminderDedupFromSnapshot(snapshotEntries);
-      await this.seedAgentReminderDedupFromCurrent();
-      const systemInstruction = this.getMainSessionSystemInstruction();
 
-      this.chat = new GeminiChat(
-        this.config,
-        {
-          systemInstruction,
-        },
-        history,
-        this.config.getChatRecordingService(),
-        uiTelemetryService,
+      const chat = profiler.timeSync(
+        'gemini_chat_construct',
+        () =>
+          new GeminiChat(
+            this.config,
+            {
+              systemInstruction,
+            },
+            history,
+            this.config.getChatRecordingService(),
+            uiTelemetryService,
+          ),
       );
+      this.chat = chat;
 
       // Repair any dangling `model[functionCall]` whose `functionResponse`
       // never made it back into the transcript before we wrote the JSONL.
@@ -1297,26 +1329,34 @@ export class GeminiClient {
       // compaction reordering is also caught — but doing it here keeps
       // any pre-send code reading `chat.history` from seeing a malformed
       // shape.)
-      this.repairOrphanedToolUseTurnsInHistory();
+      profiler.timeSync('orphan_tool_use_repair', () => {
+        this.repairOrphanedToolUseTurnsInHistory();
+      });
 
-      const sessionStartAdditionalContext =
-        await this.fireSessionStartHook(sessionStartSource);
+      const sessionStartAdditionalContext = await profiler.time(
+        'session_start_hook',
+        () => this.fireSessionStartHook(sessionStartSource),
+      );
       this.lastSessionStartContext = sessionStartAdditionalContext;
       this.lastSessionStartSource = sessionStartAdditionalContext
         ? sessionStartSource
         : undefined;
 
       if (sessionStartAdditionalContext) {
-        this.chat.applySessionStartContext(
-          sessionStartAdditionalContext,
-          sessionStartSource,
-        );
+        profiler.timeSync('session_start_context_apply', () => {
+          chat.applySessionStartContext(
+            sessionStartAdditionalContext,
+            sessionStartSource,
+          );
+        });
       }
 
-      await this.setTools();
+      await profiler.time('set_tools', () => this.setTools());
 
+      finishProfile(true);
       return this.chat;
     } catch (error) {
+      finishProfile(false);
       await reportError(
         error,
         'Error initializing chat session.',