Skip to content

Record time it takes for each command to execute #2294

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Record time it takes for each command to execute #2294

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
dd64a54
Determine command execution time
nagilson May 28, 2025
ebc8a33
Log timer even when command fails
nagilson May 28, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions vscode-dotnet-runtime-library/src/EventStream/EventStreamEvents.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down
15 changes: 10 additions & 5 deletions vscode-dotnet-runtime-library/src/Utils/CommandExecutor.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import
CommandExecutionStatusEvent,
CommandExecutionStdError,
CommandExecutionStdOut,
CommandExecutionTimer,
CommandExecutionUnderSudoEvent,
CommandExecutionUnknownCommandExecutionAttempt,
CommandExecutionUserAskDialogueEvent,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -513,6 +514,7 @@ ${stderr}`));
});
}

const commandStartTime = process.hrtime.bigint();
const commandResult: CommandExecutorResult = await promisify(proc.exec)(fullCommandString, options).then(
fulfilled =>
{
Expand All @@ -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
Expand All @@ -536,7 +538,7 @@ ${stderr}`));
}
);

this.logCommandResult(commandResult, fullCommandString);
this.logCommandResult(commandResult, fullCommandString, commandStartTime, command.commandRoot);

if (useCache)
{
Expand All @@ -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}.`));

Expand Down