diff --git a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts index 7f6a00850363f..242f446d9eddb 100644 --- a/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts +++ b/src/vs/platform/agentHost/node/agentHostTelemetryReporter.ts @@ -197,6 +197,70 @@ 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; + prepareMcpReconcileMs: number; + sendBlockedMs: number; + outcome: AgentHostProviderSendOutcome; + isFirstSendOfSession: boolean; + mcpServerCount: number; + mcpReadyCount: number; + mcpFailedCount: number; + mcpUnresolvedCount: number; + mcpStoppedCount: 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 stoppedCount: number; + readonly slowestServerMs: number | undefined; +} + +export interface IAgentHostProviderSendBlockedReport { + readonly provider: string; + readonly session: string; + readonly turnId: string; + readonly sendKind: AgentHostProviderSendKind; + readonly prepareBlockedMs: number; + readonly prepareMcpReconcileMs: 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 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 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.' }; + 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-dispatch phases that precede provider execution, with the MCP server startup context they overlap.'; +}; + export type AgentHostTurnResult = 'success' | 'error' | 'cancelled'; export type AgentHostModelTelemetryKind = 'trusted' | 'byok' | 'unknown'; type AgentHostModelSelectionKind = 'default' | 'auto' | 'explicit'; @@ -1018,6 +1082,34 @@ export class AgentHostTelemetryReporter { }); } + /** + * Reports the two phases that precede provider execution: turn preparation + * (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(report: IAgentHostProviderSendBlockedReport): void { + this._telemetryService.publicLog2('agentHost.providerSendBlocked', { + provider: report.provider, + agentSessionId: AgentSession.id(report.session), + turnId: report.turnId, + sendKind: report.sendKind, + prepareBlockedMs: report.prepareBlockedMs, + prepareMcpReconcileMs: report.prepareMcpReconcileMs, + 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, + }); + } + /** * 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..0a77836d8b85f 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'; @@ -64,12 +64,13 @@ 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'; 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'; @@ -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; @@ -3053,11 +3063,26 @@ export class CopilotAgentSession extends Disposable { const sdkAttachments = await this._toSdkAttachments(attachments); - await this._prepareSdkTurn(mode); - 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 mcpReconcileMs = 0; + let sendBlockedMs = 0; + let outcome: AgentHostProviderSendOutcome = 'prepareFailed'; + const isFirstSendOfSession = this._pendingFirstSend; + this._pendingFirstSend = false; + let sendingTurn: CopilotTurn | undefined; try { + mcpReconcileMs = 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({ @@ -3068,13 +3093,50 @@ export class CopilotAgentSession extends Disposable { return this._wrapper.session.send({ prompt, attachments: sdkAttachments?.length ? sdkAttachments : undefined }); }); sendingTurn?.markProviderCallResolved(); + outcome = 'success'; } catch (error) { - sendingTurn?.markProviderCallRejected(); + if (outcome === 'sendFailed') { + sendingTurn?.markProviderCallRejected(); + } + if (isCancellationError(error)) { + outcome = 'cancelled'; + } throw error; + } finally { + sendBlockedMs = Math.round(phaseWatch.elapsed()) - prepareBlockedMs; + this._reportSendPhases('message', prepareBlockedMs, mcpReconcileMs, 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, mcpReconcileMs: 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, + prepareMcpReconcileMs: mcpReconcileMs, + sendBlockedMs, + outcome, + isFirstSendOfSession, + 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)}`); + } + } + 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); @@ -3085,11 +3147,22 @@ 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 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()); 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) { @@ -3099,7 +3172,12 @@ export class CopilotAgentSession extends Disposable { turn.markProviderCallRejected(); this._clearActiveTurn(); } + if (isCancellationError(error)) { + outcome = 'cancelled'; + } throw error; + } finally { + this._reportSendPhases('resume', prepareBlockedMs, mcpReconcileMs, Math.round(phaseWatch.elapsed()) - prepareBlockedMs, outcome, isFirstSendOfSession); } } @@ -3194,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()); } /** @@ -6336,6 +6422,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 +6479,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..29128524cd85e --- /dev/null +++ b/src/vs/platform/agentHost/node/copilot/copilotMcpReadiness.ts @@ -0,0 +1,119 @@ +/*--------------------------------------------------------------------------------------------- + * 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'; + +/** + * 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 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, including ones that never started. */ + readonly serverCount: number; + /** Servers that reached `connected`. */ + readonly readyCount: number; + /** Servers that reached `failed`. */ + readonly failedCount: number; + /** 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; + /** + * 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; +} + +/** + * Tracks MCP server startup timing for a single Copilot SDK session. + * + * 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 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 duration, so repeated inventory snapshots + * do not inflate the measurement. + */ +export class CopilotMcpReadinessTracker { + + private readonly _statuses = new Map(); + private readonly _startedAtMs = new Map(); + private readonly _durationMs = new Map(); + + constructor(private readonly _clock: Pick = StopWatch.create()) { } + + /** 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; + } + 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); + } + } + + snapshot(): IMcpReadinessSnapshot { + 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 (!isParticipatingStatus(status)) { + stoppedCount++; + } else { + unresolvedCount++; + } + } + return { + serverCount: this._statuses.size, + readyCount, + failedCount, + unresolvedCount, + stoppedCount, + 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 c6b60e4fa37be..653f9bd25fedc 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -671,6 +671,33 @@ class CapturingTelemetryService implements ITelemetryService { // ---- Helpers ---------------------------------------------------------------- +/** + * Projects `agentHost.providerSendBlocked` payloads into a stable shape for + * 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, 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', + }; + }); +} + +/** 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 @@ -3180,6 +3207,125 @@ 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', turnId: 'turn-1', sendKind: 'message', outcome: 'success', isFirstSendOfSession: true, + mcpServerCount: 4, mcpReadyCount: 1, mcpFailedCount: 1, mcpUnresolvedCount: 1, mcpStoppedCount: 1, + 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, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false, + }, + ]); + }); + + test('send blocking telemetry distinguishes a failed send from a failed preparation', async () => { + const telemetryService = new CapturingTelemetryService(); + 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-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, hasMcpReconcileMs: true, hasSlowestMcpServerMs: false }, + { provider: 'copilot', turnId: 'turn-prepare-failed', sendKind: 'message', outcome: 'prepareFailed', isFirstSendOfSession: false, hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: 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-resumed', sendKind: 'resume', outcome: 'success', isFirstSendOfSession: true, + mcpServerCount: 0, mcpReadyCount: 0, mcpFailedCount: 0, mcpUnresolvedCount: 0, mcpStoppedCount: 0, + hasBlockedMs: true, hasPrepareMs: true, hasMcpReconcileMs: 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 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('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 = { @@ -9900,7 +10046,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..5dbb34206d28d --- /dev/null +++ b/src/vs/platform/agentHost/test/node/copilotMcpReadiness.test.ts @@ -0,0 +1,112 @@ +/*--------------------------------------------------------------------------------------------- + * 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 individual server startup', () => { + 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, + stoppedCount: 0, + slowestServerMs: 28918, + }); + }); + + 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'); + 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, stoppedCount: 0, slowestServerMs: 500, + }); + }); + + test('reports no duration for startups it did not observe end to end', () => { + const clock = new TestClock(); + // 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([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, 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'); + + // 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); + enabledLater.observe('later', 'pending'); + clock.advanceTo(2000); + enabledLater.observe('later', 'connected'); + + assert.deepStrictEqual([allStopped.snapshot(), enabledLater.snapshot()], [ + { serverCount: 2, readyCount: 0, failedCount: 0, unresolvedCount: 0, stoppedCount: 2, slowestServerMs: undefined }, + { serverCount: 1, readyCount: 1, failedCount: 0, unresolvedCount: 0, stoppedCount: 0, slowestServerMs: 1000 }, + ]); + }); +});