Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
104 changes: 104 additions & 0 deletions docs/design/acp-channel-initialize-profiling.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,104 @@
# 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.
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
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.
71 changes: 70 additions & 1 deletion packages/acp-bridge/src/bridge.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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<string, Record<string, unknown>>();
const eventAttributes = new Map<string, Record<string, unknown>>();
const activeSpanAttributes: Array<Record<string, unknown>> = [];
const telemetry: BridgeTelemetry = {
captureContext: () => {
events.push('capture');
Expand All @@ -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);
Expand Down Expand Up @@ -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',
Expand Down Expand Up @@ -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<void>();
Expand Down
28 changes: 25 additions & 3 deletions packages/acp-bridge/src/bridge.ts
Original file line number Diff line number Diff line change
Expand Up @@ -85,13 +85,16 @@ 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,
LOAD_REPLAY_PAGE_SIZE_META_KEY,
LOAD_REPLAY_VERSION,
TODO_STOP_GUARD_QUEUE_RELEASE_METHOD,
} from './bridgeTypes.js';
import { getChannelStartupProfileAttributes } from './channel-startup-profile.js';
import type {
BridgeSession,
BridgeRestoreSessionRequest,
Expand Down Expand Up @@ -2132,18 +2135,37 @@ 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 },
},
clientInfo: { name: 'qwen-serve-bridge', version: '0' },
}),
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
Expand Down
1 change: 1 addition & 0 deletions packages/acp-bridge/src/bridgeOptions.ts
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,7 @@ export interface BridgeTelemetry {
attributes: BridgeTelemetryAttributes,
fn: () => Promise<T>,
): Promise<T>;
setActiveSpanAttributes?(attributes: BridgeTelemetryAttributes): void;
event(name: string, attributes: BridgeTelemetryAttributes): void;
injectPromptContext<T extends object>(request: T): T;
metrics?: BridgeTelemetryMetrics;
Expand Down
35 changes: 35 additions & 0 deletions packages/acp-bridge/src/bridgeTypes.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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[];
Expand Down
Loading
Loading