Skip to content

Make the status-bar read-lock flake deterministic under a loaded runner - #4670

Merged
erikdarlingdata merged 4 commits into
devfrom
feature/statusbar-readlock-flake
Sep 28, 2026
Merged

erikdarlingdata merged 4 commits into
devfrom
feature/statusbar-readlock-flake

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 28, 2026 •

Copy link
Copy Markdown
Owner

Test-only flake fix. No issue filed; this was reported directly as a flake in StatusBarSizeReadLockTests.cs:38, GetUsedDataSizeMb_WhenTheWriteLockIsHeld_GivesUpInsteadOfBlocking, which failed once in a loaded full Lite run on 2026-09-28 and passed when rerun alone.

Why

DuckDbInitializer.s_dbLock is one static ReaderWriterLockSlim shared by every DuckDbInitializer instance in the test process (confirmed in the class doc at Lite/Database/DuckDbInitializer.cs:169 and independently by a sibling fix, #4655 (merged as 2d44c9b76), which hit the same root cause in a different test file).

The old test held the writer's own acquire to a 5-second bound: Assert.True(lockHeld.Wait(TimeSpan.FromSeconds(5)), "the write lock was never acquired"). Under a loaded full-suite run, other tests' DuckDbInitializer instances also contend for that same static lock, so the holder task's blocking, untimed AcquireWriteLock() call can legitimately need more than 5 seconds to get its turn. That is a real resource-contention timeout, not a bug in the code under test.

Confirmed by direct reproduction, not just reasoning: a scratch diagnostic (never committed) ran the test's exact holder/wait logic 30 times while 6 busy-spin threads plus 4 other DuckDbInitializer instances hammered the same static lock with randomized short reads/writes.

  • At heavy synthetic load (32 busy-spin threads + 16 lock contenders on this 32-core box), the 5s writer wait failed 30/30 times, consistently landing at ~5000-5030ms - i.e. it hit its own bound almost exactly, rather than blowing past it by seconds. That rules out "the wait mechanism itself overshot" and confirms "the writer genuinely could not get a turn on the lock in 5s" - the same failure mode the sibling fix already documented and fixed elsewhere.
  • At moderate load (6 spin threads + 4 contenders), the writer always acquired quickly (13-93ms) and the existing 100ms-budgeted read (GetUsedDataSizeMb -> TryAcquireReadLock(StatusBarReadLockTimeout), 100ms) consistently returned in 107-112ms - nowhere near the old 2-second ceiling. TryEnterReadLock(TimeSpan) is a real kernel timed wait, and it stayed accurate even under contention.
  • I also searched recent Actions runs from 2026-09-28 for the original failure text ("StatusBar", --log-failed) and found nothing recoverable - the original failure most likely came from a local loaded run, not a run recorded in Actions history available here. The direct reproduction above stands in for that log.

So the flaky assertion is the writer's 5-second acquire wait, not the 2-second give-up ceiling - but the give-up ceiling was still only a timing proxy for the actual invariant ("gave up while the lock was genuinely still held"), which is worth proving directly regardless.

What changes

All changes are in Lite.Tests/StatusBarSizeReadLockTests.cs. Lite/Database/DuckDbInitializer.cs (the file under test) is untouched - confirmed both in the original round and again in the second pass below (git diff origin/dev -- Lite/ is empty), and no PRODUCT code change is included in this PR (each scratch plant used to prove RED was made, verified, and discarded before committing).

  • The writer's own wait to take the lock is bumped from 5s to 30s, with a comment explaining why: it is a hang backstop against the process-wide static lock, not a timing budget, mirroring the same fix already applied in the sibling AnalysisPassTokenThreadingTests fix.
  • (Corrected in the second pass below.) The 2-second Stopwatch/GaveUpCeiling proxy was initially replaced outright by a direct proof: GetUsedDataSizeMb() runs on its own Task, bounded on the WAIT by an 8-second HangBackstop (Task.WaitAsync, so a real hang throws TimeoutException instead of hanging the run); immediately after it returns, the test asserts the write lock had NOT yet been released (a new holderReleased signal, set only after the holder's using block actually disposes the lock) and that the holder task is still running (!holder.IsCompleted). Those two facts distinguish "gave up while held" from "returned fast and got lucky", which a wall clock alone cannot - but dropping the timing check entirely left a gap: nothing bounded how long the give-up itself took, so a regression that blocked for several seconds instead of ~100ms still passed as long as it returned before the writer's ten-second hold ended. The second pass restores a ceiling (GaveUpCeiling, 2s) alongside the direct proof rather than instead of it, timed via a Stopwatch started inside the read's own Task so a thread-pool scheduling delay under load isn't charged against it.
  • A fix to a real bug in the old test: release.Set() (telling the holder it can stop holding) only ran on the success path, after the assertions. If an assertion threw, the holder was left holding s_dbLock - a process-wide static - for the rest of its 10-second hold, which would have stalled every other test sharing that lock while this one test's failure was still being reported. release.Set() and the holder join now run in a finally.
  • The class doc comment was rewritten to describe the direct-proof approach; the second pass rewrote it again to describe both proofs together (gave up while held, AND gave up fast), since the first rewrite's "proved directly, not by the clock" framing became misleading once the timing budget was dropped instead of carried forward under the new task-internal measurement.

Diagnosis: confirmed or corrected

Confirmed the sibling fix's framing applies here too, with fresh numbers specific to this test (see Why). Corrected my own initial scratch reproduction's shape partway through: an all-cores busy-spin (32 threads) plus 16 lock contenders caused total starvation (0/30 writer acquisitions succeeded within 5s), which was useful to prove the writer-wait failure mode but gave no read-timing data; a second, moderate-load run (6 spin threads + 4 contenders) was needed to separately confirm the 100ms read budget stays accurate (107-112ms) under realistic contention.

Test plan (first pass)

  • dotnet build Lite.Tests/Lite.Tests.csproj -c Debug - Build succeeded, 0 Warning(s), 0 Error(s) (both before and after merging origin/dev).
  • RED: planted a scratch-only change in Lite/Database/DuckDbInitializer.cs (TryAcquireReadLock(StatusBarReadLockTimeout) -> TryAcquireReadLock(TimeSpan.FromMinutes(5)), i.e. the read blocks instead of giving up) and reran the fixed test 3 times: deterministic failure every time, System.TimeoutException: The operation has timed out. at ~8.3-8.5s (the HangBackstop), from the await read.WaitAsync(HangBackstop) line. Then discarded the plant with git checkout -- Lite/Database/DuckDbInitializer.cs, rebuilt, and confirmed git diff against the merge base shows only the test file changed.
  • GREEN: StatusBarSizeReadLockTests alone, 30 consecutive runs, while 24 busy-spin OS processes (a separate Python process, self-terminating after 180s) loaded all 32 cores externally. 30/30 passed, ~0.56-0.67s each. (Cross-process load can't contend the in-process static lock directly; the full-suite run below covers in-process contention from the other 60+ DuckDbInitializer-using test classes.)
  • Full Lite suite, once, after merging origin/dev: Total: 5525, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0, Time: 282.588s.

Second pass

On its own, the direct proof (holderReleased/holder.IsCompleted) checked that the read gave up WHILE the lock was held, but nothing bounded how long that took. A regression that makes GetUsedDataSizeMb() wait several seconds for the lock instead of giving up in ~100ms still passed every assertion, as long as it returned before the writer's ten-second hold ended and before the 8-second HangBackstop. That is exactly the freeze this test exists to catch - the read runs on the dispatcher thread. Asserting only "it took a lock" would pass a fix that hangs the UI, which is why the test now measures the time again too - but from inside the read's own task, not the old calling-thread Stopwatch, so a thread-pool scheduling delay under load isn't charged against it.

Fix: restored a GaveUpCeiling (2s) assertion alongside the existing direct proof, timed via a Stopwatch started inside the Task.Run lambda that calls GetUsedDataSizeMb(), returned alongside the result as a tuple ((Used, Elapsed)). GaveUpCeiling is generous against the 100ms StatusBarReadLockTimeout budget it checks - a CI machine under load can overshoot 100ms without the give-up behavior being wrong - but a fifth of WriteLockHold, so the distinction it draws is against a wait for the writer's full ten-second hold, not against the read's own soft budget. Corrected the class doc and the inline comment on the read task to describe both proofs; also corrected a stale claim below (see last bullet).

Proof, all runs against this branch after merging origin/dev:

  • Gap demonstration (pre-edit). On this PR's head before this pass's edit (test unedited), planted TryAcquireReadLock(TimeSpan.FromSeconds(5)) in place of TryAcquireReadLock(StatusBarReadLockTimeout) at Lite/Database/DuckDbInitializer.cs:2650. Rebuilt (Build succeeded, 0 Warning(s), 0 Error(s)), ran the class once: passed, Total: 1, Errors: 0, Failed: 0, Time: 5.637s - a five-second freeze of the read went green, confirming the gap.
  • RED on the restored ceiling, 3/3. Same plant (5s), now against the edited test. Rebuilt. Three runs, all failed on the new Assert.True(elapsed < GaveUpCeiling, ...): "the status-bar size read waited 4999 ms for the write lock...", then 5004 ms, then 5004 ms. The two direct-proof asserts (holderReleased, holder.IsCompleted) passed first each time, as expected (5s is still less than the 10s WriteLockHold) - confirming RED lands on the ceiling specifically, not on the proof that survived from the first pass.
  • RED at the hang backstop, 3/3. Swapped the plant to TryAcquireReadLock(TimeSpan.FromMinutes(5)). Rebuilt. Three runs, all failed with System.TimeoutException: The operation has timed out. at 8.589s, 8.195s, 8.174s - the HangBackstop firing, as designed, ahead of the writer's 10s hold.
  • Plant discarded. git checkout -- Lite/Database/DuckDbInitializer.cs, rebuilt (Build succeeded, 0 Warning(s), 0 Error(s)). git diff origin/dev -- Lite/ empty both before and after merging origin/dev - no product file differs.
  • Merged origin/dev (2b5e3ef55..2f0c9d80a): clean merge, no conflicts, touched only Darling/Darling.Tests/*, Darling/PerformanceMonitor.Darling.Service/* and deprecated/Dashboard/Themes/CoolBreezeTheme.xaml - nothing under Lite/ or Lite.Tests/. Rebuilt clean.
  • GREEN, 30/30, under load. Started 24 CPU-bound Python spinner processes (self-terminating after 240s, started and killed by their own recorded PIDs) to load all 32 cores externally. Ran the class 30 consecutive times: 30/30 passed, 0.464s-0.742s each - comfortably under both GaveUpCeiling (2s) and HangBackstop (8s). Killed all 24 spinner PIDs afterward.
  • Full Lite suite, once, after the merge: Total: 5525, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0, Time: 206.082s. No [FAIL] lines.
  • Drift note, updated. The first pass's note (below) listed Lite/Themes/CoolBreezeTheme.xaml as dev's drift in git diff origin/dev -- Lite/. That was right then: the branch predated Darken Cool Breeze's default WarningColor to clear the 4.5:1 text floor (#4651) #4658's Lite theme change. After this pass's merge of origin/dev, git diff origin/dev -- Lite/ is empty.

Lite.Tests/AnalysisPassTokenThreadingTests.cs is not touched.

Note

No GitHub issue is filed or closed by this PR (test-only flake). The diff is exactly Lite.Tests/StatusBarSizeReadLockTests.cs, confirmed via git diff origin/dev -- Lite/ (empty) after this pass's merge.

CHANGELOG

SECTION: None - test-only change; no user-visible behavior changes.

GetUsedDataSizeMb_WhenTheWriteLockIsHeld_GivesUpInsteadOfBlocking used a
5s wait for the holder task to take DuckDbInitializer's write lock, then
proved the read gave up by measuring a Stopwatch against a 2s ceiling.
s_dbLock is one static field shared by every DuckDbInitializer in the
test process, so under a loaded full-suite run the writer's own 5s wait
to take its turn on that lock can legitimately run out - other tests
hold it too - which has nothing to do with the 100ms read budget under
test. Reproduced directly: under synthetic contention, the 5s writer
wait ran out 30/30 times, landing right at its own ~5000-5030ms bound
rather than blowing past it by seconds, which is real contention for a
turn on the lock rather than the wait mechanism overshooting.

The writer's wait is now 30s, generous against process-wide contention.
The read is proved directly instead of by the clock: it runs on its own
task, bounded only by a hang backstop (8s, below the 10s hold) rather
than a timing budget, and the test asserts the write lock had NOT yet
been released and the holder task was still running at the moment the
read produced its answer - the actual invariant, not a timing proxy for
it. Also moves release.Set() into a finally so a failed assertion can no
longer strand the holder on the process-wide lock for the rest of its
hold, which would otherwise cascade into unrelated tests.
…s own task

#4670 replaced the old Stopwatch-on-the-calling-thread ceiling with a direct
proof (the write lock is still held when the read returns) but dropped the
timing assertion entirely. That leaves a gap: with the 100ms
StatusBarReadLockTimeout changed to something much larger, the read still
returns null while the lock is held (holderReleased unset, holder not
complete), and every assertion in the test still passes even though the read
blocked for seconds instead of giving up. The read runs on the dispatcher
thread, so that is exactly the regression this test exists to catch.

Restores the timing check, but measured from inside the read's own Task so a
thread-pool scheduling delay under load isn't charged against it, and bounds
it with a new GaveUpCeiling (2s) that is generous against the 100ms budget
under test but an order of magnitude below the 10s write-lock hold, so the
two proofs are independent: one shows the read gave up rather than getting
lucky, the other shows giving up was fast rather than merely eventual.
Updates the class doc and inline comments to describe both proofs instead of
just the one that survived.
…itude below it

GaveUpCeiling is 2 s and WriteLockHold is 10 s, a 5x gap. Two doc
comments called it an order of magnitude.
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review September 28, 2026 22:48
@erikdarlingdata
erikdarlingdata merged commit 003980e into dev Sep 28, 2026
16 of 18 checks passed
@erikdarlingdata
erikdarlingdata deleted the feature/statusbar-readlock-flake branch September 28, 2026 22:48
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