From bd1fbb0eabbf61cc3373503ef5f00c275b9a48a4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ralph=20K=C3=BCpper?= Date: Tue, 15 Sep 2026 11:59:04 +0200 Subject: [PATCH 1/3] Gate timer precision on what the host can resolve, not a fixed bound timer_precision compared the loop's median expiry lateness for a 250 us deadline against a fixed 500 us (native) / 2 ms (WASI) bound. The M1 Windows spike had already measured 275.2 us p50 on real hardware, so that bound carried under a factor of two of clear air, and a loaded CI VM crossed it with no backend regression: 756.2 us on main run 34947726746 and 594.2 us on PR #29 run 34950806076 within an hour, and 2.31 ms on WASI 0.3 during #22, whose samples spanned 1.07-6.44 ms. Each failure blocked a merge or skipped the release workflow (issue #30). Two independent requirements replace the single fixed median. Capability: the second-best expiry of twenty must still meet the same platform floor. Load only ever makes a sample later, never earlier, so this clause cannot be excused by a loaded or mismeasured host, while a wait floor or a deadline rounded up to milliseconds raises every sample and fails it. Typical case: the median must stay within the larger of that floor and twice what this host achieves with its own sleep, measured interleaved with the expiries so a load spike moves the bound as well as its subject. The calibration never touches the Driver, so no backend regression can move it. Measured on CI, it tracks the loop within a few per cent on windows-2025 (280.5-292.2 us against 285.1-298.5 us), ubuntu-24.04 (65.5 us against 69.6 us) and both WASI targets, and is 8.7x too pessimistic on macos-15, which coalesces nanosleep to 1.66 ms while the loop resolves 189.7 us -- exactly why the capability clause does not depend on it. Only a demonstrably loaded host retries, at most three times: an attempt whose own sleep stays inside half the quiet-host floor fails immediately. Every attempt reports min/2nd/p50/p90/max for both measurements and which clause it missed. --- crates/turnloop-contract/src/lib.rs | 198 +++++++++++++++++++++------- 1 file changed, 149 insertions(+), 49 deletions(-) diff --git a/crates/turnloop-contract/src/lib.rs b/crates/turnloop-contract/src/lib.rs index 69e7a73..f4db02b 100644 --- a/crates/turnloop-contract/src/lib.rs +++ b/crates/turnloop-contract/src/lib.rs @@ -432,6 +432,151 @@ pub fn ref_unref() { assert!(matches!(out[1].result, OpResult::Closed)); assert!(!l.alive()); } +/// Timer-precision gate for [`timer_precision`], measured against this host. +/// +/// Wake precision is as much a property of the host as of the backend. The M1 +/// Windows spike measured p50/p95/max lateness of 275.2/285.8/380.9 us for a +/// 250 us deadline on real hardware (`spikes/iocp/WINDOWS_RESULTS.md`), so a fixed +/// 500 us bound left the Windows backend under a factor of two of clear air and a +/// loaded CI VM crossed it with no backend regression at all: 756.2 us and 594.2 us +/// on windows-2025 within one hour, and 2.31 ms against the 2 ms Wasmtime bound on +/// WASI 0.3, whose samples that run spanned 1.07-6.44 ms (issue #30). +/// +/// Two independent requirements replace the single fixed median, and every attempt +/// reports the whole distribution of both measurements: +/// +/// 1. **Capability.** The backend's second-best expiry of twenty must still meet the +/// platform floor. Load only ever makes a sample later, never earlier, so this is +/// immune to a loaded or mismeasured host -- while a wait floor or a deadline +/// rounded up to milliseconds raises *every* sample and fails it. This is the +/// clause the mutation proof in `docs/lanes/flakes.md` exercises. +/// 2. **Typical case.** The median must stay within the larger of that same floor +/// and twice what this host achieves with its own sleep, measured interleaved +/// with the expiries so a load spike moves the bound as well as its subject. +/// +/// The calibration never touches the `Driver`: `std::thread::sleep` waits on the OS +/// primitive directly -- a `CREATE_WAITABLE_TIMER_HIGH_RESOLUTION` timer on Windows +/// (the same object the backend arms), `nanosleep` on Unix and a `wasi:clocks` +/// monotonic pollable on WASI -- so a backend that loses precision cannot move it. +/// It is a bound, not a verdict: a host whose own sleep is coarser than its timers +/// (macos-15 runners coalesce `nanosleep` to ~2 ms while the loop resolves 234 us) +/// can only relax the median clause, never the capability clause. +#[cfg(any(not(target_os = "wasi"), not(debug_assertions)))] +mod precision { + use super::*; + /// Short enough that any millisecond rounding or wait floor dominates. + const DELAY: Duration = Duration::from_micros(250); + /// Samples of each kind per attempt. + const SAMPLES: usize = 20; + /// A demonstrably loaded host may retry; a wait floor is systematic and fails + /// every attempt. + const ATTEMPTS: usize = 3; + /// The lateness a quiet host must meet whatever the calibration says. A host + /// that beats it cannot buy itself a looser bound. + #[cfg(not(target_os = "wasi"))] + const FLOOR: Duration = Duration::from_micros(500); + #[cfg(target_os = "wasi")] + const FLOOR: Duration = Duration::from_millis(2); + + /// Sorted lateness samples, with the statistics every attempt reports. + struct Samples(Vec); + impl Samples { + fn new(mut values: Vec) -> Self { + assert_eq!(values.len(), SAMPLES, "every sample must be recorded"); + values.sort_unstable(); + Self(values) + } + /// The capability statistic: the second-best sample, so one lucky expiry + /// cannot certify a backend, and one stalled one cannot condemn it. + fn best(&self) -> Duration { + self.0[1] + } + /// The typical-case statistic: a few stalled wakes cannot move it. + fn median(&self) -> Duration { + self.0[SAMPLES / 2] + } + fn report(&self) -> String { + format!( + "min={:?} 2nd={:?} p50={:?} p90={:?} max={:?}", + self.0[0], + self.best(), + self.median(), + self.0[SAMPLES * 9 / 10], + self.0[SAMPLES - 1] + ) + } + } + + /// One loop expiry: arm a `DELAY` timer, turn until it fires, then release it. + /// The 100 ms ceiling still rejects a wake that never arrives. + fn expiry(l: &mut Driver, out: &mut Completions) -> Duration { + let at = l.now() + DELAY; + let h = l.timer(at, None, Token(77)).expect("precision sample"); + let until = at + Duration::from_millis(100); + let late = loop { + assert!(l.now() < until, "precision sample missed maximum bound"); + l.turn(Timeout::Until(until), out).expect("sample turn"); + if out + .iter() + .any(|c| c.token == Token(77) && matches!(c.result, OpResult::Timer)) + { + break l.now().duration_since(at); + } + }; + l.close(h, Token(78)).expect("close sample"); + l.turn(Timeout::Now, out).expect("release sample"); + late + } + + /// The same measurement with no loop in it: what this host resolves on its own. + fn calibration(l: &Driver) -> Duration { + let at = l.now() + DELAY; + thread::sleep(DELAY); + l.now().duration_since(at) + } + + /// Require the loop to still reach the platform floor, and to be typical of + /// what this host can do at all. + pub(super) fn check(l: &mut Driver, out: &mut Completions) { + let mut attempts = Vec::with_capacity(ATTEMPTS); + for _ in 0..ATTEMPTS { + let mut expiries = Vec::with_capacity(SAMPLES); + let mut sleeps = Vec::with_capacity(SAMPLES); + // Interleaved, so a load spike moves the bound as well as its subject. + for _ in 0..SAMPLES { + expiries.push(expiry(l, out)); + sleeps.push(calibration(l)); + } + let (expiries, sleeps) = (Samples::new(expiries), Samples::new(sleeps)); + let allowance = FLOOR.max(sleeps.median() * 2); + let capable = expiries.best() <= FLOOR; + let typical = expiries.median() <= allowance; + let attempt = format!( + "loop {} | host sleep {} | floor {FLOOR:?} {} | allowance {allowance:?} {}", + expiries.report(), + sleeps.report(), + if capable { "met" } else { "MISSED" }, + if typical { "met" } else { "MISSED" } + ); + println!("turnloop timer precision: {attempt}"); + attempts.push(attempt); + if capable && typical { + return; + } + // A host whose own sleep stays inside half the quiet-host floor is not + // loaded, so the loop is the only explanation: retrying such an attempt + // could only hide a real regression. + if sleeps.median() * 2 <= FLOOR { + break; + } + } + panic!( + "timer precision missed its bound in {} attempt(s): {}", + attempts.len(), + attempts.join(" ;; ") + ); + } +} pub fn timer_precision() { let mut l = Driver::::new(Config::default()).expect("loop"); let mut out = Completions::default(); @@ -487,56 +632,11 @@ pub fn timer_precision() { assert!(l.stop(op)); l.turn(Timeout::Now, &mut out).expect("stop"); assert!(matches!(out[0].result, OpResult::Stopped)); - // WASI wake precision is host-dependent (DESIGN §7.4); compare release - // builds against the measured Wasmtime bound. Debug still exercises all - // timer semantics above and the independent mandatory no-spin contract. + // WASI wake precision is host-dependent (DESIGN §7.4); debug builds exercise + // every timer semantic above and the independent mandatory no-spin contract, + // and leave the measured precision gate to release. #[cfg(any(not(target_os = "wasi"), not(debug_assertions)))] - { - // A 100 ms ceiling admits occasional scheduler stalls, but it must not hide - // a systematic 1 ms wait floor. Twenty sub-millisecond samples check that - // typical lateness remains below half a millisecond. - let mut lateness = Vec::with_capacity(20); - for _ in 0..20 { - let at = l.now() + Duration::from_micros(250); - let h = l.timer(at, None, Token(77)).expect("precision sample"); - let until = at + Duration::from_millis(100); - loop { - assert!(l.now() < until, "precision sample missed maximum bound"); - l.turn(Timeout::Until(until), &mut out) - .expect("sample turn"); - if out - .iter() - .any(|c| c.token == Token(77) && matches!(c.result, OpResult::Timer)) - { - lateness.push(l.now().duration_since(at)); - break; - } - } - l.close(h, Token(78)).expect("close sample"); - l.turn(Timeout::Now, &mut out).expect("release sample"); - } - #[cfg(target_os = "wasi")] - println!( - "turnloop WASI lateness_ns={:?}", - lateness.iter().map(Duration::as_nanos).collect::>() - ); - lateness.sort_unstable(); - assert_eq!(lateness.len(), 20); - #[cfg(target_os = "wasi")] - let within_bound = lateness[10] <= Duration::from_millis(2); - #[cfg(not(target_os = "wasi"))] - let within_bound = lateness[10] < Duration::from_micros(500); - #[cfg(target_os = "wasi")] - println!( - "turnloop WASI expiries=20 median_ns={}", - lateness[10].as_nanos() - ); - assert!( - within_bound, - "timer precision exceeded platform bound: median lateness {:?}", - lateness[10] - ); - } + precision::check(&mut l, &mut out); } pub fn udp_round_trip() { let mut l = Driver::::new(Config::default()).expect("loop"); From 8610b971fd90b6e7feec6f4842126b64bb76d3ae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ralph=20K=C3=BCpper?= Date: Tue, 15 Sep 2026 11:59:04 +0200 Subject: [PATCH 2/3] Wait out the Windows thread pool's own wait-packet release loop_drop_terminates_live_children_and_releases_their_handles sampled GetProcessHandleCount once per cycle and compared it to an exact baseline. It failed on windows-2025 in PR #24's run 34941544032 with 83 against 82, on a PR that only changed release scripts (issue #26). The outstanding handle is a WaitCompletionPacket, and it is not leaked. The backend learns a child exited through RegisterWaitForSingleObject, which the thread pool backs with such a packet. UnregisterWaitEx(INVALID_HANDLE_VALUE) is the strongest join Windows documents and it joins the callback; the pool closes its own packet afterwards, on its own threads. An instrumented 192-cycle sweep on windows-2025 (run 34954538795) saw the table oscillate 130 -> 131 -> 130, gaining and releasing exactly one WaitCompletionPacket, on 117 to 138 of the 192 rounds with eight busy threads, and move zero times on the same idle runner. So the comparison stays exact and gains a bounded deadline instead of a single sample: settled() requires the count to be exactly the baseline again within five seconds. A leaked handle never comes back and still fails, and now names itself -- handle_table walks this process's handle table with GetHandleInformation and NtQueryObject(ObjectTypeInformation), and the failure reports what the table gained and released. The two other whole-process handle comparisons in this file get the same treatment for the same reason. --- crates/turnloop-contract/Cargo.toml | 2 +- .../tests/windows_lifetimes.rs | 164 ++++++++++++++++-- 2 files changed, 150 insertions(+), 16 deletions(-) diff --git a/crates/turnloop-contract/Cargo.toml b/crates/turnloop-contract/Cargo.toml index 171dcf6..87fae1e 100644 --- a/crates/turnloop-contract/Cargo.toml +++ b/crates/turnloop-contract/Cargo.toml @@ -23,7 +23,7 @@ workspace = true libc.workspace = true [target.'cfg(windows)'.dependencies] -windows-sys = { version = "=0.61.2", features = ["Win32_Foundation", "Win32_UI_WindowsAndMessaging", "Win32_System_Threading", "Win32_System_Console", "Win32_Storage_FileSystem", "Win32_Security", "Win32_System_IO", "Win32_System_Pipes"] } +windows-sys = { version = "=0.61.2", features = ["Wdk_Foundation", "Win32_Foundation", "Win32_UI_WindowsAndMessaging", "Win32_System_Threading", "Win32_System_Console", "Win32_Storage_FileSystem", "Win32_Security", "Win32_System_IO", "Win32_System_Pipes"] } [package.metadata.turnloop-ci] role = "contract" diff --git a/crates/turnloop-contract/tests/windows_lifetimes.rs b/crates/turnloop-contract/tests/windows_lifetimes.rs index 470348e..50ce07a 100644 --- a/crates/turnloop-contract/tests/windows_lifetimes.rs +++ b/crates/turnloop-contract/tests/windows_lifetimes.rs @@ -1,24 +1,28 @@ #![cfg(all(windows, not(loom)))] #![deny(unsafe_op_in_unsafe_fn)] use std::{ + collections::BTreeMap, io::Write, os::windows::io::{AsRawHandle, FromRawHandle, OwnedHandle}, ptr, sync::Mutex, - time::Duration, + time::{Duration, Instant}, }; // GetProcessHandleCount measures the entire test process. Every test in this // binary must hold this guard until its handles and helper threads are dropped. static HANDLES: Mutex<()> = Mutex::new(()); use turnloop::*; -use windows_sys::Win32::{ - Foundation::{WAIT_OBJECT_0, WAIT_TIMEOUT}, - System::{ - Pipes::CreatePipe, - Threading::{ - GetCurrentProcess, GetProcessHandleCount, OpenProcess, PROCESS_SYNCHRONIZE, - WaitForSingleObject, +use windows_sys::{ + Wdk::Foundation::{NtQueryObject, ObjectTypeInformation}, + Win32::{ + Foundation::{GetHandleInformation, HANDLE, UNICODE_STRING, WAIT_OBJECT_0, WAIT_TIMEOUT}, + System::{ + Pipes::CreatePipe, + Threading::{ + GetCurrentProcess, GetProcessHandleCount, GetProcessId, GetThreadId, OpenProcess, + PROCESS_SYNCHRONIZE, WaitForSingleObject, + }, }, }, }; @@ -286,6 +290,137 @@ fn handles() -> u32 { ); count } +/// One entry of this process's kernel handle table: what the handle names. +#[derive(Clone, Debug, Eq, PartialEq)] +struct Named { + /// The object type: `Process`, `Thread`, `Job`, `IoCompletion`, `Event`, ... + kind: String, + /// The thread or process this handle names, where its type has an identity. + id: u32, +} +impl std::fmt::Display for Named { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + if self.id == 0 { + write!(f, "{}", self.kind) + } else { + write!(f, "{}#{}", self.kind, self.id) + } + } +} +/// Every valid handle in this process, by handle value, with its object type. +/// +/// `GetProcessHandleCount` reports a number; a leak report needs the identity, so +/// this names each handle instead. Kernel handle values are multiples of four +/// drawn from a dense per-process table, so scanning the low range covers a test +/// process completely. Both calls are pure queries -- `GetHandleInformation` +/// asks whether a value is a handle at all, and `ObjectTypeInformation` never +/// blocks the way `ObjectNameInformation` can on a synchronous pipe -- so the +/// scan cannot change the count it is explaining. +fn handle_table() -> BTreeMap { + let mut table = BTreeMap::new(); + // Eight-byte aligned PUBLIC_OBJECT_TYPE_INFORMATION storage: a UNICODE_STRING + // header, the reserved words, and room for the name it points at. + let mut buffer = [0u64; 128]; + for value in (4..0x10000usize).step_by(4) { + let handle = value as HANDLE; + let mut flags = 0; + // SAFETY: pure query with a writable output; a value that is not a handle + // of this process simply reports failure. + if unsafe { GetHandleInformation(handle, &mut flags) } == 0 { + continue; + } + let mut returned = 0; + // SAFETY: live handle, documented class, and a writable buffer described + // by its own byte length. + let status = unsafe { + NtQueryObject( + handle, + ObjectTypeInformation, + buffer.as_mut_ptr().cast(), + size_of_val(&buffer) as u32, + &mut returned, + ) + }; + // SAFETY: a successful query wrote a PUBLIC_OBJECT_TYPE_INFORMATION whose + // first member is the type name; it is read, not retained. + let name = unsafe { buffer.as_ptr().cast::().read() }; + let kind = if status < 0 || name.Buffer.is_null() { + format!("untyped({status:#010x})") + } else { + // SAFETY: the returned name points into `buffer`, and UNICODE_STRING + // counts bytes, not UTF-16 units. + let units = + unsafe { std::slice::from_raw_parts(name.Buffer, name.Length as usize / 2) }; + String::from_utf16_lossy(units) + }; + let id = match kind.as_str() { + // SAFETY: a live handle of exactly the type this query accepts. + "Thread" => unsafe { GetThreadId(handle) }, + // SAFETY: a live handle of exactly the type this query accepts. + "Process" => unsafe { GetProcessId(handle) }, + _ => 0, + }; + table.insert(value, Named { kind, id }); + } + table +} +/// How long the Windows thread pool may take to finish releasing what a cycle +/// already unregistered. Bounded, so a real leak still fails this test. +const SETTLE: Duration = Duration::from_secs(5); +/// Require this process's handle count to be exactly `baseline` again. +/// +/// The comparison stays exact; only the moment of sampling is allowed to wait. +/// `GetProcessHandleCount` covers the whole process, and `RegisterWaitForSingleObject` +/// -- how the backend learns a child exited -- is backed by a thread-pool +/// `WaitCompletionPacket`. `UnregisterWaitEx(INVALID_HANDLE_VALUE)` is the strongest +/// join Windows documents and it joins the *callback*; the pool then closes its own +/// packet on its own threads. On a loaded runner that release lags the cycle that +/// caused it. A 192-cycle sweep on windows-2025 with eight busy threads saw the +/// table oscillate 130 -> 131 -> 130, gaining and releasing exactly one +/// `WaitCompletionPacket` each time, on 129 of the 192 rounds; the identical sweep +/// on the same idle runner moved zero times (issue #26, run 34954538795). A single +/// sample therefore reports the pool's tear-down as a leak once in a while, which +/// is what failed PR #24 with 83 against an 82 baseline. +/// +/// A genuinely leaked handle never comes back, so it fails at the deadline -- and +/// names itself, because the report walks the handle table by object type. +fn settled(subject: &str, baseline: u32, named: &BTreeMap) { + let deadline = Instant::now() + SETTLE; + loop { + // Read once, so the deadline verdict and the message describe the same + // observation. + let count = handles(); + if count == baseline { + return; + } + assert!( + Instant::now() < deadline, + "{subject}: {count} handles against a {baseline} baseline, still outstanding \ + {SETTLE:?} after the drop, so this is not the thread pool releasing its own wait \ + packet; {}", + handle_diff(named, &handle_table()) + ); + // Yield a slot: the pool thread that closes the packet needs one too. + std::thread::sleep(Duration::from_millis(1)); + } +} +/// Name what a handle table gained and lost, for a leak report. +fn handle_diff(before: &BTreeMap, after: &BTreeMap) -> String { + let side = |a: &BTreeMap, b: &BTreeMap| { + a.iter() + .filter(|(value, named)| b.get(value) != Some(named)) + .map(|(value, named)| format!("{value:#x}={named}")) + .collect::>() + .join(", ") + }; + format!( + "{} -> {} handles; gained [{}]; released [{}]", + before.len(), + after.len(), + side(after, before), + side(before, after) + ) +} #[test] fn cancelled_synchronous_reads_release_buffers_and_threads() { let _guard = HANDLES @@ -444,9 +579,10 @@ fn loop_drop_and_stale_wakers_release_windows_handles() { }; cycle(); // process-lifetime Winsock/runtime setup precedes the baseline let baseline = handles(); + let named = handle_table(); for _ in 0..32 { cycle(); - assert_eq!(handles(), baseline, "native handle leak"); + settled("native handle leak", baseline, &named); } } @@ -844,14 +980,11 @@ fn loop_drop_terminates_live_children_and_releases_their_handles() { }; assert_eq!(cycle(), 8); // initialize Windows thread-pool wait infrastructure let baseline = handles(); + let named = handle_table(); let mut reaped = 0; for _ in 0..16 { reaped += cycle(); - assert_eq!( - handles(), - baseline, - "live-child drop leaked a native handle" - ); + settled("live-child drop leaked a native handle", baseline, &named); } assert_eq!(reaped, 128); } @@ -1167,10 +1300,11 @@ fn listener_reuse_and_busy_connect_drop_release_native_handles() { }; assert_eq!(cycle(), 4); let baseline = handles(); + let named = handle_table(); let mut drops = 0; for _ in 0..8 { drops += cycle(); - assert_eq!(handles(), baseline, "listener or availability handle leak"); + settled("listener or availability handle leak", baseline, &named); } assert_eq!(drops, 32); } From e73b5a58079fe2d8c2a0890d8414c78876a8802a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ralph=20K=C3=BCpper?= Date: Tue, 15 Sep 2026 12:09:08 +0200 Subject: [PATCH 3/3] Record the flakes lane: root causes, fix and mutation proof --- docs/lanes/flakes.md | 299 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 299 insertions(+) create mode 100644 docs/lanes/flakes.md diff --git a/docs/lanes/flakes.md b/docs/lanes/flakes.md new file mode 100644 index 0000000..edbd3be --- /dev/null +++ b/docs/lanes/flakes.md @@ -0,0 +1,299 @@ +# flakes — two CI flakes, `timer_precision` (#30) and the Windows handle count (#26) + +Status: **implemented; two consecutive fully green CI runs on the final commit** +(`34956471189` and `34957283051`, 38/38 jobs each). Base `d5e4113` (main), branch +`lane/flakes`, commits `bd1fbb0` (#30) and `8610b97` (#26). Evidence for both was +collected on throwaway `diag/flake-evidence` runs, listed in the ledger. + +Both flakes had the same shape — a gate whose constant was close enough to the +host's own floor that ordinary CI scheduling crossed it — and different answers. +`timer_precision` was measuring the right thing against the wrong bound, so the +bound is now measured. The Windows handle count was measuring the right thing at +the wrong moment, so the comparison is unchanged and only the sampling waits. + +--- + +## #30 `timer_precision` — the bound was below the platform's own floor + +### Root cause + +`timer_precision` (`crates/turnloop-contract/src/lib.rs`) took twenty expiries of +a 250 µs deadline and required the median lateness to be under a **fixed** 500 µs +on native backends and 2 ms on WASI. + +That constant was never far from what the platform itself can do. The M1 Windows +spike had already measured it: `spikes/iocp/WINDOWS_RESULTS.md` records +p50/p95/max lateness of **275.2 / 285.8 / 380.9 µs** for exactly this 250 µs +deadline through exactly this NT-packet route, on real hardware, and closes with +"this single host does not establish the minimum-version or VM precision matrix". +So the gate ran with under a factor of two of clear air on the one backend whose +floor had been measured, and GitHub's windows-2025 runners are VMs. + +Measured on the diag run (`34954538795`, windows-2025, all three feature modes, +idle runner): loop p50 **285.1–298.5 µs**, p90 up to 799.3 µs, max up to 805 µs. +Two of twenty samples already exceed the 500 µs bound on an *idle* runner; it only +takes load to move the median past it. That is precisely what was reported: + +| run | arm | reported | +|---|---|---| +| `34947726746` attempt 1 (main, `7e367cd`) | test-native (windows-2025, default) | `timer precision exceeded platform bound: median lateness 756.2µs` | +| `34950806076` attempt 1 (PR #29) | test-native (windows-2025) | median lateness 594.2 µs, within the hour | +| #22 | wasi (wasm32-wasip3, release) | median 2.31 ms against the 2 ms bound, samples **1.07–6.44 ms**, host load average 148–182 (`docs/lanes/tl-i06.md` row 41) | + +Neither was a backend regression: both passed on re-run of the same commit, and +the main failure skipped the release workflow, which is how it blocked publishing +0.1.0-alpha.3. + +The flake also reproduces off CI. On the shared macOS development box, with other +agents building, an unmodified run measured loop p50 **506.5 µs** — a failure of +the old gate — while the host's own sleep measured 566.2 µs in the same window. +The WASI half reproduces there too: a `wasm32-wasip2` release run measured loop +p50 **2.230 ms** against the old 2 ms bound, with the host's own sleep at 1.258 ms. + +### What actually moves on windows-2025 + +The lateness distribution there is **bimodal**, and visibly so on an *idle* +runner. From the load-curve diag (`34957467265`, windows-2025, 20 samples per +row): + +| busy threads | loop min | loop 2nd | loop p50 | loop p90 | loop max | +|---|---|---|---|---|---| +| 0 | 293.3 µs | 297.5 µs | 301.0 µs | **800.1 µs** | 807.1 µs | +| 1 | 301.7 µs | 302.4 µs | 306.1 µs | 311.9 µs | 419.6 µs | +| 2 | 297.9 µs | 297.9 µs | 301.7 µs | **800.7 µs** | 813.6 µs | +| 3 | 301.6 µs | 302.0 µs | 304.7 µs | 309.7 µs | 309.9 µs | +| 4 (= all vCPUs) | 1.841 ms | 4.352 ms | 8.752 ms | 21.33 ms | 27.41 ms | +| 8 | 33.38 ms | 33.41 ms | 44.46 ms | 57.36 ms | 57.91 ms | + +There is a fast mode at ~300 µs and a slow mode at ~800 µs, and a couple of the +twenty samples land in the slow mode even with nothing else running. **756.2 µs +and 594.2 µs are that slow mode taking the median** — not the fast mode moving. +The old gate was a coin toss on how many of twenty samples landed in a bucket +that sits above its 500 µs constant. + +That is exactly what the capability clause keys on: the fast mode is stable to +within 3 % from an idle runner up to three of four vCPUs busy, so the second-best +of twenty stays at ~300 µs — 1.65× inside the floor — while the median wanders. +The runner only loses the fast mode entirely once every vCPU is saturated, and at +that point the host's own sleep is equally hopeless (min 2.31 ms at four busy +threads, 33.31 ms at eight): no gate can certify sub-millisecond timing on a +machine that cannot schedule a thread, and this one fails rather than pretend. +That is the documented boundary, not a flake mode — the reported failures were a +2–2.7× degradation, two orders of magnitude short of it. + +On the macOS box the same curve is flat: the second-best stays between 37.3 µs +and 58.4 µs at every load level from 0 to 8 spinners, because that host has ten +cores and never saturates. + +### The fix + +Two independent requirements replace the single fixed median, in a private +`precision` module beside the test. Every attempt reports min / 2nd / p50 / p90 / +max for **both** measurements and says which clause it missed. + +1. **Capability** — the *second-best* expiry of twenty must still meet the same + platform floor (500 µs native, 2 ms WASI). Load only ever makes a sample later, + never earlier, so no amount of host noise or calibration error can excuse this + clause; a wait floor or a deadline rounded up to milliseconds raises *every* + sample, including these, and fails it. Second-best rather than best, so one + lucky expiry cannot certify a backend and one stalled one cannot condemn it. +2. **Typical case** — the median must stay within `max(floor, 2 × the host's own + median)`, where the host's median is measured with `std::thread::sleep` at the + same 250 µs delay, **interleaved** with the expiries so a load spike moves the + bound as well as its subject. + +The calibration never touches the `Driver`. `std::thread::sleep` goes straight to +the OS primitive — a `CREATE_WAITABLE_TIMER_HIGH_RESOLUTION` timer on Windows +(the same object kind `backend/iocp/timer.rs` arms, and a host that cannot create +one fails `Loop::new` rather than relaxing this bound), `nanosleep` on Unix, and a +`wasi:clocks` monotonic pollable on WASI — so a backend that loses precision +cannot move it. + +Retries are bounded at three and **granted only to a demonstrably loaded host**: +an attempt whose own sleep median stays inside half the quiet-host floor fails +immediately, because on such a host the loop is the only explanation. A wait floor +is systematic and fails every attempt regardless. + +### Why the median clause needs the capability clause + +Calibrating against the host's own sleep is accurate on three of four platforms +and badly pessimistic on the fourth. Measured on run `34954538795`: + +| arm | loop p50 | host sleep p50 | ratio | +|---|---|---|---| +| windows-2025 default / executor / all-features | 298.3 / 298.5 / 285.1 µs | 293.1 / 291.6 / 280.5 µs | ~1.0 | +| ubuntu-24.04 default | 69.6 µs | 65.5 µs | ~1.06 | +| wasm32-wasip2 (release, Wasmtime 46) | 900.8 µs | 866.3 µs | ~1.04 | +| wasm32-wasip3 (release, Wasmtime 46) | 867.9 µs | 864.6 µs | ~1.00 | +| **macos-15 default** | **189.7 µs** | **1.657 ms** | **0.11** | + +macos-15 runners coalesce `nanosleep` to about 1.7 ms while the kqueue path +resolves 190 µs, so on that arm the calibration alone would raise the allowance to +3.3 ms and hide a millisecond regression. The capability clause is what keeps that +arm honest, and it is the clause both mutations trip. + +### Mutation proof + +Neither mutation touches the calibration, so a gate that only calibrated would +have to catch them on the median; both are in fact caught by the capability +clause, on the first attempt, on a quiet host. Each mutation was applied to +`crates/turnloop/src/driver.rs:1239`, the one place the loop turns its deadline +into a wait: + +```rust +let mut timeout = deadline.map(|d| d.saturating_duration_since(start)); +// MUTATION A: 5 ms wait floor. +timeout = timeout.map(|d| if d.is_zero() { d } else { d.max(Duration::from_millis(5)) }); +// MUTATION B: round every wait up to a whole millisecond. +timeout = timeout.map(|d| Duration::from_millis(d.as_nanos().div_ceil(1_000_000) as u64)); +``` + +macOS arm64, `cargo test -p turnloop-contract --lib timer_bounds`: + +| mutation | runs | result | +|---|---|---| +| A, 5 ms floor | 3/3 | **FAIL** — `loop min=5.05ms 2nd=5.42ms p50=5.82ms … floor 500µs MISSED`, worst case after 2 of 3 attempts | +| B, millisecond rounding | 3/3 | **FAIL** — `loop min=905.75µs 2nd=907.375µs p50=1.07ms … floor 500µs MISSED`, 1 attempt | +| B, under four CPU spinners | 3/3 | **FAIL** (against the earlier single-clause draft, which the load could not rescue either) | +| unmutated | 10/10 + 3/3 | **PASS**, allowance stayed at the 500 µs floor on every quiet run | + +Mutation A's second attempt shows the design working end to end: the first attempt +had a loaded calibration (allowance 638.9 µs) and still failed, because +`2nd=5.42 ms` missed the floor. + +The Windows arm of the same proof is **UNRUN** — no Windows host here, and running +a deliberately broken driver through CI was not worth a 30-minute run. The +capability clause is platform-independent (it compares the backend against the +same constant the old gate used), and the Windows numbers above show the clause +has 1.7× of margin on an idle runner. + +--- + +## #26 the Windows handle count — a thread-pool wait packet, released asynchronously + +### Root cause: not a leak + +`loop_drop_terminates_live_children_and_releases_their_handles` +(`crates/turnloop-contract/tests/windows_lifetimes.rs`) spawns eight live children, +drops the loop, and compares `GetProcessHandleCount` against an exact baseline, +sixteen times. It failed once on windows-2025 in PR #24's run `34941544032` — +`left: 83, right: 82`, "live-child drop leaked a native handle" — on a PR that +only changed `release.yml` and `release.py`. + +The outstanding handle is a **`WaitCompletionPacket`**, and the driver never owned +it. `backend/iocp/process.rs:622` learns a child exited through +`RegisterWaitForSingleObject`; the Windows thread pool backs each such +registration with a wait-completion packet of its own. +`UnregisterWaitEx(INVALID_HANDLE_VALUE)` in `Child::join` is the strongest join +Windows documents and it joins the **callback** — the pool then closes its own +packet afterwards, on its own threads. `GetProcessHandleCount` counts the whole +process, so it sees that packet until the pool is finished with it. + +Measured directly, by walking this process's handle table by object type after +every cycle (diag run `34954538795`, 192 cycles, all three windows-2025 feature +modes): + +| condition | table movements over 192 cycles | +|---|---| +| idle runner | **0**, all three modes | +| eight busy threads | **129 / 138 / 117** (default / all-features / executor) | + +and every single movement is the same event: + +``` +round 0: 130 -> 131 handles; gained [0x458=WaitCompletionPacket]; released [] +round 1: 131 -> 131 handles; gained [0x160=WaitCompletionPacket]; released [0x458=WaitCompletionPacket] +round 4: 131 -> 130 handles; gained []; released [0x414=WaitCompletionPacket] +``` + +The count oscillates 130 → 131 → 130, one `WaitCompletionPacket` at a time, and +always comes back. Nothing accumulates: the final count after 192 loaded cycles is +the same 130 the sweep started from. That is an asynchronous release, not a leak, +and it matches the load-dependence of the original failure — a runner busy enough +to delay a pool thread is exactly when a single sample lands on the 131. + +### The fix + +The comparison stays exact; only the moment of sampling is allowed to wait. +`settled(subject, baseline, &named)` requires the count to be **exactly** the +baseline again within a bounded five seconds, sleeping a millisecond between +polls so the pool thread that closes the packet gets a slot too. A genuinely +leaked handle never comes back, so it still fails — at the deadline, with a +message that says the wait already elapsed, so the reader knows this is not the +pool tearing down its own packet. + +The deadline is validated, not assumed. Diag run `34955502692` ran the same +192-cycle loaded sweep *through* `settled()` on all three windows-2025 modes: + +| mode | settled immediately | needed the wait | worst wait | +|---|---|---|---| +| default | 117 / 192 | 75 | **1.646 ms** | +| executor | 133 / 192 | 59 | **1.583 ms** | +| all-features | 143 / 192 | 49 | **1.614 ms** | + +A third of the cycles on a loaded runner do have a packet outstanding — which is +the flake, reproduced 183 times — and every one of them converged inside two +milliseconds, against a five-second deadline. The release also does not need more +work to drive it: `settled()` only sleeps. + +And the failure now names the handle, which is what turned this issue from a guess +into a measurement: `handle_table()` walks the process's kernel handle table +(handle values are multiples of four, so probing the low range covers a test +process) and types each entry with `NtQueryObject(ObjectTypeInformation)`; +`handle_diff()` reports what the table gained and released. Both calls are pure +queries — `ObjectTypeInformation` never blocks the way `ObjectNameInformation` can +on a synchronous pipe — so the scan cannot change the count it is explaining, and +it runs only to build a failure message. This needed `Wdk_Foundation` added to +`turnloop-contract`'s `windows-sys` features. + +The two other whole-process handle comparisons in the same file +(`loop_drop_and_stale_wakers_release_windows_handles`, +`listener_reuse_and_busy_connect_drop_release_native_handles`) get the same +treatment: the reason — a process-wide counter can lag a per-loop teardown — is +generic, even though the measured evidence is for the child-wait path. On a host +with nothing outstanding `settled()` returns on its first check and costs nothing. + +### Not done, and why + +The packet exists only because child-exit notification goes through the OS thread +pool. `backend/iocp/timer.rs` already owns the alternative — +`NtCreateWaitCompletionPacket` / `NtAssociateWaitCompletionPacket` against the +driver's own port — and associating each child's process handle the same way would +delete the thread pool from this path entirely, make the packet ours, and close it +deterministically at `Child::drop`. That is a real improvement and a real change +to process-exit routing (`Child::ready`/`status`/`join`, completion-key +assignment, and `bridge.rs`, which registers the same way for the GUI event). It +is not a flake fix and the evidence says there is nothing leaking, so it is left +as a follow-up. + +--- + +## Verification ledger + +Host: macOS 15 arm64, shared with other builds. Toolchain `nightly-2026-08-20` +from `rust-toolchain.toml`. `CARGO_BUILD_JOBS=4` throughout. + +| # | Command | Result | +|---|---|---| +| 1 | `cargo fmt --all --check` | **PASS** | +| 2 | `cargo clippy --locked -p turnloop -p turnloop-contract -p turnloop-io --all-targets -- -D warnings -D clippy::undocumented_unsafe_blocks` | **PASS** | +| 3 | the same, `--all-features` | **PASS** | +| 4 | the same, `--target x86_64-pc-windows-msvc` | **PASS** | +| 5 | the same, `--target x86_64-pc-windows-msvc --all-features` | **PASS** | +| 6 | `cargo test --locked -p turnloop -p turnloop-contract --no-fail-fast -- --test-threads=1` | **PASS**, 15 suites | +| 7 | `python3 scripts/ci/run-tests.py wasi --target wasm32-wasip2` (Wasmtime 46.0.0, pinned) | **PASS**, exit 0 | +| 8 | `python3 -m unittest discover -s scripts/ci -p 'test_*.py'` | **PASS** | +| 9 | `cargo test -p turnloop-contract --lib timer_bounds`, unmutated, ×13 | **PASS** 13/13 | +| 10 | the same with mutation A (5 ms floor), ×3 | **FAIL** 3/3, capability clause | +| 11 | the same with mutation B (millisecond rounding), ×3 | **FAIL** 3/3, capability clause | +| 12 | the same with mutation B under four CPU spinners, ×3 | **FAIL** 3/3 | +| 13 | CI on `diag/flake-evidence`, run `34954538795` — handle-table sweep and calibration numbers on every arm | **PASS** as a measurement; the three windows-2025 arms fail by design (the diag tests panic to print their report) and `workflow-lint` fails on the diag-only `--nocapture` edit to `run-tests.py` | +| 14 | CI on `diag/flake-evidence`, run `34955502692` — `settled()` under eight busy threads on windows-2025 | **PASS**, 183 of 576 loaded cycles waited, worst wait 1.646 ms of 5 s, none reached the deadline (the diag test still panics by design to print its report) | +| 15 | CI on `diag/flake-evidence`, run `34956506068` — the gate under eight busy threads on windows-2025 | **FAIL by design**, and the reason is recorded above: at 200 % CPU the host's own sleep is 33 ms too. Superseded by row 16 | +| 16 | CI on `diag/flake-evidence`, run `34957467265` — the load curve, windows-2025 and macos-15 | **PASS** as a measurement; the gate holds at 0-3 of 4 busy vCPUs and fails only at full saturation | +| 17 | CI on `lane/flakes`, run `34955472126` (code identical to the final commit except `settled()`'s failure text) | **PASS**, 38/38 jobs green | +| 18 | CI on `lane/flakes`, run `34956471189`, final code commit `e4bc116` | **PASS**, 38/38 jobs green | +| 19 | CI on `lane/flakes`, run `34957283051`, same commit, consecutive | **PASS**, 38/38 jobs green | +| 16 | `python3 scripts/ci/run-tests.py native` on Windows / Linux | **UNRUN**, no host; covered by rows 13–15 | +| 17 | `python3 scripts/ci/run-tests.py web` / `node` | **UNRUN**, `wasm-bindgen-test-runner` not installed; neither file is compiled for `wasm32-unknown-unknown` tests, and cross-clippy covers the code | +| 22 | Mutation proof on the Windows CI arm | **UNRUN**, see #30 above |