From dd64a54311ff9aaa9d37b19462eb71937816d3d3 Mon Sep 17 00:00:00 2001 From: Noah Gilson Date: Wed, 28 May 2025 15:35:05 -0700 Subject: [PATCH 1/2] Determine command execution time This enables us to see which commands we are running that take the most time to inform performance optimization choices. --- .../src/EventStream/EventStreamEvents.ts | 15 +++++++++++++++ .../src/Utils/CommandExecutor.ts | 4 ++++ 2 files changed, 19 insertions(+) diff --git a/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts b/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts index 807a0ed0fb..75a41324e1 100644 --- a/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts +++ b/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts @@ -963,6 +963,21 @@ export abstract class WebRequestTimer extends DotnetCustomMessageEvent } } +export class CommandExecutionTimer extends DotnetCustomMessageEvent +{ + public readonly eventName = 'CommandExecutionTimer'; + + constructor(public readonly eventMessage: string, public readonly durationMs: string, public readonly commandRoot: string, public readonly fullCommandString) { super(eventMessage); } + + public getProperties() + { + return { + ...super.getProperties(), DurationMs: this.durationMs, CommandRoot: TelemetryUtilities.HashAllPaths(this.fullCommandString), + HashedFullCommand: TelemetryUtilities.HashData(this.commandRoot) + }; + } +} + export class WebRequestTime extends WebRequestTimer { public readonly eventName = 'WebRequestTime'; diff --git a/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts b/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts index c2d33556f4..106ec59e4f 100644 --- a/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts +++ b/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts @@ -18,6 +18,7 @@ import CommandExecutionStatusEvent, CommandExecutionStdError, CommandExecutionStdOut, + CommandExecutionTimer, CommandExecutionUnderSudoEvent, CommandExecutionUnknownCommandExecutionAttempt, CommandExecutionUserAskDialogueEvent, @@ -513,6 +514,7 @@ ${stderr}`)); }); } + const commandStartTime = process.hrtime.bigint(); const commandResult: CommandExecutorResult = await promisify(proc.exec)(fullCommandString, options).then( fulfilled => { @@ -530,6 +532,8 @@ ${stderr}`)); } else { + const durationMs = (Number(process.hrtime.bigint() - commandStartTime) / 1000000).toFixed(2); + this.context?.eventStream.post(new CommandExecutionTimer(`The command ${fullCommandString} took ${durationMs} ms to run.`, durationMs, command.commandRoot, fullCommandString)); // signal is a string or obj, code is a number return result; } From ebc8a3354f01ae1c73c026ea2282a89c93045ee5 Mon Sep 17 00:00:00 2001 From: Noah Gilson Date: Wed, 28 May 2025 15:56:55 -0700 Subject: [PATCH 2/2] Log timer even when command fails --- .../src/EventStream/EventStreamEvents.ts | 2 +- .../src/Utils/CommandExecutor.ts | 15 ++++++++------- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts b/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts index 75a41324e1..71b5eb65c2 100644 --- a/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts +++ b/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts @@ -967,7 +967,7 @@ export class CommandExecutionTimer extends DotnetCustomMessageEvent { public readonly eventName = 'CommandExecutionTimer'; - constructor(public readonly eventMessage: string, public readonly durationMs: string, public readonly commandRoot: string, public readonly fullCommandString) { super(eventMessage); } + constructor(public readonly eventMessage: string, public readonly durationMs: string, public readonly commandRoot: string, public readonly fullCommandString: string) { super(eventMessage); } public getProperties() { diff --git a/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts b/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts index 106ec59e4f..4f78fb0176 100644 --- a/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts +++ b/vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts @@ -300,7 +300,7 @@ ${stderr}`)); this.context?.eventStream.post(new SudoProcCommandExchangeBegin(`Handing command off to master process. ${new Date().toISOString()}`)); this.context?.eventStream.post(new CommandProcessorExecutionBegin(`The command ${commandToExecuteString} was forwarded to the master process to run.`)); - + const commandStartTime = process.hrtime.bigint(); const waitTimeMs = this.context?.timeoutSeconds ? (Math.max(this.context?.timeoutSeconds * 1000, 1000)) : 600000; const sampleRateMs = 100; await loopWithTimeoutOnCond(sampleRateMs, waitTimeMs, @@ -340,7 +340,7 @@ ${stderr}`)); { this.context?.eventStream.post(new CommandProcessorExecutionEnd(`The command ${commandToExecuteString} was finished by the master process, as ${outputFile} was found.`)); - this.logCommandResult(commandOutputJson, commandToExecuteString); + this.logCommandResult(commandOutputJson, commandToExecuteString, commandStartTime, commandToExecuteString.split(' ')?.[0] ?? 'sudo'); if ((commandOutputJson as CommandExecutorResult).status !== '0' && terminalFailure) { @@ -527,20 +527,18 @@ ${stderr}`)); const result = { stdout: rejected?.stdout?.toString() ?? '', stderr: rejected?.stderr?.toString() ?? '', status: rejected?.code?.toString() ?? rejected?.signal?.toString() ?? '' }; if (terminalFailure) { - this.logCommandResult(result, fullCommandString); + this.logCommandResult(result, fullCommandString, commandStartTime, command.commandRoot); throw rejected ?? new Error(`Spawning ${fullCommandString} failed with an unspecified error.`); // according to nodejs spec, this should never be possible } else { - const durationMs = (Number(process.hrtime.bigint() - commandStartTime) / 1000000).toFixed(2); - this.context?.eventStream.post(new CommandExecutionTimer(`The command ${fullCommandString} took ${durationMs} ms to run.`, durationMs, command.commandRoot, fullCommandString)); // signal is a string or obj, code is a number return result; } } ); - this.logCommandResult(commandResult, fullCommandString); + this.logCommandResult(commandResult, fullCommandString, commandStartTime, command.commandRoot); if (useCache) { @@ -550,8 +548,11 @@ ${stderr}`)); } } - private logCommandResult(commandResult: CommandExecutorResult, fullCommandStringForTelemetryOnly: string) + private logCommandResult(commandResult: CommandExecutorResult, fullCommandStringForTelemetryOnly: string, commandStartTime: bigint, commandRoot: string) { + const durationMs = (Number(process.hrtime.bigint() - commandStartTime) / 1000000).toFixed(2); + this.context?.eventStream.post(new CommandExecutionTimer(`The command ${fullCommandStringForTelemetryOnly} took ${durationMs} ms to run.`, durationMs, commandRoot, fullCommandStringForTelemetryOnly)); + this.context?.eventStream.post(new CommandExecutionStatusEvent(`The command ${fullCommandStringForTelemetryOnly} exited: ${commandResult.status}.`));