Skip to content

Add elapsed-time telemetry to RunProcessAndGetOutput test helper #13836

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

Closed
jankratochvilcz wants to merge 3 commits into from
Closed

Add elapsed-time telemetry to RunProcessAndGetOutput test helper #13836

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
34add7c
Add elapsed-time telemetry to RunProcessAndGetOutput
May 21, 2026
ddf7d2d
Apply review nit: 'Nms remaining' wording
May 21, 2026
c080179
Merge branch 'main' into upstream-pr/nettaskhost-telemetry
jankratochvilcz May 21, 2026
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
19 changes: 19 additions & 0 deletions src/UnitTests.Shared/RunnerUtilities.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -172,6 +172,7 @@ public static string RunProcessAndGetOutput(
p.StandardInput.Dispose();

TimeSpan timeout = TimeSpan.FromMilliseconds(timeoutMilliseconds);
Stopwatch sw = Stopwatch.StartNew();
Copy link
Copy Markdown
Contributor

@github-actions github-actions Bot May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit (documentation gap): The stopwatch starts after p.Start() and async output reading has begun (lines 168–172). This means exitElapsedMs measures wait time (time spent in WaitForExit), not total process execution time. The process may have done significant work between Start() and this line.

This is arguably the right thing to measure for timeout-budget purposes (since it's the same duration WaitForExit(timeout) is checking), but the log message says "exited in {exitElapsedMs}ms" which could be misread as total execution time. Consider rewording to something like "Process {pid} waited {exitElapsedMs}ms for exit" or adding a brief inline comment noting it's measuring wait duration, not wall-clock execution time from process start.

if (Traits.Instance.DebugUnitTests)
{
p.WaitForExit();
Expand All @@ -184,13 +185,31 @@ public static string RunProcessAndGetOutput(
throw new TimeoutException($"Test failed due to timeout: process {p.Id} is active for more than {timeout.TotalSeconds} sec.");
}

// Capture elapsed at process exit, before the post-exit drain below, so the
// telemetry below reports the budget-relevant time only (the drain is bookkeeping).
long exitElapsedMs = sw.ElapsedMilliseconds;

// We need the WaitForExit call without parameters because our processing of output/error streams is not synchronous.
// See https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.process.waitforexit?view=net-6.0#system-diagnostics-process-waitforexit(system-int32).
// The overload WaitForExit() waits for the error and output to be handled. The WaitForExit(int timeout) overload does not, so we could lose the data.
p.WaitForExit();
sw.Stop();
Copy link
Copy Markdown
Contributor

@github-actions github-actions Bot May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit (dead code): sw.Stop() has no observable effect here — exitElapsedMs was already captured on line 190 and the stopwatch is never read again after this point. It could be removed to reduce noise, or if you prefer to keep it for clarity/hygiene that's fine too — just noting it's functionally inert.


pid = p.Id;
successfulExit = p.ExitCode == 0;

// Telemetry: log actual elapsed time so callers tuning their timeouts can see
Copy link
Copy Markdown
Contributor

@github-actions github-actions Bot May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit (naming): The comment says "Telemetry" but this is diagnostic logging via WriteOutput, not actual telemetry infrastructure (no counters, no structured events, no collection pipeline). Consider using "Diagnostics:" or just removing the label — the comment already explains the purpose clearly without it.

// how close to the budget we ran. In DebugUnitTests mode the budget is not
// enforced (WaitForExit without timeout above), so the budget/headroom fields
// would be misleading and are omitted.
if (Traits.Instance.DebugUnitTests)
{
WriteOutput($"Process {pid} exited in {exitElapsedMs}ms (DebugUnitTests: budget not enforced)");
}
else
{
WriteOutput($"Process {pid} exited in {exitElapsedMs}ms (budget {timeoutMilliseconds}ms, {timeoutMilliseconds - exitElapsedMs}ms remaining)");
Copy link
Copy Markdown
Contributor

@github-actions github-actions Bot May 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Minor robustness: timeoutMilliseconds - exitElapsedMs mixes int and long, producing a long result. In normal operation this should always be non-negative (since WaitForExit(timeout) would have thrown on timeout). However, there's a theoretical window where thread scheduling after WaitForExit returns could make exitElapsedMs slightly exceed timeoutMilliseconds. A negative "remaining" value would be confusing in the log.

Consider using Math.Max(0, timeoutMilliseconds - exitElapsedMs) or simply documenting that negative values indicate measurement jitter. This is very low severity — just a polish item.

}
}

if (attachProcessId)
Expand Down
Loading