From 34882f346ed6807d0a5c9194064ac9aeb1d84201 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Sat, 18 Jul 2026 08:59:57 +0800 Subject: [PATCH 1/2] feat(daemon): Profile ACP channel initialization Co-authored-by: Qwen-Coder --- .../acp-channel-initialize-profiling.md | 102 +++++++ packages/acp-bridge/src/bridge.test.ts | 71 ++++- packages/acp-bridge/src/bridge.ts | 28 +- packages/acp-bridge/src/bridgeOptions.ts | 1 + packages/acp-bridge/src/bridgeTypes.ts | 35 +++ .../src/channel-startup-profile.test.ts | 131 +++++++++ .../acp-bridge/src/channel-startup-profile.ts | 153 +++++++++++ packages/acp-bridge/src/internal/testUtils.ts | 11 +- .../cli/src/acp-integration/acpAgent.test.ts | 50 +++- packages/cli/src/acp-integration/acpAgent.ts | 62 ++++- packages/cli/src/cli.test.ts | 28 ++ packages/cli/src/cli.ts | 8 + packages/cli/src/gemini.tsx | 24 +- .../src/utils/acp-startup-profiler.test.ts | 144 ++++++++++ .../cli/src/utils/acp-startup-profiler.ts | 253 ++++++++++++++++++ .../core/src/config/config.safe-mode.test.ts | 30 +++ packages/core/src/config/config.ts | 18 ++ .../core/src/telemetry/daemon-tracing.test.ts | 15 ++ packages/core/src/telemetry/daemon-tracing.ts | 9 + scripts/check-serve-fast-path-bundle.js | 21 ++ .../serve-fast-path-bundle-check.test.js | 34 +++ 21 files changed, 1209 insertions(+), 19 deletions(-) create mode 100644 docs/design/acp-channel-initialize-profiling.md create mode 100644 packages/acp-bridge/src/channel-startup-profile.test.ts create mode 100644 packages/acp-bridge/src/channel-startup-profile.ts create mode 100644 packages/cli/src/utils/acp-startup-profiler.test.ts create mode 100644 packages/cli/src/utils/acp-startup-profiler.ts diff --git a/docs/design/acp-channel-initialize-profiling.md b/docs/design/acp-channel-initialize-profiling.md new file mode 100644 index 00000000000..f30d1af22f5 --- /dev/null +++ b/docs/design/acp-channel-initialize-profiling.md @@ -0,0 +1,102 @@ +# ACP Channel Initialize Profiling + +## Summary + +The daemon's `channel.initialize` span starts after the ACP child is spawned and +ends when the child returns its ACP initialize response. It therefore includes +Node and ESM startup, CLI bootstrap, ACP module loading, bootstrap +`Config.initialize()`, transport setup, and the initialize handler. The handler +itself only returns capabilities and is not expected to explain the observed +latency. + +This design adds a fixed, opt-in child startup profile to the ACP initialize +response and copies the validated durations onto the existing parent +`channel.initialize` span. It does not change channel readiness, initialization +ordering, failure handling, or session behavior. + +## Protocol + +The bridge requests version 1 of the profile through initialize request +metadata: + +```json +{ + "_meta": { + "qwen.daemon.channelStartupProfile": { "v": 1 } + } +} +``` + +Supporting children return the profile under the same top-level response +metadata key. The response contains only fixed duration fields, a completeness +flag, the response-build wall-clock timestamp, and the total child process to +response duration. It never contains paths, extension names, settings, or +other user-derived values. + +The profile divides the child startup into non-overlapping top-level phases: + +- process start to profiler readiness; +- Gemini module import; +- argument parsing; +- settings loading; +- Config construction; +- generic application initialization; +- ACP module import; +- bootstrap Config initialization; +- transport construction; +- initialize handler execution; +- unattributed time between the fixed phases. + +Bootstrap Config initialization is split into initial extension refresh, +hooks, skills, final extension refresh, hierarchical memory, tool registry, +tool warmup, and residual time. The ripgrep probe is reported as a child of +tool registry time and is not subtracted again when calculating residual time. + +All durations use `performance.now()` and are rounded to two decimal places. +The response-build epoch uses `performance.timeOrigin` plus the response mark +and is used only for the optional parent-side transport estimate. + +## Collection lifecycle + +The CLI dynamically initializes the ACP profiler only when the raw arguments +contain `--acp` or `--experimental-acp`, before importing the Gemini runtime. +The profiler stores the first timestamp for a finite union of mark names. It +does not perform file I/O, heap capture, telemetry initialization, or dynamic +event retention. + +The core startup-event sink forwards fixed Config phase events to the ACP +profiler only while the ACP bootstrap Config is initializing. This prevents +later per-session Config initialization from contaminating the startup +profile. Skipped Config phases still emit adjacent start and end marks so a +successful startup can produce a complete profile in bare or safe mode. + +The initialize handler freezes the profiler after building the first response, +whether or not the caller negotiated the profile. Missing marks produce +`complete: false`; collection never delays or fails the initialize response. + +## Parent span enrichment + +The bridge validates the response metadata before adding fixed numeric +attributes to the active `channel.initialize` span. Unknown profile versions +are ignored. Unknown fields are ignored. Known values must be finite, +non-negative, and no greater than 600 seconds. Invalid or missing known fields +are omitted and make the effective completeness flag false. + +The optional response transport estimate is the parent receive time minus the +child response-build epoch. It is recorded only when finite, non-negative, and +no greater than the configured initialize timeout. + +Profile parsing and telemetry enrichment are fail-open. A missing, malformed, +or unsupported profile must not change initialize success, channel teardown, +coalesced caller behavior, or retry behavior. New parents remain compatible +with old children because ACP metadata is extensible; new children return no +profile to old parents that do not opt in. + +## Verification + +Focused tests cover collector activation and freezing, fixed phase arithmetic, +payload size, protocol negotiation, malformed profiles, span enrichment, +telemetry failure isolation, Config event ordering, and the serve fast-path +bundle boundary. The release-built candidate is compared with the exact #6907 +merge baseline on the representative 2C4G host with paired, alternating cold +runs before any optimization is selected. diff --git a/packages/acp-bridge/src/bridge.test.ts b/packages/acp-bridge/src/bridge.test.ts index d48ebbf89ec..d61501b2b81 100644 --- a/packages/acp-bridge/src/bridge.test.ts +++ b/packages/acp-bridge/src/bridge.test.ts @@ -56,6 +56,10 @@ import type { ChannelFactory } from './channel.js'; import type { BridgeTelemetry } from './bridgeOptions.js'; import { createInMemoryChannel } from './inMemoryChannel.js'; import { EventBus, type BridgeEvent } from './eventBus.js'; +import { + CHANNEL_STARTUP_PROFILE_META_KEY, + CHANNEL_STARTUP_PROFILE_VERSION, +} from './bridgeTypes.js'; import { ApprovalMode, SESSION_ARTIFACT_PERSISTENCE_VERSION, @@ -848,11 +852,25 @@ describe('createAcpSessionBridge', () => { }); it('uses bridge telemetry for channel/session/prompt dispatch and prompt metadata injection', async () => { - const handle = makeChannel(); + const handle = makeChannel({ + initializeImpl: async () => ({ + protocolVersion: PROTOCOL_VERSION, + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + complete: false, + processToResponseMs: 10, + phases: {}, + config: {}, + }, + }, + }), + }); const operations: string[] = []; const events: string[] = []; const spanAttributes = new Map>(); const eventAttributes = new Map>(); + const activeSpanAttributes: Array> = []; const telemetry: BridgeTelemetry = { captureContext: () => { events.push('capture'); @@ -874,6 +892,9 @@ describe('createAcpSessionBridge', () => { events.push(`span:${operation}:end`); } }, + setActiveSpanAttributes(attributes) { + activeSpanAttributes.push(attributes); + }, event(name, attributes) { events.push(`event:${name}`); eventAttributes.set(name, attributes); @@ -924,6 +945,18 @@ describe('createAcpSessionBridge', () => { 'prompt.dispatch', ]), ); + expect(handle.agent.initializeCalls[0]!._meta).toEqual({ + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + }, + }); + expect(activeSpanAttributes).toContainEqual( + expect.objectContaining({ + 'qwen-code.daemon.acp_startup.profile.version': 1, + 'qwen-code.daemon.acp_startup.profile.complete': false, + 'qwen-code.daemon.acp_startup.child.process_to_response_ms': 10, + }), + ); expect(events.slice(-4)).toEqual([ 'run:true', 'span:prompt.dispatch:start', @@ -968,6 +1001,42 @@ describe('createAcpSessionBridge', () => { }); }); + it('does not fail initialization when span enrichment throws', async () => { + const handle = makeChannel({ + initializeImpl: async () => ({ + protocolVersion: PROTOCOL_VERSION, + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + complete: false, + phases: {}, + config: {}, + }, + }, + }), + }); + const telemetry: BridgeTelemetry = { + captureContext: () => undefined, + runWithContext: (_captured, fn) => fn(), + withSpan: (_operation, _attributes, fn) => fn(), + setActiveSpanAttributes() { + throw new Error('telemetry failed'); + }, + event() {}, + injectPromptContext: (request) => request, + }; + const bridge = makeBridge({ + channelFactory: async () => handle.channel, + telemetry, + }); + + await expect( + bridge.spawnOrAttach({ workspaceCwd: WS_A }), + ).resolves.toMatchObject({ workspaceCwd: WS_A }); + + await bridge.shutdown(); + }); + it('profiles Session channel waits as joined or reused', async () => { const handle = makeChannel(); const factoryStarted = deferred(); diff --git a/packages/acp-bridge/src/bridge.ts b/packages/acp-bridge/src/bridge.ts index 62da2a81bff..af9f17da0e5 100644 --- a/packages/acp-bridge/src/bridge.ts +++ b/packages/acp-bridge/src/bridge.ts @@ -85,6 +85,8 @@ import { import { canonicalizeWorkspace } from './workspacePaths.js'; import { parseSessionSource } from './session-source.js'; import { + CHANNEL_STARTUP_PROFILE_META_KEY, + CHANNEL_STARTUP_PROFILE_VERSION, LOAD_REPLAY_BULK_MODE, LOAD_REPLAY_META_KEY, LOAD_REPLAY_MODE_META_KEY, @@ -92,6 +94,7 @@ import { LOAD_REPLAY_VERSION, TODO_STOP_GUARD_QUEUE_RELEASE_METHOD, } from './bridgeTypes.js'; +import { getChannelStartupProfileAttributes } from './channel-startup-profile.js'; import type { BridgeSession, BridgeRestoreSessionRequest, @@ -2132,10 +2135,15 @@ export function createAcpSessionBridge(opts: BridgeOptions): AcpSessionBridge { 'qwen-code.daemon.bridge.operation': 'channel.initialize', 'qwen-code.daemon.acp_channel.id': acpChannelId, }, - async () => - await withTimeout( + async () => { + const response = await withTimeout( connection.initialize({ protocolVersion: PROTOCOL_VERSION, + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + }, + }, clientCapabilities: { fs: { readTextFile: true, writeTextFile: true }, }, @@ -2143,7 +2151,21 @@ export function createAcpSessionBridge(opts: BridgeOptions): AcpSessionBridge { }), initTimeoutMs, 'initialize', - ), + ); + try { + const attributes = getChannelStartupProfileAttributes( + response, + Date.now(), + initTimeoutMs, + ); + if (attributes && telemetry.setActiveSpanAttributes) { + telemetry.setActiveSpanAttributes(attributes); + } + } catch { + // Startup profiling must not affect bridge behavior. + } + return response; + }, ); } catch (err) { // Mark the half-initialized channel as dying/unavailable, then diff --git a/packages/acp-bridge/src/bridgeOptions.ts b/packages/acp-bridge/src/bridgeOptions.ts index 3138d7e8593..03df36aa073 100644 --- a/packages/acp-bridge/src/bridgeOptions.ts +++ b/packages/acp-bridge/src/bridgeOptions.ts @@ -143,6 +143,7 @@ export interface BridgeTelemetry { attributes: BridgeTelemetryAttributes, fn: () => Promise, ): Promise; + setActiveSpanAttributes?(attributes: BridgeTelemetryAttributes): void; event(name: string, attributes: BridgeTelemetryAttributes): void; injectPromptContext(request: T): T; metrics?: BridgeTelemetryMetrics; diff --git a/packages/acp-bridge/src/bridgeTypes.ts b/packages/acp-bridge/src/bridgeTypes.ts index bdeb2292044..65b749791ee 100644 --- a/packages/acp-bridge/src/bridgeTypes.ts +++ b/packages/acp-bridge/src/bridgeTypes.ts @@ -160,6 +160,41 @@ export const LOAD_REPLAY_PAGE_SIZE_META_KEY = 'qwen.session.loadReplayPageSize'; export const LOAD_REPLAY_BULK_MODE = 'bulk'; export const LOAD_REPLAY_VERSION = 1 as const; +export const CHANNEL_STARTUP_PROFILE_META_KEY = + 'qwen.daemon.channelStartupProfile'; +export const CHANNEL_STARTUP_PROFILE_VERSION = 1 as const; + +export interface ChannelStartupProfileV1 { + v: typeof CHANNEL_STARTUP_PROFILE_VERSION; + complete: boolean; + responseBuiltAtEpochMs?: number; + processToResponseMs?: number; + phases: { + processToProfilerReadyMs?: number; + geminiImportMs?: number; + argsParseMs?: number; + settingsLoadMs?: number; + configConstructionMs?: number; + appInitializationMs?: number; + acpImportMs?: number; + bootstrapConfigInitializationMs?: number; + transportSetupMs?: number; + initializeHandlerMs?: number; + unattributedMs?: number; + }; + config: { + extensionsInitialMs?: number; + hooksMs?: number; + skillsMs?: number; + extensionsFinalMs?: number; + hierarchicalMemoryMs?: number; + toolRegistryMs?: number; + ripgrepProbeMs?: number; + toolWarmupMs?: number; + otherMs?: number; + }; +} + export interface BridgeLoadReplayEnvelope { v: typeof LOAD_REPLAY_VERSION; updates: SessionUpdate[]; diff --git a/packages/acp-bridge/src/channel-startup-profile.test.ts b/packages/acp-bridge/src/channel-startup-profile.test.ts new file mode 100644 index 00000000000..b1763972319 --- /dev/null +++ b/packages/acp-bridge/src/channel-startup-profile.test.ts @@ -0,0 +1,131 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { describe, expect, it } from 'vitest'; +import { + CHANNEL_STARTUP_PROFILE_META_KEY, + type ChannelStartupProfileV1, +} from './bridgeTypes.js'; +import { getChannelStartupProfileAttributes } from './channel-startup-profile.js'; + +function makeProfile(): ChannelStartupProfileV1 { + return { + v: 1, + complete: true, + responseBuiltAtEpochMs: 1_000, + processToResponseMs: 900, + phases: { + processToProfilerReadyMs: 100, + geminiImportMs: 200, + argsParseMs: 10, + settingsLoadMs: 20, + configConstructionMs: 30, + appInitializationMs: 40, + acpImportMs: 50, + bootstrapConfigInitializationMs: 300, + transportSetupMs: 10, + initializeHandlerMs: 1, + unattributedMs: 139, + }, + config: { + extensionsInitialMs: 20, + hooksMs: 30, + skillsMs: 40, + extensionsFinalMs: 20, + hierarchicalMemoryMs: 30, + toolRegistryMs: 80, + ripgrepProbeMs: 50, + toolWarmupMs: 20, + otherMs: 60, + }, + }; +} + +function makeResponse(profile: unknown): Record { + return { + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: profile, + }, + }; +} + +describe('channel startup profile parsing', () => { + it('maps a valid profile to fixed span attributes', () => { + const attributes = getChannelStartupProfileAttributes( + makeResponse(makeProfile()), + 1_007, + 10_000, + ); + + expect(attributes).toMatchObject({ + 'qwen-code.daemon.acp_startup.profile.version': 1, + 'qwen-code.daemon.acp_startup.profile.complete': true, + 'qwen-code.daemon.acp_startup.child.process_to_response_ms': 900, + 'qwen-code.daemon.acp_startup.child.unattributed_ms': 139, + 'qwen-code.daemon.acp_startup.phase.gemini_import_ms': 200, + 'qwen-code.daemon.acp_startup.config.ripgrep_probe_ms': 50, + 'qwen-code.daemon.acp_startup.response_transport_ms': 7, + }); + }); + + it('ignores missing and unsupported profiles', () => { + expect( + getChannelStartupProfileAttributes({}, 1_000, 10_000), + ).toBeUndefined(); + expect( + getChannelStartupProfileAttributes( + makeResponse({ ...makeProfile(), v: 2 }), + 1_000, + 10_000, + ), + ).toBeUndefined(); + }); + + it('omits invalid values and marks a partial profile incomplete', () => { + const profile = makeProfile(); + profile.phases.geminiImportMs = Number.NaN; + profile.phases.argsParseMs = Number.POSITIVE_INFINITY; + profile.config.toolRegistryMs = -1; + profile.config.toolWarmupMs = 600_001; + + const attributes = getChannelStartupProfileAttributes( + makeResponse({ ...profile, extra: 'ignored' }), + 1_007, + 10_000, + ); + + expect(attributes?.['qwen-code.daemon.acp_startup.profile.complete']).toBe( + false, + ); + expect(attributes).not.toHaveProperty( + 'qwen-code.daemon.acp_startup.phase.gemini_import_ms', + ); + expect(attributes).not.toHaveProperty( + 'qwen-code.daemon.acp_startup.phase.args_parse_ms', + ); + expect(attributes).not.toHaveProperty( + 'qwen-code.daemon.acp_startup.config.tool_registry_ms', + ); + expect(attributes).not.toHaveProperty( + 'qwen-code.daemon.acp_startup.config.tool_warmup_ms', + ); + }); + + it('omits an invalid cross-process transport estimate', () => { + const profile = makeProfile(); + profile.responseBuiltAtEpochMs = 2_000; + + const attributes = getChannelStartupProfileAttributes( + makeResponse(profile), + 1_000, + 10_000, + ); + + expect(attributes).not.toHaveProperty( + 'qwen-code.daemon.acp_startup.response_transport_ms', + ); + }); +}); diff --git a/packages/acp-bridge/src/channel-startup-profile.ts b/packages/acp-bridge/src/channel-startup-profile.ts new file mode 100644 index 00000000000..2193f8cfc7a --- /dev/null +++ b/packages/acp-bridge/src/channel-startup-profile.ts @@ -0,0 +1,153 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { + CHANNEL_STARTUP_PROFILE_META_KEY, + CHANNEL_STARTUP_PROFILE_VERSION, + type ChannelStartupProfileV1, +} from './bridgeTypes.js'; +import type { BridgeTelemetryAttributes } from './bridgeOptions.js'; + +const MAX_PROFILE_DURATION_MS = 600_000; +const ATTRIBUTE_PREFIX = 'qwen-code.daemon.acp_startup'; + +type ProfileDurations = Record; + +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === 'object' && !Array.isArray(value); +} + +function readDuration( + source: Record, + key: string, +): number | undefined { + const value = source[key]; + return typeof value === 'number' && + Number.isFinite(value) && + value >= 0 && + value <= MAX_PROFILE_DURATION_MS + ? value + : undefined; +} + +function readDurations( + source: unknown, + keys: readonly string[], +): { values: ProfileDurations; complete: boolean } { + if (!isRecord(source)) { + return { values: {}, complete: false }; + } + const values: ProfileDurations = {}; + let complete = true; + for (const key of keys) { + const value = readDuration(source, key); + if (value === undefined) { + complete = false; + } else { + values[key] = value; + } + } + return { values, complete }; +} + +function addDurationAttributes( + attributes: BridgeTelemetryAttributes, + group: 'phase' | 'config', + values: ProfileDurations, +): void { + for (const [key, value] of Object.entries(values)) { + if (group === 'phase' && key === 'unattributedMs') continue; + const attributeKey = key.replace( + /[A-Z]/g, + (letter) => `_${letter.toLowerCase()}`, + ); + attributes[`${ATTRIBUTE_PREFIX}.${group}.${attributeKey}`] = value; + } +} + +const PHASE_KEYS = [ + 'processToProfilerReadyMs', + 'geminiImportMs', + 'argsParseMs', + 'settingsLoadMs', + 'configConstructionMs', + 'appInitializationMs', + 'acpImportMs', + 'bootstrapConfigInitializationMs', + 'transportSetupMs', + 'initializeHandlerMs', + 'unattributedMs', +] as const satisfies ReadonlyArray; + +const CONFIG_KEYS = [ + 'extensionsInitialMs', + 'hooksMs', + 'skillsMs', + 'extensionsFinalMs', + 'hierarchicalMemoryMs', + 'toolRegistryMs', + 'ripgrepProbeMs', + 'toolWarmupMs', + 'otherMs', +] as const satisfies ReadonlyArray; + +export function getChannelStartupProfileAttributes( + response: unknown, + receivedAtEpochMs: number, + initializeTimeoutMs: number, +): BridgeTelemetryAttributes | undefined { + if (!isRecord(response) || !isRecord(response['_meta'])) { + return undefined; + } + const profile = response['_meta'][CHANNEL_STARTUP_PROFILE_META_KEY]; + if (!isRecord(profile) || profile['v'] !== CHANNEL_STARTUP_PROFILE_VERSION) { + return undefined; + } + + const phases = readDurations(profile['phases'], PHASE_KEYS); + const config = readDurations(profile['config'], CONFIG_KEYS); + const processToResponseMs = readDuration(profile, 'processToResponseMs'); + const responseBuiltAtEpochMs = profile['responseBuiltAtEpochMs']; + const childComplete = profile['complete'] === true; + const validResponseEpoch = + typeof responseBuiltAtEpochMs === 'number' && + Number.isFinite(responseBuiltAtEpochMs) && + responseBuiltAtEpochMs >= 0; + const effectiveComplete = + childComplete && + phases.complete && + config.complete && + processToResponseMs !== undefined && + validResponseEpoch; + + const attributes: BridgeTelemetryAttributes = { + [`${ATTRIBUTE_PREFIX}.profile.version`]: CHANNEL_STARTUP_PROFILE_VERSION, + [`${ATTRIBUTE_PREFIX}.profile.complete`]: effectiveComplete, + }; + if (processToResponseMs !== undefined) { + attributes[`${ATTRIBUTE_PREFIX}.child.process_to_response_ms`] = + processToResponseMs; + } + if (phases.values['unattributedMs'] !== undefined) { + attributes[`${ATTRIBUTE_PREFIX}.child.unattributed_ms`] = + phases.values['unattributedMs']; + } + addDurationAttributes(attributes, 'phase', phases.values); + addDurationAttributes(attributes, 'config', config.values); + + if (validResponseEpoch) { + const transportMs = receivedAtEpochMs - responseBuiltAtEpochMs; + if ( + Number.isFinite(transportMs) && + transportMs >= 0 && + transportMs <= initializeTimeoutMs + ) { + attributes[`${ATTRIBUTE_PREFIX}.response_transport_ms`] = transportMs; + } + } + + return attributes; +} diff --git a/packages/acp-bridge/src/internal/testUtils.ts b/packages/acp-bridge/src/internal/testUtils.ts index 44b51486c79..41a7627d773 100644 --- a/packages/acp-bridge/src/internal/testUtils.ts +++ b/packages/acp-bridge/src/internal/testUtils.ts @@ -106,6 +106,10 @@ export interface FakeAgentOpts { initializeDelayMs?: number; /** Force `initialize` to throw. */ initializeThrows?: Error; + initializeImpl?: ( + p: InitializeRequest, + self: FakeAgent, + ) => Promise | InitializeResponse; /** * Custom prompt handler. Default returns `end_turn` synchronously. Useful * for test cases that want to observe prompt ordering. @@ -141,6 +145,7 @@ export interface FakeAgentOpts { } export class FakeAgent implements Agent { + initializeCalls: InitializeRequest[] = []; newSessionCalls: NewSessionRequest[] = []; loadSessionCalls: LoadSessionRequest[] = []; resumeSessionCalls: ResumeSessionRequest[] = []; @@ -150,11 +155,15 @@ export class FakeAgent implements Agent { []; constructor(private readonly opts: FakeAgentOpts = {}) {} - async initialize(_p: InitializeRequest): Promise { + async initialize(p: InitializeRequest): Promise { + this.initializeCalls.push(p); if (this.opts.initializeThrows) throw this.opts.initializeThrows; if (this.opts.initializeDelayMs) { await new Promise((r) => setTimeout(r, this.opts.initializeDelayMs)); } + if (this.opts.initializeImpl) { + return await this.opts.initializeImpl(p, this); + } return { protocolVersion: PROTOCOL_VERSION, agentInfo: { name: 'fake-agent', version: '0' }, diff --git a/packages/cli/src/acp-integration/acpAgent.test.ts b/packages/cli/src/acp-integration/acpAgent.test.ts index b4bd40a4c61..125f90a4101 100644 --- a/packages/cli/src/acp-integration/acpAgent.test.ts +++ b/packages/cli/src/acp-integration/acpAgent.test.ts @@ -769,13 +769,21 @@ import { SERVE_STATUS_EXT_METHODS, SERVE_CONTROL_EXT_METHODS, } from '@qwen-code/acp-bridge/status'; -import { TODO_STOP_GUARD_QUEUE_RELEASE_METHOD } from '@qwen-code/acp-bridge/bridgeTypes'; import type { ServeWorkspaceSkillsStatus } from '@qwen-code/acp-bridge/status'; import { updateOutputLanguageFile, writeOutputLanguageAndRegisterPath, } from '../utils/languageUtils.js'; import { buildAuthMethods } from './authMethods.js'; +import { + CHANNEL_STARTUP_PROFILE_META_KEY, + CHANNEL_STARTUP_PROFILE_VERSION, + TODO_STOP_GUARD_QUEUE_RELEASE_METHOD, +} from '@qwen-code/acp-bridge/bridgeTypes'; +import { + initializeAcpStartupProfiler, + resetAcpStartupProfilerForTesting, +} from '../utils/acp-startup-profiler.js'; describe('runAcpAgent shutdown cleanup', () => { let processExitSpy: MockInstance; @@ -791,6 +799,7 @@ describe('runAcpAgent shutdown cleanup', () => { const mockArgv = {} as CliArgs; beforeEach(() => { + resetAcpStartupProfilerForTesting(); vi.clearAllMocks(); mockMcpApprovals.getState.mockReturnValue('approved'); mockMcpApprovals.setState.mockResolvedValue(undefined); @@ -849,6 +858,7 @@ describe('runAcpAgent shutdown cleanup', () => { }); afterEach(() => { + resetAcpStartupProfilerForTesting(); processExitSpy.mockRestore(); stdinDestroySpy.mockRestore(); stdoutDestroySpy.mockRestore(); @@ -1457,6 +1467,44 @@ describe('QwenAgent MCP SSE/HTTP support', () => { }, }, }); + expect(response).not.toHaveProperty('_meta'); + + mockConnectionState.resolve(); + await agentPromise; + }); + + it('returns the startup profile only when initialize metadata requests v1', async () => { + initializeAcpStartupProfiler(); + const mockSettings = { + merged: { mcpServers: {} }, + } as unknown as LoadedSettings; + const agentPromise = runAcpAgent(mockConfig, mockSettings, mockArgv); + await vi.waitFor(() => expect(capturedAgentFactory).toBeDefined()); + const fakeConn = { + get closed() { + return mockConnectionState.promise; + }, + } as AgentSideConnectionLike; + const agent = capturedAgentFactory!(fakeConn) as AgentLike; + + const response = (await agent.initialize({ + clientCapabilities: {}, + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + }, + }, + })) as Record; + + expect(response['_meta']).toMatchObject({ + [CHANNEL_STARTUP_PROFILE_META_KEY]: { + v: CHANNEL_STARTUP_PROFILE_VERSION, + complete: false, + phases: expect.any(Object), + config: expect.any(Object), + }, + }); + expect(JSON.stringify(response['_meta']).length).toBeLessThan(2048); mockConnectionState.resolve(); await agentPromise; diff --git a/packages/cli/src/acp-integration/acpAgent.ts b/packages/cli/src/acp-integration/acpAgent.ts index e4aa5c876eb..959d535c56d 100644 --- a/packages/cli/src/acp-integration/acpAgent.ts +++ b/packages/cli/src/acp-integration/acpAgent.ts @@ -283,6 +283,8 @@ import { } from '@qwen-code/acp-bridge/status'; import { parseSessionSource } from '@qwen-code/acp-bridge'; import { + CHANNEL_STARTUP_PROFILE_META_KEY, + CHANNEL_STARTUP_PROFILE_VERSION, CLIENT_MCP_OVER_WS_CONFIG_FLAG, LOAD_REPLAY_BULK_MODE, LOAD_REPLAY_META_KEY, @@ -293,6 +295,12 @@ import { type ClientMcpOverWsRuntimeConfig, type BridgeLoadReplayEnvelope, } from '@qwen-code/acp-bridge/bridgeTypes'; +import { + beginAcpBootstrapConfigProfiling, + buildAndFreezeAcpStartupProfile, + endAcpBootstrapConfigProfiling, + markAcpStartup, +} from '../utils/acp-startup-profiler.js'; import { isValidServerName } from '../serve/validate-server-name.js'; import { MAX_REMEMBER_CONTENT_BYTES } from '../serve/workspace-memory-remember-constants.js'; import { computeCpuPercent } from '../serve/daemon-metrics-ring.js'; @@ -2546,16 +2554,21 @@ export async function runAcpAgent( const bootstrapClientMcpSender: SendSdkMcpMessage = (serverName, message) => deliverClientMcpMessage(acpConnection, serverName, message); - await config.initialize({ - skipGeminiInitialization: true, - // Bootstrap skips MCP discovery — each session runs its own - // pool-routed discovery, so bootstrap-level spawns would be - // redundant subprocess leaks (W119). - skipMcpDiscovery: true, - // Bind the workspace-level manager's SDK callback so a runtime-added - // client-hosted MCP server (#5626) round-trips over the parent WS. - sendSdkMcpMessage: bootstrapClientMcpSender, - }); + beginAcpBootstrapConfigProfiling(); + try { + await config.initialize({ + skipGeminiInitialization: true, + // Bootstrap skips MCP discovery — each session runs its own + // pool-routed discovery, so bootstrap-level spawns would be + // redundant subprocess leaks (W119). + skipMcpDiscovery: true, + // Bind the workspace-level manager's SDK callback so a runtime-added + // client-hosted MCP server (#5626) round-trips over the parent WS. + sendSdkMcpMessage: bootstrapClientMcpSender, + }); + } finally { + endAcpBootstrapConfigProfiling(); + } const eventLoopMonitor = startEventLoopLagMonitor({ onNewMaxStall: (maxMs) => { console.error(`[perf] acp agent event loop stall: max=${maxMs}ms`); @@ -2564,6 +2577,7 @@ export async function runAcpAgent( let agentInstance: QwenAgent | undefined; let connection: AgentSideConnection; + markAcpStartup('transportSetupStart'); try { const stdout = Writable.toWeb(process.stdout) as WritableStream; const stdin = Readable.toWeb(process.stdin) as ReadableStream; @@ -2580,6 +2594,7 @@ export async function runAcpAgent( agentInstance = new QwenAgent(config, settings, argv, conn); return agentInstance; }, stream); + markAcpStartup('transportSetupEnd'); } catch (err) { eventLoopMonitor.dispose(); throw err; @@ -3345,11 +3360,12 @@ class QwenAgent implements Agent { } async initialize(args: InitializeRequest): Promise { + markAcpStartup('initializeHandlerStart'); this.clientCapabilities = args.clientCapabilities; const authMethods = buildAuthMethods(); const version = process.env['CLI_VERSION'] || process.version; - return { + const response: InitializeResponse = { protocolVersion: PROTOCOL_VERSION, agentInfo: { name: 'qwen-code', @@ -3377,6 +3393,30 @@ class QwenAgent implements Agent { }, }, }; + markAcpStartup('initializeHandlerEnd'); + markAcpStartup('responseBuilt'); + let startupProfile; + try { + startupProfile = buildAndFreezeAcpStartupProfile(); + } catch { + startupProfile = undefined; + } + const requestedProfile = args._meta?.[CHANNEL_STARTUP_PROFILE_META_KEY]; + const profileRequested = + requestedProfile !== null && + typeof requestedProfile === 'object' && + !Array.isArray(requestedProfile) && + (requestedProfile as Record)['v'] === + CHANNEL_STARTUP_PROFILE_VERSION; + + return profileRequested && startupProfile + ? { + ...response, + _meta: { + [CHANNEL_STARTUP_PROFILE_META_KEY]: startupProfile, + }, + } + : response; } async authenticate({ methodId }: AuthenticateRequest): Promise { diff --git a/packages/cli/src/cli.test.ts b/packages/cli/src/cli.test.ts index d5b2a6b5339..d1b6dac2ff3 100644 --- a/packages/cli/src/cli.test.ts +++ b/packages/cli/src/cli.test.ts @@ -34,6 +34,8 @@ const mocks = vi.hoisted(() => ({ main: vi.fn(), tryRunServeFastPath: vi.fn(), initStartupProfiler: vi.fn(), + initializeAcpStartupProfiler: vi.fn(), + markAcpStartup: vi.fn(), initCpuProfiler: vi.fn(), mcpHandler: vi.fn(), mcpBuilder: vi.fn(), @@ -54,6 +56,11 @@ vi.mock('./utils/startupProfiler.js', () => ({ initStartupProfiler: mocks.initStartupProfiler, })); +vi.mock('./utils/acp-startup-profiler.js', () => ({ + initializeAcpStartupProfiler: mocks.initializeAcpStartupProfiler, + markAcpStartup: mocks.markAcpStartup, +})); + vi.mock('./utils/cpuProfiler.js', () => ({ initCpuProfiler: mocks.initCpuProfiler, })); @@ -300,6 +307,26 @@ describe('runCliEntry', () => { await runCliEntry([]); expect(mocks.main).toHaveBeenCalledTimes(1); + expect(mocks.initializeAcpStartupProfiler).not.toHaveBeenCalled(); + }); + + it('profiles the Gemini module import only on the ACP path', async () => { + await runCliEntry(['--acp']); + + expect(mocks.initializeAcpStartupProfiler).toHaveBeenCalledTimes(1); + expect(mocks.markAcpStartup.mock.calls).toEqual([ + ['geminiImportStart'], + ['geminiImportEnd'], + ]); + expect(mocks.main).toHaveBeenCalledTimes(1); + }); + + it('does not profile when ACP is explicitly disabled', async () => { + await runCliEntry(['--acp=false']); + + expect(mocks.initializeAcpStartupProfiler).not.toHaveBeenCalled(); + expect(mocks.markAcpStartup).not.toHaveBeenCalled(); + expect(mocks.main).toHaveBeenCalledTimes(1); }); }); @@ -311,6 +338,7 @@ describe('bootstrap import boundaries', () => { expect(source).not.toContain("from '@qwen-code/qwen-code-core'"); expect(source).not.toContain("import './gemini.js'"); expect(source).not.toContain("import { main } from './gemini.js'"); + expect(source).not.toContain("from './utils/acp-startup-profiler.js'"); }); it('initializes profilers during bootstrap module evaluation', () => { diff --git a/packages/cli/src/cli.ts b/packages/cli/src/cli.ts index 591b688f6b0..56592777c72 100644 --- a/packages/cli/src/cli.ts +++ b/packages/cli/src/cli.ts @@ -360,7 +360,15 @@ export async function runCliEntry( return; } + const acpStartupProfiler = rawArgv.some( + (arg) => arg === '--acp' || arg === '--experimental-acp', + ) + ? await import('./utils/acp-startup-profiler.js') + : undefined; + acpStartupProfiler?.initializeAcpStartupProfiler(); + acpStartupProfiler?.markAcpStartup('geminiImportStart'); const { main } = await import('./gemini.js'); + acpStartupProfiler?.markAcpStartup('geminiImportEnd'); await main(); } diff --git a/packages/cli/src/gemini.tsx b/packages/cli/src/gemini.tsx index 102d43d2331..dd5e9d2a9b3 100644 --- a/packages/cli/src/gemini.tsx +++ b/packages/cli/src/gemini.tsx @@ -67,6 +67,11 @@ import { finalizeStartupProfile, isStartupProfilerEnabled, } from './utils/startupProfiler.js'; +import { + isAcpStartupProfilerEnabled, + markAcpStartup, + recordAcpConfigStartupEvent, +} from './utils/acp-startup-profiler.js'; import { relaunchAppInChildProcess, relaunchOnExitCode, @@ -262,6 +267,7 @@ function installInteractiveSignalHandlers(wasRaw: boolean): () => void { export async function main() { profileCheckpoint('main_entry'); + const acpStartupProfilerEnabled = isAcpStartupProfilerEnabled(); // Bridge core-package startup events (Config.initialize, MCP discovery, // GeminiClient.setTools) into the cli's startup profiler. Gated on // `isStartupProfilerEnabled()` so that when QWEN_CODE_PROFILE_STARTUP is @@ -269,8 +275,12 @@ export async function main() { // sees a null sink and short-circuits at the first comparison, instead // of going through this arrow wrapper and the profiler's own enabled // check. - if (isStartupProfilerEnabled()) { - setStartupEventSink((name, attrs) => recordStartupEvent(name, attrs)); + const startupProfilerEnabled = isStartupProfilerEnabled(); + if (startupProfilerEnabled || acpStartupProfilerEnabled) { + setStartupEventSink((name, attrs) => { + if (startupProfilerEnabled) recordStartupEvent(name, attrs); + if (acpStartupProfilerEnabled) recordAcpConfigStartupEvent(name); + }); } setupUnhandledRejectionHandler(); initializeWarningHandler(); @@ -283,7 +293,9 @@ export async function main() { // call `process.exit` before `loadSettings()` would otherwise bootstrap. preResolveHomeEnvOverrides(); + markAcpStartup('argsParseStart'); let argv = await parseArguments(); + markAcpStartup('argsParseEnd'); profileCheckpoint('after_parse_arguments'); if ( @@ -301,9 +313,11 @@ export async function main() { } // Load user settings — bare mode uses minimal config, normal mode loads full. + markAcpStartup('settingsLoadStart'); const settings = isBareMode(argv.bare) ? createMinimalSettings() : loadSettings(); + markAcpStartup('settingsLoadEnd'); // Propagate corruption state to child process via env vars so // relaunchAppInChildProcess() doesn't lose the marker. @@ -698,6 +712,7 @@ export async function main() { : new SettingsWatcher(settings); settingsWatcher?.startWatching(); + markAcpStartup('configConstructionStart'); const config = await loadCliConfig( settings.merged, argv, @@ -712,6 +727,7 @@ export async function main() { undefined, settingsWatcher, ); + markAcpStartup('configConstructionEnd'); profileCheckpoint('after_load_cli_config'); // Subscribe the running Config to settings changes so MCP servers @@ -894,13 +910,17 @@ export async function main() { !config.getExperimentalZedIntegration() && !input && !hasRemoteInput; + markAcpStartup('appInitializationStart'); const initializationResult = await initializeApp(config, settings, { deferIdeConnection, }); + markAcpStartup('appInitializationEnd'); profileCheckpoint('after_initialize_app'); if (config.getExperimentalZedIntegration()) { + markAcpStartup('acpImportStart'); const { runAcpAgent } = await import('./acp-integration/acpAgent.js'); + markAcpStartup('acpImportEnd'); await runAcpAgent(config, settings, argv); // Clean up child processes and force exit, matching other non-interactive modes await runExitCleanup(); diff --git a/packages/cli/src/utils/acp-startup-profiler.test.ts b/packages/cli/src/utils/acp-startup-profiler.test.ts new file mode 100644 index 00000000000..9bb14dafdac --- /dev/null +++ b/packages/cli/src/utils/acp-startup-profiler.test.ts @@ -0,0 +1,144 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { performance } from 'node:perf_hooks'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { + beginAcpBootstrapConfigProfiling, + buildAndFreezeAcpStartupProfile, + endAcpBootstrapConfigProfiling, + initializeAcpStartupProfiler, + isAcpStartupProfilerEnabled, + markAcpStartup, + recordAcpConfigStartupEvent, + resetAcpStartupProfilerForTesting, +} from './acp-startup-profiler.js'; + +const CONFIG_EVENTS = [ + 'config_initialize_extensions_initial_start', + 'config_initialize_extensions_initial_end', + 'config_initialize_hooks_start', + 'config_initialize_hooks_end', + 'config_initialize_skills_start', + 'config_initialize_skills_end', + 'config_initialize_extensions_final_start', + 'config_initialize_extensions_final_end', + 'config_initialize_hierarchical_memory_start', + 'config_initialize_hierarchical_memory_end', + 'config_initialize_tool_registry_start', + 'config_initialize_ripgrep_probe_start', + 'config_initialize_ripgrep_probe_end', + 'config_initialize_tool_registry_end', + 'config_initialize_tool_warmup_start', + 'config_initialize_tool_warmup_end', +] as const; + +function recordCompleteProfile(): void { + markAcpStartup('geminiImportStart'); + markAcpStartup('geminiImportEnd'); + markAcpStartup('argsParseStart'); + markAcpStartup('argsParseEnd'); + markAcpStartup('settingsLoadStart'); + markAcpStartup('settingsLoadEnd'); + markAcpStartup('configConstructionStart'); + markAcpStartup('configConstructionEnd'); + markAcpStartup('appInitializationStart'); + markAcpStartup('appInitializationEnd'); + markAcpStartup('acpImportStart'); + markAcpStartup('acpImportEnd'); + beginAcpBootstrapConfigProfiling(); + for (const event of CONFIG_EVENTS) recordAcpConfigStartupEvent(event); + endAcpBootstrapConfigProfiling(); + markAcpStartup('transportSetupStart'); + markAcpStartup('transportSetupEnd'); + markAcpStartup('initializeHandlerStart'); + markAcpStartup('initializeHandlerEnd'); + markAcpStartup('responseBuilt'); +} + +describe('ACP startup profiler', () => { + beforeEach(() => { + resetAcpStartupProfilerForTesting(); + let now = 0; + vi.spyOn(performance, 'now').mockImplementation(() => { + now += 10; + return now; + }); + }); + + afterEach(() => { + resetAcpStartupProfilerForTesting(); + vi.restoreAllMocks(); + }); + + it('is disabled until the ACP route initializes it', () => { + markAcpStartup('argsParseStart'); + + expect(isAcpStartupProfilerEnabled()).toBe(false); + expect(buildAndFreezeAcpStartupProfile()).toBeUndefined(); + }); + + it('builds a complete bounded profile with nested Config phases', () => { + initializeAcpStartupProfiler(); + recordCompleteProfile(); + + const profile = buildAndFreezeAcpStartupProfile(); + + expect(profile).toMatchObject({ + v: 1, + complete: true, + phases: { + processToProfilerReadyMs: 10, + geminiImportMs: 10, + bootstrapConfigInitializationMs: 170, + transportSetupMs: 10, + initializeHandlerMs: 10, + }, + config: { + extensionsInitialMs: 10, + hooksMs: 10, + skillsMs: 10, + extensionsFinalMs: 10, + hierarchicalMemoryMs: 10, + toolRegistryMs: 30, + ripgrepProbeMs: 10, + toolWarmupMs: 10, + }, + }); + expect(profile!.config.otherMs).toBeGreaterThanOrEqual(0); + expect(profile!.phases.unattributedMs).toBeGreaterThanOrEqual(0); + expect(JSON.stringify(profile).length).toBeLessThan(2048); + }); + + it('keeps the first mark and ignores marks after freezing', () => { + initializeAcpStartupProfiler(); + markAcpStartup('geminiImportStart'); + markAcpStartup('geminiImportStart'); + markAcpStartup('geminiImportEnd'); + markAcpStartup('responseBuilt'); + + const before = buildAndFreezeAcpStartupProfile(); + markAcpStartup('argsParseStart'); + markAcpStartup('argsParseEnd'); + const after = buildAndFreezeAcpStartupProfile(); + + expect(before!.phases.geminiImportMs).toBe(10); + expect(after).toEqual(before); + expect(after!.phases.argsParseMs).toBeUndefined(); + }); + + it('ignores Config events outside the bootstrap window', () => { + initializeAcpStartupProfiler(); + recordAcpConfigStartupEvent('config_initialize_extensions_initial_start'); + recordAcpConfigStartupEvent('config_initialize_extensions_initial_end'); + markAcpStartup('responseBuilt'); + + const profile = buildAndFreezeAcpStartupProfile(); + + expect(profile!.complete).toBe(false); + expect(profile!.config.extensionsInitialMs).toBeUndefined(); + }); +}); diff --git a/packages/cli/src/utils/acp-startup-profiler.ts b/packages/cli/src/utils/acp-startup-profiler.ts new file mode 100644 index 00000000000..c2bf0412505 --- /dev/null +++ b/packages/cli/src/utils/acp-startup-profiler.ts @@ -0,0 +1,253 @@ +/** + * @license + * Copyright 2026 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { performance } from 'node:perf_hooks'; +import { + CHANNEL_STARTUP_PROFILE_VERSION, + type ChannelStartupProfileV1, +} from '@qwen-code/acp-bridge/bridgeTypes'; + +export type AcpStartupMark = + | 'profilerReady' + | 'geminiImportStart' + | 'geminiImportEnd' + | 'argsParseStart' + | 'argsParseEnd' + | 'settingsLoadStart' + | 'settingsLoadEnd' + | 'configConstructionStart' + | 'configConstructionEnd' + | 'appInitializationStart' + | 'appInitializationEnd' + | 'acpImportStart' + | 'acpImportEnd' + | 'bootstrapConfigInitializationStart' + | 'bootstrapConfigInitializationEnd' + | 'transportSetupStart' + | 'transportSetupEnd' + | 'initializeHandlerStart' + | 'initializeHandlerEnd' + | 'responseBuilt' + | 'extensionsInitialStart' + | 'extensionsInitialEnd' + | 'hooksStart' + | 'hooksEnd' + | 'skillsStart' + | 'skillsEnd' + | 'extensionsFinalStart' + | 'extensionsFinalEnd' + | 'hierarchicalMemoryStart' + | 'hierarchicalMemoryEnd' + | 'toolRegistryStart' + | 'toolRegistryEnd' + | 'ripgrepProbeStart' + | 'ripgrepProbeEnd' + | 'toolWarmupStart' + | 'toolWarmupEnd'; + +const CONFIG_EVENT_MARKS = { + config_initialize_extensions_initial_start: 'extensionsInitialStart', + config_initialize_extensions_initial_end: 'extensionsInitialEnd', + config_initialize_hooks_start: 'hooksStart', + config_initialize_hooks_end: 'hooksEnd', + config_initialize_skills_start: 'skillsStart', + config_initialize_skills_end: 'skillsEnd', + config_initialize_extensions_final_start: 'extensionsFinalStart', + config_initialize_extensions_final_end: 'extensionsFinalEnd', + config_initialize_hierarchical_memory_start: 'hierarchicalMemoryStart', + config_initialize_hierarchical_memory_end: 'hierarchicalMemoryEnd', + config_initialize_tool_registry_start: 'toolRegistryStart', + config_initialize_tool_registry_end: 'toolRegistryEnd', + config_initialize_ripgrep_probe_start: 'ripgrepProbeStart', + config_initialize_ripgrep_probe_end: 'ripgrepProbeEnd', + config_initialize_tool_warmup_start: 'toolWarmupStart', + config_initialize_tool_warmup_end: 'toolWarmupEnd', +} as const satisfies Record; + +let enabled = false; +let frozen = false; +let bootstrapConfigActive = false; +let marks: Partial> = {}; + +function roundMs(value: number): number { + return Math.round(value * 100) / 100; +} + +function duration( + start: AcpStartupMark, + end: AcpStartupMark, +): number | undefined { + const startMs = marks[start]; + const endMs = marks[end]; + return startMs === undefined || endMs === undefined || endMs < startMs + ? undefined + : roundMs(endMs - startMs); +} + +function sumDurations( + values: ReadonlyArray, +): number | undefined { + return values.every((value): value is number => value !== undefined) + ? values.reduce((sum, value) => sum + value, 0) + : undefined; +} + +export function initializeAcpStartupProfiler(): void { + if (enabled) return; + enabled = true; + frozen = false; + bootstrapConfigActive = false; + marks = { profilerReady: performance.now() }; +} + +export function isAcpStartupProfilerEnabled(): boolean { + return enabled; +} + +export function markAcpStartup(mark: AcpStartupMark): void { + if (!enabled || frozen || marks[mark] !== undefined) return; + marks[mark] = performance.now(); +} + +export function beginAcpBootstrapConfigProfiling(): void { + if (!enabled || frozen) return; + bootstrapConfigActive = true; + markAcpStartup('bootstrapConfigInitializationStart'); +} + +export function endAcpBootstrapConfigProfiling(): void { + if (!enabled || frozen) return; + markAcpStartup('bootstrapConfigInitializationEnd'); + bootstrapConfigActive = false; +} + +export function recordAcpConfigStartupEvent(name: string): void { + if (!enabled || frozen || !bootstrapConfigActive) return; + const mark = CONFIG_EVENT_MARKS[name as keyof typeof CONFIG_EVENT_MARKS]; + if (mark) markAcpStartup(mark); +} + +export function buildAndFreezeAcpStartupProfile(): + | ChannelStartupProfileV1 + | undefined { + if (!enabled) return undefined; + + const phases: ChannelStartupProfileV1['phases'] = { + processToProfilerReadyMs: + marks.profilerReady === undefined + ? undefined + : roundMs(marks.profilerReady), + geminiImportMs: duration('geminiImportStart', 'geminiImportEnd'), + argsParseMs: duration('argsParseStart', 'argsParseEnd'), + settingsLoadMs: duration('settingsLoadStart', 'settingsLoadEnd'), + configConstructionMs: duration( + 'configConstructionStart', + 'configConstructionEnd', + ), + appInitializationMs: duration( + 'appInitializationStart', + 'appInitializationEnd', + ), + acpImportMs: duration('acpImportStart', 'acpImportEnd'), + bootstrapConfigInitializationMs: duration( + 'bootstrapConfigInitializationStart', + 'bootstrapConfigInitializationEnd', + ), + transportSetupMs: duration('transportSetupStart', 'transportSetupEnd'), + initializeHandlerMs: duration( + 'initializeHandlerStart', + 'initializeHandlerEnd', + ), + }; + + const config: ChannelStartupProfileV1['config'] = { + extensionsInitialMs: duration( + 'extensionsInitialStart', + 'extensionsInitialEnd', + ), + hooksMs: duration('hooksStart', 'hooksEnd'), + skillsMs: duration('skillsStart', 'skillsEnd'), + extensionsFinalMs: duration('extensionsFinalStart', 'extensionsFinalEnd'), + hierarchicalMemoryMs: duration( + 'hierarchicalMemoryStart', + 'hierarchicalMemoryEnd', + ), + toolRegistryMs: duration('toolRegistryStart', 'toolRegistryEnd'), + ripgrepProbeMs: duration('ripgrepProbeStart', 'ripgrepProbeEnd'), + toolWarmupMs: duration('toolWarmupStart', 'toolWarmupEnd'), + }; + + const processToResponseMs = + marks.responseBuilt === undefined + ? undefined + : roundMs(marks.responseBuilt); + const topLevelSum = sumDurations([ + phases.processToProfilerReadyMs, + phases.geminiImportMs, + phases.argsParseMs, + phases.settingsLoadMs, + phases.configConstructionMs, + phases.appInitializationMs, + phases.acpImportMs, + phases.bootstrapConfigInitializationMs, + phases.transportSetupMs, + phases.initializeHandlerMs, + ]); + if (processToResponseMs !== undefined && topLevelSum !== undefined) { + phases.unattributedMs = roundMs( + Math.max(0, processToResponseMs - topLevelSum), + ); + } + + const configSum = sumDurations([ + config.extensionsInitialMs, + config.hooksMs, + config.skillsMs, + config.extensionsFinalMs, + config.hierarchicalMemoryMs, + config.toolRegistryMs, + config.toolWarmupMs, + ]); + if ( + phases.bootstrapConfigInitializationMs !== undefined && + configSum !== undefined + ) { + config.otherMs = roundMs( + Math.max(0, phases.bootstrapConfigInitializationMs - configSum), + ); + } + + const complete = + processToResponseMs !== undefined && + marks.responseBuilt !== undefined && + Object.values(phases).every((value) => value !== undefined) && + Object.values(config).every((value) => value !== undefined); + const profile: ChannelStartupProfileV1 = { + v: CHANNEL_STARTUP_PROFILE_VERSION, + complete, + phases, + config, + ...(processToResponseMs === undefined ? {} : { processToResponseMs }), + ...(marks.responseBuilt === undefined + ? {} + : { + responseBuiltAtEpochMs: roundMs( + performance.timeOrigin + marks.responseBuilt, + ), + }), + }; + + frozen = true; + bootstrapConfigActive = false; + return profile; +} + +export function resetAcpStartupProfilerForTesting(): void { + enabled = false; + frozen = false; + bootstrapConfigActive = false; + marks = {}; +} diff --git a/packages/core/src/config/config.safe-mode.test.ts b/packages/core/src/config/config.safe-mode.test.ts index 844685d4137..2992bcdbd71 100644 --- a/packages/core/src/config/config.safe-mode.test.ts +++ b/packages/core/src/config/config.safe-mode.test.ts @@ -9,6 +9,7 @@ import type { Mock } from 'vitest'; import type { ConfigParameters } from './config.js'; import { Config } from './config.js'; import * as fs from 'node:fs'; +import { recordStartupEvent } from '../utils/startupEventSink.js'; vi.mock('node:fs', async (importOriginal) => { const actual = await importOriginal(); @@ -309,5 +310,34 @@ describe('Config safe mode', () => { expect(config.getUserMemory()).toBe(''); expect(config.getGeminiMdFileCount()).toBe(0); }); + + it('records every fixed Config startup phase in order when skipped', async () => { + const config = new Config({ ...baseParams, safeMode: true }); + + await config.initialize(); + + const events = vi + .mocked(recordStartupEvent) + .mock.calls.map(([name]) => name) + .filter((name) => name.startsWith('config_initialize_')); + expect(events).toEqual([ + 'config_initialize_extensions_initial_start', + 'config_initialize_extensions_initial_end', + 'config_initialize_hooks_start', + 'config_initialize_hooks_end', + 'config_initialize_skills_start', + 'config_initialize_skills_end', + 'config_initialize_extensions_final_start', + 'config_initialize_extensions_final_end', + 'config_initialize_hierarchical_memory_start', + 'config_initialize_hierarchical_memory_end', + 'config_initialize_tool_registry_start', + 'config_initialize_ripgrep_probe_start', + 'config_initialize_ripgrep_probe_end', + 'config_initialize_tool_registry_end', + 'config_initialize_tool_warmup_start', + 'config_initialize_tool_warmup_end', + ]); + }); }); }); diff --git a/packages/core/src/config/config.ts b/packages/core/src/config/config.ts index 68717ab1219..2e83c1f9a88 100644 --- a/packages/core/src/config/config.ts +++ b/packages/core/src/config/config.ts @@ -2285,6 +2285,7 @@ export class Config { : (this.overrideExtensions ?? []).filter( (n) => n.trim() !== '' && n.toLowerCase() !== 'none', ); + recordStartupEvent('config_initialize_extensions_initial_start'); if (!this.isSafeMode() && !this.getBareMode()) { await this.extensionManager.refreshCache(); } else if (!this.isSafeMode() && explicitExtensionNames.length > 0) { @@ -2292,9 +2293,11 @@ export class Config { names: explicitExtensionNames, }); } + recordStartupEvent('config_initialize_extensions_initial_end'); this.debugLogger.debug('Extension manager initialized'); // Bare mode and read-only replay helpers skip all hook loading and execution. + recordStartupEvent('config_initialize_hooks_start'); if (!options?.skipHooks && !this.getDisableAllHooks()) { this.hookSystem = new HookSystem(this); await this.hookSystem.initialize(); @@ -2512,8 +2515,10 @@ export class Config { } else { this.debugLogger.debug('Hook system disabled, skipping initialization'); } + recordStartupEvent('config_initialize_hooks_end'); this.subagentManager = new SubagentManager(this); + recordStartupEvent('config_initialize_skills_start'); if (!options?.skipSkillManager) { this.skillManager = new SkillManager(this); if (this.getBareMode() || this.isSafeMode()) { @@ -2526,6 +2531,7 @@ export class Config { this.skillManager = null; this.debugLogger.debug('Skill manager skipped'); } + recordStartupEvent('config_initialize_skills_end'); this.memoryPressureConfig = loadMemoryPressureConfig(); this.memoryPressureMonitor = new MemoryPressureMonitor( @@ -2542,11 +2548,15 @@ export class Config { this.subagentManager.loadSessionSubagents(this.sessionSubagents); } + recordStartupEvent('config_initialize_extensions_final_start'); if (!this.getBareMode() && !this.isSafeMode()) { await this.extensionManager.refreshCache(); } + recordStartupEvent('config_initialize_extensions_final_end'); + recordStartupEvent('config_initialize_hierarchical_memory_start'); await this.refreshHierarchicalMemory('session_start'); + recordStartupEvent('config_initialize_hierarchical_memory_end'); this.debugLogger.debug('Hierarchical memory loaded'); // Progressive MCP availability: skip MCP discovery in the synchronous @@ -2568,10 +2578,12 @@ export class Config { !legacyBlockingMcp || options?.skipMcpDiscovery === true; + recordStartupEvent('config_initialize_tool_registry_start'); this.toolRegistry = await this.createToolRegistry( options?.sendSdkMcpMessage, skipInlineMcpDiscovery ? { skipDiscovery: true } : undefined, ); + recordStartupEvent('config_initialize_tool_registry_end'); recordStartupEvent('tool_registry_created', { toolCount: this.toolRegistry.getAllToolNames().length, mcpInline: !skipInlineMcpDiscovery, @@ -2595,9 +2607,11 @@ export class Config { // read-only replay Configs pass `lenientToolWarmup` so a tool that cannot be // constructed under their deliberately-skipped subsystems (e.g. SkillTool without // a SkillManager) is logged and skipped instead of aborting initialize(). + recordStartupEvent('config_initialize_tool_warmup_start'); await this.toolRegistry.warmAll({ strict: options?.lenientToolWarmup !== true, }); + recordStartupEvent('config_initialize_tool_warmup_end'); // Fire-and-forget MCP discovery. Each server's tools land in the // registry as it becomes ready; the cli's AppContainer debounces @@ -6541,11 +6555,13 @@ export class Config { if (this.getUseRipgrep()) { let useRipgrep = false; let errorString: undefined | string = undefined; + recordStartupEvent('config_initialize_ripgrep_probe_start'); try { useRipgrep = await canUseRipgrep(this.getUseBuiltinRipgrep()); } catch (error: unknown) { errorString = getErrorMessage(error); } + recordStartupEvent('config_initialize_ripgrep_probe_end'); if (useRipgrep) { await registerLazy(ToolNames.GREP, async () => { const { RipGrepTool } = await import('../tools/ripGrep.js'); @@ -6566,6 +6582,8 @@ export class Config { }); } } else { + recordStartupEvent('config_initialize_ripgrep_probe_start'); + recordStartupEvent('config_initialize_ripgrep_probe_end'); await registerLazy(ToolNames.GREP, async () => { const { GrepTool } = await import('../tools/grep.js'); return new GrepTool(this); diff --git a/packages/core/src/telemetry/daemon-tracing.test.ts b/packages/core/src/telemetry/daemon-tracing.test.ts index 79bf455c872..01c5fd709b6 100644 --- a/packages/core/src/telemetry/daemon-tracing.test.ts +++ b/packages/core/src/telemetry/daemon-tracing.test.ts @@ -341,4 +341,19 @@ describe('daemon-tracing', () => { addDaemonRequestAttribute('qwen-code.prompt_id', 'orphan'), ).not.toThrow(); }); + + it('bridge telemetry sets attributes on the active span', () => { + const setAttributes = vi.fn(); + vi.spyOn(trace, 'getSpan').mockReturnValue({ + setAttributes, + } as unknown as Span); + + createDaemonBridgeTelemetry().setActiveSpanAttributes?.({ + 'qwen-code.daemon.acp_startup.profile.version': 1, + }); + + expect(setAttributes).toHaveBeenCalledWith({ + 'qwen-code.daemon.acp_startup.profile.version': 1, + }); + }); }); diff --git a/packages/core/src/telemetry/daemon-tracing.ts b/packages/core/src/telemetry/daemon-tracing.ts index c4f53605deb..c571e735c17 100644 --- a/packages/core/src/telemetry/daemon-tracing.ts +++ b/packages/core/src/telemetry/daemon-tracing.ts @@ -362,6 +362,7 @@ export function createDaemonBridgeTelemetry(): { attributes: DaemonAttributes, fn: () => Promise, ): Promise; + setActiveSpanAttributes?(attributes: DaemonAttributes): void; event(name: string, attributes: DaemonAttributes): void; injectPromptContext(request: T): T; metrics?: DaemonBridgeTelemetryMetrics; @@ -370,6 +371,14 @@ export function createDaemonBridgeTelemetry(): { captureContext: captureDaemonTelemetryContext, runWithContext: runWithDaemonTelemetryContext, withSpan: withDaemonBridgeSpan, + setActiveSpanAttributes(attributes) { + if (!isTelemetrySdkInitialized()) return; + try { + trace.getSpan(otelContext.active())?.setAttributes(attributes); + } catch { + // Telemetry must not affect bridge behavior. + } + }, event(name, attributes) { if (!isTelemetrySdkInitialized()) return; try { diff --git a/scripts/check-serve-fast-path-bundle.js b/scripts/check-serve-fast-path-bundle.js index b39fad2932b..949a488ea4a 100644 --- a/scripts/check-serve-fast-path-bundle.js +++ b/scripts/check-serve-fast-path-bundle.js @@ -37,6 +37,27 @@ const SERVE_PRE_LISTEN_ROOTS = [ ]; const FORBIDDEN_SOURCE_INPUTS = [ + { + label: 'Gemini runtime', + suffixes: [ + 'packages/cli/src/gemini.tsx', + 'packages/cli/dist/src/gemini.js', + ], + }, + { + label: 'ACP agent runtime', + suffixes: [ + 'packages/cli/src/acp-integration/acpAgent.ts', + 'packages/cli/dist/src/acp-integration/acpAgent.js', + ], + }, + { + label: 'ACP startup profiler', + suffixes: [ + 'packages/cli/src/utils/acp-startup-profiler.ts', + 'packages/cli/dist/src/utils/acp-startup-profiler.js', + ], + }, { label: 'Serve ACP compatibility shim', suffixes: [ diff --git a/scripts/tests/serve-fast-path-bundle-check.test.js b/scripts/tests/serve-fast-path-bundle-check.test.js index 715c4e95d79..2d18b423e27 100644 --- a/scripts/tests/serve-fast-path-bundle-check.test.js +++ b/scripts/tests/serve-fast-path-bundle-check.test.js @@ -100,6 +100,40 @@ describe('serve fast-path bundle check', () => { ); }); + it('keeps the ACP startup profiler out of the pre-listen closure', () => { + const metafile = makeMetafile({ + 'dist/chunks/run-qwen-serve.js': output({ + inputs: [ + 'packages/cli/src/serve/run-qwen-serve.ts', + 'packages/cli/src/utils/acp-startup-profiler.ts', + ], + }), + }); + + expect(findServeFastPathBundleOffenders(metafile)).toEqual([ + expect.objectContaining({ label: 'ACP startup profiler' }), + ]); + }); + + it('keeps the Gemini and ACP runtimes out of the pre-listen closure', () => { + const metafile = makeMetafile({ + 'dist/chunks/run-qwen-serve.js': output({ + inputs: [ + 'packages/cli/src/serve/run-qwen-serve.ts', + 'packages/cli/src/gemini.tsx', + 'packages/cli/src/acp-integration/acpAgent.ts', + ], + }), + }); + + expect(findServeFastPathBundleOffenders(metafile)).toEqual( + expect.arrayContaining([ + expect.objectContaining({ label: 'Gemini runtime' }), + expect.objectContaining({ label: 'ACP agent runtime' }), + ]), + ); + }); + it('reports forbidden built package files reached through static imports', () => { const metafile = makeMetafile({ 'dist/chunks/run-qwen-serve.js': output({ From b3db6d8ad33811c4c5faff49be890b11b7dd098b Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Sat, 18 Jul 2026 11:35:25 +0800 Subject: [PATCH 2/2] codex: address PR review feedback (#7145) Co-authored-by: Qwen-Coder --- docs/design/acp-channel-initialize-profiling.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/docs/design/acp-channel-initialize-profiling.md b/docs/design/acp-channel-initialize-profiling.md index f30d1af22f5..4c7bb7652fc 100644 --- a/docs/design/acp-channel-initialize-profiling.md +++ b/docs/design/acp-channel-initialize-profiling.md @@ -51,6 +51,8 @@ Bootstrap Config initialization is split into initial extension refresh, hooks, skills, final extension refresh, hierarchical memory, tool registry, tool warmup, and residual time. The ripgrep probe is reported as a child of tool registry time and is not subtracted again when calculating residual time. +Top-level unattributed time also includes the wait between transport setup and +the initialize request reaching the child handler. All durations use `performance.now()` and are rounded to two decimal places. The response-build epoch uses `performance.timeOrigin` plus the response mark