agentHost: attribute turn preparation and provider send, with MCP startup context

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<IAgentHostProviderSendBlockedEvent, IAgentHostProviderSendBlockedClassification>('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

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<string, SdkMcpServerStatus>();
 
+	/**
+	 * 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<string>;
@@ -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<void> {
 		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<void> {
+	/**
+	 * 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<number> {
 		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);