Fix flaky metrics test caused by DateTime.UtcNow timer resolution race

[niemyjski]

Fix flaky CanQueueAndDequeueMultipleWorkItemsAsync test

Fixes the intermittent CI failure in InMemoryQueueTests.CanQueueAndDequeueMultipleWorkItemsAsync observed in build run #24208176373:

Assert.Equal() Failure: CanQueueAndDequeueMultipleWorkItemsAsync
Expected: 25
Actual:   0

Root cause analysis

The failure chain

1. InMemoryMetrics uses a Timer initialized with TimeSpan.Zero delay — This means the timer callback fires almost immediately after construction, calling RecordObservableInstruments() before the test has enqueued any work items. This records a measurement with value 0 for the queue count gauge.

2. The test then enqueues 25 items and explicitly calls RecordObservableInstruments() — This records a second measurement with value 25. Both measurements land in the same ConcurrentQueue<RecordedMeasurement<long>>.

3. Value<T>() selects the "latest" measurement using OrderByDescending(m => m.Timestamp) — Under normal conditions, the 25 measurement has a later timestamp and wins.

4. On Windows CI, DateTime.UtcNow has ~15.6ms resolution — When the timer callback and the test's explicit call both execute within the same clock tick, both measurements get identical timestamps.

5. LINQ's OrderByDescending is a stable sort — For equal keys, it preserves insertion order. Since the 0 measurement was enqueued first (by the timer) and the 25 measurement second (by the test), stable descending sort places 0 before 25 when timestamps are equal. FirstOrDefault() then returns 0 instead of 25.

Why this manifests intermittently

The race window is ~15.6ms on Windows (the OS timer interrupt period). On Linux CI runners or developer machines with higher-resolution clocks, the two DateTime.UtcNow calls almost always return different values, making the test pass. The failure requires the timer callback and test code to execute within the same timer tick — a narrow but reproducible window under CI load.

5 Whys

#	Why?	Answer
1	Why did the assertion fail?	Value<long>("foundatio.simpleworkitem.count") returned 0 instead of 25
2	Why did it return 0?	OrderByDescending(m => m.Timestamp).FirstOrDefault() selected the stale measurement
3	Why was the stale measurement selected?	Both measurements had identical DateTime.UtcNow timestamps, and stable sort preserved FIFO order
4	Why were timestamps identical?	DateTime.UtcNow resolution on Windows is ~15.6ms; both calls fell in the same tick
5	Why were there two calls?	The InMemoryMetrics timer (initialized with TimeSpan.Zero) races with the test's explicit RecordObservableInstruments()

Fix

Replace DateTime.UtcNow timestamp ordering with a monotonically increasing sequence number using Interlocked.Increment on a static long counter in RecordedMeasurement<T>. This guarantees strict total ordering regardless of clock resolution.

Changes (1 file, 5 insertions, 3 deletions)

src/Foundatio.TestHarness/Utility/InMemoryMetrics.cs:

• Add static long s_sequenceCounter to RecordedMeasurement<T>
• Replace Timestamp = DateTime.UtcNow with Sequence = Interlocked.Increment(ref s_sequenceCounter)
• Change Value<T>() ordering from .OrderByDescending(m => m.Timestamp) to .OrderByDescending(m => m.Sequence)
• Remove dead Timestamp property (no references anywhere in the workspace)

Design notes

• Why long? — Interlocked.Increment natively supports long. At 1 billion increments/second, overflow would take ~292 years.
• Why static? — RecordedMeasurement<T> is a struct; there's no instance to attach state to. The counter is per closed generic type (e.g., RecordedMeasurement<long> has its own counter), which is correct since Value<T>() only compares within a single T.
• Why not fix the timer? — The TimeSpan.Zero timer is intentional for test responsiveness. The bug is in the ordering logic, not the timer behavior.

Test plan

• dotnet build Foundatio.slnx — 0 warnings, 0 errors
• dotnet test Foundatio.slnx — 1837 passed, 13 skipped, 0 failed
• Targeted test: CanQueueAndDequeueMultipleWorkItemsAsync passes consistently
• Code review: no issues found

[Copilot]

Pull request overview

Fixes an intermittent CI failure in InMemoryQueueTests.CanQueueAndDequeueMultipleWorkItemsAsync by making “latest measurement” selection deterministic even when DateTime.UtcNow timestamps collide (e.g., due to Windows timer resolution).

Changes:

• Replace timestamp-based ordering of RecordedMeasurement<T> with a monotonically increasing sequence number (Interlocked.Increment).
• Add a per-T static sequence counter in RecordedMeasurement<T> and assign Sequence during measurement capture.
• Update Value<T>() to select the latest measurement via Sequence instead of Timestamp.

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.