From 3a554f425302b9c331d9252950027696c2a8ca5f Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 14:09:24 -0700 Subject: [PATCH 1/6] agentHost: measure provider send blocking and surface MCP launch projection --- .../node/agentHostTelemetryReporter.ts | 58 ++++++++++++ .../node/copilot/copilotAgentSession.ts | 43 +++++++++ .../node/copilot/copilotMcpReadiness.ts | 89 +++++++++++++++++++ .../node/copilot/copilotSessionLauncher.ts | 22 +++-- .../test/node/copilotAgentSession.test.ts | 2 +- .../test/node/copilotMcpReadiness.test.ts | 67 ++++++++++++++ .../test/node/copilotSessionLauncher.test.ts | 7 +- 7 files changed, 274 insertions(+), 14 deletions(-) create mode 100644 src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts create mode 100644 src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index 7f6a00850363f..9724c0669c31e 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -197,6 +197,43 @@ export interface IAgentHostClientConnectionReport { subscriptionCount?: number; } +export interface IAgentHostProviderSendBlockedEvent { + provider: string; + agentSessionId: string; + sendBlockedMs: number; + isFirstSendOfSession: boolean; + sendFailed: boolean; + mcpServerCount: number; + mcpReadyCount: number; + mcpFailedCount: number; + mcpUnresolvedCount: number; + slowestMcpServerMs: number | undefined; +} + +/** Provider-agnostic MCP startup context, satisfied structurally by each provider's tracker. */ +export interface IAgentHostMcpReadinessReport { + readonly serverCount: number; + readonly readyCount: number; + readonly failedCount: number; + readonly unresolvedCount: number; + readonly slowestServerMs: number | undefined; +} + +export type IAgentHostProviderSendBlockedClassification = { + provider: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The provider handling the agent host session.' }; + agentSessionId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The agent host session identifier.' }; + sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider send call blocked before returning. This precedes turn start, so it is not covered by turn timings.' }; + isFirstSendOfSession: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether this was the first send on a newly created provider session, where startup costs are paid.' }; + sendFailed: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether the provider send call threw instead of returning normally.' }; + mcpServerCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers observed for the session when the send returned.' }; + mcpReadyCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had connected when the send returned.' }; + mcpFailedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had failed when the send returned.' }; + mcpUnresolvedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers still starting or awaiting authentication when the send returned.' }; + slowestMcpServerMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Milliseconds from the first observed MCP server to the last one to settle; absent when none had settled.' }; + owner: 'vijayupadya'; + comment: 'Measures how long the provider send call blocks before a turn can start, with the MCP server startup context it overlaps.'; +}; + export type AgentHostTurnResult = 'success' | 'error' | 'cancelled'; export type AgentHostModelTelemetryKind = 'trusted' | 'byok' | 'unknown'; type AgentHostModelSelectionKind = 'default' | 'auto' | 'explicit'; @@ -1018,6 +1055,27 @@ export class AgentHostTelemetryReporter { }); } + /** + * Reports how long a provider send call blocked before returning. This + * window sits before turn start, so it is invisible to turn telemetry even + * though the user is already waiting. MCP counts describe the server + * startup this window overlaps, which is the usual reason it is long. + */ + providerSendBlocked(provider: string, session: string, sendBlockedMs: number, isFirstSendOfSession: boolean, sendFailed: boolean, mcp: IAgentHostMcpReadinessReport): void { + this._telemetryService.publicLog2('agentHost.providerSendBlocked', { + provider, + agentSessionId: AgentSession.id(session), + sendBlockedMs, + isFirstSendOfSession, + sendFailed, + mcpServerCount: mcp.serverCount, + mcpReadyCount: mcp.readyCount, + mcpFailedCount: mcp.failedCount, + mcpUnresolvedCount: mcp.unresolvedCount, + slowestMcpServerMs: mcp.slowestServerMs, + }); + } + /** * Mirrors the Copilot extension's enhanced GH `request.options.tools` event for the agent-host * flow. The extension emits it per LLM request from its model fetcher; the agent host observes diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 03f3625620f9e..43a03e15d2663 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -64,6 +64,7 @@ import { ActionType, isChatAction, type ChatAction, type SessionAction } from '. import { MessageKind, ResponsePartKind, ChatInputAnswerState, ChatInputAnswerValueKind, ChatInputQuestionKind, ChatInputResponseKind, ToolCallConfirmationReason, ToolCallRiskAssessmentKind, ToolCallRiskAssessmentStatus, ToolCallStatus, ToolResultContentType, buildSubagentSessionUri, createErrorResponsePart, isSubagentSession, parseRequiredSessionUriFromChatUri, type Customization, type Message, type PendingMessage, type ChatInputAnswer, type ChatInputOption, type ChatInputQuestion, type ChatInputRequest, type ToolCallResult, type ToolResultContent, type ToolResultTerminalContent, type Turn, type ITurnTokenTotal, type UsageInfo, type UsageInfoMeta, type IContextAttributionData, type ISessionPromptCacheState } from '../../common/state/sessionState.js'; import { IAgentConfigurationService } from '../agentConfigurationService.js'; import { CopilotSessionWrapper, type ICopilotModelCallFinishedEvent } from './copilotSessionWrapper.js'; +import { CopilotMcpReadinessTracker } from './copilotMcpReadiness.js'; import { getCopilotSdkToolResourceUri } from './copilotSdkMeta.js'; import { isAutoModel } from './modelIdentifiers.js'; import { applySandboxConfig, clientToolNamesFromSnapshot, isMcpServerExplicitlyProjected, type CopilotSessionLaunchPlan, type IActiveClientSnapshot, type ICopilotSessionLauncher, type ICopilotSessionRuntime } from './copilotSessionLauncher.js'; @@ -1190,6 +1191,15 @@ export class CopilotAgentSession extends Disposable { */ private readonly _lastLoggedMcpStatus = new Map(); + /** + * Tracks MCP server startup timing for this session so a blocked provider + * send can be attributed to the servers it waited on. + */ + private readonly _mcpReadiness = new CopilotMcpReadinessTracker(); + + /** Cleared after the first provider send, which is the one that pays session startup costs. */ + private _pendingFirstSend = true; + /** Platform used to compute the SDK sandbox policy (injectable for tests). */ private readonly _platform: NodeJS.Platform; private readonly _realpath: (path: string) => Promise; @@ -3057,6 +3067,10 @@ export class CopilotAgentSession extends Disposable { const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); const sendingTurn = this._currentTurn.value; sendingTurn?.markProviderCallPending(); + const isFirstSendOfSession = this._pendingFirstSend; + this._pendingFirstSend = false; + const sendWatch = StopWatch.create(false); + let sendFailed = false; try { await this._otelService.withTraceContext(traceContext, () => { if (!this._environmentService.isBuilt && prompt === '$error') { @@ -3069,8 +3083,33 @@ export class CopilotAgentSession extends Disposable { }); sendingTurn?.markProviderCallResolved(); } catch (error) { + sendFailed = true; sendingTurn?.markProviderCallRejected(); throw error; + } finally { + // Measured around `session.send()` alone: the provider holds this call + // until session startup (notably MCP server readiness) settles, and the + // user is already waiting with nothing on screen. It ends before the + // turn begins, so no turn telemetry covers it. + // + // Guarded because this runs in a `finally`: a throw from reporting here + // would replace the provider error the `catch` above is rethrowing, + // turning a real send failure into a telemetry failure. + try { + const sendBlockedMs = Math.round(sendWatch.elapsed()); + const mcp = this._mcpReadiness.snapshot(); + this._telemetryReporter.providerSendBlocked( + this.resourceUri.scheme, + this.resourceUri.toString(), + sendBlockedMs, + isFirstSendOfSession, + sendFailed, + mcp, + ); + this._logService.info(`[Copilot:${this.sessionId}] session.send() blocked for ${sendBlockedMs}ms (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); + } catch (err) { + this._logService.trace(`[Copilot:${this.sessionId}] Telemetry emission failed: ${getErrorMessage(err)}`); + } } this._logService.info(`[Copilot:${this.sessionId}] session.send() returned`); } @@ -6336,6 +6375,7 @@ export class CopilotAgentSession extends Disposable { })); this._register(wrapper.onMcpServerStatusChanged(e => { this._logMcpServerLifecycle({ name: e.data.serverName, status: e.data.status, error: e.data.error, origin: 'statusChanged' }); + this._mcpReadiness.observe(e.data.serverName, e.data.status); const server = this._toSdkMcpServer(e.data.serverName, e.data.status, e.data.error); if (!server) { this._mcpCustomizations.remove(e.data.serverName); @@ -6392,6 +6432,9 @@ export class CopilotAgentSession extends Disposable { } private _applyMcpServerList(servers: readonly { readonly name: string; readonly status: SdkMcpServerStatus; readonly error?: string }[]): void { + for (const server of servers) { + this._mcpReadiness.observe(server.name, server.status); + } const sdkServers = servers .map(s => this._toSdkMcpServer(s.name, s.status, s.error)); this._mcpCustomizations.applyAll(sdkServers); diff --git a/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts new file mode 100644 index 0000000000000..7b16be8a742b5 --- /dev/null +++ b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts @@ -0,0 +1,89 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import { StopWatch } from '../../../../base/common/stopwatch.js'; +import type { McpServerStatus as SdkMcpServerStatus } from '@github/copilot-sdk'; + +/** + * SDK statuses that mean the server has finished starting, whether or not it + * became usable. `pending` and `needs-auth` are excluded because the server is + * still resolving; everything else is a settled outcome. + */ +function isTerminalStatus(status: SdkMcpServerStatus): boolean { + return status !== 'pending' && status !== 'needs-auth'; +} + +export interface IMcpReadinessSnapshot { + /** Servers observed in any state. */ + readonly serverCount: number; + /** Servers that reached `connected`. */ + readonly readyCount: number; + /** Servers that reached `failed`. */ + readonly failedCount: number; + /** Servers still in `pending` or `needs-auth` when the snapshot was taken. */ + readonly unresolvedCount: number; + /** + * Milliseconds from the first observed server to the last one to settle, + * or `undefined` when nothing has settled yet. Startup is parallel, so this + * is the cost of the slowest server rather than the sum. + */ + readonly slowestServerMs: number | undefined; +} + +/** + * Tracks MCP server startup timing for a single Copilot SDK session. + * + * Servers start in parallel, so the wall-clock cost of MCP startup is set by + * the slowest server. This records when the first server was seen and when the + * last one settled, which is the window a blocked first turn overlaps with. + * + * Only forward progress is recorded: a server that settles and is later + * re-reported keeps its original settle time, so repeated inventory snapshots + * do not inflate the measurement. + */ +export class CopilotMcpReadinessTracker { + + private readonly _statuses = new Map(); + private readonly _settledAtMs = new Map(); + private _firstObservedMs: number | undefined; + + constructor(private readonly _clock: Pick = StopWatch.create()) { } + + /** Records `status` for `name`, stamping the settle time on first terminal status. */ + observe(name: string, status: SdkMcpServerStatus): void { + const now = this._clock.elapsed(); + this._firstObservedMs ??= now; + this._statuses.set(name, status); + if (isTerminalStatus(status) && !this._settledAtMs.has(name)) { + this._settledAtMs.set(name, now); + } + } + + snapshot(): IMcpReadinessSnapshot { + let readyCount = 0; + let failedCount = 0; + let unresolvedCount = 0; + for (const status of this._statuses.values()) { + if (status === 'connected') { + readyCount++; + } else if (status === 'failed') { + failedCount++; + } else if (!isTerminalStatus(status)) { + unresolvedCount++; + } + } + const lastSettledMs = this._settledAtMs.size > 0 ? Math.max(...this._settledAtMs.values()) : undefined; + const firstObservedMs = this._firstObservedMs; + return { + serverCount: this._statuses.size, + readyCount, + failedCount, + unresolvedCount, + slowestServerMs: lastSettledMs !== undefined && firstObservedMs !== undefined + ? Math.round(lastSettledMs - firstObservedMs) + : undefined, + }; + } +} diff --git a/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts b/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts index e375321ff50b9..a5e63db8fd21b 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts @@ -966,19 +966,23 @@ export class CopilotSessionLauncher implements ICopilotSessionLauncher { ] : undefined; const disabledMcpServers = disabledMcpServersSessionOption(plugins, plan.disabledRootMcpServers, additionalDisabledMcpServers); const mcpServers = plan.isEphemeral ? {} : { ...toSdkMcpServersFromConfigMap(plan.snapshot.mcpServers), ...toSdkMcpServers(explicitMcpServers) }; + const sortedUnique = (names: readonly string[]) => [...new Set(names)].sort(); + // Logged at info: servers in `finalSessionConfig` are handed to the SDK at + // session creation and the provider holds the first send until they settle, + // while `pluginDiscovery` servers resolve lazily. That split is the first + // thing needed to explain a slow first turn, so it must not require trace. + this._logService.info(`[Copilot:${plan.sessionId}] MCP launch projection: ${JSON.stringify({ + ephemeral: plan.isEphemeral === true, + pluginDiscovery: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'pluginDiscovery').map(server => server.name))), + sessionConfig: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'sessionConfig').map(server => server.name))), + rootConfig: Object.keys(plan.snapshot.mcpServers).sort(), + disabled: [...(disabledMcpServers.disabledMcpServers ?? [])].sort(), + finalSessionConfig: Object.keys(mcpServers).sort(), + })}`); if (this._logService.getLevel() <= LogLevel.Trace) { // Guarded: a `replace`-mode prompt's content can be multiple KB, so only // serialize it when trace output is actually emitted. this._logService.trace(`[Copilot:${plan.sessionId}] System message config: ${JSON.stringify(systemMessage, (_key, value) => typeof value === 'function' ? '[transform fn]' : value)}`); - const sortedUnique = (names: readonly string[]) => [...new Set(names)].sort(); - this._logService.trace(`[Copilot:${plan.sessionId}] MCP launch projection: ${JSON.stringify({ - ephemeral: plan.isEphemeral === true, - pluginDiscovery: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'pluginDiscovery').map(server => server.name))), - sessionConfig: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'sessionConfig').map(server => server.name))), - rootConfig: Object.keys(plan.snapshot.mcpServers).sort(), - disabled: [...(disabledMcpServers.disabledMcpServers ?? [])].sort(), - finalSessionConfig: Object.keys(mcpServers).sort(), - })}`); } return { ...byok, diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index c6b60e4fa37be..83d1ecac6a80b 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -9900,7 +9900,7 @@ Use the attached image as context. mockSession.fire('session.idle', { aborted: true } as SessionEventPayload<'session.idle'>['data']); assert.deepStrictEqual({ - telemetry: telemetryService.events.map(event => { + telemetry: telemetryService.events.filter(event => event.eventName === 'toolCallDetails').map(event => { const data = event.data as Record; return { eventName: event.eventName, diff --git a/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts new file mode 100644 index 0000000000000..934b0f5a03c84 --- /dev/null +++ b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts @@ -0,0 +1,67 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import assert from 'assert'; +import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../base/test/common/utils.js'; +import { CopilotMcpReadinessTracker } from '../../node/copilot/copilotMcpReadiness.js'; + +/** Controllable stand-in for the tracker's stopwatch. */ +class TestClock { + private _now = 0; + advanceTo(ms: number): void { this._now = ms; } + elapsed(): number { return this._now; } +} + +suite('CopilotMcpReadinessTracker', () => { + ensureNoDisposablesAreLeakedInTestSuite(); + + test('reports the slowest parallel server as the startup window', () => { + const clock = new TestClock(); + const tracker = new CopilotMcpReadinessTracker(clock); + for (const name of ['fast', 'slow', 'broken', 'waiting']) { + tracker.observe(name, 'pending'); + } + clock.advanceTo(12); + tracker.observe('broken', 'failed'); + clock.advanceTo(6920); + tracker.observe('fast', 'connected'); + clock.advanceTo(28918); + tracker.observe('slow', 'connected'); + + assert.deepStrictEqual(tracker.snapshot(), { + serverCount: 4, + readyCount: 2, + failedCount: 1, + unresolvedCount: 1, + slowestServerMs: 28918, + }); + }); + + test('keeps the first settle time when a server is re-reported', () => { + const clock = new TestClock(); + const tracker = new CopilotMcpReadinessTracker(clock); + tracker.observe('server', 'pending'); + clock.advanceTo(500); + tracker.observe('server', 'connected'); + clock.advanceTo(90000); + tracker.observe('server', 'connected'); + + assert.deepStrictEqual(tracker.snapshot(), { + serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, slowestServerMs: 500, + }); + }); + + test('treats needs-auth as unsettled and reports no window until something settles', () => { + const clock = new TestClock(); + const tracker = new CopilotMcpReadinessTracker(clock); + tracker.observe('auth', 'needs-auth'); + clock.advanceTo(2000); + + assert.deepStrictEqual([tracker.snapshot(), new CopilotMcpReadinessTracker(new TestClock()).snapshot()], [ + { serverCount: 1, readyCount: 0, failedCount: 0, unresolvedCount: 1, slowestServerMs: undefined }, + { serverCount: 0, readyCount: 0, failedCount: 0, unresolvedCount: 0, slowestServerMs: undefined }, + ]); + }); +}); diff --git a/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts b/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts index 8e2dd04e0e3b1..fd6ff2ad70e2d 100644 --- a/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts @@ -711,7 +711,7 @@ suite('CopilotSessionLauncher shared session config', () => { ephemeralMcpServers: createConfigs[1].mcpServers, ephemeralDisabledMcpServers: createConfigs[1].disabledMcpServers, ephemeralExcludedTools: createConfigs[1].excludedTools, - mcpProjectionTraces: logService.traces.filter(message => message.includes('MCP launch projection:')).map(message => JSON.parse(message.slice(message.indexOf('{')))), + mcpProjectionLogs: logService.infos.filter(message => message.includes('MCP launch projection:')).map(message => JSON.parse(message.slice(message.indexOf('{')))), sensitiveProjectionValues: [ '/sensitive/plugin-command', 'sensitive-plugin-env', @@ -720,8 +720,7 @@ suite('CopilotSessionLauncher shared session config', () => { pluginDir.fsPath, syntheticPluginDir.fsPath, testWorkingDirectory.fsPath, - ].filter(value => logService.traces.some(message => message.includes('MCP launch projection:') && message.includes(value)) - || logService.infos.some(message => message.includes(value))), + ].filter(value => logService.infos.some(message => message.includes(value))), resumeLogs: logService.infos.filter(message => message.includes('SDK resumeSession ')) .map(message => message.replace(/attemptId=[\da-f-]+/g, 'attemptId=').replace(/elapsedMs=\d+$/, 'elapsedMs=')), }, { @@ -764,7 +763,7 @@ suite('CopilotSessionLauncher shared session config', () => { ephemeralMcpServers: {}, ephemeralDisabledMcpServers: ['azure', 'disabled-workspace-server', 'github', 'native-plugin-server', 'synced-server'], ephemeralExcludedTools: ['task', `builtin:${SEMANTIC_SEARCH_TOOL_NAME}`], - mcpProjectionTraces: [ + mcpProjectionLogs: [ { ephemeral: false, pluginDiscovery: ['native-plugin-server'], From dffaa979e16bdb5dabaa493968005c6b6847bf42 Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 14:21:15 -0700 Subject: [PATCH 2/6] measure provider send blocking --- .../node/copilot/copilotSessionLauncher.ts | 22 ++++++++----------- .../test/node/copilotSessionLauncher.test.ts | 7 +++--- 2 files changed, 13 insertions(+), 16 deletions(-) diff --git a/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts b/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts index a5e63db8fd21b..e375321ff50b9 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotSessionLauncher.ts @@ -966,23 +966,19 @@ export class CopilotSessionLauncher implements ICopilotSessionLauncher { ] : undefined; const disabledMcpServers = disabledMcpServersSessionOption(plugins, plan.disabledRootMcpServers, additionalDisabledMcpServers); const mcpServers = plan.isEphemeral ? {} : { ...toSdkMcpServersFromConfigMap(plan.snapshot.mcpServers), ...toSdkMcpServers(explicitMcpServers) }; - const sortedUnique = (names: readonly string[]) => [...new Set(names)].sort(); - // Logged at info: servers in `finalSessionConfig` are handed to the SDK at - // session creation and the provider holds the first send until they settle, - // while `pluginDiscovery` servers resolve lazily. That split is the first - // thing needed to explain a slow first turn, so it must not require trace. - this._logService.info(`[Copilot:${plan.sessionId}] MCP launch projection: ${JSON.stringify({ - ephemeral: plan.isEphemeral === true, - pluginDiscovery: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'pluginDiscovery').map(server => server.name))), - sessionConfig: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'sessionConfig').map(server => server.name))), - rootConfig: Object.keys(plan.snapshot.mcpServers).sort(), - disabled: [...(disabledMcpServers.disabledMcpServers ?? [])].sort(), - finalSessionConfig: Object.keys(mcpServers).sort(), - })}`); if (this._logService.getLevel() <= LogLevel.Trace) { // Guarded: a `replace`-mode prompt's content can be multiple KB, so only // serialize it when trace output is actually emitted. this._logService.trace(`[Copilot:${plan.sessionId}] System message config: ${JSON.stringify(systemMessage, (_key, value) => typeof value === 'function' ? '[transform fn]' : value)}`); + const sortedUnique = (names: readonly string[]) => [...new Set(names)].sort(); + this._logService.trace(`[Copilot:${plan.sessionId}] MCP launch projection: ${JSON.stringify({ + ephemeral: plan.isEphemeral === true, + pluginDiscovery: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'pluginDiscovery').map(server => server.name))), + sessionConfig: sortedUnique(plugins.flatMap(plugin => plugin.mcpServers.filter(server => server.sdkRegistration === 'sessionConfig').map(server => server.name))), + rootConfig: Object.keys(plan.snapshot.mcpServers).sort(), + disabled: [...(disabledMcpServers.disabledMcpServers ?? [])].sort(), + finalSessionConfig: Object.keys(mcpServers).sort(), + })}`); } return { ...byok, diff --git a/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts b/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts index fd6ff2ad70e2d..8e2dd04e0e3b1 100644 --- a/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotSessionLauncher.test.ts @@ -711,7 +711,7 @@ suite('CopilotSessionLauncher shared session config', () => { ephemeralMcpServers: createConfigs[1].mcpServers, ephemeralDisabledMcpServers: createConfigs[1].disabledMcpServers, ephemeralExcludedTools: createConfigs[1].excludedTools, - mcpProjectionLogs: logService.infos.filter(message => message.includes('MCP launch projection:')).map(message => JSON.parse(message.slice(message.indexOf('{')))), + mcpProjectionTraces: logService.traces.filter(message => message.includes('MCP launch projection:')).map(message => JSON.parse(message.slice(message.indexOf('{')))), sensitiveProjectionValues: [ '/sensitive/plugin-command', 'sensitive-plugin-env', @@ -720,7 +720,8 @@ suite('CopilotSessionLauncher shared session config', () => { pluginDir.fsPath, syntheticPluginDir.fsPath, testWorkingDirectory.fsPath, - ].filter(value => logService.infos.some(message => message.includes(value))), + ].filter(value => logService.traces.some(message => message.includes('MCP launch projection:') && message.includes(value)) + || logService.infos.some(message => message.includes(value))), resumeLogs: logService.infos.filter(message => message.includes('SDK resumeSession ')) .map(message => message.replace(/attemptId=[\da-f-]+/g, 'attemptId=').replace(/elapsedMs=\d+$/, 'elapsedMs=')), }, { @@ -763,7 +764,7 @@ suite('CopilotSessionLauncher shared session config', () => { ephemeralMcpServers: {}, ephemeralDisabledMcpServers: ['azure', 'disabled-workspace-server', 'github', 'native-plugin-server', 'synced-server'], ephemeralExcludedTools: ['task', `builtin:${SEMANTIC_SEARCH_TOOL_NAME}`], - mcpProjectionLogs: [ + mcpProjectionTraces: [ { ephemeral: false, pluginDiscovery: ['native-plugin-server'], From 772c62b31877b8abc4abc778e4f2393ea61c9871 Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 14:43:32 -0700 Subject: [PATCH 3/6] agentHost: exclude never-started MCP servers from the startup window Address PR feedback: - disabled/not_configured servers no longer receive settle timestamps, so a session of only stopped servers reports no startup window instead of 0ms, and a stopped server observed first no longer anchors the window early. - Add mcpStoppedCount so the outcome buckets account for every observed server. - Add CopilotAgentSession tests covering providerSendBlocked wiring: the first/subsequent send flag, the failure flag, and the MCP snapshot fed through the real status-changed subscription. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../node/agentHostTelemetryReporter.ts | 4 ++ .../node/copilot/copilotMcpReadiness.ts | 61 +++++++++++++------ .../test/node/copilotAgentSession.test.ts | 55 +++++++++++++++++ .../test/node/copilotMcpReadiness.test.ts | 27 +++++++- 4 files changed, 125 insertions(+), 22 deletions(-) diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index 9724c0669c31e..99d3abb906e5b 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -207,6 +207,7 @@ export interface IAgentHostProviderSendBlockedEvent { mcpReadyCount: number; mcpFailedCount: number; mcpUnresolvedCount: number; + mcpStoppedCount: number; slowestMcpServerMs: number | undefined; } @@ -216,6 +217,7 @@ export interface IAgentHostMcpReadinessReport { readonly readyCount: number; readonly failedCount: number; readonly unresolvedCount: number; + readonly stoppedCount: number; readonly slowestServerMs: number | undefined; } @@ -229,6 +231,7 @@ export type IAgentHostProviderSendBlockedClassification = { mcpReadyCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had connected when the send returned.' }; mcpFailedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had failed when the send returned.' }; mcpUnresolvedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers still starting or awaiting authentication when the send returned.' }; + mcpStoppedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that never started because they are disabled or not configured, and so took no part in the startup window.' }; slowestMcpServerMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Milliseconds from the first observed MCP server to the last one to settle; absent when none had settled.' }; owner: 'vijayupadya'; comment: 'Measures how long the provider send call blocks before a turn can start, with the MCP server startup context it overlaps.'; @@ -1072,6 +1075,7 @@ export class AgentHostTelemetryReporter { mcpReadyCount: mcp.readyCount, mcpFailedCount: mcp.failedCount, mcpUnresolvedCount: mcp.unresolvedCount, + mcpStoppedCount: mcp.stoppedCount, slowestMcpServerMs: mcp.slowestServerMs, }); } diff --git a/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts index 7b16be8a742b5..02164212a0f6d 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts @@ -7,27 +7,40 @@ import { StopWatch } from '../../../../base/common/stopwatch.js'; import type { McpServerStatus as SdkMcpServerStatus } from '@github/copilot-sdk'; /** - * SDK statuses that mean the server has finished starting, whether or not it - * became usable. `pending` and `needs-auth` are excluded because the server is - * still resolving; everything else is a settled outcome. + * Statuses that mean the server actually attempted to start. `disabled` and + * `not_configured` servers never launch a process, so they take no part in the + * startup window even though they appear in the session's inventory. */ -function isTerminalStatus(status: SdkMcpServerStatus): boolean { - return status !== 'pending' && status !== 'needs-auth'; +function isParticipatingStatus(status: SdkMcpServerStatus): boolean { + return status !== 'disabled' && status !== 'not_configured'; +} + +/** + * Statuses that mean a started server has finished, whether or not it became + * usable. `pending` and `needs-auth` are still resolving, and non-participating + * statuses never started, so neither settles. + */ +function isSettledStatus(status: SdkMcpServerStatus): boolean { + return status === 'connected' || status === 'failed'; } export interface IMcpReadinessSnapshot { - /** Servers observed in any state. */ + /** Servers observed in any state, including ones that never started. */ readonly serverCount: number; /** Servers that reached `connected`. */ readonly readyCount: number; /** Servers that reached `failed`. */ readonly failedCount: number; - /** Servers still in `pending` or `needs-auth` when the snapshot was taken. */ + /** Started servers still in `pending` or `needs-auth` when the snapshot was taken. */ readonly unresolvedCount: number; + /** Servers that never started because they are `disabled` or `not_configured`. */ + readonly stoppedCount: number; /** - * Milliseconds from the first observed server to the last one to settle, - * or `undefined` when nothing has settled yet. Startup is parallel, so this - * is the cost of the slowest server rather than the sum. + * Milliseconds from the first server that started to the last one to settle, + * or `undefined` when no server has settled — including a session whose + * servers are all disabled, which has no startup window at all rather than a + * zero-length one. Startup is parallel, so this is the cost of the slowest + * server rather than the sum. */ readonly slowestServerMs: number | undefined; } @@ -36,8 +49,11 @@ export interface IMcpReadinessSnapshot { * Tracks MCP server startup timing for a single Copilot SDK session. * * Servers start in parallel, so the wall-clock cost of MCP startup is set by - * the slowest server. This records when the first server was seen and when the + * the slowest server. This records when the first server started and when the * last one settled, which is the window a blocked first turn overlaps with. + * Servers that never start (`disabled` / `not_configured`) are counted in the + * inventory but excluded from that window, so a session of only disabled + * servers reports no window rather than a zero-length one. * * Only forward progress is recorded: a server that settles and is later * re-reported keeps its original settle time, so repeated inventory snapshots @@ -47,16 +63,19 @@ export class CopilotMcpReadinessTracker { private readonly _statuses = new Map(); private readonly _settledAtMs = new Map(); - private _firstObservedMs: number | undefined; + private _firstStartedMs: number | undefined; constructor(private readonly _clock: Pick = StopWatch.create()) { } - /** Records `status` for `name`, stamping the settle time on first terminal status. */ + /** Records `status` for `name`, stamping the settle time the first time it finishes starting. */ observe(name: string, status: SdkMcpServerStatus): void { const now = this._clock.elapsed(); - this._firstObservedMs ??= now; this._statuses.set(name, status); - if (isTerminalStatus(status) && !this._settledAtMs.has(name)) { + if (!isParticipatingStatus(status)) { + return; + } + this._firstStartedMs ??= now; + if (isSettledStatus(status) && !this._settledAtMs.has(name)) { this._settledAtMs.set(name, now); } } @@ -65,24 +84,28 @@ export class CopilotMcpReadinessTracker { let readyCount = 0; let failedCount = 0; let unresolvedCount = 0; + let stoppedCount = 0; for (const status of this._statuses.values()) { if (status === 'connected') { readyCount++; } else if (status === 'failed') { failedCount++; - } else if (!isTerminalStatus(status)) { + } else if (!isParticipatingStatus(status)) { + stoppedCount++; + } else { unresolvedCount++; } } const lastSettledMs = this._settledAtMs.size > 0 ? Math.max(...this._settledAtMs.values()) : undefined; - const firstObservedMs = this._firstObservedMs; + const firstStartedMs = this._firstStartedMs; return { serverCount: this._statuses.size, readyCount, failedCount, unresolvedCount, - slowestServerMs: lastSettledMs !== undefined && firstObservedMs !== undefined - ? Math.round(lastSettledMs - firstObservedMs) + stoppedCount, + slowestServerMs: lastSettledMs !== undefined && firstStartedMs !== undefined + ? Math.round(lastSettledMs - firstStartedMs) : undefined, }; } diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index 83d1ecac6a80b..9281dbdc8b5ca 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -671,6 +671,20 @@ class CapturingTelemetryService implements ITelemetryService { // ---- Helpers ---------------------------------------------------------------- +/** + * Projects `agentHost.providerSendBlocked` payloads into a stable shape for + * assertions: the two duration fields are wall-clock measurements, so only + * their presence is comparable. + */ +function providerSendBlockedEvents(telemetryService: CapturingTelemetryService): unknown[] { + return telemetryService.events + .filter(event => event.eventName === 'agentHost.providerSendBlocked') + .map(event => { + const { sendBlockedMs, slowestMcpServerMs, agentSessionId, ...rest } = event.data as Record; + return { ...rest, hasBlockedMs: typeof sendBlockedMs === 'number', hasSlowestMcpServerMs: typeof slowestMcpServerMs === 'number' }; + }); +} + /** * Invokes a client-SDK tool's handler with the minimal fields the SDK * contract requires, and narrows the `unknown` return type to @@ -3180,6 +3194,47 @@ suite('CopilotAgentSession', () => { assert.deepStrictEqual({ hasActiveTurn: session.hasActiveTurn, turnEndCount }, { hasActiveTurn: false, turnEndCount: 1 }); }); + test('send blocking telemetry carries the MCP snapshot and flags only the first send', async () => { + const telemetryService = new CapturingTelemetryService(); + const { session, mockSession } = await createAgentSession(disposables, { telemetryService }); + + // Drive the readiness tracker through the real subscription rather than + // the tracker API, so a broken wiring in `_registerHandlers` is caught. + for (const [serverName, status] of [['ready-server', 'connected'], ['broken-server', 'failed'], ['off-server', 'disabled'], ['slow-server', 'pending']] as const) { + mockSession.fire('session.mcp_server_status_changed', { serverName, status } as SessionEventPayload<'session.mcp_server_status_changed'>['data']); + } + + await session.send('first', undefined, 'turn-1'); + await session.send('second', undefined, 'turn-2'); + + assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [ + { + provider: 'copilot', isFirstSendOfSession: true, sendFailed: false, + mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, + hasBlockedMs: true, hasSlowestMcpServerMs: true, + }, + { + provider: 'copilot', isFirstSendOfSession: false, sendFailed: false, + mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, + hasBlockedMs: true, hasSlowestMcpServerMs: true, + }, + ]); + }); + + test('send blocking telemetry still reports when the provider send rejects', async () => { + const telemetryService = new CapturingTelemetryService(); + const { session, mockSession } = await createAgentSession(disposables, { telemetryService }); + mockSession.send = async () => { throw new Error('send failed'); }; + + await assert.rejects(() => session.send('hello', undefined, 'turn-failed'), /send failed/); + + assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [{ + provider: 'copilot', isFirstSendOfSession: true, sendFailed: true, + mcpServerCount: 0, mcpReadyCount: 0, mcpFailedCount: 0, mcpUnresolvedCount: 0, mcpStoppedCount: 0, + hasBlockedMs: true, hasSlowestMcpServerMs: false, + }]); + }); + test('`/env` runs the runtime command when listed and emits markdown output', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); mockSession.commandListResult = { diff --git a/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts index 934b0f5a03c84..06fe418c09026 100644 --- a/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts @@ -35,6 +35,7 @@ suite('CopilotMcpReadinessTracker', () => { readyCount: 2, failedCount: 1, unresolvedCount: 1, + stoppedCount: 0, slowestServerMs: 28918, }); }); @@ -49,7 +50,7 @@ suite('CopilotMcpReadinessTracker', () => { tracker.observe('server', 'connected'); assert.deepStrictEqual(tracker.snapshot(), { - serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, slowestServerMs: 500, + serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: 500, }); }); @@ -60,8 +61,28 @@ suite('CopilotMcpReadinessTracker', () => { clock.advanceTo(2000); assert.deepStrictEqual([tracker.snapshot(), new CopilotMcpReadinessTracker(new TestClock()).snapshot()], [ - { serverCount: 1, readyCount: 0, failedCount: 0, unresolvedCount: 1, slowestServerMs: undefined }, - { serverCount: 0, readyCount: 0, failedCount: 0, unresolvedCount: 0, slowestServerMs: undefined }, + { serverCount: 1, readyCount: 0, failedCount: 0, unresolvedCount: 1, stoppedCount: 0, slowestServerMs: undefined }, + { serverCount: 0, readyCount: 0, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: undefined }, + ]); + }); + + test('excludes servers that never start from the window rather than reporting zero', () => { + const clock = new TestClock(); + const allStopped = new CopilotMcpReadinessTracker(clock); + allStopped.observe('off', 'disabled'); + allStopped.observe('absent', 'not_configured'); + + // A stopped server observed first must not anchor the window early. + const mixed = new CopilotMcpReadinessTracker(clock); + mixed.observe('off', 'disabled'); + clock.advanceTo(1000); + mixed.observe('real', 'pending'); + clock.advanceTo(4000); + mixed.observe('real', 'connected'); + + assert.deepStrictEqual([allStopped.snapshot(), mixed.snapshot()], [ + { serverCount: 2, readyCount: 0, failedCount: 0, unresolvedCount: 0, stoppedCount: 2, slowestServerMs: undefined }, + { serverCount: 2, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 1, slowestServerMs: 3000 }, ]); }); }); From ed56e0d86241edefe1e5570656a2e936fed6f9d0 Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 15:00:04 -0700 Subject: [PATCH 4/6] agentHost: split turn preparation from the provider send, and time MCP per server Address PR review: - Preparation awaits an MCP inventory refresh that can wait on live server discovery, so a stall there was invisible or misattributed. Time it as its own prepareBlockedMs phase and keep sendBlockedMs to the provider call. - Measure each MCP server's own startup interval and report the longest, so idle time between an early server settling and a later one starting is no longer counted, and a server first seen already settled contributes none. - Derive provider and session from the owning session URI, so peer chats report copilotcli rather than the ahp-chat persistence scheme. - Add turnId so the phases join to turn and first-response timings. - Add tests for phase attribution, per-server timing, and the wiring. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../node/agentHostTelemetryReporter.ts | 26 ++++++--- .../node/copilot/copilotAgentSession.ts | 22 +++++--- .../node/copilot/copilotMcpReadiness.ts | 51 +++++++++-------- .../test/node/copilotAgentSession.test.ts | 56 +++++++++++++++---- .../test/node/copilotMcpReadiness.test.ts | 54 +++++++++++++----- 5 files changed, 146 insertions(+), 63 deletions(-) diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index 99d3abb906e5b..a5ef53d02bce0 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -200,6 +200,8 @@ export interface IAgentHostClientConnectionReport { export interface IAgentHostProviderSendBlockedEvent { provider: string; agentSessionId: string; + turnId: string; + prepareBlockedMs: number; sendBlockedMs: number; isFirstSendOfSession: boolean; sendFailed: boolean; @@ -224,17 +226,19 @@ export interface IAgentHostMcpReadinessReport { export type IAgentHostProviderSendBlockedClassification = { provider: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The provider handling the agent host session.' }; agentSessionId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The agent host session identifier.' }; - sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider send call blocked before returning. This precedes turn start, so it is not covered by turn timings.' }; + turnId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The turn this send belongs to, so the phases can be joined to the turn and first-response timings.' }; + prepareBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds spent preparing the turn before the provider send call, including the MCP inventory refresh that can wait on live server discovery.' }; + sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider send call itself blocked before returning, excluding turn preparation.' }; isFirstSendOfSession: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether this was the first send on a newly created provider session, where startup costs are paid.' }; sendFailed: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether the provider send call threw instead of returning normally.' }; mcpServerCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers observed for the session when the send returned.' }; mcpReadyCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had connected when the send returned.' }; mcpFailedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had failed when the send returned.' }; mcpUnresolvedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers still starting or awaiting authentication when the send returned.' }; - mcpStoppedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that never started because they are disabled or not configured, and so took no part in the startup window.' }; - slowestMcpServerMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Milliseconds from the first observed MCP server to the last one to settle; absent when none had settled.' }; + mcpStoppedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that never started because they are disabled or not configured, and so contributed no startup time.' }; + slowestMcpServerMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'The longest startup any single MCP server took, in milliseconds; absent when no server startup was observed end to end.' }; owner: 'vijayupadya'; - comment: 'Measures how long the provider send call blocks before a turn can start, with the MCP server startup context it overlaps.'; + comment: 'Measures the turn-preparation and provider-send phases that precede provider execution, with the MCP server startup context they overlap.'; }; export type AgentHostTurnResult = 'success' | 'error' | 'cancelled'; @@ -1059,15 +1063,19 @@ export class AgentHostTelemetryReporter { } /** - * Reports how long a provider send call blocked before returning. This - * window sits before turn start, so it is invisible to turn telemetry even - * though the user is already waiting. MCP counts describe the server - * startup this window overlaps, which is the usual reason it is long. + * Reports the two phases that precede provider execution: turn preparation + * (which awaits an MCP inventory refresh that can wait on live server + * discovery) and the provider send call itself. Host turn timing covers + * both inside its total but attributes neither, so a stall in one cannot + * be told from a stall in the other. MCP counts describe the server startup + * these phases overlap, which is the usual reason either is long. */ - providerSendBlocked(provider: string, session: string, sendBlockedMs: number, isFirstSendOfSession: boolean, sendFailed: boolean, mcp: IAgentHostMcpReadinessReport): void { + providerSendBlocked(provider: string, session: string, turnId: string, prepareBlockedMs: number, sendBlockedMs: number, isFirstSendOfSession: boolean, sendFailed: boolean, mcp: IAgentHostMcpReadinessReport): void { this._telemetryService.publicLog2('agentHost.providerSendBlocked', { provider, agentSessionId: AgentSession.id(session), + turnId, + prepareBlockedMs, sendBlockedMs, isFirstSendOfSession, sendFailed, diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 43a03e15d2663..2ea212273d0fc 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -3063,7 +3063,13 @@ export class CopilotAgentSession extends Disposable { const sdkAttachments = await this._toSdkAttachments(attachments); + // Preparation is timed separately from the send: it awaits several RPCs, + // including an MCP inventory refresh that can itself wait on live server + // discovery. Folding the two together would attribute a preparation stall + // to the provider call, or hide it entirely. + const prepareWatch = StopWatch.create(false); await this._prepareSdkTurn(mode); + const prepareBlockedMs = Math.round(prepareWatch.elapsed()); const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); const sendingTurn = this._currentTurn.value; sendingTurn?.markProviderCallPending(); @@ -3087,10 +3093,10 @@ export class CopilotAgentSession extends Disposable { sendingTurn?.markProviderCallRejected(); throw error; } finally { - // Measured around `session.send()` alone: the provider holds this call - // until session startup (notably MCP server readiness) settles, and the - // user is already waiting with nothing on screen. It ends before the - // turn begins, so no turn telemetry covers it. + // Reported as two separate phases so a stall can be attributed. The + // send is the provider call alone; preparation precedes it and awaits + // an MCP inventory refresh that can wait on live server discovery. + // Host turn timing covers both in its total but attributes neither. // // Guarded because this runs in a `finally`: a throw from reporting here // would replace the provider error the `catch` above is rethrowing, @@ -3099,14 +3105,16 @@ export class CopilotAgentSession extends Disposable { const sendBlockedMs = Math.round(sendWatch.elapsed()); const mcp = this._mcpReadiness.snapshot(); this._telemetryReporter.providerSendBlocked( - this.resourceUri.scheme, - this.resourceUri.toString(), + this._ownerSessionUri.scheme, + this._ownerSessionUri.toString(), + this._turnId, + prepareBlockedMs, sendBlockedMs, isFirstSendOfSession, sendFailed, mcp, ); - this._logService.info(`[Copilot:${this.sessionId}] session.send() blocked for ${sendBlockedMs}ms (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); + this._logService.info(`[Copilot:${this.sessionId}] send phases: prepare=${prepareBlockedMs}ms, send=${sendBlockedMs}ms (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); } catch (err) { this._logService.trace(`[Copilot:${this.sessionId}] Telemetry emission failed: ${getErrorMessage(err)}`); } diff --git a/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts index 02164212a0f6d..29128524cd85e 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts @@ -36,11 +36,11 @@ export interface IMcpReadinessSnapshot { /** Servers that never started because they are `disabled` or `not_configured`. */ readonly stoppedCount: number; /** - * Milliseconds from the first server that started to the last one to settle, - * or `undefined` when no server has settled — including a session whose - * servers are all disabled, which has no startup window at all rather than a - * zero-length one. Startup is parallel, so this is the cost of the slowest - * server rather than the sum. + * The longest startup any single server took, in milliseconds, or + * `undefined` when no server's startup was observed end to end. Servers + * start in parallel, so this is the cost that gates readiness rather than + * the sum. Measured per server, so idle time between one server settling + * and another starting later in the session is excluded. */ readonly slowestServerMs: number | undefined; } @@ -48,35 +48,46 @@ export interface IMcpReadinessSnapshot { /** * Tracks MCP server startup timing for a single Copilot SDK session. * - * Servers start in parallel, so the wall-clock cost of MCP startup is set by - * the slowest server. This records when the first server started and when the - * last one settled, which is the window a blocked first turn overlaps with. + * Each server is timed individually, from the first observation showing it + * starting to the observation showing it settled, and the reported figure is + * the longest of those. Measuring per server rather than across the whole + * session keeps the figure meaningful when servers are added or restarted + * later in a long-lived session: idle time between an early server settling + * and a later one starting is not part of any server's startup. + * * Servers that never start (`disabled` / `not_configured`) are counted in the - * inventory but excluded from that window, so a session of only disabled - * servers reports no window rather than a zero-length one. + * inventory but contribute no duration, and a server first seen already + * settled contributes none either — its startup was not observed, which is + * different from it having taken no time. * * Only forward progress is recorded: a server that settles and is later - * re-reported keeps its original settle time, so repeated inventory snapshots + * re-reported keeps its original duration, so repeated inventory snapshots * do not inflate the measurement. */ export class CopilotMcpReadinessTracker { private readonly _statuses = new Map(); - private readonly _settledAtMs = new Map(); - private _firstStartedMs: number | undefined; + private readonly _startedAtMs = new Map(); + private readonly _durationMs = new Map(); constructor(private readonly _clock: Pick = StopWatch.create()) { } - /** Records `status` for `name`, stamping the settle time the first time it finishes starting. */ + /** Records `status` for `name`, closing that server's startup interval once it settles. */ observe(name: string, status: SdkMcpServerStatus): void { const now = this._clock.elapsed(); this._statuses.set(name, status); if (!isParticipatingStatus(status)) { return; } - this._firstStartedMs ??= now; - if (isSettledStatus(status) && !this._settledAtMs.has(name)) { - this._settledAtMs.set(name, now); + if (!isSettledStatus(status)) { + if (!this._startedAtMs.has(name)) { + this._startedAtMs.set(name, now); + } + return; + } + const startedAtMs = this._startedAtMs.get(name); + if (startedAtMs !== undefined && !this._durationMs.has(name)) { + this._durationMs.set(name, now - startedAtMs); } } @@ -96,17 +107,13 @@ export class CopilotMcpReadinessTracker { unresolvedCount++; } } - const lastSettledMs = this._settledAtMs.size > 0 ? Math.max(...this._settledAtMs.values()) : undefined; - const firstStartedMs = this._firstStartedMs; return { serverCount: this._statuses.size, readyCount, failedCount, unresolvedCount, stoppedCount, - slowestServerMs: lastSettledMs !== undefined && firstStartedMs !== undefined - ? Math.round(lastSettledMs - firstStartedMs) - : undefined, + slowestServerMs: this._durationMs.size > 0 ? Math.round(Math.max(...this._durationMs.values())) : undefined, }; } } diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index 9281dbdc8b5ca..178de04573620 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -673,18 +673,30 @@ class CapturingTelemetryService implements ITelemetryService { /** * Projects `agentHost.providerSendBlocked` payloads into a stable shape for - * assertions: the two duration fields are wall-clock measurements, so only - * their presence is comparable. + * assertions: the duration fields are wall-clock measurements, so only their + * presence is comparable. */ function providerSendBlockedEvents(telemetryService: CapturingTelemetryService): unknown[] { return telemetryService.events .filter(event => event.eventName === 'agentHost.providerSendBlocked') .map(event => { - const { sendBlockedMs, slowestMcpServerMs, agentSessionId, ...rest } = event.data as Record; - return { ...rest, hasBlockedMs: typeof sendBlockedMs === 'number', hasSlowestMcpServerMs: typeof slowestMcpServerMs === 'number' }; + const { sendBlockedMs, prepareBlockedMs, slowestMcpServerMs, agentSessionId, ...rest } = event.data as Record; + return { + ...rest, + hasBlockedMs: typeof sendBlockedMs === 'number', + hasPrepareMs: typeof prepareBlockedMs === 'number', + hasSlowestMcpServerMs: typeof slowestMcpServerMs === 'number', + }; }); } +/** Raw payload of the single `agentHost.providerSendBlocked` event, for timing assertions. */ +function singleProviderSendBlockedEvent(telemetryService: CapturingTelemetryService): Record { + const events = telemetryService.events.filter(event => event.eventName === 'agentHost.providerSendBlocked'); + assert.strictEqual(events.length, 1, 'expected exactly one providerSendBlocked event'); + return events[0].data as Record; +} + /** * Invokes a client-SDK tool's handler with the minimal fields the SDK * contract requires, and narrows the `unknown` return type to @@ -3209,14 +3221,14 @@ suite('CopilotAgentSession', () => { assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [ { - provider: 'copilot', isFirstSendOfSession: true, sendFailed: false, + provider: 'copilot', turnId: 'turn-1', isFirstSendOfSession: true, sendFailed: false, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, - hasBlockedMs: true, hasSlowestMcpServerMs: true, + hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }, { - provider: 'copilot', isFirstSendOfSession: false, sendFailed: false, + provider: 'copilot', turnId: 'turn-2', isFirstSendOfSession: false, sendFailed: false, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, - hasBlockedMs: true, hasSlowestMcpServerMs: true, + hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }, ]); }); @@ -3229,12 +3241,36 @@ suite('CopilotAgentSession', () => { await assert.rejects(() => session.send('hello', undefined, 'turn-failed'), /send failed/); assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [{ - provider: 'copilot', isFirstSendOfSession: true, sendFailed: true, + provider: 'copilot', turnId: 'turn-failed', isFirstSendOfSession: true, sendFailed: true, mcpServerCount: 0, mcpReadyCount: 0, mcpFailedCount: 0, mcpUnresolvedCount: 0, mcpStoppedCount: 0, - hasBlockedMs: true, hasSlowestMcpServerMs: false, + hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }]); }); + test('a slow turn preparation is attributed to the prepare phase, not the provider send', async () => { + const telemetryService = new CapturingTelemetryService(); + const { session, mockSession } = await createAgentSession(disposables, { telemetryService }); + + // `_prepareSdkTurn` awaits several RPCs before the send, including an MCP + // inventory refresh that can itself wait on live server discovery. Gate one + // of those awaits: the delay must land in `prepareBlockedMs`, never in + // `sendBlockedMs`, or a preparation stall would be misread as a slow send. + let releasePrepare = () => { }; + const prepareGate = new Promise(resolve => { releasePrepare = resolve; }); + mockSession.rpc.mode.set = async () => { await prepareGate; }; + + const sent = session.send('hello', undefined, 'turn-slow-prepare', 'plan'); + await timeout(40); + releasePrepare(); + await sent; + + const event = singleProviderSendBlockedEvent(telemetryService); + assert.ok( + event.prepareBlockedMs >= 30 && event.sendBlockedMs < 30, + `preparation delay must not be attributed to the send: ${JSON.stringify(event)}`, + ); + }); + test('`/env` runs the runtime command when listed and emits markdown output', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); mockSession.commandListResult = { diff --git a/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts index 06fe418c09026..5dbb34206d28d 100644 --- a/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts @@ -17,7 +17,7 @@ class TestClock { suite('CopilotMcpReadinessTracker', () => { ensureNoDisposablesAreLeakedInTestSuite(); - test('reports the slowest parallel server as the startup window', () => { + test('reports the slowest individual server startup', () => { const clock = new TestClock(); const tracker = new CopilotMcpReadinessTracker(clock); for (const name of ['fast', 'slow', 'broken', 'waiting']) { @@ -40,7 +40,25 @@ suite('CopilotMcpReadinessTracker', () => { }); }); - test('keeps the first settle time when a server is re-reported', () => { + test('excludes idle time between an early server settling and a later one starting', () => { + const clock = new TestClock(); + const tracker = new CopilotMcpReadinessTracker(clock); + tracker.observe('a', 'pending'); + clock.advanceTo(100); + tracker.observe('a', 'connected'); + + // Ten minutes later a second server is added and takes one second. + clock.advanceTo(600_000); + tracker.observe('b', 'pending'); + clock.advanceTo(601_000); + tracker.observe('b', 'connected'); + + assert.deepStrictEqual(tracker.snapshot(), { + serverCount: 2, readyCount: 2, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: 1000, + }); + }); + + test('keeps the first duration when a server is re-reported', () => { const clock = new TestClock(); const tracker = new CopilotMcpReadinessTracker(clock); tracker.observe('server', 'pending'); @@ -54,35 +72,41 @@ suite('CopilotMcpReadinessTracker', () => { }); }); - test('treats needs-auth as unsettled and reports no window until something settles', () => { + test('reports no duration for startups it did not observe end to end', () => { const clock = new TestClock(); - const tracker = new CopilotMcpReadinessTracker(clock); - tracker.observe('auth', 'needs-auth'); + // Still starting. + const unresolved = new CopilotMcpReadinessTracker(clock); + unresolved.observe('auth', 'needs-auth'); + // First seen already connected, e.g. an inventory seed after the fact. + const seeded = new CopilotMcpReadinessTracker(clock); + seeded.observe('already-up', 'connected'); clock.advanceTo(2000); - assert.deepStrictEqual([tracker.snapshot(), new CopilotMcpReadinessTracker(new TestClock()).snapshot()], [ + assert.deepStrictEqual([unresolved.snapshot(), seeded.snapshot(), new CopilotMcpReadinessTracker(new TestClock()).snapshot()], [ { serverCount: 1, readyCount: 0, failedCount: 0, unresolvedCount: 1, stoppedCount: 0, slowestServerMs: undefined }, + { serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: undefined }, { serverCount: 0, readyCount: 0, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: undefined }, ]); }); - test('excludes servers that never start from the window rather than reporting zero', () => { + test('excludes servers that never start, and times one that starts after being disabled', () => { const clock = new TestClock(); const allStopped = new CopilotMcpReadinessTracker(clock); allStopped.observe('off', 'disabled'); allStopped.observe('absent', 'not_configured'); - // A stopped server observed first must not anchor the window early. - const mixed = new CopilotMcpReadinessTracker(clock); - mixed.observe('off', 'disabled'); + // Disabled first, then enabled and takes a second: the disabled + // observation must not anchor or short-circuit the measurement. + const enabledLater = new CopilotMcpReadinessTracker(clock); + enabledLater.observe('later', 'disabled'); clock.advanceTo(1000); - mixed.observe('real', 'pending'); - clock.advanceTo(4000); - mixed.observe('real', 'connected'); + enabledLater.observe('later', 'pending'); + clock.advanceTo(2000); + enabledLater.observe('later', 'connected'); - assert.deepStrictEqual([allStopped.snapshot(), mixed.snapshot()], [ + assert.deepStrictEqual([allStopped.snapshot(), enabledLater.snapshot()], [ { serverCount: 2, readyCount: 0, failedCount: 0, unresolvedCount: 0, stoppedCount: 2, slowestServerMs: undefined }, - { serverCount: 2, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 1, slowestServerMs: 3000 }, + { serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: 1000 }, ]); }); }); From 06063c15297a6b205a96240f684901ca9fd528ff Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 15:48:28 -0700 Subject: [PATCH 5/6] agentHost: report dispatch phases for resume and preparation failures Close the two gaps flagged in review: - resume() runs the same _prepareSdkTurn but emitted no telemetry, so a resume continuation could pay the MCP inventory cost invisibly. It now reports on the same event, tagged sendKind=resume. - A failure during preparation threw before the instrumented block and emitted nothing. Both phases are now inside one try, and the new outcome field records which phase failed, with cancellation distinguished from other failures. Replaces the sendFailed boolean with outcome, and moves the reporter to a report object rather than nine positional arguments. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../node/agentHostTelemetryReporter.ts | 78 ++++++++----- .../node/copilot/copilotAgentSession.ts | 110 +++++++++++------- .../test/node/copilotAgentSession.test.ts | 40 +++++-- 3 files changed, 150 insertions(+), 78 deletions(-) diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index a5ef53d02bce0..0e1b21a6f6e11 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -197,14 +197,18 @@ export interface IAgentHostClientConnectionReport { subscriptionCount?: number; } +export type AgentHostProviderSendKind = 'message' | 'resume'; +export type AgentHostProviderSendOutcome = 'success' | 'prepareFailed' | 'sendFailed' | 'cancelled'; + export interface IAgentHostProviderSendBlockedEvent { provider: string; agentSessionId: string; turnId: string; + sendKind: AgentHostProviderSendKind; prepareBlockedMs: number; sendBlockedMs: number; + outcome: AgentHostProviderSendOutcome; isFirstSendOfSession: boolean; - sendFailed: boolean; mcpServerCount: number; mcpReadyCount: number; mcpFailedCount: number; @@ -223,22 +227,35 @@ export interface IAgentHostMcpReadinessReport { readonly slowestServerMs: number | undefined; } +export interface IAgentHostProviderSendBlockedReport { + readonly provider: string; + readonly session: string; + readonly turnId: string; + readonly sendKind: AgentHostProviderSendKind; + readonly prepareBlockedMs: number; + readonly sendBlockedMs: number; + readonly outcome: AgentHostProviderSendOutcome; + readonly isFirstSendOfSession: boolean; + readonly mcp: IAgentHostMcpReadinessReport; +} + export type IAgentHostProviderSendBlockedClassification = { provider: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The provider handling the agent host session.' }; agentSessionId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The agent host session identifier.' }; - turnId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The turn this send belongs to, so the phases can be joined to the turn and first-response timings.' }; - prepareBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds spent preparing the turn before the provider send call, including the MCP inventory refresh that can wait on live server discovery.' }; - sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider send call itself blocked before returning, excluding turn preparation.' }; - isFirstSendOfSession: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether this was the first send on a newly created provider session, where startup costs are paid.' }; - sendFailed: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether the provider send call threw instead of returning normally.' }; - mcpServerCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers observed for the session when the send returned.' }; - mcpReadyCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had connected when the send returned.' }; - mcpFailedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had failed when the send returned.' }; - mcpUnresolvedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers still starting or awaiting authentication when the send returned.' }; + turnId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The turn this dispatch belongs to, so the phases can be joined to the turn and first-response timings.' }; + sendKind: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'Whether this dispatched a user or agent message, or resumed a turn with a zero-message continuation.' }; + prepareBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds spent preparing the turn before the provider call, including the MCP inventory refresh that can wait on server discovery.' }; + sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider call itself blocked before returning, excluding turn preparation. Zero when preparation failed and the provider was never called.' }; + outcome: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Whether the dispatch succeeded, was cancelled, or failed, and for a failure which phase it failed in.' }; + isFirstSendOfSession: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether this was the first dispatch on a newly created provider session, where startup costs are paid.' }; + mcpServerCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers observed for the session when the dispatch ended.' }; + mcpReadyCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had connected when the dispatch ended.' }; + mcpFailedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that had failed when the dispatch ended.' }; + mcpUnresolvedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers still starting or awaiting authentication when the dispatch ended.' }; mcpStoppedCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Number of MCP servers that never started because they are disabled or not configured, and so contributed no startup time.' }; slowestMcpServerMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'The longest startup any single MCP server took, in milliseconds; absent when no server startup was observed end to end.' }; owner: 'vijayupadya'; - comment: 'Measures the turn-preparation and provider-send phases that precede provider execution, with the MCP server startup context they overlap.'; + comment: 'Measures the turn-preparation and provider-dispatch phases that precede provider execution, with the MCP server startup context they overlap.'; }; export type AgentHostTurnResult = 'success' | 'error' | 'cancelled'; @@ -1064,27 +1081,28 @@ export class AgentHostTelemetryReporter { /** * Reports the two phases that precede provider execution: turn preparation - * (which awaits an MCP inventory refresh that can wait on live server - * discovery) and the provider send call itself. Host turn timing covers - * both inside its total but attributes neither, so a stall in one cannot - * be told from a stall in the other. MCP counts describe the server startup - * these phases overlap, which is the usual reason either is long. + * (which awaits an MCP inventory refresh that can wait on server discovery) + * and the provider call itself. Host turn timing covers both inside its + * total but attributes neither, so a stall in one cannot be told from a + * stall in the other. MCP counts describe the server startup these phases + * overlap, which is the usual reason either is long. */ - providerSendBlocked(provider: string, session: string, turnId: string, prepareBlockedMs: number, sendBlockedMs: number, isFirstSendOfSession: boolean, sendFailed: boolean, mcp: IAgentHostMcpReadinessReport): void { + providerSendBlocked(report: IAgentHostProviderSendBlockedReport): void { this._telemetryService.publicLog2('agentHost.providerSendBlocked', { - provider, - agentSessionId: AgentSession.id(session), - turnId, - prepareBlockedMs, - sendBlockedMs, - isFirstSendOfSession, - sendFailed, - mcpServerCount: mcp.serverCount, - mcpReadyCount: mcp.readyCount, - mcpFailedCount: mcp.failedCount, - mcpUnresolvedCount: mcp.unresolvedCount, - mcpStoppedCount: mcp.stoppedCount, - slowestMcpServerMs: mcp.slowestServerMs, + provider: report.provider, + agentSessionId: AgentSession.id(report.session), + turnId: report.turnId, + sendKind: report.sendKind, + prepareBlockedMs: report.prepareBlockedMs, + sendBlockedMs: report.sendBlockedMs, + outcome: report.outcome, + isFirstSendOfSession: report.isFirstSendOfSession, + mcpServerCount: report.mcp.serverCount, + mcpReadyCount: report.mcp.readyCount, + mcpFailedCount: report.mcp.failedCount, + mcpUnresolvedCount: report.mcp.unresolvedCount, + mcpStoppedCount: report.mcp.stoppedCount, + slowestMcpServerMs: report.mcp.slowestServerMs, }); } diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 2ea212273d0fc..81af180094258 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -11,7 +11,7 @@ import { DeferredPromise, firstParallel, raceCancellation, raceTimeout, RunOnceS import { encodeBase64, VSBuffer } from '../../../../base/common/buffer.js'; import { CancellationToken, CancellationTokenSource } from '../../../../base/common/cancellation.js'; import { Emitter } from '../../../../base/common/event.js'; -import { CancellationError, getErrorMessage } from '../../../../base/common/errors.js'; +import { CancellationError, getErrorMessage, isCancellationError } from '../../../../base/common/errors.js'; import { escapeMarkdownSyntaxTokens } from '../../../../base/common/htmlContent.js'; import { Disposable, DisposableMap, IReference, MutableDisposable, toDisposable } from '../../../../base/common/lifecycle.js'; import { LRUCache } from '../../../../base/common/map.js'; @@ -70,7 +70,7 @@ import { isAutoModel } from './modelIdentifiers.js'; import { applySandboxConfig, clientToolNamesFromSnapshot, isMcpServerExplicitlyProjected, type CopilotSessionLaunchPlan, type IActiveClientSnapshot, type ICopilotSessionLauncher, type ICopilotSessionRuntime } from './copilotSessionLauncher.js'; import { CLIENT_TOOL_SEARCH_REFERENCE_NAME, NON_DEFERRED_CLIENT_TOOL_NAMES, RUNTIME_TOOL_SEARCH_TOOL_NAME } from './toolSearchDeferral.js'; import { ActiveClientToolSet } from '../activeClientState.js'; -import { AgentHostTelemetryReporter, toInitiatorTelemetry, type IAgentHostEventClassification, type IAgentHostEventTelemetry } from '../agentHostTelemetryReporter.js'; +import { AgentHostTelemetryReporter, toInitiatorTelemetry, type AgentHostProviderSendKind, type AgentHostProviderSendOutcome, type IAgentHostEventClassification, type IAgentHostEventTelemetry } from '../agentHostTelemetryReporter.js'; import { AgentHostRepoInfoTelemetry } from '../agentHostRepoInfoTelemetry.js'; import { PendingRequestRegistry } from '../../common/pendingRequestRegistry.js'; import { buildCopilotSystemNotification } from './copilotSystemNotification.js'; @@ -3063,21 +3063,25 @@ export class CopilotAgentSession extends Disposable { const sdkAttachments = await this._toSdkAttachments(attachments); - // Preparation is timed separately from the send: it awaits several RPCs, - // including an MCP inventory refresh that can itself wait on live server - // discovery. Folding the two together would attribute a preparation stall - // to the provider call, or hide it entirely. - const prepareWatch = StopWatch.create(false); - await this._prepareSdkTurn(mode); - const prepareBlockedMs = Math.round(prepareWatch.elapsed()); - const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); - const sendingTurn = this._currentTurn.value; - sendingTurn?.markProviderCallPending(); + // Preparation and the provider call are timed separately: preparation + // awaits several RPCs, including an MCP inventory refresh that can wait + // on server discovery. Folding them together would attribute a + // preparation stall to the provider call, or hide it. Both are inside + // one try so a failure in either phase still reports where it happened. + const phaseWatch = StopWatch.create(false); + let prepareBlockedMs = 0; + let sendBlockedMs = 0; + let outcome: AgentHostProviderSendOutcome = 'prepareFailed'; const isFirstSendOfSession = this._pendingFirstSend; this._pendingFirstSend = false; - const sendWatch = StopWatch.create(false); - let sendFailed = false; + let sendingTurn: CopilotTurn | undefined; try { + await this._prepareSdkTurn(mode); + prepareBlockedMs = Math.round(phaseWatch.elapsed()); + outcome = 'sendFailed'; + const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); + sendingTurn = this._currentTurn.value; + sendingTurn?.markProviderCallPending(); await this._otelService.withTraceContext(traceContext, () => { if (!this._environmentService.isBuilt && prompt === '$error') { return this._wrapper.session.rpc.sendMessages({ @@ -3088,40 +3092,49 @@ export class CopilotAgentSession extends Disposable { return this._wrapper.session.send({ prompt, attachments: sdkAttachments?.length ? sdkAttachments : undefined }); }); sendingTurn?.markProviderCallResolved(); + outcome = 'success'; } catch (error) { - sendFailed = true; - sendingTurn?.markProviderCallRejected(); + if (outcome === 'sendFailed') { + sendingTurn?.markProviderCallRejected(); + } + if (isCancellationError(error)) { + outcome = 'cancelled'; + } throw error; } finally { - // Reported as two separate phases so a stall can be attributed. The - // send is the provider call alone; preparation precedes it and awaits - // an MCP inventory refresh that can wait on live server discovery. - // Host turn timing covers both in its total but attributes neither. - // - // Guarded because this runs in a `finally`: a throw from reporting here - // would replace the provider error the `catch` above is rethrowing, - // turning a real send failure into a telemetry failure. - try { - const sendBlockedMs = Math.round(sendWatch.elapsed()); - const mcp = this._mcpReadiness.snapshot(); - this._telemetryReporter.providerSendBlocked( - this._ownerSessionUri.scheme, - this._ownerSessionUri.toString(), - this._turnId, - prepareBlockedMs, - sendBlockedMs, - isFirstSendOfSession, - sendFailed, - mcp, - ); - this._logService.info(`[Copilot:${this.sessionId}] send phases: prepare=${prepareBlockedMs}ms, send=${sendBlockedMs}ms (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); - } catch (err) { - this._logService.trace(`[Copilot:${this.sessionId}] Telemetry emission failed: ${getErrorMessage(err)}`); - } + sendBlockedMs = Math.round(phaseWatch.elapsed()) - prepareBlockedMs; + this._reportSendPhases('message', prepareBlockedMs, sendBlockedMs, outcome, isFirstSendOfSession); } this._logService.info(`[Copilot:${this.sessionId}] session.send() returned`); } + /** + * Emits the preparation and provider-call phase timings for one dispatch. + * + * Guarded because callers invoke this from a `finally`: a throw from + * reporting would replace the error being rethrown, turning a real provider + * failure into a telemetry failure. + */ + private _reportSendPhases(sendKind: AgentHostProviderSendKind, prepareBlockedMs: number, sendBlockedMs: number, outcome: AgentHostProviderSendOutcome, isFirstSendOfSession: boolean): void { + try { + const mcp = this._mcpReadiness.snapshot(); + this._telemetryReporter.providerSendBlocked({ + provider: this._ownerSessionUri.scheme, + session: this._ownerSessionUri.toString(), + turnId: this._turnId, + sendKind, + prepareBlockedMs, + sendBlockedMs, + outcome, + isFirstSendOfSession, + mcp, + }); + this._logService.info(`[Copilot:${this.sessionId}] ${sendKind} phases: prepare=${prepareBlockedMs}ms, send=${sendBlockedMs}ms, outcome=${outcome} (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); + } catch (err) { + this._logService.trace(`[Copilot:${this.sessionId}] Telemetry emission failed: ${getErrorMessage(err)}`); + } + } + async resume(turnId: string, mode?: CopilotSdkMode, senderClientId?: string, clientType = AgentHostClientType.Unknown, clientContext = createUnknownAgentHostClientTelemetryContext(clientType), agentMergeTurn = false): Promise { this._resetAbortToken(); this.resetTurnState(turnId, senderClientId, clientType, clientContext); @@ -3132,11 +3145,21 @@ export class CopilotAgentSession extends Disposable { const turn = this._currentTurn.value; this._resumingTurnAwaitingProviderStart = turn; turn?.markProviderCallPending(); + // Resume runs the same `_prepareSdkTurn`, so it can pay the same MCP + // inventory cost as a message send and is reported on the same event. + const phaseWatch = StopWatch.create(false); + let prepareBlockedMs = 0; + let outcome: AgentHostProviderSendOutcome = 'prepareFailed'; + const isFirstSendOfSession = this._pendingFirstSend; + this._pendingFirstSend = false; try { await this._prepareSdkTurn(mode); + prepareBlockedMs = Math.round(phaseWatch.elapsed()); + outcome = 'sendFailed'; const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); await this._otelService.withTraceContext(traceContext, () => this._wrapper.session.rpc.sendMessages({ messages: [] })); turn?.markProviderCallResolved(); + outcome = 'success'; this._logService.info(`[Copilot:${this.sessionId}] zero-message continuation returned`); } catch (error) { if (this._resumingTurnAwaitingProviderStart === turn) { @@ -3146,7 +3169,12 @@ export class CopilotAgentSession extends Disposable { turn.markProviderCallRejected(); this._clearActiveTurn(); } + if (isCancellationError(error)) { + outcome = 'cancelled'; + } throw error; + } finally { + this._reportSendPhases('resume', prepareBlockedMs, Math.round(phaseWatch.elapsed()) - prepareBlockedMs, outcome, isFirstSendOfSession); } } diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index 178de04573620..9584f2cd2d9ff 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -3221,27 +3221,53 @@ suite('CopilotAgentSession', () => { assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [ { - provider: 'copilot', turnId: 'turn-1', isFirstSendOfSession: true, sendFailed: false, + provider: 'copilot', turnId: 'turn-1', sendKind: 'message', outcome: 'success', isFirstSendOfSession: true, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }, { - provider: 'copilot', turnId: 'turn-2', isFirstSendOfSession: false, sendFailed: false, + provider: 'copilot', turnId: 'turn-2', sendKind: 'message', outcome: 'success', isFirstSendOfSession: false, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }, ]); }); - test('send blocking telemetry still reports when the provider send rejects', async () => { + test('send blocking telemetry distinguishes a failed send from a failed preparation', async () => { const telemetryService = new CapturingTelemetryService(); - const { session, mockSession } = await createAgentSession(disposables, { telemetryService }); + const { session, mockSession, setConfigValue, fireSessionConfigChange } = await createAgentSession(disposables, { telemetryService }); + const workingSend = mockSession.send.bind(mockSession); mockSession.send = async () => { throw new Error('send failed'); }; - await assert.rejects(() => session.send('hello', undefined, 'turn-failed'), /send failed/); + await assert.rejects(() => session.send('hello', undefined, 'turn-send-failed'), /send failed/); + + // Preparation runs before the provider call, so a failure there must be + // reported as its own phase rather than going unrecorded. The sandbox + // sync propagates, unlike `applyMode`, which logs and continues. + mockSession.send = workingSend; + mockSession.sandboxConfigUpdateSuccess = false; + setConfigValue(SessionConfigKey.SandboxEnabled, 'on'); + fireSessionConfigChange({ [SessionConfigKey.SandboxEnabled]: 'on' }); + await timeout(0); + await assert.rejects(() => session.send('hello', undefined, 'turn-prepare-failed'), /rejected sandbox config update/); + + assert.deepStrictEqual(providerSendBlockedEvents(telemetryService).map(event => { + const { mcpServerCount, mcpReadyCount, mcpFailedCount, mcpUnresolvedCount, mcpStoppedCount, ...rest } = event as Record; + return rest; + }), [ + { provider: 'copilot', turnId: 'turn-send-failed', sendKind: 'message', outcome: 'sendFailed', isFirstSendOfSession: true, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false }, + { provider: 'copilot', turnId: 'turn-prepare-failed', sendKind: 'message', outcome: 'prepareFailed', isFirstSendOfSession: false, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false }, + ]); + }); + + test('resume reports its own preparation and provider call', async () => { + const telemetryService = new CapturingTelemetryService(); + const { session } = await createAgentSession(disposables, { telemetryService }); + + await session.resume('turn-resumed'); assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [{ - provider: 'copilot', turnId: 'turn-failed', isFirstSendOfSession: true, sendFailed: true, + provider: 'copilot', turnId: 'turn-resumed', sendKind: 'resume', outcome: 'success', isFirstSendOfSession: true, mcpServerCount: 0, mcpReadyCount: 0, mcpFailedCount: 0, mcpUnresolvedCount: 0, mcpStoppedCount: 0, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, }]); @@ -3252,7 +3278,7 @@ suite('CopilotAgentSession', () => { const { session, mockSession } = await createAgentSession(disposables, { telemetryService }); // `_prepareSdkTurn` awaits several RPCs before the send, including an MCP - // inventory refresh that can itself wait on live server discovery. Gate one + // inventory refresh that can itself wait on server discovery. Gate one // of those awaits: the delay must land in `prepareBlockedMs`, never in // `sendBlockedMs`, or a preparation stall would be misread as a slow send. let releasePrepare = () => { }; From 1d28fe5d7a3dd4e13e1ae9aaadbbd3f5eac0e274 Mon Sep 17 00:00:00 2001 From: Vijay Upadya <41652029+vijayupadya@users.noreply.github.com> Date: Fri, 18 Sep 2026 16:50:45 -0700 Subject: [PATCH 6/6] agentHost: report the MCP enablement reconcile as its own phase Local validation with 7 configured MCP servers shows the reconcile is the dominant cost of turn preparation, and that the provider send is not the bottleneck at all: prepare.applyMode=5ms prepare.syncPermissionMode=4ms prepare.applySandboxConfig=44ms prepare.syncShellInitScript=0ms prepare.reconcileMcpServerEnablement=57228ms message prepare=57281ms send=8ms outcome=success Add prepareMcpReconcileMs so that step is attributable on its own instead of being hidden inside the preparation total. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../node/agentHostTelemetryReporter.ts | 6 ++- .../node/copilot/copilotAgentSession.ts | 25 +++++++---- .../test/node/copilotAgentSession.test.ts | 41 ++++++++++++++++--- 3 files changed, 58 insertions(+), 14 deletions(-) diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index 0e1b21a6f6e11..242f446d9eddb 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -206,6 +206,7 @@ export interface IAgentHostProviderSendBlockedEvent { turnId: string; sendKind: AgentHostProviderSendKind; prepareBlockedMs: number; + prepareMcpReconcileMs: number; sendBlockedMs: number; outcome: AgentHostProviderSendOutcome; isFirstSendOfSession: boolean; @@ -233,6 +234,7 @@ export interface IAgentHostProviderSendBlockedReport { readonly turnId: string; readonly sendKind: AgentHostProviderSendKind; readonly prepareBlockedMs: number; + readonly prepareMcpReconcileMs: number; readonly sendBlockedMs: number; readonly outcome: AgentHostProviderSendOutcome; readonly isFirstSendOfSession: boolean; @@ -244,7 +246,8 @@ export type IAgentHostProviderSendBlockedClassification = { agentSessionId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The agent host session identifier.' }; turnId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'The turn this dispatch belongs to, so the phases can be joined to the turn and first-response timings.' }; sendKind: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'Whether this dispatched a user or agent message, or resumed a turn with a zero-message continuation.' }; - prepareBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds spent preparing the turn before the provider call, including the MCP inventory refresh that can wait on server discovery.' }; + prepareBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds spent preparing the turn before the provider call, including the MCP enablement reconcile.' }; + prepareMcpReconcileMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds of the MCP enablement reconcile within turn preparation. It awaits an inventory refresh whose latency tracks MCP server discovery, so it can dominate preparation.' }; sendBlockedMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Time in milliseconds the provider call itself blocked before returning, excluding turn preparation. Zero when preparation failed and the provider was never called.' }; outcome: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Whether the dispatch succeeded, was cancelled, or failed, and for a failure which phase it failed in.' }; isFirstSendOfSession: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Whether this was the first dispatch on a newly created provider session, where startup costs are paid.' }; @@ -1094,6 +1097,7 @@ export class AgentHostTelemetryReporter { turnId: report.turnId, sendKind: report.sendKind, prepareBlockedMs: report.prepareBlockedMs, + prepareMcpReconcileMs: report.prepareMcpReconcileMs, sendBlockedMs: report.sendBlockedMs, outcome: report.outcome, isFirstSendOfSession: report.isFirstSendOfSession, diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 81af180094258..0a77836d8b85f 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -3070,13 +3070,14 @@ export class CopilotAgentSession extends Disposable { // one try so a failure in either phase still reports where it happened. const phaseWatch = StopWatch.create(false); let prepareBlockedMs = 0; + let mcpReconcileMs = 0; let sendBlockedMs = 0; let outcome: AgentHostProviderSendOutcome = 'prepareFailed'; const isFirstSendOfSession = this._pendingFirstSend; this._pendingFirstSend = false; let sendingTurn: CopilotTurn | undefined; try { - await this._prepareSdkTurn(mode); + mcpReconcileMs = await this._prepareSdkTurn(mode); prepareBlockedMs = Math.round(phaseWatch.elapsed()); outcome = 'sendFailed'; const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); @@ -3103,7 +3104,7 @@ export class CopilotAgentSession extends Disposable { throw error; } finally { sendBlockedMs = Math.round(phaseWatch.elapsed()) - prepareBlockedMs; - this._reportSendPhases('message', prepareBlockedMs, sendBlockedMs, outcome, isFirstSendOfSession); + this._reportSendPhases('message', prepareBlockedMs, mcpReconcileMs, sendBlockedMs, outcome, isFirstSendOfSession); } this._logService.info(`[Copilot:${this.sessionId}] session.send() returned`); } @@ -3115,7 +3116,7 @@ export class CopilotAgentSession extends Disposable { * reporting would replace the error being rethrown, turning a real provider * failure into a telemetry failure. */ - private _reportSendPhases(sendKind: AgentHostProviderSendKind, prepareBlockedMs: number, sendBlockedMs: number, outcome: AgentHostProviderSendOutcome, isFirstSendOfSession: boolean): void { + private _reportSendPhases(sendKind: AgentHostProviderSendKind, prepareBlockedMs: number, mcpReconcileMs: number, sendBlockedMs: number, outcome: AgentHostProviderSendOutcome, isFirstSendOfSession: boolean): void { try { const mcp = this._mcpReadiness.snapshot(); this._telemetryReporter.providerSendBlocked({ @@ -3124,12 +3125,13 @@ export class CopilotAgentSession extends Disposable { turnId: this._turnId, sendKind, prepareBlockedMs, + prepareMcpReconcileMs: mcpReconcileMs, sendBlockedMs, outcome, isFirstSendOfSession, mcp, }); - this._logService.info(`[Copilot:${this.sessionId}] ${sendKind} phases: prepare=${prepareBlockedMs}ms, send=${sendBlockedMs}ms, outcome=${outcome} (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); + this._logService.info(`[Copilot:${this.sessionId}] ${sendKind} phases: prepare=${prepareBlockedMs}ms (mcpReconcile=${mcpReconcileMs}ms), send=${sendBlockedMs}ms, outcome=${outcome} (firstSend=${isFirstSendOfSession}, mcp=${JSON.stringify(mcp)})`); } catch (err) { this._logService.trace(`[Copilot:${this.sessionId}] Telemetry emission failed: ${getErrorMessage(err)}`); } @@ -3149,11 +3151,12 @@ export class CopilotAgentSession extends Disposable { // inventory cost as a message send and is reported on the same event. const phaseWatch = StopWatch.create(false); let prepareBlockedMs = 0; + let mcpReconcileMs = 0; let outcome: AgentHostProviderSendOutcome = 'prepareFailed'; const isFirstSendOfSession = this._pendingFirstSend; this._pendingFirstSend = false; try { - await this._prepareSdkTurn(mode); + mcpReconcileMs = await this._prepareSdkTurn(mode); prepareBlockedMs = Math.round(phaseWatch.elapsed()); outcome = 'sendFailed'; const traceContext = this._otelService.getSessionTraceContext(this.sessionId, this.resourceUri.toString()); @@ -3174,7 +3177,7 @@ export class CopilotAgentSession extends Disposable { } throw error; } finally { - this._reportSendPhases('resume', prepareBlockedMs, Math.round(phaseWatch.elapsed()) - prepareBlockedMs, outcome, isFirstSendOfSession); + this._reportSendPhases('resume', prepareBlockedMs, mcpReconcileMs, Math.round(phaseWatch.elapsed()) - prepareBlockedMs, outcome, isFirstSendOfSession); } } @@ -3269,12 +3272,20 @@ export class CopilotAgentSession extends Disposable { * permission mode, sandbox, shell init script, and MCP enablement. * Permission and sandbox failures prevent the turn from starting. */ - private async _prepareSdkTurn(mode: CopilotSdkMode | undefined): Promise { + /** + * Runs the pre-dispatch RPCs and returns how long the MCP enablement + * reconcile took. That step awaits an inventory refresh whose latency + * tracks MCP server discovery, so it is reported separately: it can + * dominate the whole preparation phase. + */ + private async _prepareSdkTurn(mode: CopilotSdkMode | undefined): Promise { await this.applyMode(mode); await this.syncPermissionMode('turn-start'); await this._applyEffectiveSandboxConfig(); await this._syncShellInitScript(); + const reconcileWatch = StopWatch.create(false); await this._reconcileMcpServerEnablement(); + return Math.round(reconcileWatch.elapsed()); } /** diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index 9584f2cd2d9ff..653f9bd25fedc 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -680,11 +680,12 @@ function providerSendBlockedEvents(telemetryService: CapturingTelemetryService): return telemetryService.events .filter(event => event.eventName === 'agentHost.providerSendBlocked') .map(event => { - const { sendBlockedMs, prepareBlockedMs, slowestMcpServerMs, agentSessionId, ...rest } = event.data as Record; + const { sendBlockedMs, prepareBlockedMs, prepareMcpReconcileMs, slowestMcpServerMs, agentSessionId, ...rest } = event.data as Record; return { ...rest, hasBlockedMs: typeof sendBlockedMs === 'number', hasPrepareMs: typeof prepareBlockedMs === 'number', + hasMcpReconcileMs: typeof prepareMcpReconcileMs === 'number', hasSlowestMcpServerMs: typeof slowestMcpServerMs === 'number', }; }); @@ -3223,12 +3224,12 @@ suite('CopilotAgentSession', () => { { provider: 'copilot', turnId: 'turn-1', sendKind: 'message', outcome: 'success', isFirstSendOfSession: true, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, - hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, + hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false, }, { provider: 'copilot', turnId: 'turn-2', sendKind: 'message', outcome: 'success', isFirstSendOfSession: false, mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, - hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, + hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false, }, ]); }); @@ -3255,8 +3256,8 @@ suite('CopilotAgentSession', () => { const { mcpServerCount, mcpReadyCount, mcpFailedCount, mcpUnresolvedCount, mcpStoppedCount, ...rest } = event as Record; return rest; }), [ - { provider: 'copilot', turnId: 'turn-send-failed', sendKind: 'message', outcome: 'sendFailed', isFirstSendOfSession: true, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false }, - { provider: 'copilot', turnId: 'turn-prepare-failed', sendKind: 'message', outcome: 'prepareFailed', isFirstSendOfSession: false, hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false }, + { provider: 'copilot', turnId: 'turn-send-failed', sendKind: 'message', outcome: 'sendFailed', isFirstSendOfSession: true, hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false }, + { provider: 'copilot', turnId: 'turn-prepare-failed', sendKind: 'message', outcome: 'prepareFailed', isFirstSendOfSession: false, hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false }, ]); }); @@ -3269,7 +3270,7 @@ suite('CopilotAgentSession', () => { assert.deepStrictEqual(providerSendBlockedEvents(telemetryService), [{ provider: 'copilot', turnId: 'turn-resumed', sendKind: 'resume', outcome: 'success', isFirstSendOfSession: true, mcpServerCount: 0, mcpReadyCount: 0, mcpFailedCount: 0, mcpUnresolvedCount: 0, mcpStoppedCount: 0, - hasBlockedMs: true, hasPrepareMs: true, hasSlowestMcpServerMs: false, + hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false, }]); }); @@ -3297,6 +3298,34 @@ suite('CopilotAgentSession', () => { ); }); + test('a slow MCP inventory refresh is attributed to the reconcile step within preparation', async () => { + const telemetryService = new CapturingTelemetryService(); + const { session, mockSession, setConfigValue, fireSessionConfigChange } = await createAgentSession(disposables, { + telemetryService, + configureMockSession: m => { + m.mcpListResult = { servers: [{ name: 'slow-server', status: 'connected' }] }; + }, + }); + // Give the reconcile a desired-enablement entry, so it does not early-return + // before reaching the inventory refresh. + setConfigValue(SessionConfigKey.SandboxEnabled, 'off'); + fireSessionConfigChange({ [SessionConfigKey.SandboxEnabled]: 'off' }); + + // `rpc.mcp.list()` latency tracks MCP server discovery, so it is the step + // that can dominate preparation. It must be attributable on its own rather + // than hidden inside the preparation total. + const listed = mockSession.rpc.mcp.list.bind(mockSession.rpc.mcp); + mockSession.rpc.mcp.list = async () => { await timeout(40); return listed(); }; + + await session.send('hello', undefined, 'turn-slow-reconcile'); + + const event = singleProviderSendBlockedEvent(telemetryService); + assert.ok( + event.prepareMcpReconcileMs <= event.prepareBlockedMs && event.sendBlockedMs < 30, + `reconcile must be a bounded part of preparation and not the send: ${JSON.stringify(event)}`, + ); + }); + test('`/env` runs the runtime command when listed and emits markdown output', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); mockSession.commandListResult = {