From aad72f66548f6630bb339665e4b7dd387d2165ae Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 01:00:37 +0800 Subject: [PATCH 01/16] perf(core): Add session start profiler Add an opt-in internal profiler for GeminiClient.startChat so session initialization can be broken down by bounded stages before choosing the next #6312 optimization. The profiler writes best-effort JSONL records only when QWEN_CODE_PROFILE_SESSION_START=1 and avoids sensitive values such as prompts, paths, session IDs, hook output, model responses, and tool names. Co-authored-by: Qwen-Coder --- .../2026-07-06-session-start-profiler.md | 31 +++ packages/core/src/core/client.test.ts | 117 +++++++++++ packages/core/src/core/client.ts | 117 +++++++---- .../src/core/session-start-profiler.test.ts | 188 ++++++++++++++++++ .../core/src/core/session-start-profiler.ts | 179 +++++++++++++++++ 5 files changed, 595 insertions(+), 37 deletions(-) create mode 100644 .qwen/design/2026-07-06-session-start-profiler.md create mode 100644 packages/core/src/core/session-start-profiler.test.ts create mode 100644 packages/core/src/core/session-start-profiler.ts diff --git a/.qwen/design/2026-07-06-session-start-profiler.md b/.qwen/design/2026-07-06-session-start-profiler.md new file mode 100644 index 00000000000..a6344044b8f --- /dev/null +++ b/.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. diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 15a46aa757a..3f5056e78ee 100644 --- a/packages/core/src/core/client.test.ts +++ b/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) => + 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,93 @@ 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, + ]); + }); + + 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, + ); + + 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, + }), + ); + }); + }); + 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. diff --git a/packages/core/src/core/client.ts b/packages/core/src/core/client.ts index 01d6cf8f28f..1ab4eac3976 100644 --- a/packages/core/src/core/client.ts +++ b/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,10 @@ 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; try { // Warm the tool registry before building startup reminders and tool @@ -1240,7 +1244,7 @@ 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 @@ -1248,41 +1252,60 @@ export class GeminiClient { // 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 +1320,46 @@ 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()); + profiler.finish({ + ok: true, + extraHistoryLength: extraHistory?.length ?? 0, + historyLength: history.length, + snapshotEntryCount: snapshotEntries.length, + deferredReminderCount, + }); return this.chat; } catch (error) { + profiler.finish({ + ok: false, + extraHistoryLength: extraHistory?.length ?? 0, + historyLength: history.length, + snapshotEntryCount: snapshotEntries.length, + deferredReminderCount, + }); await reportError( error, 'Error initializing chat session.', diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts new file mode 100644 index 00000000000..7f986bf120a --- /dev/null +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -0,0 +1,188 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { mkdtemp, readFile, readdir, rm } from 'node:fs/promises'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { SessionStartSource } from '../hooks/types.js'; +import { + createSessionStartProfiler, + type SessionStartProfileRecord, +} from './session-start-profiler.js'; + +function clockFrom(values: number[]) { + let last = values[values.length - 1] ?? 0; + return vi.fn(() => { + const next = values.shift(); + if (next !== undefined) { + last = next; + } + return last; + }); +} + +describe('session-start-profiler', () => { + afterEach(() => { + vi.unstubAllEnvs(); + }); + + it('is a no-op when disabled', async () => { + const now = vi.fn(() => { + throw new Error('disabled profiler should not read time'); + }); + const writeRecord = vi.fn(); + const profiler = createSessionStartProfiler(SessionStartSource.Startup, { + enabled: false, + now, + writeRecord, + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + await expect( + profiler.time('tool_registry_warm', async () => 'ok'), + ).resolves.toBe('ok'); + expect(profiler.timeSync('system_instruction', () => 42)).toBe(42); + profiler.finish({ ok: true }); + + expect(profiler.enabled).toBe(false); + expect(now).not.toHaveBeenCalled(); + expect(writeRecord).not.toHaveBeenCalled(); + }); + + it('records sync and async stages when enabled', async () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Resume, { + enabled: true, + now: clockFrom([10, 12, 15, 16, 21, 30]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + await expect( + profiler.time('initial_chat_history', async () => 'history'), + ).resolves.toBe('history'); + expect( + profiler.timeSync('system_instruction', () => 'system'), + ).toBe('system'); + profiler.finish({ + ok: true, + extraHistoryLength: 3, + historyLength: 4, + snapshotEntryCount: 2, + deferredReminderCount: 1, + }); + + expect(records).toEqual([ + { + timestamp: '2026-07-06T00:00:00.000Z', + source: 'resume', + ok: true, + totalMs: 20, + stages: { + initial_chat_history: 3, + system_instruction: 5, + }, + extraHistoryLength: 3, + historyLength: 4, + snapshotEntryCount: 2, + deferredReminderCount: 1, + }, + ]); + }); + + it('rethrows stage errors and preserves the failed stage', async () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Startup, { + enabled: true, + now: clockFrom([100, 110, 125, 130]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + const error = new Error('setTools failed'); + + await expect( + profiler.time('set_tools', async () => { + throw error; + }), + ).rejects.toBe(error); + profiler.finish({ ok: false }); + + expect(records[0]).toMatchObject({ + ok: false, + totalMs: 30, + stages: { + set_tools: 15, + }, + failedStage: 'set_tools', + }); + }); + + it('does not throw when the output writer fails', () => { + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([1, 2]), + writeRecord: () => { + throw new Error('disk full'); + }, + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + expect(() => profiler.finish({ ok: true })).not.toThrow(); + }); + + it('writes bounded JSONL without sensitive fields', async () => { + const runtimeDir = await mkdtemp( + join(tmpdir(), 'session-start-profiler-'), + ); + vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); + vi.stubEnv('QWEN_CODE_PROFILE_SESSION_START', '1'); + + try { + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + now: clockFrom([10, 15, 20, 30]), + getTimestamp: () => new Date('2026-07-06T12:34:56.789Z'), + }); + profiler.timeSync('system_instruction', () => 'system'); + profiler.finish({ + ok: true, + extraHistoryLength: 0, + historyLength: 1, + snapshotEntryCount: 0, + deferredReminderCount: 0, + }); + + const files = await readdir(join(runtimeDir, 'session-start-perf')); + expect(files).toEqual(['session-start-2026-07-06.jsonl']); + const raw = await readFile( + join( + runtimeDir, + 'session-start-perf', + 'session-start-2026-07-06.jsonl', + ), + 'utf8', + ); + const record = JSON.parse(raw.trim()) as SessionStartProfileRecord; + const serialized = JSON.stringify(record); + + expect(record).toMatchObject({ + timestamp: '2026-07-06T12:34:56.789Z', + source: 'clear', + ok: true, + totalMs: 20, + stages: { system_instruction: 5 }, + }); + expect(record).not.toHaveProperty('sessionId'); + expect(serialized).not.toContain('prompt'); + expect(serialized).not.toContain('/test/'); + expect(serialized).not.toContain('test-session-id'); + expect(serialized).not.toContain('hook output'); + expect(serialized).not.toContain('tool name'); + } finally { + await rm(runtimeDir, { recursive: true, force: true }); + } + }); +}); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts new file mode 100644 index 00000000000..18add496fd3 --- /dev/null +++ b/packages/core/src/core/session-start-profiler.ts @@ -0,0 +1,179 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import * as fs from 'node:fs'; +import * as path from 'node:path'; +import { performance } from 'node:perf_hooks'; +import { Storage } from '../config/storage.js'; +import type { SessionStartSource } from '../hooks/types.js'; + +export const SESSION_START_PROFILE_ENV = 'QWEN_CODE_PROFILE_SESSION_START'; + +export interface SessionStartProfileRecord { + timestamp: string; + source: SessionStartSource; + ok: boolean; + totalMs: number; + stages: Record; + extraHistoryLength?: number; + historyLength?: number; + snapshotEntryCount?: number; + deferredReminderCount?: number; + failedStage?: string; +} + +export interface SessionStartProfileFinishAttrs { + ok: boolean; + extraHistoryLength?: number; + historyLength?: number; + snapshotEntryCount?: number; + deferredReminderCount?: number; +} + +export interface SessionStartProfiler { + readonly enabled: boolean; + time(stage: string, fn: () => T | Promise): Promise; + timeSync(stage: string, fn: () => T): T; + finish(attrs: SessionStartProfileFinishAttrs): void; +} + +interface SessionStartProfilerOptions { + enabled?: boolean; + now?: () => number; + getTimestamp?: () => Date; + writeRecord?: (record: SessionStartProfileRecord) => void; +} + +function roundMs(value: number): number { + return Math.round(value * 100) / 100; +} + +function writeProfileRecord(record: SessionStartProfileRecord): void { + const dir = path.join(Storage.getRuntimeBaseDir(), 'session-start-perf'); + fs.mkdirSync(dir, { recursive: true }); + const filename = `session-start-${record.timestamp.slice(0, 10)}.jsonl`; + fs.appendFileSync( + path.join(dir, filename), + `${JSON.stringify(record)}\n`, + 'utf8', + ); +} + +const disabledProfiler: SessionStartProfiler = { + enabled: false, + async time(_stage: string, fn: () => T | Promise): Promise { + return await fn(); + }, + timeSync(_stage: string, fn: () => T): T { + return fn(); + }, + finish(): void {}, +}; + +class EnabledSessionStartProfiler implements SessionStartProfiler { + readonly enabled = true; + private readonly source: SessionStartSource; + private readonly now: () => number; + private readonly getTimestamp: () => Date; + private readonly writeRecord: (record: SessionStartProfileRecord) => void; + private readonly startMs: number; + private readonly stages: Record = {}; + private failedStage: string | undefined; + private finished = false; + + constructor( + source: SessionStartSource, + options: Required< + Pick + >, + ) { + this.source = source; + this.now = options.now; + this.getTimestamp = options.getTimestamp; + this.writeRecord = options.writeRecord; + this.startMs = this.now(); + } + + async time(stage: string, fn: () => T | Promise): Promise { + const start = this.now(); + try { + return await fn(); + } catch (error) { + this.failedStage ??= stage; + throw error; + } finally { + this.recordStage(stage, start, this.now()); + } + } + + timeSync(stage: string, fn: () => T): T { + const start = this.now(); + try { + return fn(); + } catch (error) { + this.failedStage ??= stage; + throw error; + } finally { + this.recordStage(stage, start, this.now()); + } + } + + finish(attrs: SessionStartProfileFinishAttrs): void { + if (this.finished) { + return; + } + this.finished = true; + + const record: SessionStartProfileRecord = { + timestamp: this.getTimestamp().toISOString(), + source: this.source, + ok: attrs.ok, + totalMs: roundMs(this.now() - this.startMs), + stages: { ...this.stages }, + ...(attrs.extraHistoryLength !== undefined + ? { extraHistoryLength: attrs.extraHistoryLength } + : {}), + ...(attrs.historyLength !== undefined + ? { historyLength: attrs.historyLength } + : {}), + ...(attrs.snapshotEntryCount !== undefined + ? { snapshotEntryCount: attrs.snapshotEntryCount } + : {}), + ...(attrs.deferredReminderCount !== undefined + ? { deferredReminderCount: attrs.deferredReminderCount } + : {}), + ...(this.failedStage ? { failedStage: this.failedStage } : {}), + }; + + try { + this.writeRecord(record); + } catch { + // Profiling must never affect session creation. + } + } + + private recordStage(stage: string, start: number, end: number): void { + const previous = this.stages[stage] ?? 0; + this.stages[stage] = roundMs(previous + end - start); + } +} + +export function createSessionStartProfiler( + source: SessionStartSource, + options: SessionStartProfilerOptions = {}, +): SessionStartProfiler { + const enabled = + options.enabled ?? process.env[SESSION_START_PROFILE_ENV] === '1'; + if (!enabled) { + return disabledProfiler; + } + + return new EnabledSessionStartProfiler(source, { + now: options.now ?? (() => performance.now()), + getTimestamp: options.getTimestamp ?? (() => new Date()), + writeRecord: options.writeRecord ?? writeProfileRecord, + }); +} From facfb13a25f370189b2042a75897cf6108f81860 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 01:41:09 +0800 Subject: [PATCH 02/16] fix(core): Keep session profiler finish best-effort Wrap session-start profiler finish metadata collection in the same best-effort boundary as record writes, and cover repeat finish plus sync failure handling in tests. Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 3 + .../src/core/session-start-profiler.test.ts | 61 +++++++++++++++++++ .../core/src/core/session-start-profiler.ts | 42 ++++++------- 3 files changed, 85 insertions(+), 21 deletions(-) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 3f5056e78ee..e7497121c56 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -950,6 +950,9 @@ describe('Gemini Client (client.ts)', () => { SessionStartSource.Resume, SessionStartSource.Clear, ]); + for (const profiler of sessionStartProfilerMocks.profilers) { + expect(profiler.finish).toHaveBeenCalledTimes(1); + } }); it('finalizes successful startChat profiles with bounded counts', async () => { diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 7f986bf120a..aaabd9b7a8c 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -121,6 +121,52 @@ describe('session-start-profiler', () => { }); }); + it('rethrows sync stage errors and preserves the failed stage', () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Startup, { + enabled: true, + now: clockFrom([100, 110, 120, 130]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + const error = new Error('system instruction failed'); + + expect(() => + profiler.timeSync('system_instruction', () => { + throw error; + }), + ).toThrow(error); + profiler.finish({ ok: false }); + + expect(records[0]).toMatchObject({ + ok: false, + totalMs: 30, + stages: { + system_instruction: 10, + }, + failedStage: 'system_instruction', + }); + }); + + it('writes at most one record when finish is called multiple times', () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([1, 2, 3]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + profiler.finish({ ok: true }); + profiler.finish({ ok: false }); + + expect(records).toHaveLength(1); + expect(records[0]).toMatchObject({ + ok: true, + totalMs: 1, + }); + }); + it('does not throw when the output writer fails', () => { const profiler = createSessionStartProfiler(SessionStartSource.Clear, { enabled: true, @@ -134,6 +180,21 @@ describe('session-start-profiler', () => { expect(() => profiler.finish({ ok: true })).not.toThrow(); }); + it('does not throw when finish metadata collection fails', () => { + const writeRecord = vi.fn(); + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([1, 2]), + writeRecord, + getTimestamp: () => { + throw new Error('clock failed'); + }, + }); + + expect(() => profiler.finish({ ok: false })).not.toThrow(); + expect(writeRecord).not.toHaveBeenCalled(); + }); + it('writes bounded JSONL without sensitive fields', async () => { const runtimeDir = await mkdtemp( join(tmpdir(), 'session-start-profiler-'), diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 18add496fd3..68107b516f3 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -127,28 +127,28 @@ class EnabledSessionStartProfiler implements SessionStartProfiler { } this.finished = true; - const record: SessionStartProfileRecord = { - timestamp: this.getTimestamp().toISOString(), - source: this.source, - ok: attrs.ok, - totalMs: roundMs(this.now() - this.startMs), - stages: { ...this.stages }, - ...(attrs.extraHistoryLength !== undefined - ? { extraHistoryLength: attrs.extraHistoryLength } - : {}), - ...(attrs.historyLength !== undefined - ? { historyLength: attrs.historyLength } - : {}), - ...(attrs.snapshotEntryCount !== undefined - ? { snapshotEntryCount: attrs.snapshotEntryCount } - : {}), - ...(attrs.deferredReminderCount !== undefined - ? { deferredReminderCount: attrs.deferredReminderCount } - : {}), - ...(this.failedStage ? { failedStage: this.failedStage } : {}), - }; - try { + const record: SessionStartProfileRecord = { + timestamp: this.getTimestamp().toISOString(), + source: this.source, + ok: attrs.ok, + totalMs: roundMs(this.now() - this.startMs), + stages: { ...this.stages }, + ...(attrs.extraHistoryLength !== undefined + ? { extraHistoryLength: attrs.extraHistoryLength } + : {}), + ...(attrs.historyLength !== undefined + ? { historyLength: attrs.historyLength } + : {}), + ...(attrs.snapshotEntryCount !== undefined + ? { snapshotEntryCount: attrs.snapshotEntryCount } + : {}), + ...(attrs.deferredReminderCount !== undefined + ? { deferredReminderCount: attrs.deferredReminderCount } + : {}), + ...(this.failedStage ? { failedStage: this.failedStage } : {}), + }; + this.writeRecord(record); } catch { // Profiling must never affect session creation. From 3c418731f7a622e18e5b456583c45fbdb213a995 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 01:46:47 +0800 Subject: [PATCH 03/16] test(core): Cover profiler review suggestions Deduplicate startChat profile finalization attributes and add coverage for repeated stage duration accumulation. Co-authored-by: Qwen-Coder --- packages/core/src/core/client.ts | 25 ++++++++---------- .../src/core/session-start-profiler.test.ts | 26 +++++++++++++++++++ 2 files changed, 37 insertions(+), 14 deletions(-) diff --git a/packages/core/src/core/client.ts b/packages/core/src/core/client.ts index 1ab4eac3976..1ced17ddb1b 100644 --- a/packages/core/src/core/client.ts +++ b/packages/core/src/core/client.ts @@ -1236,6 +1236,15 @@ export class GeminiClient { 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 @@ -1344,22 +1353,10 @@ export class GeminiClient { await profiler.time('set_tools', () => this.setTools()); - profiler.finish({ - ok: true, - extraHistoryLength: extraHistory?.length ?? 0, - historyLength: history.length, - snapshotEntryCount: snapshotEntries.length, - deferredReminderCount, - }); + finishProfile(true); return this.chat; } catch (error) { - profiler.finish({ - ok: false, - extraHistoryLength: extraHistory?.length ?? 0, - historyLength: history.length, - snapshotEntryCount: snapshotEntries.length, - deferredReminderCount, - }); + finishProfile(false); await reportError( error, 'Error initializing chat session.', diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index aaabd9b7a8c..e0be5dc0a47 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -94,6 +94,32 @@ describe('session-start-profiler', () => { ]); }); + it('accumulates repeated stage durations', () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([10, 12, 15, 18, 23, 30]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + expect(profiler.timeSync('system_instruction', () => 'first')).toBe( + 'first', + ); + expect(profiler.timeSync('system_instruction', () => 'second')).toBe( + 'second', + ); + profiler.finish({ ok: true }); + + expect(records[0]).toMatchObject({ + ok: true, + totalMs: 20, + stages: { + system_instruction: 8, + }, + }); + }); + it('rethrows stage errors and preserves the failed stage', async () => { const records: SessionStartProfileRecord[] = []; const profiler = createSessionStartProfiler(SessionStartSource.Startup, { From bb06b61627313556b6cdf2d97068e1db0197a5b4 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 03:09:22 +0800 Subject: [PATCH 04/16] test(core): Cover profiler failure paths Strengthen session-start profiler tests for first-failure tracking and startChat sync-stage failure finalization. Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 30 +++++++++++++++++ .../src/core/session-start-profiler.test.ts | 32 +++++++++++++++++++ 2 files changed, 62 insertions(+) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index e7497121c56..c3f9bec91cd 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -1015,6 +1015,36 @@ describe('Gemini Client (client.ts)', () => { 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, }), ); }); diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index e0be5dc0a47..26b31a7f3c1 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -147,6 +147,38 @@ describe('session-start-profiler', () => { }); }); + it('preserves the first failed stage', async () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Startup, { + enabled: true, + now: clockFrom([100, 110, 115, 120, 130, 140]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + await expect( + profiler.time('stage_a', async () => { + throw new Error('stage a failed'); + }), + ).rejects.toThrow('stage a failed'); + await expect( + profiler.time('stage_b', async () => { + throw new Error('stage b failed'); + }), + ).rejects.toThrow('stage b failed'); + profiler.finish({ ok: false }); + + expect(records[0]).toMatchObject({ + ok: false, + totalMs: 40, + stages: { + stage_a: 5, + stage_b: 10, + }, + failedStage: 'stage_a', + }); + }); + it('rethrows sync stage errors and preserves the failed stage', () => { const records: SessionStartProfileRecord[] = []; const profiler = createSessionStartProfiler(SessionStartSource.Startup, { From b78a28e1b4d7df17d92daecb6382736be58712ab Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 04:18:01 +0800 Subject: [PATCH 05/16] fix(core): Harden session profiler output Restrict session-start profiler JSONL output permissions and add review-requested tests for optional fields and first-stage warm failures. Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 27 +++++++++++++++++++ .../src/core/session-start-profiler.test.ts | 24 ++++++++++------- .../core/src/core/session-start-profiler.ts | 26 +++++++++++++----- 3 files changed, 61 insertions(+), 16 deletions(-) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index c3f9bec91cd..f7c85bca251 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -1022,6 +1022,33 @@ describe('Gemini Client (client.ts)', () => { ); }); + it('finalizes failed startChat profiles for first-stage warm errors', async () => { + const toolRegistry = vi.mocked( + mockConfig.getToolRegistry, + )() as unknown as { + warmAll: ReturnType; + }; + 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 }, diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 26b31a7f3c1..57c69b9aa40 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -4,7 +4,7 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { mkdtemp, readFile, readdir, rm } from 'node:fs/promises'; +import { mkdtemp, readFile, readdir, rm, stat } from 'node:fs/promises'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; import { afterEach, describe, expect, it, vi } from 'vitest'; @@ -223,6 +223,11 @@ describe('session-start-profiler', () => { ok: true, totalMs: 1, }); + expect(records[0]).not.toHaveProperty('extraHistoryLength'); + expect(records[0]).not.toHaveProperty('historyLength'); + expect(records[0]).not.toHaveProperty('snapshotEntryCount'); + expect(records[0]).not.toHaveProperty('deferredReminderCount'); + expect(records[0]).not.toHaveProperty('failedStage'); }); it('does not throw when the output writer fails', () => { @@ -274,16 +279,15 @@ describe('session-start-profiler', () => { deferredReminderCount: 0, }); - const files = await readdir(join(runtimeDir, 'session-start-perf')); + const perfDir = join(runtimeDir, 'session-start-perf'); + const profilePath = join(perfDir, 'session-start-2026-07-06.jsonl'); + const files = await readdir(perfDir); expect(files).toEqual(['session-start-2026-07-06.jsonl']); - const raw = await readFile( - join( - runtimeDir, - 'session-start-perf', - 'session-start-2026-07-06.jsonl', - ), - 'utf8', - ); + if (process.platform !== 'win32') { + expect((await stat(perfDir)).mode & 0o777).toBe(0o700); + expect((await stat(profilePath)).mode & 0o777).toBe(0o600); + } + const raw = await readFile(profilePath, 'utf8'); const record = JSON.parse(raw.trim()) as SessionStartProfileRecord; const serialized = JSON.stringify(record); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 68107b516f3..7ab27033a15 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -53,13 +53,27 @@ function roundMs(value: number): number { function writeProfileRecord(record: SessionStartProfileRecord): void { const dir = path.join(Storage.getRuntimeBaseDir(), 'session-start-perf'); - fs.mkdirSync(dir, { recursive: true }); + fs.mkdirSync(dir, { recursive: true, mode: 0o700 }); + try { + fs.chmodSync(dir, 0o700); + } catch { + // Best-effort hardening on filesystems without POSIX chmod semantics. + } const filename = `session-start-${record.timestamp.slice(0, 10)}.jsonl`; - fs.appendFileSync( - path.join(dir, filename), - `${JSON.stringify(record)}\n`, - 'utf8', - ); + const filePath = path.join(dir, filename); + const fd = fs.openSync(filePath, 'a', 0o600); + try { + try { + fs.fchmodSync(fd, 0o600); + } catch { + // Best-effort hardening; profiling output must not block startup. + } + fs.appendFileSync(fd, `${JSON.stringify(record)}\n`, { + encoding: 'utf8', + }); + } finally { + fs.closeSync(fd); + } } const disabledProfiler: SessionStartProfiler = { From e45559c125a73f8767d95b5d5560a67e78637dbe Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 05:24:45 +0800 Subject: [PATCH 06/16] test(core): Reuse session profiler env constant Use the profiler env constant in the JSONL test so the test cannot drift from the runtime gate. Co-authored-by: Qwen-Coder --- packages/core/src/core/session-start-profiler.test.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 57c69b9aa40..26f9dc950ac 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -10,6 +10,7 @@ import { join } from 'node:path'; import { afterEach, describe, expect, it, vi } from 'vitest'; import { SessionStartSource } from '../hooks/types.js'; import { + SESSION_START_PROFILE_ENV, createSessionStartProfiler, type SessionStartProfileRecord, } from './session-start-profiler.js'; @@ -263,7 +264,7 @@ describe('session-start-profiler', () => { join(tmpdir(), 'session-start-profiler-'), ); vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); - vi.stubEnv('QWEN_CODE_PROFILE_SESSION_START', '1'); + vi.stubEnv(SESSION_START_PROFILE_ENV, '1'); try { const profiler = createSessionStartProfiler(SessionStartSource.Clear, { From a76536e61c4bc0bfc5187abe6c7d2148e6744baa Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 06:26:08 +0800 Subject: [PATCH 07/16] test(core): Cover profiler timing edge cases Add coverage for fractional session profiler rounding and the absence of session context application timing when SessionStart returns no additional context. Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 9 ++++++++ .../src/core/session-start-profiler.test.ts | 23 +++++++++++++++++++ 2 files changed, 32 insertions(+) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index f7c85bca251..5e9689f5da0 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -1001,6 +1001,15 @@ describe('Gemini Client (client.ts)', () => { ]); }); + it('does not record context apply stage without SessionStart context', async () => { + await client.startChat(); + + const profiler = sessionStartProfilerMocks.profilers.at(-1)!; + expect(profiler.timeSync.mock.calls.map(([stage]) => stage)).not.toContain( + 'session_start_context_apply', + ); + }); + it('finalizes failed startChat profiles without changing the thrown error', async () => { vi.mocked(getInitialChatHistory).mockRejectedValueOnce( new Error('history failed'), diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 26f9dc950ac..30f9557988b 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -95,6 +95,29 @@ describe('session-start-profiler', () => { ]); }); + it('rounds elapsed durations to two decimal places', async () => { + const records: SessionStartProfileRecord[] = []; + const profiler = createSessionStartProfiler(SessionStartSource.Resume, { + enabled: true, + now: clockFrom([100.111, 100.222, 100.678, 101.111, 102.345, 102.789]), + writeRecord: (record) => records.push(record), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + + await profiler.time('initial_chat_history', async () => undefined); + profiler.timeSync('system_instruction', () => undefined); + profiler.finish({ ok: true }); + + expect(records[0]).toMatchObject({ + ok: true, + totalMs: 2.68, + stages: { + initial_chat_history: 0.46, + system_instruction: 1.23, + }, + }); + }); + it('accumulates repeated stage durations', () => { const records: SessionStartProfileRecord[] = []; const profiler = createSessionStartProfiler(SessionStartSource.Clear, { From 6b7133a24af0c65fe07a2df9315bc36b57631607 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 07:29:03 +0800 Subject: [PATCH 08/16] test(core): Cover non-zero profiler counts Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 44 +++++++++++++++++++++++++-- 1 file changed, 41 insertions(+), 3 deletions(-) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 5e9689f5da0..0c369837e73 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -1001,15 +1001,53 @@ describe('Gemini Client (client.ts)', () => { ]); }); - it('does not record context apply stage without SessionStart context', async () => { + it('records non-zero snapshot and deferred reminder counts', async () => { + const toolRegistry = vi.mocked( + mockConfig.getToolRegistry, + )() as unknown as { + getDeferredToolSummary: ReturnType; + getTool: ReturnType; + }; + toolRegistry.getDeferredToolSummary.mockReturnValue([ + { name: 'cron_create', description: 'schedule' }, + ]); + toolRegistry.getTool.mockImplementation((name: string) => + name === ToolNames.TOOL_SEARCH ? ({} as never) : null, + ); + vi.mocked(getInitialChatHistory).mockResolvedValueOnce([ + [ + { + role: 'user', + parts: [{ text: 'context' }], + }, + ], + [ + { name: 'skill-one', description: 'first skill' }, + { name: 'skill-two', description: 'second skill' }, + ], + ]); + await client.startChat(); const profiler = sessionStartProfilerMocks.profilers.at(-1)!; - expect(profiler.timeSync.mock.calls.map(([stage]) => stage)).not.toContain( - 'session_start_context_apply', + expect(profiler.finish).toHaveBeenCalledWith( + expect.objectContaining({ + ok: true, + snapshotEntryCount: 2, + deferredReminderCount: 1, + }), ); }); + it('does not record context apply stage without SessionStart context', async () => { + await client.startChat(); + + const profiler = sessionStartProfilerMocks.profilers.at(-1)!; + expect( + profiler.timeSync.mock.calls.map(([stage]) => stage), + ).not.toContain('session_start_context_apply'); + }); + it('finalizes failed startChat profiles without changing the thrown error', async () => { vi.mocked(getInitialChatHistory).mockRejectedValueOnce( new Error('history failed'), From 228028929748929082e0dab1576a50233a8c7ae2 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 07:56:10 +0800 Subject: [PATCH 09/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 2 +- packages/core/src/core/client.ts | 13 +++---- .../src/core/session-start-profiler.test.ts | 34 ++++++++++++++----- .../core/src/core/session-start-profiler.ts | 16 ++++++++- 4 files changed, 47 insertions(+), 18 deletions(-) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 0c369837e73..10e4c6aa141 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -992,7 +992,7 @@ describe('Gemini Client (client.ts)', () => { ]); expect(profiler.timeSync.mock.calls.map(([stage]) => stage)).toEqual([ 'resume_deferred_tool_reveal', - 'deferred_reminder_resolution', + 'deferred_reminder_setup', 'skill_reminder_seed', 'system_instruction', 'gemini_chat_construct', diff --git a/packages/core/src/core/client.ts b/packages/core/src/core/client.ts index 1ced17ddb1b..c1a735bfd18 100644 --- a/packages/core/src/core/client.ts +++ b/packages/core/src/core/client.ts @@ -1278,14 +1278,11 @@ export class GeminiClient { } } }); - const deferredTools = profiler.timeSync( - 'deferred_reminder_resolution', - () => { - const resolved = this.resolveDeferredToolsForReminder(); - this.rememberAnnouncedDeferredTools(resolved); - return resolved; - }, - ); + const deferredTools = profiler.timeSync('deferred_reminder_setup', () => { + const resolved = this.resolveDeferredToolsForReminder(); + this.rememberAnnouncedDeferredTools(resolved); + return resolved; + }); deferredReminderCount = deferredTools?.length ?? 0; [history, snapshotEntries] = await profiler.time( 'initial_chat_history', diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 30f9557988b..5705a0783c1 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -7,7 +7,7 @@ import { mkdtemp, readFile, readdir, rm, stat } from 'node:fs/promises'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; -import { afterEach, describe, expect, it, vi } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import { SessionStartSource } from '../hooks/types.js'; import { SESSION_START_PROFILE_ENV, @@ -15,6 +15,18 @@ import { type SessionStartProfileRecord, } from './session-start-profiler.js'; +const debugLoggerMock = vi.hoisted(() => ({ + debug: vi.fn(), + error: vi.fn(), + info: vi.fn(), + isEnabled: vi.fn(() => true), + warn: vi.fn(), +})); + +vi.mock('../utils/debugLogger.js', () => ({ + createDebugLogger: vi.fn(() => debugLoggerMock), +})); + function clockFrom(values: number[]) { let last = values[values.length - 1] ?? 0; return vi.fn(() => { @@ -27,6 +39,10 @@ function clockFrom(values: number[]) { } describe('session-start-profiler', () => { + beforeEach(() => { + debugLoggerMock.debug.mockClear(); + }); + afterEach(() => { vi.unstubAllEnvs(); }); @@ -66,9 +82,9 @@ describe('session-start-profiler', () => { await expect( profiler.time('initial_chat_history', async () => 'history'), ).resolves.toBe('history'); - expect( - profiler.timeSync('system_instruction', () => 'system'), - ).toBe('system'); + expect(profiler.timeSync('system_instruction', () => 'system')).toBe( + 'system', + ); profiler.finish({ ok: true, extraHistoryLength: 3, @@ -259,12 +275,16 @@ describe('session-start-profiler', () => { enabled: true, now: clockFrom([1, 2]), writeRecord: () => { - throw new Error('disk full'); + throw Object.assign(new Error('disk full'), { code: 'ENOSPC' }); }, getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), }); expect(() => profiler.finish({ ok: true })).not.toThrow(); + expect(debugLoggerMock.debug).toHaveBeenCalledWith( + 'session-start-profiler write failed', + { name: 'Error', code: 'ENOSPC' }, + ); }); it('does not throw when finish metadata collection fails', () => { @@ -283,9 +303,7 @@ describe('session-start-profiler', () => { }); it('writes bounded JSONL without sensitive fields', async () => { - const runtimeDir = await mkdtemp( - join(tmpdir(), 'session-start-profiler-'), - ); + const runtimeDir = await mkdtemp(join(tmpdir(), 'session-start-profiler-')); vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); vi.stubEnv(SESSION_START_PROFILE_ENV, '1'); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 7ab27033a15..5d35eceb674 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -9,9 +9,12 @@ import * as path from 'node:path'; import { performance } from 'node:perf_hooks'; import { Storage } from '../config/storage.js'; import type { SessionStartSource } from '../hooks/types.js'; +import { createDebugLogger } from '../utils/debugLogger.js'; export const SESSION_START_PROFILE_ENV = 'QWEN_CODE_PROFILE_SESSION_START'; +const debugLogger = createDebugLogger('SESSION_START_PROFILER'); + export interface SessionStartProfileRecord { timestamp: string; source: SessionStartSource; @@ -164,7 +167,18 @@ class EnabledSessionStartProfiler implements SessionStartProfiler { }; this.writeRecord(record); - } catch { + } catch (error) { + const code = + typeof error === 'object' && + error !== null && + 'code' in error && + typeof error.code === 'string' + ? error.code + : undefined; + debugLogger.debug('session-start-profiler write failed', { + name: error instanceof Error ? error.name : typeof error, + ...(code ? { code } : {}), + }); // Profiling must never affect session creation. } } From 5660c572d2c98a0c70f00a69528bb96d72ec8104 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 10:03:19 +0800 Subject: [PATCH 10/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- .qwen/design/2026-07-06-session-start-profiler.md | 6 ++++-- packages/core/src/core/client.test.ts | 5 +++++ 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/.qwen/design/2026-07-06-session-start-profiler.md b/.qwen/design/2026-07-06-session-start-profiler.md index a6344044b8f..6363ec4e4f9 100644 --- a/.qwen/design/2026-07-06-session-start-profiler.md +++ b/.qwen/design/2026-07-06-session-start-profiler.md @@ -10,9 +10,9 @@ It does not change session behavior, public protocol fields, SDK behavior, CLI f 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. +When enabled, core writes JSONL records under `Storage.getRuntimeBaseDir()/session-start-perf/`. Daily JSONL filenames use the UTC date from the record timestamp. 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()`. +The measured stages follow the existing `startChat()` sequence: tool registry warm, resumed deferred-tool reveal scan, deferred reminder setup, initial chat history build, skill reminder dedup seeding, agent reminder dedup seeding, system instruction build, `GeminiChat` construction, orphan tool-use repair, SessionStart hook, optional SessionStart context apply, and `setTools()`. ## Safety Boundaries @@ -22,6 +22,8 @@ All profiler writes are best-effort. File-system failures are swallowed so profi When disabled, the helper performs no file writes and does not read the high-resolution clock. +`failedStage` only records stages that throw through the profiler wrapper. Stages whose underlying helpers catch and suppress their own errors, such as agent reminder dedup seeding and the SessionStart hook, remain successful from the profiler's perspective. + ## Non-Goals This change does not optimize `GeminiClient.initialize()` or `startChat()`. diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 10e4c6aa141..10dfac84632 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -950,6 +950,11 @@ describe('Gemini Client (client.ts)', () => { SessionStartSource.Resume, SessionStartSource.Clear, ]); + expect( + sessionStartProfilerMocks.profilers[1].finish, + ).toHaveBeenCalledWith( + expect.objectContaining({ extraHistoryLength: 1 }), + ); for (const profiler of sessionStartProfilerMocks.profilers) { expect(profiler.finish).toHaveBeenCalledTimes(1); } From af1016b361cf63cf5d7eb42dd83165f91bd0517d Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 10:42:00 +0800 Subject: [PATCH 11/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- .../src/core/session-start-profiler.test.ts | 74 ++++++++++++++++++- .../core/src/core/session-start-profiler.ts | 43 ++++++++++- 2 files changed, 115 insertions(+), 2 deletions(-) diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 5705a0783c1..65b46928465 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -4,7 +4,16 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { mkdtemp, readFile, readdir, rm, stat } from 'node:fs/promises'; +import { + mkdir, + mkdtemp, + readFile, + readdir, + rm, + stat, + symlink, + writeFile, +} from 'node:fs/promises'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; @@ -39,6 +48,8 @@ function clockFrom(values: number[]) { } describe('session-start-profiler', () => { + const itNoSymlink = process.platform === 'win32' ? it.skip : it; + beforeEach(() => { debugLoggerMock.debug.mockClear(); }); @@ -350,4 +361,65 @@ describe('session-start-profiler', () => { await rm(runtimeDir, { recursive: true, force: true }); } }); + + itNoSymlink('does not write through a symlinked JSONL file', async () => { + const runtimeDir = await mkdtemp(join(tmpdir(), 'session-start-profiler-')); + vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); + vi.stubEnv(SESSION_START_PROFILE_ENV, '1'); + + try { + const perfDir = join(runtimeDir, 'session-start-perf'); + const targetPath = join(runtimeDir, 'target.jsonl'); + const profilePath = join(perfDir, 'session-start-2026-07-06.jsonl'); + await mkdir(perfDir); + await writeFile(targetPath, 'sentinel', 'utf8'); + await symlink(targetPath, profilePath); + + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + now: clockFrom([10, 20]), + getTimestamp: () => new Date('2026-07-06T12:34:56.789Z'), + }); + expect(() => profiler.finish({ ok: true })).not.toThrow(); + + await expect(readFile(targetPath, 'utf8')).resolves.toBe('sentinel'); + expect(debugLoggerMock.debug).toHaveBeenCalledWith( + 'session-start-profiler write failed', + expect.objectContaining({ name: 'Error' }), + ); + } finally { + await rm(runtimeDir, { recursive: true, force: true }); + } + }); + + itNoSymlink( + 'does not write through a symlinked profile directory', + async () => { + const runtimeDir = await mkdtemp( + join(tmpdir(), 'session-start-profiler-'), + ); + vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); + vi.stubEnv(SESSION_START_PROFILE_ENV, '1'); + + try { + const targetDir = join(runtimeDir, 'target-perf'); + const perfDir = join(runtimeDir, 'session-start-perf'); + await mkdir(targetDir); + await symlink(targetDir, perfDir); + + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + now: clockFrom([10, 20]), + getTimestamp: () => new Date('2026-07-06T12:34:56.789Z'), + }); + expect(() => profiler.finish({ ok: true })).not.toThrow(); + + await expect(readdir(targetDir)).resolves.toEqual([]); + expect(debugLoggerMock.debug).toHaveBeenCalledWith( + 'session-start-profiler write failed', + expect.objectContaining({ name: 'Error' }), + ); + } finally { + await rm(runtimeDir, { recursive: true, force: true }); + } + }, + ); }); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 5d35eceb674..9e8d6b7c9ee 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -54,9 +54,46 @@ function roundMs(value: number): number { return Math.round(value * 100) / 100; } +function getAppendProfileOpenFlags(): number { + const constants = fs.constants; + return ( + (constants.O_APPEND ?? 0) | + (constants.O_CREAT ?? 0) | + (constants.O_WRONLY ?? 0) | + (constants.O_NOFOLLOW ?? 0) + ); +} + +function assertSafeProfileDirectory(dir: string): void { + const dirStat = fs.lstatSync(dir); + if (!dirStat.isDirectory() || dirStat.isSymbolicLink()) { + throw new Error('session-start profiler path must be a real directory'); + } +} + +function assertSafeExistingProfileFile(filePath: string): void { + try { + const fileStat = fs.lstatSync(filePath); + if (!fileStat.isFile() || fileStat.isSymbolicLink()) { + throw new Error('session-start profiler path must be a real file'); + } + } catch (error) { + if ( + typeof error === 'object' && + error !== null && + 'code' in error && + error.code === 'ENOENT' + ) { + return; + } + throw error; + } +} + function writeProfileRecord(record: SessionStartProfileRecord): void { const dir = path.join(Storage.getRuntimeBaseDir(), 'session-start-perf'); fs.mkdirSync(dir, { recursive: true, mode: 0o700 }); + assertSafeProfileDirectory(dir); try { fs.chmodSync(dir, 0o700); } catch { @@ -64,8 +101,12 @@ function writeProfileRecord(record: SessionStartProfileRecord): void { } const filename = `session-start-${record.timestamp.slice(0, 10)}.jsonl`; const filePath = path.join(dir, filename); - const fd = fs.openSync(filePath, 'a', 0o600); + assertSafeExistingProfileFile(filePath); + const fd = fs.openSync(filePath, getAppendProfileOpenFlags(), 0o600); try { + if (!fs.fstatSync(fd).isFile()) { + throw new Error('session-start profiler path must be a real file'); + } try { fs.fchmodSync(fd, 0o600); } catch { From 3f74d473551556829ab37f6a660f1c6025663853 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 11:43:54 +0800 Subject: [PATCH 12/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- packages/core/src/core/client.test.ts | 42 +++++++++++++++++++ .../src/core/session-start-profiler.test.ts | 32 ++++++++++++++ .../core/src/core/session-start-profiler.ts | 20 ++++----- 3 files changed, 81 insertions(+), 13 deletions(-) diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 10dfac84632..574a1968d36 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -1127,6 +1127,48 @@ describe('Gemini Client (client.ts)', () => { }), ); }); + + it('finalizes failed startChat profiles with partial counts', async () => { + const toolRegistry = vi.mocked( + mockConfig.getToolRegistry, + )() as unknown as { + getDeferredToolSummary: ReturnType; + getTool: ReturnType; + }; + toolRegistry.getDeferredToolSummary.mockReturnValue([ + { name: 'cron_create', description: 'schedule' }, + ]); + toolRegistry.getTool.mockImplementation((name: string) => + name === ToolNames.TOOL_SEARCH ? ({} as never) : null, + ); + vi.mocked(getInitialChatHistory).mockResolvedValueOnce([ + [ + { + role: 'user', + parts: [{ text: 'context' }], + }, + ], + [{ name: 'skill-one', description: 'first skill' }], + ]); + vi.spyOn(client, 'setTools').mockRejectedValueOnce( + new Error('set tools failed'), + ); + + await expect(client.startChat()).rejects.toThrow( + 'Failed to initialize chat: set tools failed', + ); + + const profiler = sessionStartProfilerMocks.profilers.at(-1)!; + expect(profiler.finish).toHaveBeenCalledWith( + expect.objectContaining({ + ok: false, + extraHistoryLength: 0, + historyLength: 1, + snapshotEntryCount: 1, + deferredReminderCount: 1, + }), + ); + }); }); describe('startChat — deferred tools', () => { diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index 65b46928465..ac8842f6d61 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -362,6 +362,38 @@ describe('session-start-profiler', () => { } }); + it('appends to an existing JSONL file', async () => { + const runtimeDir = await mkdtemp(join(tmpdir(), 'session-start-profiler-')); + vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); + vi.stubEnv(SESSION_START_PROFILE_ENV, '1'); + + try { + const perfDir = join(runtimeDir, 'session-start-perf'); + const profilePath = join(perfDir, 'session-start-2026-07-06.jsonl'); + await mkdir(perfDir); + await writeFile(profilePath, '{"existing":true}\n', 'utf8'); + + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + now: clockFrom([10, 15, 20]), + getTimestamp: () => new Date('2026-07-06T12:34:56.789Z'), + }); + profiler.timeSync('system_instruction', () => undefined); + profiler.finish({ ok: true }); + + const lines = (await readFile(profilePath, 'utf8')).trim().split('\n'); + expect(lines).toHaveLength(2); + expect(JSON.parse(lines[0]!)).toEqual({ existing: true }); + expect(JSON.parse(lines[1]!)).toMatchObject({ + timestamp: '2026-07-06T12:34:56.789Z', + source: 'clear', + ok: true, + stages: { system_instruction: 5 }, + }); + } finally { + await rm(runtimeDir, { recursive: true, force: true }); + } + }); + itNoSymlink('does not write through a symlinked JSONL file', async () => { const runtimeDir = await mkdtemp(join(tmpdir(), 'session-start-profiler-')); vi.stubEnv('QWEN_RUNTIME_DIR', runtimeDir); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 9e8d6b7c9ee..8866e93ed45 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -10,6 +10,7 @@ import { performance } from 'node:perf_hooks'; import { Storage } from '../config/storage.js'; import type { SessionStartSource } from '../hooks/types.js'; import { createDebugLogger } from '../utils/debugLogger.js'; +import { isNodeError } from '../utils/errors.js'; export const SESSION_START_PROFILE_ENV = 'QWEN_CODE_PROFILE_SESSION_START'; @@ -19,6 +20,10 @@ export interface SessionStartProfileRecord { timestamp: string; source: SessionStartSource; ok: boolean; + /** + * Wall-clock session start duration. The sum of `stages` can be lower because + * only profiled callbacks are included in stage timings. + */ totalMs: number; stages: Record; extraHistoryLength?: number; @@ -78,12 +83,7 @@ function assertSafeExistingProfileFile(filePath: string): void { throw new Error('session-start profiler path must be a real file'); } } catch (error) { - if ( - typeof error === 'object' && - error !== null && - 'code' in error && - error.code === 'ENOENT' - ) { + if (isNodeError(error) && error.code === 'ENOENT') { return; } throw error; @@ -209,13 +209,7 @@ class EnabledSessionStartProfiler implements SessionStartProfiler { this.writeRecord(record); } catch (error) { - const code = - typeof error === 'object' && - error !== null && - 'code' in error && - typeof error.code === 'string' - ? error.code - : undefined; + const code = isNodeError(error) ? error.code : undefined; debugLogger.debug('session-start-profiler write failed', { name: error instanceof Error ? error.name : typeof error, ...(code ? { code } : {}), From 100164580842debbcd1e66912c6540690b3e4d82 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 12:56:57 +0800 Subject: [PATCH 13/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- packages/core/src/core/session-start-profiler.test.ts | 6 +++++- packages/core/src/core/session-start-profiler.ts | 7 +++++-- 2 files changed, 10 insertions(+), 3 deletions(-) diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index ac8842f6d61..f1c73a07298 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -120,6 +120,10 @@ describe('session-start-profiler', () => { deferredReminderCount: 1, }, ]); + expect(debugLoggerMock.debug).toHaveBeenCalledWith( + 'session-start-profiler enabled', + { source: 'resume' }, + ); }); it('rounds elapsed durations to two decimal places', async () => { @@ -294,7 +298,7 @@ describe('session-start-profiler', () => { expect(() => profiler.finish({ ok: true })).not.toThrow(); expect(debugLoggerMock.debug).toHaveBeenCalledWith( 'session-start-profiler write failed', - { name: 'Error', code: 'ENOSPC' }, + { name: 'Error', message: 'disk full', code: 'ENOSPC' }, ); }); diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 8866e93ed45..11125f72803 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -112,8 +112,8 @@ function writeProfileRecord(record: SessionStartProfileRecord): void { } catch { // Best-effort hardening; profiling output must not block startup. } - fs.appendFileSync(fd, `${JSON.stringify(record)}\n`, { - encoding: 'utf8', + fs.appendFileSync(fd, Buffer.from(`${JSON.stringify(record)}\n`, 'utf8'), { + flush: true, }); } finally { fs.closeSync(fd); @@ -212,6 +212,7 @@ class EnabledSessionStartProfiler implements SessionStartProfiler { const code = isNodeError(error) ? error.code : undefined; debugLogger.debug('session-start-profiler write failed', { name: error instanceof Error ? error.name : typeof error, + message: error instanceof Error ? error.message : undefined, ...(code ? { code } : {}), }); // Profiling must never affect session creation. @@ -234,6 +235,8 @@ export function createSessionStartProfiler( return disabledProfiler; } + debugLogger.debug('session-start-profiler enabled', { source }); + return new EnabledSessionStartProfiler(source, { now: options.now ?? (() => performance.now()), getTimestamp: options.getTimestamp ?? (() => new Date()), From c9f055790241a2c82957a5bcee51ea1a4286a03e Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 14:10:21 +0800 Subject: [PATCH 14/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- packages/core/src/core/client.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/core/src/core/client.ts b/packages/core/src/core/client.ts index c1a735bfd18..4f8d90234a1 100644 --- a/packages/core/src/core/client.ts +++ b/packages/core/src/core/client.ts @@ -1348,6 +1348,8 @@ export class GeminiClient { }); } + // setTools() intentionally keeps its own warmAll() guard, so this stage + // overlaps with tool_registry_warm while preserving the startup path. await profiler.time('set_tools', () => this.setTools()); finishProfile(true); From 691d0e689c15bad83853e81cd6a6e6c479898ff7 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Mon, 6 Jul 2026 15:16:11 +0800 Subject: [PATCH 15/16] codex: address PR review feedback (#6349) Co-authored-by: Qwen-Coder --- .../2026-07-06-session-start-profiler.md | 2 + .../src/core/session-start-profiler.test.ts | 45 ++++++++++++++++++- .../core/src/core/session-start-profiler.ts | 41 ++++++++++++----- 3 files changed, 76 insertions(+), 12 deletions(-) diff --git a/.qwen/design/2026-07-06-session-start-profiler.md b/.qwen/design/2026-07-06-session-start-profiler.md index 6363ec4e4f9..d81ec280323 100644 --- a/.qwen/design/2026-07-06-session-start-profiler.md +++ b/.qwen/design/2026-07-06-session-start-profiler.md @@ -20,6 +20,8 @@ The output intentionally excludes session IDs, prompts, model responses, hook ou All profiler writes are best-effort. File-system failures are swallowed so profiling cannot break or slow a session through error handling. +The JSONL writer uses restrictive permissions and `O_NOFOLLOW` on the profile file. Parent-directory replacement remains best-effort because Node does not expose a portable fd-relative append path here; the runtime directory is treated as same-user diagnostic storage, not a boundary against a local same-user attacker. + When disabled, the helper performs no file writes and does not read the high-resolution clock. `failedStage` only records stages that throw through the profiler wrapper. Stages whose underlying helpers catch and suppress their own errors, such as agent reminder dedup seeding and the SessionStart hook, remain successful from the profiler's perspective. diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index f1c73a07298..bd8088c8f57 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -51,7 +51,7 @@ describe('session-start-profiler', () => { const itNoSymlink = process.platform === 'win32' ? it.skip : it; beforeEach(() => { - debugLoggerMock.debug.mockClear(); + debugLoggerMock.debug.mockReset(); }); afterEach(() => { @@ -73,6 +73,16 @@ describe('session-start-profiler', () => { await expect( profiler.time('tool_registry_warm', async () => 'ok'), ).resolves.toBe('ok'); + const existingPromise = Promise.resolve('same-promise'); + expect(profiler.time('same_promise', () => existingPromise)).toBe( + existingPromise, + ); + const disabledError = new Error('disabled failure'); + await expect( + profiler.time('disabled_error', () => { + throw disabledError; + }), + ).rejects.toBe(disabledError); expect(profiler.timeSync('system_instruction', () => 42)).toBe(42); profiler.finish({ ok: true }); @@ -302,6 +312,39 @@ describe('session-start-profiler', () => { ); }); + it('does not throw when recovery debug logging fails', () => { + const profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([1, 2]), + writeRecord: () => { + throw new Error('disk full'); + }, + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + debugLoggerMock.debug.mockImplementation(() => { + throw new Error('debug log failed'); + }); + + expect(() => profiler.finish({ ok: true })).not.toThrow(); + }); + + it('does not throw when enabled debug logging fails', () => { + debugLoggerMock.debug.mockImplementation(() => { + throw new Error('debug log failed'); + }); + let profiler: ReturnType | undefined; + + expect(() => { + profiler = createSessionStartProfiler(SessionStartSource.Clear, { + enabled: true, + now: clockFrom([1, 2]), + writeRecord: vi.fn(), + getTimestamp: () => new Date('2026-07-06T00:00:00.000Z'), + }); + }).not.toThrow(); + expect(profiler?.enabled).toBe(true); + }); + it('does not throw when finish metadata collection fails', () => { const writeRecord = vi.fn(); const profiler = createSessionStartProfiler(SessionStartSource.Clear, { diff --git a/packages/core/src/core/session-start-profiler.ts b/packages/core/src/core/session-start-profiler.ts index 11125f72803..3390962372d 100644 --- a/packages/core/src/core/session-start-profiler.ts +++ b/packages/core/src/core/session-start-profiler.ts @@ -21,8 +21,9 @@ export interface SessionStartProfileRecord { source: SessionStartSource; ok: boolean; /** - * Wall-clock session start duration. The sum of `stages` can be lower because - * only profiled callbacks are included in stage timings. + * Wall-clock session start duration. The sum of `stages` can differ from + * `totalMs` because some stages overlap and unmeasured code runs between + * stages. */ totalMs: number; stages: Record; @@ -61,11 +62,15 @@ function roundMs(value: number): number { function getAppendProfileOpenFlags(): number { const constants = fs.constants; + const noFollow = constants.O_NOFOLLOW; + if (noFollow === undefined) { + throw new Error('session-start profiler requires O_NOFOLLOW support'); + } return ( (constants.O_APPEND ?? 0) | (constants.O_CREAT ?? 0) | (constants.O_WRONLY ?? 0) | - (constants.O_NOFOLLOW ?? 0) + noFollow ); } @@ -93,6 +98,8 @@ function assertSafeExistingProfileFile(filePath: string): void { function writeProfileRecord(record: SessionStartProfileRecord): void { const dir = path.join(Storage.getRuntimeBaseDir(), 'session-start-perf'); fs.mkdirSync(dir, { recursive: true, mode: 0o700 }); + // Node does not expose a portable fd-relative append here; parent-directory + // replacement is best-effort while O_NOFOLLOW protects the JSONL file itself. assertSafeProfileDirectory(dir); try { fs.chmodSync(dir, 0o700); @@ -122,8 +129,12 @@ function writeProfileRecord(record: SessionStartProfileRecord): void { const disabledProfiler: SessionStartProfiler = { enabled: false, - async time(_stage: string, fn: () => T | Promise): Promise { - return await fn(); + time(_stage: string, fn: () => T | Promise): Promise { + try { + return Promise.resolve(fn()); + } catch (error) { + return Promise.reject(error); + } }, timeSync(_stage: string, fn: () => T): T { return fn(); @@ -210,11 +221,15 @@ class EnabledSessionStartProfiler implements SessionStartProfiler { this.writeRecord(record); } catch (error) { const code = isNodeError(error) ? error.code : undefined; - debugLogger.debug('session-start-profiler write failed', { - name: error instanceof Error ? error.name : typeof error, - message: error instanceof Error ? error.message : undefined, - ...(code ? { code } : {}), - }); + try { + debugLogger.debug('session-start-profiler write failed', { + name: error instanceof Error ? error.name : typeof error, + message: error instanceof Error ? error.message : undefined, + ...(code ? { code } : {}), + }); + } catch { + // Recovery logging must not propagate into session creation. + } // Profiling must never affect session creation. } } @@ -235,7 +250,11 @@ export function createSessionStartProfiler( return disabledProfiler; } - debugLogger.debug('session-start-profiler enabled', { source }); + try { + debugLogger.debug('session-start-profiler enabled', { source }); + } catch { + // Activation logging must not affect session startup. + } return new EnabledSessionStartProfiler(source, { now: options.now ?? (() => performance.now()), From 03b00ef14be7716906b47a636461e91305b49011 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 7 Jul 2026 01:54:22 +0800 Subject: [PATCH 16/16] test(core): cover disabled session profile env values Co-authored-by: Qwen-Coder --- .../src/core/session-start-profiler.test.ts | 22 +++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/packages/core/src/core/session-start-profiler.test.ts b/packages/core/src/core/session-start-profiler.test.ts index bd8088c8f57..2b67636f2d9 100644 --- a/packages/core/src/core/session-start-profiler.test.ts +++ b/packages/core/src/core/session-start-profiler.test.ts @@ -91,6 +91,28 @@ describe('session-start-profiler', () => { expect(writeRecord).not.toHaveBeenCalled(); }); + it.each(['true', '0', ''])( + 'stays disabled when env var is set to %j', + (envValue) => { + vi.stubEnv(SESSION_START_PROFILE_ENV, envValue); + const now = vi.fn(() => { + throw new Error('disabled profiler should not read time'); + }); + const writeRecord = vi.fn(); + + const profiler = createSessionStartProfiler(SessionStartSource.Startup, { + now, + writeRecord, + }); + profiler.finish({ ok: true }); + + expect(profiler.enabled).toBe(false); + expect(now).not.toHaveBeenCalled(); + expect(writeRecord).not.toHaveBeenCalled(); + expect(debugLoggerMock.debug).not.toHaveBeenCalled(); + }, + ); + it('records sync and async stages when enabled', async () => { const records: SessionStartProfileRecord[] = []; const profiler = createSessionStartProfiler(SessionStartSource.Resume, {