Add chat perf marks (#302950)

This commit is contained in:
Paul
2026-03-26 15:41:02 -07:00
committed by GitHub
parent a5a24b45ea
commit fc86786770
9 changed files with 250 additions and 2 deletions

View File

@@ -24,7 +24,14 @@ function _definePolyfillMarks(timeOrigin?: number) {
}
return result;
}
return { mark, getMarks };
function clearMarks(prefix: string) {
for (let i = _data.length - 2; i >= 0; i -= 2) {
if (typeof _data[i] === 'string' && (_data[i] as string).startsWith(prefix)) {
_data.splice(i, 2);
}
}
}
return { mark, getMarks, clearMarks };
}
declare const process: INodeProcess;
@@ -42,6 +49,7 @@ interface IPerformanceTiming {
interface IPerformance {
mark(name: string, markOptions?: { startTime?: number }): void;
clearMarks(name?: string): void;
getEntriesByType(type: string): IPerformanceEntry[];
readonly timeOrigin: number;
readonly timing: IPerformanceTiming;
@@ -69,6 +77,17 @@ function _define() {
mark(name: string, markOptions?: { startTime?: number }) {
performance.mark(name, markOptions);
},
clearMarks(prefix: string) {
const toRemove = new Set<string>();
for (const entry of performance.getEntriesByType('mark')) {
if (entry.name.startsWith(prefix)) {
toRemove.add(entry.name);
}
}
for (const name of toRemove) {
performance.clearMarks(name);
}
},
getMarks() {
let timeOrigin = performance.timeOrigin;
if (typeof timeOrigin !== 'number') {
@@ -112,6 +131,11 @@ const perf = _factory(globalThis);
export const mark: (name: string, markOptions?: { startTime?: number }) => void = perf.mark;
/**
* Clears all marks whose name starts with the given prefix.
*/
export const clearMarks: (prefix: string) => void = perf.clearMarks;
export interface PerformanceMark {
readonly name: string;
readonly startTime: number;

View File

@@ -0,0 +1,50 @@
/*---------------------------------------------------------------------------------------------
* 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 { clearMarks, getMarks, mark } from '../../common/performance.js';
import { ensureNoDisposablesAreLeakedInTestSuite } from './utils.js';
function marksFor(prefix: string) {
return getMarks().filter(m => m.name.startsWith(prefix));
}
// Each test uses a unique prefix via a counter to avoid singleton state leaking between tests.
let testCounter = 0;
function uniquePrefix(): string {
return `test/perf/${testCounter++}/`;
}
suite('clearMarks', () => {
ensureNoDisposablesAreLeakedInTestSuite();
let prefix: string;
setup(() => {
prefix = uniquePrefix();
});
test('clears all marks with matching prefix', () => {
mark(`${prefix}a`);
mark(`${prefix}b`);
mark(`${prefix}c`);
clearMarks(prefix);
assert.strictEqual(marksFor(prefix).length, 0);
});
test('does not clear marks with a different prefix', () => {
const otherPrefix = uniquePrefix();
mark(`${prefix}a`);
mark(`${otherPrefix}b`);
clearMarks(prefix);
assert.strictEqual(marksFor(prefix).length, 0);
assert.strictEqual(marksFor(otherPrefix).length, 1);
clearMarks(otherPrefix);
});
});

View File

@@ -47,6 +47,7 @@ import { ACTION_START as INLINE_CHAT_START } from '../../../inlineChat/common/in
import { IPosition } from '../../../../../editor/common/core/position.js';
import { IMarker, IMarkerService, MarkerSeverity } from '../../../../../platform/markers/common/markers.js';
import { ChatSetupController } from './chatSetupController.js';
import { ChatGlobalPerfMark, markChatGlobal } from '../../common/chatPerf.js';
import { ChatSetupAnonymous, ChatSetupStep, IChatSetupResult, maybeEnableAuthExtension, refreshTokens } from './chatSetup.js';
import { ChatSetup } from './chatSetupRunner.js';
import { chatViewsWelcomeRegistry } from '../viewsWelcome/chatViewsWelcome.js';
@@ -339,6 +340,8 @@ export class SetupAgent extends Disposable implements IChatAgentImplementation {
let languageModelReady = false;
let toolsModelReady = false;
markChatGlobal(ChatGlobalPerfMark.WillWaitForActivation);
const whenAgentActivated = this.whenAgentActivated(chatService).then(() => agentActivated = true);
const whenAgentReady = this.whenAgentReady(chatAgentService, modeInfo?.kind)?.then(() => agentReady = true);
if (!whenAgentReady) {
@@ -534,6 +537,7 @@ export class SetupAgent extends Disposable implements IChatAgentImplementation {
}
}
markChatGlobal(ChatGlobalPerfMark.DidWaitForActivation);
await chatService.resendRequest(requestModel, {
...widget?.getModeRequestOptions(),
modeInfo,

View File

@@ -27,6 +27,7 @@ import { extUri, isEqual } from '../../../../../base/common/resources.js';
import { MicrotaskDelay } from '../../../../../base/common/symbols.js';
import { isDefined } from '../../../../../base/common/types.js';
import { URI } from '../../../../../base/common/uri.js';
import { ChatPerfMark, markChat } from '../../common/chatPerf.js';
import { ICodeEditor } from '../../../../../editor/browser/editorBrowser.js';
import { ICodeEditorService } from '../../../../../editor/browser/services/codeEditorService.js';
import { OffsetRange } from '../../../../../editor/common/core/ranges/offsetRange.js';
@@ -2205,6 +2206,9 @@ export class ChatWidget extends Disposable implements IChatWidget {
}
async acceptInput(query?: string, options?: IChatAcceptInputOptions): Promise<IChatResponseModel | undefined> {
if (this.viewModel) {
markChat(this.viewModel.sessionResource, ChatPerfMark.RequestStart);
}
return this._acceptInput(query ? { query } : undefined, options);
}
@@ -2364,7 +2368,9 @@ export class ChatWidget extends Disposable implements IChatWidget {
// process the prompt command
await this._applyPromptFileIfSet(requestInputs);
markChat(this.viewModel.sessionResource, ChatPerfMark.WillCollectInstructions);
await this._autoAttachInstructions(requestInputs);
markChat(this.viewModel.sessionResource, ChatPerfMark.DidCollectInstructions);
if (this.viewOptions.enableWorkingSet !== undefined && this.input.currentModeKind === ChatModeKind.Edit) {
const uniqueWorkingSetEntries = new ResourceSet(); // NOTE: this is used for bookkeeping so the UI can avoid rendering references in the UI that are already shown in the working set

View File

@@ -0,0 +1,95 @@
/*---------------------------------------------------------------------------------------------
* Copyright (c) Microsoft Corporation. All rights reserved.
* Licensed under the MIT License. See License.txt in the project root for license information.
*--------------------------------------------------------------------------------------------*/
import { mark, clearMarks } from '../../../../base/common/performance.js';
import { URI } from '../../../../base/common/uri.js';
import { chatSessionResourceToId } from './model/chatUri.js';
const chatPerfPrefix = 'code/chat/';
/**
* Well-defined perf scenarios for chat request lifecycle.
* Each mark is a boundary of a measurable scenario — don't add marks
* without defining what scenario they belong to.
*
* ## Scenarios
*
* **Time to UI Feedback** (perceived input lag):
* `request/start` → `request/uiUpdated`
*
* **Instruction Collection Overhead**:
* `request/willCollectInstructions` → `request/didCollectInstructions`
*
* **Extension Activation Wait** (first-request cold start):
* `code/chat/willWaitForActivation` → `code/chat/didWaitForActivation`
* (global marks, not session-scoped — emitted via {@link markChatGlobal})
*
* **Time to First Token** (the headline metric):
* `request/start` → `request/firstToken`
*
* **Total Request Duration**:
* `request/start` → `request/complete`
*
* **Agent Invocation Time** (LLM round-trip):
* `agent/willInvoke` → `agent/didInvoke`
*/
export const ChatPerfMark = {
/** User pressed Enter / request initiated */
RequestStart: 'request/start',
/** Request added to model → UI shows the message */
RequestUiUpdated: 'request/uiUpdated',
/** Begin collecting .instructions.md / skills / hooks */
WillCollectInstructions: 'request/willCollectInstructions',
/** Done collecting instructions */
DidCollectInstructions: 'request/didCollectInstructions',
/** First streamed response content received */
FirstToken: 'request/firstToken',
/** Response fully complete */
RequestComplete: 'request/complete',
/** Agent invoke begins (LLM round-trip start) */
AgentWillInvoke: 'agent/willInvoke',
/** Agent invoke returns (LLM round-trip end) */
AgentDidInvoke: 'agent/didInvoke',
} as const;
/**
* Emits a performance mark scoped to a chat session:
* `code/chat/<sessionResource>/<name>`
*
* Marks are automatically cleaned up when the corresponding chat model is
* disposed — see {@link clearChatMarks}.
*/
export function markChat(sessionResource: URI, name: string): void {
mark(`${chatPerfPrefix}${chatSessionResourceToId(sessionResource)}/${name}`);
}
/**
* Clears all performance marks for the given chat session.
* Called when the chat model is disposed.
*/
export function clearChatMarks(sessionResource: URI): void {
clearMarks(`${chatPerfPrefix}${chatSessionResourceToId(sessionResource)}/`);
}
/**
* Well-defined one-time global perf marks (not scoped to a session).
* These are emitted via {@link markChatGlobal} and are never cleared.
*/
export const ChatGlobalPerfMark = {
/** Begin waiting for chat extension activation (SetupAgent) */
WillWaitForActivation: 'willWaitForActivation',
/** Extension activation + readiness complete (SetupAgent) */
DidWaitForActivation: 'didWaitForActivation',
} as const;
/**
* Emits a global (non-session-scoped) performance mark:
* `code/chat/<name>`
*
* Used for one-time marks like activation that should persist across requests.
*/
export function markChatGlobal(name: string): void {
mark(`${chatPerfPrefix}${name}`);
}

View File

@@ -34,6 +34,7 @@ import { IChatDebugService } from '../chatDebugService.js';
import { InlineChatConfigKeys } from '../../../inlineChat/common/inlineChat.js';
import { IMcpService } from '../../../mcp/common/mcpTypes.js';
import { awaitStatsForSession } from '../chat.js';
import { ChatPerfMark, clearChatMarks, markChat } from '../chatPerf.js';
import { IChatAgentCommand, IChatAgentData, IChatAgentHistoryEntry, IChatAgentRequest, IChatAgentResult, IChatAgentService } from '../participants/chatAgents.js';
import { chatEditingSessionIsReady } from '../editing/chatEditingService.js';
import { ChatModel, ChatRequestModel, ChatRequestRemovalReason, IChatModel, IChatRequestModel, IChatRequestModeInfo, IChatRequestVariableData, IChatResponseModel, IExportableChatData, ISerializableChatData, ISerializableChatDataIn, ISerializableChatsData, ISerializedChatDataReference, normalizeSerializableChatData, toChatHistoryContent, updateRanges, ISerializableChatModelInputState } from '../model/chatModel.js';
@@ -192,6 +193,7 @@ export class ChatService extends Disposable implements IChatService {
}
}));
this._register(this._sessionModels.onDidDisposeModel(model => {
clearChatMarks(model.sessionResource);
this.chatDebugService.endSession(model.sessionResource);
this._onDidDisposeSession.fire({ sessionResource: [model.sessionResource], reason: 'cleared' });
}));
@@ -1062,6 +1064,9 @@ export class ChatService extends Disposable implements IChatService {
return;
}
if (!gotProgress) {
markChat(sessionResource, ChatPerfMark.FirstToken);
}
gotProgress = true;
for (let i = 0; i < progress.length; i++) {
@@ -1416,6 +1421,8 @@ export class ChatService extends Disposable implements IChatService {
this._pendingRequests.set(model.sessionResource, cancellableRequest);
this.telemetryService.publicLog2<ChatPendingRequestChangeEvent, ChatPendingRequestChangeClassification>(ChatPendingRequestChangeEventName, { action: 'add', source: 'sendRequest', chatSessionId: chatSessionResourceToId(model.sessionResource) });
rawResponsePromise.finally(() => {
markChat(sessionResource, ChatPerfMark.RequestComplete);
clearChatMarks(sessionResource);
if (this._pendingRequests.get(model.sessionResource) === cancellableRequest) {
this._pendingRequests.deleteAndDispose(model.sessionResource);
this.telemetryService.publicLog2<ChatPendingRequestChangeEvent, ChatPendingRequestChangeClassification>(ChatPendingRequestChangeEventName, { action: 'remove', source: 'sendRequestComplete', requestId: cancellableRequest.requestId, chatSessionId: chatSessionResourceToId(model.sessionResource) });

View File

@@ -29,6 +29,7 @@ import { ILogService } from '../../../../../platform/log/common/log.js';
import { CellUri, ICellEditOperation } from '../../../notebook/common/notebookCommon.js';
import { ChatRequestToolReferenceEntry, IChatRequestVariableEntry, isImplicitVariableEntry, isStringImplicitContextValue, isStringVariableEntry } from '../attachments/chatVariableEntries.js';
import { migrateLegacyTerminalToolSpecificData } from '../chat.js';
import { ChatPerfMark, markChat } from '../chatPerf.js';
import { ChatAgentVoteDirection, ChatAgentVoteDownReason, ChatRequestQueueKind, ChatResponseClearToPreviousToolInvocationReason, ElicitationState, IChatAgentMarkdownContentWithVulnerability, IChatClearToPreviousToolInvocation, IChatCodeCitation, IChatCommandButton, IChatConfirmation, IChatContentInlineReference, IChatContentReference, IChatDisabledClaudeHooksPart, IChatEditingSessionAction, IChatElicitationRequest, IChatElicitationRequestSerialized, IChatExternalToolInvocationUpdate, IChatExtensionsContent, IChatFollowup, IChatHookPart, IChatLocationData, IChatMarkdownContent, IChatMcpServersStarting, IChatMcpServersStartingSerialized, IChatModelReference, IChatMultiDiffData, IChatMultiDiffDataSerialized, IChatNotebookEdit, IChatProgress, IChatProgressMessage, IChatPullRequestContent, IChatQuestionCarousel, IChatResponseCodeblockUriPart, IChatResponseProgressFileTreeData, IChatSendRequestOptions, IChatService, IChatSessionContext, IChatSessionTiming, IChatTask, IChatTaskSerialized, IChatTextEdit, IChatThinkingPart, IChatToolInvocation, IChatToolInvocationSerialized, IChatTreeData, IChatUndoStop, IChatUsage, IChatUsedContext, IChatWarningMessage, IChatWorkspaceEdit, ResponseModelState, isIUsedContext } from '../chatService/chatService.js';
import { ChatAgentLocation, ChatModeKind, ChatPermissionLevel } from '../constants.js';
import { ChatToolInvocation } from './chatProgressTypes/chatToolInvocation.js';
@@ -2543,6 +2544,7 @@ export class ChatModel extends Disposable implements IChatModel {
});
this._requests.push(request);
markChat(this.sessionResource, ChatPerfMark.RequestUiUpdated);
this._onDidChange.fire({ kind: 'addRequest', request });
return request;
}

View File

@@ -27,6 +27,7 @@ import { IRawChatCommandContribution } from './chatParticipantContribTypes.js';
import { IChatFollowup, IChatLocationData, IChatProgress, IChatResponseErrorDetails, IChatTaskDto } from '../chatService/chatService.js';
import { ChatAgentLocation, ChatConfiguration, ChatModeKind, ChatPermissionLevel } from '../constants.js';
import { ILanguageModelsService } from '../languageModels.js';
import { ChatPerfMark, markChat } from '../chatPerf.js';
//#region agent service, commands etc
@@ -507,12 +508,15 @@ export class ChatAgentService extends Disposable implements IChatAgentService {
}
async invokeAgent(id: string, request: IChatAgentRequest, progress: (parts: IChatProgress[]) => void, history: IChatAgentHistoryEntry[], token: CancellationToken): Promise<IChatAgentResult> {
markChat(request.sessionResource, ChatPerfMark.AgentWillInvoke);
const data = this._agents.get(id);
if (!data?.impl) {
throw new Error(`No activated agent with id "${id}"`);
}
return await data.impl.invoke(request, progress, history, token);
const result = await data.impl.invoke(request, progress, history, token);
markChat(request.sessionResource, ChatPerfMark.AgentDidInvoke);
return result;
}
setRequestTools(id: string, requestId: string, tools: UserSelectedTools): void {

View File

@@ -0,0 +1,56 @@
/*---------------------------------------------------------------------------------------------
* 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 { getMarks } from '../../../../../base/common/performance.js';
import { URI } from '../../../../../base/common/uri.js';
import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../../base/test/common/utils.js';
import { ChatPerfMark, clearChatMarks, markChat } from '../../common/chatPerf.js';
suite('chatPerf', () => {
ensureNoDisposablesAreLeakedInTestSuite();
let sessionResource: URI;
setup(() => {
sessionResource = URI.parse(`test://session/${Date.now()}`);
});
teardown(() => {
clearChatMarks(sessionResource);
});
test('markChat emits a mark with the expected prefix', () => {
markChat(sessionResource, ChatPerfMark.RequestStart);
const marks = getMarks().filter(m => m.name.includes(sessionResource.toString()));
assert.strictEqual(marks.length, 1);
assert.ok(marks[0].name.startsWith('code/chat/'));
assert.ok(marks[0].name.endsWith('/request/start'));
});
test('clearChatMarks removes all marks for the session', () => {
markChat(sessionResource, ChatPerfMark.RequestStart);
markChat(sessionResource, ChatPerfMark.FirstToken);
clearChatMarks(sessionResource);
const marks = getMarks().filter(m => m.name.includes(sessionResource.toString()));
assert.strictEqual(marks.length, 0);
});
test('clearChatMarks does not affect marks from a different session', () => {
const otherSession = URI.parse(`test://session/other-${Date.now()}`);
markChat(sessionResource, ChatPerfMark.RequestStart);
markChat(otherSession, ChatPerfMark.FirstToken);
clearChatMarks(sessionResource);
const remaining = getMarks().filter(m => m.name.includes(otherSession.toString()));
assert.strictEqual(remaining.length, 1);
clearChatMarks(otherSession);
});
});