From 34add7c257a606f8771721fb75bc1fc564a771b6 Mon Sep 17 00:00:00 2001 From: Jan Krivanek Date: Thu, 21 May 2026 07:37:43 +0200 Subject: [PATCH 1/2] Add elapsed-time telemetry to RunProcessAndGetOutput Replaces the global default-timeout bump (reviewed against on PR #45) with elapsed-time logging in the bootstrap-MSBuild test helper. The Stopwatch around WaitForExit lets callers see actual ms taken vs the budget, so when follow-up PRs add per-test timeout overrides (e.g. the unmerged NetTaskHostTest_FallbackToDotnet tests tracked in #41/#42), the author can pick a tight value based on data instead of guessing. Rationale for not bumping the default: the helper is called from 53 test sites across 11 files; a global bump would silently triple the worst-case budget for tests that today don't even use 30s, masking perf regressions. The two flaky tests cited in the original issues don't exist in main yet (they're on a feature branch), so per-call scoping isn't possible today; this PR makes the data available so it can be scoped correctly when they land. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/UnitTests.Shared/RunnerUtilities.cs | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/src/UnitTests.Shared/RunnerUtilities.cs b/src/UnitTests.Shared/RunnerUtilities.cs index 6bd047693dd..c4dea97dd37 100644 --- a/src/UnitTests.Shared/RunnerUtilities.cs +++ b/src/UnitTests.Shared/RunnerUtilities.cs @@ -172,6 +172,7 @@ public static string RunProcessAndGetOutput( p.StandardInput.Dispose(); TimeSpan timeout = TimeSpan.FromMilliseconds(timeoutMilliseconds); + Stopwatch sw = Stopwatch.StartNew(); if (Traits.Instance.DebugUnitTests) { p.WaitForExit(); @@ -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(); pid = p.Id; successfulExit = p.ExitCode == 0; + + // Telemetry: log actual elapsed time so callers tuning their timeouts can see + // 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, headroom {timeoutMilliseconds - exitElapsedMs}ms)"); + } } if (attachProcessId) From ddf7d2d0ae39672747caba1ffdb8e21accff1dc9 Mon Sep 17 00:00:00 2001 From: jankratochvilcz Date: Thu, 21 May 2026 15:34:52 +0200 Subject: [PATCH 2/2] Apply review nit: 'Nms remaining' wording Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/UnitTests.Shared/RunnerUtilities.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/UnitTests.Shared/RunnerUtilities.cs b/src/UnitTests.Shared/RunnerUtilities.cs index c4dea97dd37..3988a5bec2c 100644 --- a/src/UnitTests.Shared/RunnerUtilities.cs +++ b/src/UnitTests.Shared/RunnerUtilities.cs @@ -208,7 +208,7 @@ public static string RunProcessAndGetOutput( } else { - WriteOutput($"Process {pid} exited in {exitElapsedMs}ms (budget {timeoutMilliseconds}ms, headroom {timeoutMilliseconds - exitElapsedMs}ms)"); + WriteOutput($"Process {pid} exited in {exitElapsedMs}ms (budget {timeoutMilliseconds}ms, {timeoutMilliseconds - exitElapsedMs}ms remaining)"); } }