Skip to content

Make Should-BeFasterThan/BeSlowerThan scriptblock tests deterministic#2855

Draft
nohwnd wants to merge 2 commits into
mainfrom
nohwnd-fix-flaky-faster-than-test
Draft

Make Should-BeFasterThan/BeSlowerThan scriptblock tests deterministic#2855
nohwnd wants to merge 2 commits into
mainfrom
nohwnd-fix-flaky-faster-than-test

Conversation

@nohwnd

@nohwnd nohwnd commented Jul 9, 2026

Copy link
Copy Markdown
Member

Problem

The script-block timing tests for Should-BeFasterThan / Should-BeSlowerThan measured a real Start-Sleep against a threshold set close to that sleep's own duration, so CI timing noise could flip the result.

A run flaked on the Test PS_5_1_Windows_Server2022 check (check run 86215719809, part of #2852):

[-] Should-BeFasterThan.Throws when scriptblock is slower than expected 8ms
 Exception: Expected the script block { $Actual | Should-BeFasterThan -Expected $Expected } to fail
 in Pester assertion, but no assertion failure error was thrown!

That test runs { Start-Sleep -Milliseconds 10 } and expects it to be slower than a 1ms threshold, so the assertion should fail. It didn't: the stopwatch measured the sleep at under 1 ms, so Should-BeFasterThan -Expected 1ms passed and the expected failure never fired.

Root cause (measured on CI, not guessed)

I instrumented the assertion and ran it 2000× per agent, measuring each Start-Sleep -Milliseconds 10 with two independent clocks — Stopwatch (QueryPerformanceCounter) and DateTime.UtcNow (wall clock) — plus a batch total, and directly reproducing the assertion. Results:

Agent Start-Sleep 10 p50 assertion wrongly passed (measured <1ms) batch QPC vs wall clock
Ubuntu 22.04 / PS7 10.2 ms 0 / 2000 20460.5 == 20460.5 ms
Ubuntu 24.04 / PS7 10.3 ms 0 / 2000 20617.0 == 20617.0 ms
Win Server 2022 / PS 5.1 15.6 ms 6 / 2000 31276.7 ≈ 31280.1 ms
Win Server 2025 / PS 5.1 15.8 ms 1 / 2000 33113.5 ≈ 33114.3 ms
Win Server 2022 / PS7 15.6 ms 1 / 2000 31586.4 ≈ 31586.7 ms
Win Server 2025 / PS7 15.8 ms 1 / 2000 32041.8 ≈ 32041.8 ms

Two facts pin it down:

  1. No time is actually lost. On every agent the batch QPC total equals the independent wall-clock total (e.g. 31276.7 ≈ 31280.1 ms over 31 s). The sleeps really take ~15.6 ms each (Windows' 15.6 ms timer tick), so the sleep is not returning early.
  2. Yet a single measurement occasionally lies. On the Windows agents the same ~15.6 ms sleep is occasionally measured at under 1 ms (0.3% on the original PS 5.1 / Server 2022 config).

So the flake is a rare per-call Stopwatch / QueryPerformanceCounter under-measurement on the virtualized, 2-vCPU Windows agents: the two timestamp reads bracketing one sleep can be served by cores whose TSC/QPC are momentarily unsynchronized, yielding a near-zero delta. Over many samples it averages out (the batch is correct); a single bracketed measurement can read almost zero.

It is not the sleep waking early (scheduling/coalescing only ever rounds up), and not a bug in where the stopwatch is started — the stopwatch wraps & $Actual tightly, and the batch experiment confirms QPC accumulates correctly. There is nothing to fix in the assertion's measurement; on real hardware QPC is reliable.

Fix

Keep exercising the real script block (& $Actual) + stopwatch path, but compare against the floor and ceiling of any measurement, never a threshold near the real duration:

  • Fail / throw-when-slow direction → 0ms. A measured script block always takes >= 0, so the result is decided the same way on every agent no matter how the clock behaves.
  • Pass / throw-when-fast direction → 10s. No real script block reaches 10 s, so no measurement — even an anomalous one — can cross it.

Applied symmetrically to Should-BeFasterThan and Should-BeSlowerThan, whose script-block tests share the identical latent flake. The deterministic [timespan]-based tests are unchanged. This is the same class of flakiness previously addressed for the Because test in #2722.

Test-only change. Both files pass locally (Should-BeFasterThan 16 tests, Should-BeSlowerThan 5 tests).

The scriptblock-based timing tests measured a real Start-Sleep against a
narrow threshold, so CI scheduling noise could flip the outcome. A recent
run saw a 10ms sleep measured under the 1ms threshold, so the expected
assertion failure never fired.

Use thresholds that timing noise cannot cross while still exercising the
script block (& $Actual) + stopwatch path: a generous upper bound (10s)
for the pass/throw-when-fast direction and a 0ms lower bound for the
fail/throw-when-slow direction, in both assertions.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@nohwnd nohwnd marked this pull request as draft July 9, 2026 20:50
…mments

CI investigation (running the assertion 2000x per agent with an independent
wall clock alongside the stopwatch) showed the flake is a rare per-call
Stopwatch/QueryPerformanceCounter under-measurement on the virtualized Windows
agents: a nominal 10ms sleep (really ~15.6ms on Windows' timer tick) is
occasionally measured under 1ms, reproduced ~6/2000 on PS 5.1 / Server 2022,
while the wall clock and the accumulated batch confirm the full time elapsed.
It is not the sleep returning early, and not a bug in where the stopwatch starts.

Comparing against the floor (0ms) and ceiling (10s) of any measurement -- never
a threshold near the real run time -- makes these [scriptblock]-path tests
immune to that per-call clock glitch.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@nohwnd nohwnd force-pushed the nohwnd-fix-flaky-faster-than-test branch from 96b4c7e to 53d163e Compare July 9, 2026 21:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant