Fix FuturesTest's wall-clock timing assumptions - #295
Closed
SalvatoreT wants to merge 2 commits into
Closed
Conversation
The test slept for a nominal 500 ms across four awaits and required the total to land in [500, 1000]. On the macOS runners it came in at 1001 ms and 1008 ms on the two most recent PR runs, failing by 1 ms and 8 ms. The overhead is structural, not contention. Each awaited Rust timer spawns a thread and resumes back through the FFI. Locally that costs about 5 ms; on the shared macOS runners the same four awaits account for roughly 500 ms, or about 125 ms each. testSleepWithRepeat shows the same effect independently in the same job: 65 sequential 20 ms sleeps, nominal 1.3 s, actual 6.9 s, so about 86 ms per await there. Either way the per-await cost dwarfs the sleeps, and raising the cap only moves the cliff since that cost has no upper bound on a shared VM. What the test is really for is that a waker firing a second time does not corrupt its own future or let a later one finish early. That is a lower bound, and lower bounds do not care how loaded the machine is: thread::sleep is an at-least guarantee and measureTime is monotonic. So assert each step took at least as long as it slept, and drop the upper bound. These bounds are weaker than ones the file already relies on: assertApproximateTime asserts an exact nominal lower bound with no slack on eight other tests, across the same platforms. Also added the shouldBe true checks the previous version dropped. What this gives up: a future that completes late but eventually, say after five seconds, is now caught by runTest's 60 s timeout rather than by a 1000 ms cap. That trade is deliberate. Verified locally. The rewritten test passes on both jvmTest and macosArm64Test. Shortening one sleep to simulate a future completing early still fails it, so the assertions have not gone slack. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Two follow-ups in the same file, both found while tracking down the testBrokenSleep failure. testFutureWithLockButNotCancelled was next in line to flake. It sleeps a nominal 100 ms and allowed [100, 600]; CI was already spending 488 ms of that, 81% of the budget. The upper bound was never the thing catching a real fault anyway: use_shared_resource returns Result<(), AsyncError> and throws AsyncError.Timeout against its own 1000 ms budget if the resource is not released, so the exception is the detector and the clock only has to confirm the first call actually held the lock. Same treatment as testBrokenSleep: keep the lower bound, drop the window. testFutureWithLockAndCancelled had a subtler problem. It launches a job, waits for it to take the lock, then cancels it. The wait was a plain delay(50) inside runTest, which runs on the virtual clock and returns in about 3 ms, measured. So the job was being cancelled before it ever took the lock and the test had not been exercising the case it describes. Moving the wait onto Dispatchers.Default makes it real, which took the test from 1-15 ms to 68 ms. Its wall-clock cap is gone rather than widened. The same reasoning applies as for its sibling: an unreleased lock surfaces as AsyncError.Timeout from the second acquire, so the cap was not the detector, and any cap large enough to be safe today is still a cliff on a runner that spent 388 ms of overhead on a single call in this very file. Both verified locally on jvmTest and macosArm64Test, and the surviving assertion still fails when it should: releasing the shared resource immediately trips the new lower bound. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Contributor
Author
|
Folded into #294, which now covers both this and Nothing is lost by closing this. #294 carries the full rationale for all four tests. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
FuturesTestasserts on wall-clock time in ways that break on shared runners.testBrokenSleepis already failing on macOS; the other two changes here are the same problem caught before it lands.testBrokenSleep
The test slept a nominal 500 ms across four awaits and required the total to land in [500, 1000]. On the macOS runners it came in at 1001 ms and 1008 ms, failing by 1 ms and 8 ms. It has been failing since at least 2026-07-22, on
mainas well as on pull requests.The overhead is structural rather than contention. Each awaited Rust timer spawns a thread and resumes back through the FFI, which costs about 5 ms locally and roughly 125 ms per await on a shared macOS runner.
testSleepWithRepeatshows the same effect independently in the same job: 65 sequential 20 ms sleeps, nominal 1.3 s, actual 6.9 s. Raising the cap only moves the cliff, since that cost has no upper bound on a shared VM.What the test is for is that a waker firing a second time does not corrupt its own future or let a later one finish early. That is a lower bound, and lower bounds do not care how loaded the machine is:
thread::sleepis an at-least guarantee andmeasureTimeis monotonic. So each step now asserts it took at least as long as it slept, and the upper bound is gone. A future that never completes is still caught byrunTest's own timeout.These bounds are weaker than ones the file already relies on.
assertApproximateTimeasserts an exact nominal lower bound with no slack on eight other tests, across these same platforms.testFutureWithLockButNotCancelled
Next in line to flake: nominal 100 ms, window [100, 600], and CI was already spending 488 ms of it. The upper bound was never the detector.
use_shared_resourcereturnsResult<(), AsyncError>and throwsAsyncError.Timeoutagainst its own 1000 ms budget if the resource is not released, so the exception is what catches a real fault. Same treatment: keep the lower bound, drop the window.testFutureWithLockAndCancelled
A different problem in the same file. The test launches a job, waits for it to take the lock, then cancels it. That wait was a plain
delay(50)insiderunTest, which runs on the virtual clock and returns in about 3 ms, measured. The job was being cancelled before it ever took the lock, so the test had not been exercising the case it describes. Moving the wait ontoDispatchers.Defaultmakes it real, which took the test from 1-15 ms to 68 ms.Its wall-clock cap is removed rather than widened, for the same reason as its sibling: an unreleased lock surfaces as
AsyncError.Timeoutfrom the second acquire, and any cap large enough to be safe today is still a cliff on a runner that spent 388 ms of overhead on a single call in this very file.Testing
All three pass locally on
jvmTestandmacosArm64Test, anduniffi-tests-gir, macospasses on CI. Each was also checked in the failing direction: shortening a sleep to simulate a future completing early trips the new lower bound, and releasing the shared resource immediately trips the other one. The oldtestBrokenSleepmeasured 523 ms locally unloaded and 524 ms under 96 spinners on 12 cores, which is why this reproduces on CI runners and not on a laptop.What this gives up
A future that completes late but eventually, say after five seconds, is now caught by
runTest's 60 s timeout rather than by a 1000 ms cap. That trade is deliberate.Written with AI assistance (Claude Code) and pending human review, per CONTRIBUTING.md.
🤖 Generated with Claude Code