diff --git a/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts b/vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts index 807a0ed0fb..71b5eb65c2 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: string) { 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..4f78fb0176 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, @@ -299,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, @@ -339,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) { @@ -513,6 +514,7 @@ ${stderr}`)); }); } + const commandStartTime = process.hrtime.bigint(); const commandResult: CommandExecutorResult = await promisify(proc.exec)(fullCommandString, options).then( fulfilled => { @@ -525,7 +527,7 @@ ${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 @@ -536,7 +538,7 @@ ${stderr}`)); } ); - this.logCommandResult(commandResult, fullCommandString); + this.logCommandResult(commandResult, fullCommandString, commandStartTime, command.commandRoot); if (useCache) { @@ -546,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}.`));