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

[Vijay Upadya (vijayupadya)]

Splits the two phases that run between a user's message and provider execution — turn preparation and the provider send call — and reports each with the MCP server startup context it overlaps.

Why

Investigating reports that the first turn in a new Agent Host session feels slow, a debug-log capture with MCP servers enabled showed ~38s from Enter to first visible text, of which ~30s was spent between sendMessage being called and the provider send returning, ending 6ms after the last MCP server settled:

Phase	Cost
Session prep	1.14s
Turn preparation + provider send	29.67s
Turn dispatch	0.91s
Auto-rename round trip	3.27s
Actual answer	2.56s

This was not model latency (turns took 2.4s and 2.6s once dispatched) and not prompt bloat (23,796 input tokens with 7 MCP servers vs 23,262 with none).

That 29.67s cannot be attributed further from the capture, which is the point of this change. Turn preparation awaits an MCP inventory refresh (_prepareSdkTurn → _reconcileMcpServerEnablement → rpc.mcp.list()) that can itself wait on live server discovery, and the provider send may also block. No log line marks the boundary, so the capture cannot say which phase held the time.

Host turn telemetry does not close the gap either: turnStarted fires before provider execution, so agentHost.turnCompleted.totalTime contains this time but has no field attributing it to either phase. The problem is attribution, not absence.

The blocking behaviour itself is in the Copilot CLI/SDK and is tracked separately in microsoft/vscode-internalbacklog#9483. This PR does not attempt to fix it; it makes the phases separable so the next capture can say where the time goes.

What

• agentHost.providerSendBlocked (new): prepareBlockedMs, sendBlockedMs, turnId, isFirstSendOfSession, sendFailed, plus MCP context (mcpServerCount, mcpReadyCount, mcpFailedCount, mcpUnresolvedCount, mcpStoppedCount, slowestMcpServerMs).
• CopilotMcpReadinessTracker (new): observation-only helper that times each MCP server's own startup interval and reports the longest. Servers start in parallel, so the longest is what gates readiness — and measuring per server rather than across the session means idle time between an early server settling and a later one starting is excluded. 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, since its startup was not observed. Only forward progress is recorded, so repeated inventory snapshots cannot inflate the measurement. Clock is injectable for tests.

Notes

• The two phases are timed separately because preparation awaits several RPCs before the send, including an MCP inventory refresh (_prepareSdkTurn → _reconcileMcpServerEnablement → rpc.mcp.list()). Folding them together would attribute a preparation stall to the provider call, or hide it.
• Scope: the event covers message sends through _send. It deliberately does not cover steering messages injected into an already-active turn (copilotAgentSession.ts:3502), or resume() continuations (which use rpc.sendMessages and whose preparation is likewise untimed) — neither is a session-startup path. Sessions with no MCP servers are included: they are the control group that makes the MCP correlation interpretable, so the event is not MCP-gated.
• Emission is in a finally around the send, so a send that throws is still reported, with sendFailed: true. Two limits worth knowing: cancellation is not distinguished from other failures, and a failure during preparation throws before the instrumented block and emits nothing at all. The reporting is itself guarded by a try/catch so it can never mask the provider error being rethrown.
• provider and agentSessionId derive from the owning session URI rather than the chat's persistence URI, so peer chats report copilotcli rather than ahp-chat.

Validation

• npm run typecheck-client clean.
• 5 unit tests for the readiness tracker, covering the slowest-server figure, idle time across later server additions, re-reported servers, startups not observed end to end, and never-started servers.
• 3 CopilotAgentSession tests covering the wiring: phase attribution under a gated preparation await, the first/subsequent send flag, the failure path, and the MCP snapshot fed through the real session.mcp_server_status_changed subscription.
• Full copilotAgentSession.test.ts suite passes (502 tests).
• Note: scripts/test.bat could not be run in this environment — it fails on a pre-existing @parcel/watcher module-resolution error in nodejsWatcher.test, reproducible with these changes stashed. Tests above were run directly via mocha.

[Copilot]

Copilot review overview

🟡 Changes recommended

Disabled-server timing, missing integration coverage, and the unimplemented info-level projection log must be addressed.

Get a fresh assessment by requesting another Copilot review.

Review effort: Balanced
Findings: 2 · 1

Open (3)

• Exclude disabled and unconfigured servers from startup timing · New
• Add session-level coverage for providerSendBlocked telemetry · New
• Raise MCP launch projection logging from trace to info · New

What changed in this PR

Adds telemetry to measure Copilot provider send latency and correlate it with MCP startup readiness.

Changes:

• Introduces MCP readiness tracking and tests.
• Emits agentHost.providerSendBlocked telemetry around provider sends.
• Adjusts an existing telemetry assertion.

File	Description
copilotMcpReadiness.test.ts	Tests readiness timing and counts.
copilotAgentSession.test.ts	Filters the new telemetry event from an existing assertion.
copilotMcpReadiness.ts	Tracks MCP startup states and timing.
copilotAgentSession.ts	Collects and emits send-blocking telemetry.
agentHostTelemetryReporter.ts	Defines and reports the new event.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[Vijay Upadya (vijayupadya)]

Thanks — this is a substantive review and finding 1 is a real error on my part. All four are addressed in ed56e0d.

1. Timer started after an MCP readiness barrier — confirmed, fixed

You are right, and I verified the chain: _prepareSdkTurn -> _reconcileMcpServerEnablement -> _doReconcileMcpServerEnablement -> await this._refreshMcpServersFromRpc() -> await mcpRpc.list(). That is all before my timer started.

The attribution in the PR description was not established by the capture, and I have corrected it. The 29.67s I quoted was measured between two log lines — sendMessage called and session.send() returned — and _prepareSdkTurn runs between them. There is no log line marking the prepare/send boundary, so that capture cannot distinguish the two phases. I should not have attributed it to session.send() alone.

Fixed by timing preparation as its own phase: prepareBlockedMs around _prepareSdkTurn, sendBlockedMs around the provider call only. The telemetry now answers the question rather than assuming it.

Added a slow turn preparation is attributed to the prepare phase, not the provider send, which gates a prepare-path await and asserts the delay lands in prepareBlockedMs and not sendBlockedMs. One note on how I built it: I gated rpc.mode.set rather than mcp.list(), because reaching the list() call requires non-empty desired MCP enablement (_doReconcileMcpServerEnablement returns early when desiredEnablement.size === 0), which needs a much larger customization-enablement fixture. Both are awaits inside _prepareSdkTurn, so the phase boundary under test is the same. Happy to build the fuller fixture if you would rather the test pin the MCP path specifically.

2. Stopped servers recorded as completed startup attempts

Already fixed in 772c62b, before this review landed — disabled/not_configured no longer receive timestamps, and your second scenario (disabled, then starts and takes 1s) is covered by a test asserting 1000ms rather than 0. Also added mcpStoppedCount so the buckets account for every observed server.

3. Readiness duration includes idle time across later additions — fixed

Valid, and not covered by the fix above. Reproduced your scenario exactly.

Changed from a session-wide window to per-server intervals: each server is timed from the observation showing it starting to the one showing it settled, and the reported figure is the longest of those. Your case now reports 1000ms instead of 601,000ms. This also makes the field mean what its name says, and it gives the same answer for the original capture, where the servers did start together.

A related case fell out of the same change: a server first seen already connected (an inventory seed after the fact) now contributes no duration, because its startup was not observed — which is different from it having taken no time.

4. Peer chats report the wrong provider — fixed

Switched to this._ownerSessionUri, which is the correct source and is already what toolCallDetails and toolApproval use in this same file. I had copied the wrong precedent. agentSessionId now derives from the owning session too, so peer-chat samples are no longer split off from their session.

Other corrections

• "invisible to turn telemetry" was wrong. You are right that host turnStarted fires before provider execution, so turnCompleted.totalTime already contains this time. The gap is phase attribution, not absence. Corrected in the code comments, the event's comment field, and the PR description.
• turnId added, so the phases join to turn and first-response timings rather than being ambiguous across sends within a session.
• Session-level tests added in 772c62b and extended here: first/subsequent send, send failure, MCP snapshot wiring through the real session.mcp_server_status_changed subscription, and now phase attribution. Preparation failure is not yet covered — worth adding, though note preparation currently swallows its own errors (applyMode logs and continues), so there is no failure signal to assert on yet.
• OTel/Can't find module with extension .es6 #8816: agreed, no claim intended there. This is product telemetry plus a debug log, not a span, and does not change that evaluation pipeline.

Full copilotAgentSession.test.ts suite passes (502), plus 5 tracker tests.

[github-actions]

Screenshot Changes

Base: de3a59e0 Current: 2678b90e

Changed (2)

sessions/sessionChatInputToolbar/SessionChatPills_HorizontalOverflow/Dark

Before	After

sessions/sessionChatInputToolbar/SessionChatPills_HorizontalOverflow/Light

Before	After

1 insignificant change(s) omitted (≤20 px, Δ≤2). See CI logs for details.