diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 67895fa08..41f6a149a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -266,6 +266,45 @@ jobs: - name: probe magnitudes (topology) if: '!cancelled()' run: cargo run -p windows-platform-probes --bin probe-topology --locked + # `--release` on the next two, and ONLY on those two, because they are the + # only probes here that report nanoseconds. Everything above measures + # BEHAVIOUR -- what an API refuses, what a handle reports, which errors + # appear -- and that does not change with the optimisation level, so those + # keep the dev profile and the build time it saves. + # + # These two do not have that luxury. They compare operations a few tens of + # nanoseconds apart, and in an unoptimized build the loop, the closure + # indirection, and the request construction around each measured call + # carry overhead that does not shrink uniformly across them. The RATIOS + # are what the design reads -- "a doorbell is x% of a submit", "a captured + # handle costs Nx a built request" -- and a ratio of two figures each + # inflated by a different amount is not the shipping one. + # + # Decides how much machinery the two-layer ring's doorbell needs. Its + # park-and-wake handshake is bounded rather than INFINITE on purpose: the + # first version of it deadlocked, because an auto-reset event does not + # count signals and the waiter's count never caught up. A probe that can + # hang is a probe that can hang a build. + # + # `if: '!cancelled()'` for the same reason the topology step above carries + # it, and the reason is not specific to topology: a probe step exists to + # produce diagnostic output, so skipping it because an earlier step failed + # suppresses it in precisely the run that wanted it. The test step above + # covers both of these probes, and a host where those tests fail is a host + # whose timings are worth reading. + # + # It matters more for these two than for a pass/fail probe. Both now assert + # every status they take and panic on a missing NDJSON label, and both go + # through `emit_report`, which prints what was already established before a + # panic -- machinery that only reaches a reader if the step runs at all. + - name: probe magnitudes (doorbell cost) + if: '!cancelled()' + run: cargo run -p windows-platform-probes --bin probe-doorbell-cost --locked --release + # Read with the doorbell probe above: together they say whether the + # queue's mechanics or the request's own cost deserves the attention. + - name: probe magnitudes (request cost) + if: '!cancelled()' + run: cargo run -p windows-platform-probes --bin probe-request-cost --locked --release # Both halves of the long-path pair, deliberately. Either alone says # nothing: the finding is the *difference* between two executables that # differ only in whether `build.rs` embedded the `longPathAware` manifest, diff --git a/Cargo.lock b/Cargo.lock index 140169c83..350590843 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -216,6 +216,7 @@ dependencies = [ name = "windows-platform-probes" version = "0.0.0" dependencies = [ + "windows-namespace-request-sys", "windows-placement-probe", "windows-sys", "windows-threadpool-sys", diff --git a/crates/windows-namespace-request-sys/RESOLVED-TEST-FAILURES.md b/crates/windows-namespace-request-sys/RESOLVED-TEST-FAILURES.md new file mode 100644 index 000000000..6de36bdd3 --- /dev/null +++ b/crates/windows-namespace-request-sys/RESOLVED-TEST-FAILURES.md @@ -0,0 +1,8 @@ +# Resolved test failures: windows-namespace-request-sys + +Entries moved here from [UNRESOLVED-TEST-FAILURES.md](UNRESOLVED-TEST-FAILURES.md) +once diagnosed, with what the cause turned out to be. Append-only: entries are +never deleted, so a failure that recurs can be matched against one already +understood. + +*No failures have been resolved yet.* diff --git a/crates/windows-namespace-request-sys/UNRESOLVED-TEST-FAILURES.md b/crates/windows-namespace-request-sys/UNRESOLVED-TEST-FAILURES.md new file mode 100644 index 000000000..d540476ba --- /dev/null +++ b/crates/windows-namespace-request-sys/UNRESOLVED-TEST-FAILURES.md @@ -0,0 +1,98 @@ +# Unresolved test failures: windows-namespace-request-sys + +Observed failures that are real but not yet diagnosed. Recorded here rather than +left in a CI log, so a later intermittent failure is recognised as a known one +instead of being re-investigated from scratch or dismissed as noise. + +When an entry is resolved, move it to a sibling +[RESOLVED-TEST-FAILURES.md](RESOLVED-TEST-FAILURES.md) under a +`## Resolved -- ` heading in the same +change that removes it from this file. Do not delete entries. + +## Observed 2026-09-09 15:35:14 -04:00 -- `close::tests` handle-value reuse poisons the allocation lock + +**Symptom.** One CI run of `cargo test --workspace` reported **96 failures** in +this crate: `close::tests::a_caller_supplied_routine_is_carried` failed with +`assertion failed: !was_still_open(raw)`, and the other 95 all failed with +`the lock is not poisoned: PoisonError { .. }`. The 95 are collateral -- the +first test panicked while holding the write guard on `handle_allocation()`, +which poisons the lock for every test that takes it afterwards. **The count is +alarming and the defect is singular.** + +**It is intermittent, and that is established rather than assumed.** The same +commit (`b90d897`) was re-run with no change and passed. The crate passes 5/5 +locally. The two commits before it passed the identical job. The commit that +"failed" was comment-only, in a different crate. + +**Mechanism, as far as it is understood.** `was_still_open` probes a raw value +by attempting to close it: + +```rust +fn was_still_open(handle: HANDLE) -> bool { + unsafe { CloseHandle(handle) != FALSE } +} +``` + +Its own comment states the precondition: "A stale value fails with +`ERROR_INVALID_HANDLE` rather than closing something else, **because these tests +hold the allocation lock**." That precondition does not hold for the whole +process. Measured on this revision: **218 tests in the crate, and 11 of them open +handles without taking `handle_allocation()`** -- among them +`open::tests::a_missing_path_reports_the_raw_code_unaltered`, +`open::tests::the_overlapped_flag_is_carried_rather_than_decided`, and +`watch::tests::a_missing_directory_reports_the_raw_code`. + +`cargo test` runs tests as threads in one process (deliberately -- see the root +[DESIGN-NOTES.md](../../DESIGN-NOTES.md)), so a handle value freed by a +lock-holding test can be immediately reallocated by one of those 11 running +concurrently. The probe then finds the value open and the assertion fails. + +**The failing assertion is not the worst of it.** `was_still_open` *closes* the +handle when the probe succeeds. So in the losing interleaving this test does not +merely mis-report -- it closes a live handle belonging to another test, which +can surface later as an unrelated failure somewhere else entirely. The visible +assertion is the benign outcome. + +**Not caused by the change that observed it.** The branch that hit this +(`mikegrier/probes-cost-pair`, PR #83) makes **no source change to this crate**: +its only file here is this record. Everything else it touches is +`crates/windows-platform-probes/`, `.github/workflows/ci.yml` and `Cargo.lock`, +and it takes `windows-namespace-request-sys` as a new *dependency* without +altering it. + +(An earlier revision of this paragraph said the branch touched only those three +paths, which was untrue the moment it was written -- the file stating it lives +under `crates/windows-namespace-request-sys/`. Corrected so a later reader +checking the claim against the diff finds it holds.) + +**Directions for whoever picks this up**, in rough order of directness: + +1. Take the allocation lock in the 11 tests that open handles without it. This is + the smallest change and closes the measured hole, but it leaves the invariant + resting on every future test author remembering -- the same "a flat rule beats + a rule someone must remember to apply" problem recorded in the root + [DESIGN-NOTES.md](../../DESIGN-NOTES.md) for status checking. +2. Make the hazard structural rather than remembered: have `Fixture` / + `captured_duplicate` take the lock themselves, so opening a handle *without* + it is not something a test can do by omission. This is the same move as + preferring a type that discharges a rule over a rule each author must apply. +3. Make the lock unnecessary by not probing a raw value at all. `was_still_open` + exists to answer "did the close routine actually run?", and asking the routine + rather than the OS cannot race. **Note this is a bigger change than it sounds** + -- the two routines here are the real `CloseHandle` and + `FindCloseChangeNotification`, called directly with no shim (a deliberate + property, recorded in [src/close.rs](src/close.rs)), so there is nothing + currently observable to ask. It would mean introducing a test-only routine + that records into a static, which is the pattern `windows-threadpool-sys` + already uses for its wait targets -- see the root + [DESIGN-NOTES.md](../../DESIGN-NOTES.md) -> "Testing it needs per-test statics, + not one global counter", which also documents why those statics must be + per-test rather than at module scope, for exactly this concurrency reason. + +Direction 1 stops the bleeding today; direction 2 is the smallest change that +stops it recurring. Direction 3 is the most thorough and touches the most. + +(An earlier revision of this list claimed the close routines "already have +observation statics". They do not -- that is `windows-threadpool-sys`'s pattern, +imported here by mistake. `was_still_open`, used at seven sites in +`close/tests.rs`, is the only mechanism this crate has for the question.) diff --git a/crates/windows-platform-probes/CHECKLIST.md b/crates/windows-platform-probes/CHECKLIST.md index 3efef01fd..f7b33dbc6 100644 --- a/crates/windows-platform-probes/CHECKLIST.md +++ b/crates/windows-platform-probes/CHECKLIST.md @@ -137,3 +137,72 @@ speculative list to extend by imagination -- a fourth is added when a fourth con than noise: across two rounds one reader raised this twice while two others cleared it, one of them explicitly after being pointed at the question. Nothing in the suite decides it either way, which is itself the argument for the oracle. + +- [ ] **M2.6** -- Say precisely what `GetFullPathNameW` does, in the crate that owns it, and decide + whether it is still the call `prepare` wants. Two successive descriptions in the cost probe were + each wrong in the same direction: *a syscall cost*, which a timing loop cannot establish, and then + *lexical*, which it also is not. The probe now states the cost and declines the mechanism, which is + honest but leaves the question open one layer down. + + [../windows-namespace-request-sys/src/full_path.rs](../windows-namespace-request-sys/src/full_path.rs) + carries the same imprecision, and is the crate that owns the answer: its module doc says "This call + is **lexical**. It resolves relative components and `.`/`..` against the process current + directory". Those two sentences disagree -- consulting the current directory is process state, and + for a drive-relative path (`C:foo`) it also reads the per-drive current directory held in the + `=C:` environment variables. "Touches no filesystem" is the claim that holds; "lexical" is not. + + **The mono-repo rule says fix the layer, so the correction belongs in + `windows-namespace-request-sys`, not in the probe that consumes it.** It is queued rather than + taken because that crate is outside this peel and is release-managed, so a docs change there is its + own commit with its own scope. + + The decision half is the part worth an engineer's attention rather than a sweep. A genuinely + lexical canonicalizer exists -- `PathCchCanonicalizeEx`, or `PathAllocCanonicalize` -- and would be + cheaper, with no process state read at all. **It is very likely the wrong call anyway**, because + resolving against the current directory *at submission* is the property the namespace design is + buying: the CWD is shared mutable state, so a relative path means something different depending on + when it is resolved, and pinning that on the submitting thread is the whole point. Record that + conclusion explicitly, with the alternative named, so the next reader does not re-derive it -- and + if it is wrong, the cheaper call is sitting there. + + Also worth settling while the question is open: whether `GetFullPathNameW` can enter the kernel at + all on any path this crate takes. The probe measured ~212 ns for a build on x86_64 and declines to + say what that is made of; the owning crate could say, and a reader of either would then stop + guessing. + +- [ ] **M2.7** -- Decide whether the other nine probe steps in CI should carry `if: '!cancelled()'`, + and apply or record the decision. + + **Measured 2026-09-09:** twelve probe steps in [ci.yml](../../.github/workflows/ci.yml), of which + three are guarded -- topology, and the doorbell/request pair added with this note. The other nine + (`error mode`, `handle state`, `worker context`, `pool growth`, `device map`, `IoRing`, + `completion port`, and both halves of the long-path pair) are skipped whenever an earlier step in + the job fails, because Actions defaults to `if: success()`. + + The argument for guarding is already written at the topology step and is not specific to it: a + probe step exists to emit diagnostics, so skipping it on failure suppresses it in exactly the run + that wanted it. **The long-path pair is the sharpest case** -- its own comment says either half + alone "says nothing", since the finding is the difference between two executables, so a partial + run of that pair is worse than useless. + + **It is queued rather than done because there is a real tradeoff, and it is an operational call.** + `!cancelled()` also runs the step when the *build* failed, where `cargo run` cannot compile and + the step turns from skipped (grey) into failed (red). That trades quieter broken-build output for + better broken-test output. The topology step already took that trade; whether all twelve should is + a judgement about how the CI log is read, not something to settle by consistency alone. + +- [ ] **M2.8** -- Carry the OS error in the remaining Win32 assertion messages. + + `last_os_error()` (or a raw `GetLastError`) is in the messages in `doorbell_cost`, `request_cost` + and `handle_state`, and missing from four sites in probes this peel did not touch: + `completion_port.rs:224` and `:234` ("create a completion port"), `ioring.rs:320` ("create the + probe pipe"), and `pool_growth.rs:62` ("create the gate event"). Each says what was being attempted + and not why it failed, which is the whole of what a CI log can offer someone who cannot rerun under + a debugger. + + Two rules worth carrying over, both learned the expensive way in this peel. Read the error + **immediately after the single call whose failure is reported** -- a code attached to a condition + spanning two calls belongs to whichever ran last, not whichever failed, and can print "The + operation completed successfully" under a message saying something failed. And attach it only to a + condition that is genuinely an OS failure: a call that returned a size rather than an error should + not carry one, since `GetLastError` says nothing about it. diff --git a/crates/windows-platform-probes/Cargo.toml b/crates/windows-platform-probes/Cargo.toml index 88cf25858..807d09fe5 100644 --- a/crates/windows-platform-probes/Cargo.toml +++ b/crates/windows-platform-probes/Cargo.toml @@ -51,6 +51,14 @@ path = "src/bin/pool_growth.rs" name = "probe-topology" path = "src/bin/topology.rs" +[[bin]] +name = "probe-doorbell-cost" +path = "src/bin/doorbell_cost.rs" + +[[bin]] +name = "probe-request-cost" +path = "src/bin/request_cost.rs" + # These two are the same code, and that is the measurement: they differ only in # whether `build.rs` embeds the `longPathAware` manifest, which is not a runtime # switch and so cannot be a flag on one binary. @@ -87,6 +95,10 @@ windows-topology-sys = { path = "../windows-topology-sys" } # somewhere and compared against something it does not describe. That banner is # `windows-placement-probe`'s to render, not a second copy here. windows-placement-probe = { path = "../windows-placement-probe" } +# The request-cost probe measures the real request type the design would put on +# a queue, not a stand-in, for the same reason the topology probe reads the +# shipping parse: a reimplementation would measure the reimplementation. +windows-namespace-request-sys = { path = "../windows-namespace-request-sys" } # The long-path probe measures a length against `MAX_PATH`, and `MAX_PATH` counts # UTF-16 code units. `OsStr::len` counts Rust's platform encoding -- WTF-8 here -- # so the two disagree the moment a non-ASCII character appears in `%TEMP%`, which @@ -115,6 +127,9 @@ features = [ "Win32_System_Diagnostics_Debug", "Win32_System_IO", "Win32_System_Pipes", + # GetSystemDirectoryW, so the request probe measures the real system + # directory instead of assuming Windows is installed on C:. + "Win32_System_SystemInformation", "Win32_System_SystemServices", "Win32_System_Threading", ] diff --git a/crates/windows-platform-probes/src/bin/doorbell_cost.rs b/crates/windows-platform-probes/src/bin/doorbell_cost.rs new file mode 100644 index 000000000..382495ab4 --- /dev/null +++ b/crates/windows-platform-probes/src/bin/doorbell_cost.rs @@ -0,0 +1,321 @@ +// Copyright (c) Mike Grier. + +//! Prints how expensive a doorbell is relative to the syscall it would guard. +//! +//! **An experiment, not a component.** These probes measure platform behaviour +//! and are not for production use. Do not call them from production code, and +//! do not lift a technique out of here. See this crate's DESIGN-NOTES.md. +//! +//! This decides whether the two-layer ring design needs an eventcount at all. +//! If a doorbell is a meaningful fraction of `SubmitIoRing`, the skip-when-busy +//! rules are load-bearing. If it is noise, a simple always-signal queue is +//! adequate and the more delicate protocol -- publish intent, re-check, park -- +//! can wait for evidence that it is worth its lost-wakeup risk. + +use std::fmt::Write as _; +use windows_platform_probes::doorbell_cost::{measure, measure_park_and_wake}; + +use windows_platform_probes::report::emit_report; + +fn main() { + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // timing number can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!( + out, + "== what does a doorbell cost, against the syscall it guards? ==\n" + ); + + // Measured HERE, after the banner is already in the buffer, and not in + // `main`'s argument list where it used to sit. + // + // `emit_report` prints whatever was composed before a panic, which is the + // property that makes a probe diagnosable rather than merely correct. A + // measurement called in the argument position runs before the renderer is + // ever entered, so it was outside that protection entirely: a panic left + // the reader with no banner, no heading, and no indication of which probe + // had died. + // + // This matters more than it did. Both measurements below now assert every + // status they take, so the panic surface they present is deliberately much + // larger than when this `main` was written -- adding loud failures to a + // probe while leaving it outside the mechanism that reports them is half a + // change. + let observation = &measure(); + let park = measure_park_and_wake(20_000); + + let _ = writeln!(out, "{:<30} {:>12}", "operation", "ns/op"); + for timing in &observation.timings { + let _ = writeln!(out, "{:<30} {:>12.1}", timing.label, timing.nanos_per_op); + } + + match park { + Some(ns) => { + let _ = writeln!(out, "{:<30} {:>12.1}", "park_and_wake round trip", ns); + } + None => { + let _ = writeln!( + out, + "{:<30} {:>12}", + "park_and_wake round trip", "TIMED OUT" + ); + } + } + + let _ = writeln!(out, "\ninterpretation:"); + + if let Some(atomic) = observation.get("atomic_fetch_add") + && let Some(doorbell) = observation.get("set_reset_event") + && atomic > 0.0 + { + let _ = writeln!( + out, + " a doorbell cycle costs {:.0}x an uncontended atomic ({:.0} ns vs {:.1} ns).", + doorbell / atomic, + doorbell, + atomic + ); + if let Some(park) = park { + let _ = writeln!( + out, + " a full park-and-wake round trip costs {:.0}x that again ({:.0} ns),", + park / doorbell, + park + ); + // "an upper bound", matching what `measure_park_and_wake` documents. + // This said "which is what is paid when the consumer genuinely + // sleeps", while the function producing the number says it is a + // round trip -- wake the peer, park, be woken -- and therefore an + // upper bound on one wakeup rather than the cost itself. The real + // doorbell path pays one handoff; this measures two. + let _ = writeln!( + out, + " which bounds ONE wakeup from above: it is two handoffs, and the" + ); + let _ = writeln!(out, " doorbell path pays one."); + } + } + + // Deliberately NOT expressed as a share of the empty submit. See below. + if let Some(submit) = observation.submit_nanos { + let _ = writeln!( + out, + "\n CAUTION: an empty SubmitIoRing measured {submit:.0} ns, and that is" + ); + let _ = writeln!( + out, + " NOT a fair denominator: it carries no work, so any 'doorbell is N%" + ); + let _ = writeln!( + out, + " of a syscall' figure derived from it would be a confident wrong" + ); + let _ = writeln!( + out, + " answer. The honest denominator is the cost of the real work a" + ); + let _ = writeln!( + out, + " submission carries, which this probe does not measure." + ); + + // Whether it short-circuits is DECIDED HERE, not asserted. This text + // used to state, unconditionally, that the empty submit was "far too + // cheap for a kernel transition -- almost certainly short-circuiting in + // user mode". That was written around a 79 ns reading on the + // Snapdragon X2 (ARM64) development machine and is contradicted by any + // host where the empty + // submit lands among this probe's own syscalls: measured here at + // 216 ns against 205 ns for an already-signalled `SetEvent` and 280 ns + // for a satisfied wait, the claim is not merely unsupported, it is + // false. The advice above holds either way, which is why it is + // unconditional and this is not. + let syscalls: Vec = ["set_event_already_signalled", "wait_zero_signalled"] + .into_iter() + .filter_map(|label| observation.get(label)) + .collect(); + if let Some(cheapest) = syscalls.iter().copied().reduce(f64::min) { + if submit < cheapest / 2.0 { + let _ = writeln!( + out, + " It is also under half this probe's cheapest measured syscall" + ); + let _ = writeln!( + out, + " ({cheapest:.0} ns), so on this host it is very likely short-circuiting" + ); + let _ = writeln!(out, " in user mode when there is nothing queued."); + } else { + let _ = writeln!( + out, + " On this host it is the same order as this probe's own syscalls" + ); + let _ = writeln!( + out, + " ({cheapest:.0} ns and up), so nothing here says it short-circuits --" + ); + let _ = writeln!(out, " it is simply an empty one."); + } + } + } + // What can be said without a denominator: how much batching it takes for + // the doorbell to disappear, which is the lever the design actually has. + if let Some(doorbell) = observation.get("set_reset_event") + && let Some(atomic) = observation.get("atomic_fetch_add") + && atomic > 0.0 + { + let _ = writeln!( + out, + "\n batching is the lever, and it is a strong one. One doorbell per" + ); + let _ = writeln!(out, " drained batch costs, per operation:"); + for batch in [1_u32, 8, 32, 128] { + let _ = writeln!( + out, + " batch of {batch:>4}: {:>7.1} ns/op ({:.1}x an atomic)", + doorbell / f64::from(batch), + doorbell / f64::from(batch) / atomic + ); + } + let break_even = (doorbell / atomic).ceil() as u32; + let _ = writeln!( + out, + " so at a batch of about {break_even}, the doorbell costs less per" + ); + let _ = writeln!(out, " operation than the atomic push it accompanies."); + + // What the arithmetic above does NOT support, spelled out because the + // conclusion drawn from it used to be its opposite. + // + // Every figure above divides ONE doorbell across a batch, which is the + // cost of signalling once per drained batch -- coalescing on the + // empty-to-non-empty edge. A producer that signals on every push pays a + // redundant `SetEvent` each time and amortizes nothing, which is the + // `set_event_already_signalled` row this probe measures precisely + // because that is the always-signal cost. + // + // This block used to end "the skip-when-busy rule is a refinement, not a + // prerequisite ... a first implementation can always-signal and stay + // honest", which reverses its own arithmetic: batching amortizes a + // doorbell only for a producer that does not ring one per push. + if let Some(redundant) = observation.get("set_event_already_signalled") { + let _ = writeln!( + out, + "\n That is the COALESCED cost -- one signal per drained batch. A" + ); + let _ = writeln!( + out, + " producer that signals on every push amortizes nothing and pays a" + ); + let _ = writeln!( + out, + " redundant SetEvent per operation: {redundant:.0} ns, or {:.0}x the push,", + redundant / atomic + ); + let _ = writeln!(out, " at every batch size."); + } + } + + let _ = writeln!( + out, + "\n => Coalescing is the prerequisite; the parked-consumer check is the" + ); + let _ = writeln!( + out, + " refinement. Signalling once per empty-to-non-empty edge is what" + ); + let _ = writeln!( + out, + " drives the doorbell below the push, and it needs no eventcount --" + ); + let _ = writeln!( + out, + " only the queue's own emptiness. Tracking whether a consumer is" + ); + let _ = writeln!( + out, + " actually parked is a further saving on top of that, and it is the" + ); + let _ = writeln!( + out, + " part carrying the lost-wakeup risk, so it can wait for a" + ); + let _ = writeln!(out, " measurement against real work."); + // `expect`, not `unwrap_or(NAN)`. These four labels are always produced by + // `measure`, so a lookup that misses means a label was renamed in one place + // and not the other -- a defect in this probe, not a condition of the host. + // + // The old default made that defect emit `"atomic_ns":NaN`, and **`NaN` is + // not JSON**: RFC 8259 has no such literal, and a strict parser rejects the + // whole line. So a renamed label would have silently converted every run + // into unparseable output for any consumer doing what this format exists + // for. + // + // Note the contrast with the three fields below, which correctly emit + // `null`. That is right for *them*: a parked handshake can time out and an + // `IoRing` may be unavailable, so absent is a real outcome those fields + // must be able to say. Absent is not a real outcome for these four, and + // giving them a way to say it only hid the bug. + let atomic = observation + .get("atomic_fetch_add") + .expect("measure always records atomic_fetch_add"); + let already = observation + .get("set_event_already_signalled") + .expect("measure always records set_event_already_signalled"); + let cycle = observation + .get("set_reset_event") + .expect("measure always records set_reset_event"); + let wait0 = observation + .get("wait_zero_signalled") + .expect("measure always records wait_zero_signalled"); + // `doorbell_over_empty_submit`, not `doorbell_share_of_submit`. The prose + // above tells a human that an empty submit is not a fair denominator and + // that any figure derived from it is a confident wrong answer -- and this + // line then handed a machine exactly that figure under a name meaning "the + // doorbell's share of a submit", with no caveat a mining pass could read. + // The name states its own denominator, so a query that wants the ratio asks + // for it knowingly, and one that wants a real share of a syscall does not + // find this field by looking for that. + // + // The accessor carries the same name, and did not at first. Renaming the + // serialized field while leaving the method as `doorbell_share_of_submit` + // left the argument above sitting a few lines from the sibling it did not + // reach -- and a reviewer duly read the method as promising a meaningful + // share. A rename for precision is not finished until every name for the + // quantity moves; the field and the method are one fact with two spellings. + let _ = writeln!( + out, + concat!( + r#"{{"reason":"x-probe-doorbell-cost","arch":"{}","atomic_ns":{:.1},"#, + r#""set_event_already_signalled_ns":{:.1},"set_reset_event_ns":{:.1},"#, + r#""wait_zero_signalled_ns":{:.1},"park_and_wake_round_trip_ns":{},"#, + r#""submit_io_ring_empty_ns":{},"doorbell_over_empty_submit":{}}}"# + ), + std::env::consts::ARCH, + atomic, + already, + cycle, + wait0, + park.map_or("null".to_string(), |n| format!("{n:.1}")), + observation + .submit_nanos + .map_or("null".to_string(), |n| format!("{n:.1}")), + observation + .doorbell_over_empty_submit() + .map_or("null".to_string(), |s| format!("{s:.4}")), + ); +} diff --git a/crates/windows-platform-probes/src/bin/request_cost.rs b/crates/windows-platform-probes/src/bin/request_cost.rs new file mode 100644 index 000000000..558fb2a91 --- /dev/null +++ b/crates/windows-platform-probes/src/bin/request_cost.rs @@ -0,0 +1,392 @@ +// Copyright (c) Mike Grier. + +//! Prints what a namespace request costs to build, against the queue that would +//! carry it. +//! +//! **An experiment, not a component.** These probes measure platform behaviour +//! and are not for production use. Do not call them from production code, and +//! do not lift a technique out of here. See this crate's DESIGN-NOTES.md. +//! +//! Read alongside `probe-doorbell-cost`: together they say whether the queue's +//! mechanics or the request's allocation model deserves the attention. + +use std::fmt::Write as _; +use windows_platform_probes::report::emit_report; +use windows_platform_probes::request_cost::measure; + +/// Measured by `probe-doorbell-cost` on a **Snapdragon X2 (ARM64)** machine, +/// and recorded in [the 2026-08-30 design session]. Restated here only to +/// render a ratio; the authoritative number is whatever that probe prints on +/// the host this runs on. +/// +/// **The platform is named because a nanosecond figure without one is not a +/// measurement, it is an anecdote.** These constants said "the development +/// machine", which is a label only its author can resolve, and everything +/// derived from them was then read as though it described machines in general. +/// It does not: an x86_64 host measured during review put the doorbell cycle at +/// ~531 ns against ~208 ns for a redundant `SetEvent`, where the ARM64 figures +/// here are 164.9 and 7.2. Two observations, two architectures, and the +/// conclusions drawn from them differ in sign -- which is the whole argument +/// against generalising from either. +/// +/// **The build profile behind these is not recorded**, which is why the report +/// below calls the ratios indicative rather than quoting them as results. They +/// are not re-baselined here: the figure is the one that session recorded, and +/// silently replacing it would leave the session describing a number that no +/// longer exists anywhere. CI runs both this probe and `probe-doorbell-cost` +/// under `--release` in the same job, so the like-for-like comparison a reader +/// actually wants is those two outputs, not this constant. +/// +/// [the 2026-08-30 design session]: ../../../../design-sessions/DESIGN-SESSION-2026-08-30-numa-sharded-io-execution-domains.md +const DOORBELL_NS_REFERENCE: f64 = 164.9; +const ATOMIC_NS_REFERENCE: f64 = 7.2; + +fn main() { + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // timing number can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== what does a namespace request cost to build? ==\n"); + + let observation = measure(); + + let _ = writeln!( + out, + "{:<26} {:>10} {:>14} {:>16}", + "operation", "ns/op", "x an atomic", "x a doorbell" + ); + // Says what the first four rows include, because their names do not. Each + // is a construct-and-DESTROY cycle: `time_loop` drops the value it is + // handed at the end of the timed statement, so the free is inside the + // figure. `capture_handle` and `close_handle` are the exception and are + // timed apart, because dropping a `CapturedHandle` calls `CloseHandle` and + // that is a second kernel transition rather than a free. + let _ = writeln!( + out, + " (the first four are construct-and-drop cycles; capture and close are\n \ + timed separately)" + ); + for timing in &observation.timings { + let _ = writeln!( + out, + "{:<26} {:>10.1} {:>14.1} {:>16.2}", + timing.label, + timing.nanos_per_op, + timing.nanos_per_op / ATOMIC_NS_REFERENCE, + timing.nanos_per_op / DOORBELL_NS_REFERENCE, + ); + } + let _ = writeln!( + out, + "\n(ratios use the reference doorbell {DOORBELL_NS_REFERENCE:.1} ns and atomic \ + {ATOMIC_NS_REFERENCE:.1} ns measured\n by probe-doorbell-cost on the development \ + machine; re-read that probe on this host\n before trusting them)" + ); + + let _ = writeln!(out, "\ninterpretation:"); + + let build = observation.get("build_open_request"); + let capture = observation.get("capture_handle"); + + if let Some(build) = build { + // The ratio names its own reference, because the two numbers do not + // come from the same machine. `build` was measured on this host just + // now; the doorbell figure is a constant captured once on the + // Snapdragon X2 (ARM64) development machine. This probe now runs on + // hosted CI runners, which are a heterogeneous fleet, so a ratio printed + // as though both halves were local can be wrong even when the + // measurement is sound. + let _ = writeln!( + out, + " building a pathed request costs {build:.0} ns, which is {:.1}x one", + build / DOORBELL_NS_REFERENCE + ); + let _ = writeln!( + out, + " doorbell AS MEASURED ON THE ARM64 DEVELOPMENT MACHINE ({DOORBELL_NS_REFERENCE:.1} ns)," + ); + let _ = writeln!( + out, + " not on this one. Run probe-doorbell-cost here to make the ratio local." + ); + let _ = writeln!(out); + let _ = writeln!( + out, + " SCOPE, because this is easy to over-read: that is a statement about" + ); + let _ = writeln!( + out, + " ONE OPERATION TYPE, not about the queue. A namespace open is the" + ); + let _ = writeln!( + out, + " heaviest payload the queue carries -- it resolves a path through" + ); + let _ = writeln!( + out, + " Win32 and may duplicate a handle -- and it ends in a CreateFileW" + ); + let _ = writeln!( + out, + " costing microseconds regardless. A registered-buffer read, which is" + ); + let _ = writeln!( + out, + " the hot path, carries no path and no handle: its descriptor is a slot" + ); + let _ = writeln!( + out, + " index and an offset, and there the queue's own mechanics are the" + ); + let _ = writeln!(out, " whole cost."); + let _ = writeln!(out); + let _ = writeln!( + out, + " Nor is per-operation overhead the same thing as queue efficiency." + ); + let _ = writeln!( + out, + " Throughput under contention, cache behaviour, batching amortization" + ); + let _ = writeln!( + out, + " and backpressure decide that, and a single uncontended construction" + ); + let _ = writeln!(out, " time measures none of them."); + let _ = writeln!(out); + // States the COMPARISON and refuses the verdict, because this probe + // does not measure a doorbell. + // + // This read "What it does support: for an open-heavy workload, doorbell + // tuning would be optimizing the small half" -- a design conclusion + // whose truth depends entirely on which of the two is larger, decided + // against a constant measured on the Snapdragon X2 (ARM64) development + // machine. It INVERTS on the x86_64 host measured during review, where + // `probe-doorbell-cost` reported a ~531 ns cycle against ~210 ns to + // build a request, so the doorbell is the large half there and tuning + // it would optimize the large one. Both probes run in the same + // CI job, so the sentence was contradicted a few lines further down the + // same log. + // + // The caveats above cover the printed ratio and the operation-type + // scope; neither guarded this, because it was phrased as what the run + // supports rather than as a ratio. + let _ = writeln!( + out, + " WHICH HALF IS LARGER IS NOT ESTABLISHED HERE. Whether doorbell" + ); + let _ = writeln!( + out, + " tuning would optimize the large or the small half depends on the" + ); + let _ = writeln!( + out, + " doorbell measured ON THIS HOST, which this probe does not measure:" + ); + let _ = writeln!( + out, + " read probe-doorbell-cost's set_reset_event from the same run and" + ); + let _ = writeln!( + out, + " compare it against the {build:.0} ns above. The comparison can invert" + ); + let _ = writeln!( + out, + " between hosts, so a conclusion about OPERATION MIX belongs to a" + ); + let _ = writeln!(out, " reader holding both figures from one machine."); + } + + if let Some(capture) = capture { + let _ = writeln!( + out, + "\n duplicating a handle costs {capture:.0} ns -- a kernel transition, not" + ); + let _ = writeln!( + out, + " a memory copy, and easy to under-count when thinking about what an" + ); + let _ = writeln!(out, " SQE holds."); + // Reported beside it because the duplication figure above excludes it by + // construction, and a reader sizing a request's real cost needs both: + // every captured handle is eventually closed, so the lifecycle is the + // pair. Keeping them separate is what stops either being quoted as the + // other. + if let Some(close) = observation.get("close_handle") { + let _ = writeln!( + out, + " Closing one costs a further {close:.0} ns, measured separately, so a" + ); + let _ = writeln!( + out, + " captured handle's whole lifecycle is {:.0} ns. The duplication figure", + capture + close + ); + let _ = writeln!(out, " above is the duplication alone."); + } + if let Some(build) = build { + if capture > build { + let _ = writeln!( + out, + " It is {:.1}x the cost of building the pathed request itself, so a", + capture / build + ); + let _ = writeln!( + out, + " request carrying a handle is dominated by the duplication, and" + ); + let _ = writeln!( + out, + " any allocation tuning on the path would be optimizing the wrong" + ); + let _ = writeln!(out, " half."); + } else { + // The ratio without a verdict. This branch fires on `capture <= + // build`, which is every ratio from 0.99 down to 0.01, and it + // said "the two are comparable and neither dominates" for all + // of them -- a claim about closeness drawn from a test for + // order. Whether two figures are comparable needs a range, and + // this probe was given one only by accident of which arm it + // landed in. + let _ = writeln!( + out, + " It is {:.2}x the pathed request. Which of the two dominates, if", + capture / build + ); + let _ = writeln!( + out, + " either does, is for a reader with a threshold in mind; this run" + ); + let _ = writeln!(out, " establishes only the two costs and their ratio."); + } + } + } + + // The split that decides whether an allocator change can help at all. + if let Some(build) = build + && let Some(clone) = observation.get("clone_prepared_units") + && build > clone + { + let _ = writeln!( + out, + "\n WHERE THE TIME ACTUALLY GOES, and it is not the allocator:" + ); + // "resolves against process state" -- not "a syscall", and not + // "lexical" either. + // + // The first was wrong because a timing loop cannot establish a kernel + // transition. The second, which replaced it, is wrong for a symmetric + // reason: `GetFullPathNameW` consults the process current directory, + // and for a drive-relative path the per-drive current directory held in + // the `=C:` environment variables, so it is not pure string work. A + // genuinely lexical canonicalizer is a different call + // (`PathCchCanonicalizeEx`), and it is deliberately NOT the one + // `prepare` wants -- resolving against the CWD at submission is the + // property the namespace design is buying. + // + // What this run established is the cost. The mechanism it did not, and + // two successive attempts to name one were each wrong in the same way. + let _ = writeln!( + out, + " `prepare` calls GetFullPathNameW to resolve the path against the" + ); + let _ = writeln!( + out, + " process working directory, because the CWD is mutable by any thread" + ); + let _ = writeln!( + out, + " and resolving later would be racy. That reads process state and" + ); + let _ = writeln!( + out, + " touches no filesystem -- and it is not an allocation, so most of the" + ); + let _ = writeln!( + out, + " cost above is work no allocation scheme can remove. Whether any of" + ); + let _ = writeln!( + out, + " it enters the kernel is not something this run measured." + ); + let _ = writeln!( + out, + " Two different schemes recover two different things, and this said" + ); + let _ = writeln!( + out, + " one number for both. RECYCLING a resolved path pays {clone:.0} ns instead" + ); + let _ = writeln!( + out, + " of {build:.0} ns, so it recovers {:.0} ns -- but that saving is the Win32", + build - clone + ); + let _ = writeln!( + out, + " resolution, not an allocation, and only a caller that can reuse a" + ); + let _ = writeln!( + out, + " resolved path gets it. INLINE STORAGE removes the allocation and" + ); + let _ = writeln!( + out, + " copy instead, which is what the {clone:.0} ns clone measures, so it" + ); + let _ = writeln!( + out, + " recovers at most that and cannot touch the resolution at all." + ); + let _ = writeln!( + out, + " A caller with a fresh path each time pays the resolution regardless." + ); + } + + // `expect`, not `null`. Every label below is recorded unconditionally by + // `measure`, so a lookup that misses means a label was renamed on one side + // and not the other -- a defect in this probe, not a condition of the host. + // + // `null` is the right answer for a value that can legitimately be absent, + // and none of these can be. Letting them say "absent" would have produced a + // partially populated record that parses cleanly and reads, to a mining + // pass, as a host on which the measurement did not apply. + let get = |label: &str| { + let ns = observation + .get(label) + .unwrap_or_else(|| panic!("measure always records {label}")); + format!("{ns:.1}") + }; + let _ = writeln!( + out, + concat!( + r#"{{"reason":"x-probe-request-cost","arch":"{}","prepare_short_cycle_ns":{},"#, + r#""prepare_long_cycle_ns":{},"build_open_request_cycle_ns":{},"#, + r#""clone_prepared_units_cycle_ns":{},"capture_handle_ns":{},"#, + r#""close_handle_ns":{}}}"# + ), + std::env::consts::ARCH, + get("prepare_short_path"), + get("prepare_long_path"), + get("build_open_request"), + get("clone_prepared_units"), + get("capture_handle"), + get("close_handle"), + ); +} diff --git a/crates/windows-platform-probes/src/bin/topology.rs b/crates/windows-platform-probes/src/bin/topology.rs index 52e44dd6a..1b1191cac 100644 --- a/crates/windows-platform-probes/src/bin/topology.rs +++ b/crates/windows-platform-probes/src/bin/topology.rs @@ -14,14 +14,23 @@ //! rather than read by eye. use windows_placement_probe::fingerprint::Fingerprint; -use windows_platform_probes::report::{Stdout, emit}; +use windows_platform_probes::report::emit_report; use windows_platform_probes::topology::measure; use windows_platform_probes::topology_report::{attribution, report, report_unmeasured}; fn main() { - // The only place that names the real stream, and the only place that reads - // the host. The text is composed in the library so every branch of it can - // be driven from a test -- see `topology_report`. + // `emit_report`, like every other probe. This used to call `emit` with a + // fully composed `String`, which gave up the one thing `emit_report` is for: + // printing what was already established when a later step panics. The three + // host reads below are exactly the steps that can, so the bypass removed the + // protection at the only place it would have been used. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // The only place that reads the host. The text is composed in the library so + // every branch of it can be driven from a test -- see `topology_report`. // // The banner is read FIRST and passed in. It runs a topology discovery of // its own, so leaving it to the renderer made the library half depend on a @@ -46,5 +55,5 @@ fn main() { Ok(observation) => report(&banner, &observation), Err(error) => report_unmeasured(&banner, &error), }; - emit(&mut Stdout, &text); + out.push_str(&text); } diff --git a/crates/windows-platform-probes/src/doorbell_cost.rs b/crates/windows-platform-probes/src/doorbell_cost.rs new file mode 100644 index 000000000..00062dddc --- /dev/null +++ b/crates/windows-platform-probes/src/doorbell_cost.rs @@ -0,0 +1,550 @@ +// Copyright (c) Mike Grier. + +//! How expensive is a doorbell, relative to the syscall it would guard? +//! +//! **An experiment, not a component.** These probes measure platform behaviour +//! and are not for production use. Do not call them from production code, and +//! do not lift a technique out of here. See this crate's DESIGN-NOTES.md. +//! +//! # The decision this exists to inform +//! +//! The two-layer ring design has a client thread push a descriptor onto a +//! bounded MPSC queue and then, sometimes, signal an event so the domain thread +//! wakes. The design assumes that signal is expensive enough to be worth +//! avoiding, and proposes an eventcount -- publish intent to park, re-check the +//! queue, then wait -- so a producer rings the doorbell only on the +//! empty-to-non-empty edge and only when a consumer is actually parked. +//! +//! That protocol is the highest-risk part of the whole design, because +//! publish-recheck-park is exactly where lost wakeups live. Building it because +//! the cost was *assumed* would be taking on that risk without evidence. So: +//! +//! - if `SetEvent` is a meaningful fraction of `SubmitIoRing`, the skip rules +//! are load-bearing and belong in the design from the start; +//! - if it is noise, a simple always-signal queue is adequate and the +//! optimization can wait for a measurement that justifies it. +//! +//! # What is timed +//! +//! Each is a tight loop over a warm path, reported as nanoseconds per +//! operation. Absolute values are host-specific and uninteresting; the +//! **ratios** are the finding. +//! +//! - `atomic_fetch_add` -- the uncontended atomic that a queue push costs, as a +//! floor for "the cheapest useful thing". +//! - `set_event_already_signalled` -- `SetEvent` on an event that is already +//! set, which is the redundant-signal case the skip rule removes. +//! - `set_reset_event` -- `SetEvent` then `ResetEvent`, the honest cost of one +//! doorbell cycle with nobody waiting. +//! - `wait_zero_signalled` -- `WaitForSingleObject(handle, 0)` on a signalled +//! event: the consumer's cost of observing it. +//! - `submit_io_ring_empty` -- `SubmitIoRing` with nothing queued, which is the +//! syscall the doorbell would be amortised against. Absent when `IoRing` is +//! unavailable. +//! +//! # The empty submit is not a fair denominator, and the first run proved it +//! +//! This probe was written expecting to divide the doorbell cost by +//! `submit_io_ring_empty` and read off "the doorbell is N% of a syscall". **Do +//! not do that.** An empty submission carries no work, so whatever it costs is +//! not the denominator that question needs, and "the doorbell is 210% of a +//! syscall" would be a confident wrong answer whatever the number turned out +//! to be. +//! +//! Whether it even reaches the kernel is host-dependent and the binary decides +//! it per run rather than asserting it. On the Snapdragon X2 (ARM64) development machine it came in +//! at ~79 ns, far below that machine's own syscalls, which reads as +//! short-circuiting in user mode when there is nothing queued; on an x86_64 +//! host measured during review it was 216 ns, sitting among that host's 206 ns +//! `SetEvent` and 280 ns satisfied wait, where nothing supports the claim. The +//! argument above needs neither reading, which is why it is stated over the +//! work carried rather than over the transition. +//! The honest denominator is the cost of the real work a submission carries, +//! which this probe deliberately does not measure -- so it reports the absolute +//! costs and the *batching* arithmetic instead, and leaves the ratio alone. +//! [`Observation::doorbell_over_empty_submit`] is retained only because the raw +//! fact is worth recording; it is named for its own denominator, and its own +//! documentation repeats this warning. + +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Instant; + +use windows_sys::Win32::Foundation::{ + CloseHandle, HANDLE, WAIT_ABANDONED, WAIT_EVENT, WAIT_FAILED, WAIT_OBJECT_0, WAIT_TIMEOUT, +}; +use windows_sys::Win32::System::Threading::{ + CreateEventW, ResetEvent, SetEvent, WaitForSingleObject, +}; + +use crate::ioring; + +/// Nanoseconds per operation for one timed loop. +#[derive(Debug, Clone, Copy, PartialEq)] +pub struct Timing { + /// What was timed. + pub label: &'static str, + /// Iterations executed. + pub iterations: u32, + /// Nanoseconds per iteration. + pub nanos_per_op: f64, +} + +/// Every timing, plus the ratios that actually decide the design question. +#[derive(Debug, Clone)] +pub struct Observation { + /// Each timed loop, in the order run. + pub timings: Vec, + /// `None` when `IoRing` is unavailable on this host. + pub submit_nanos: Option, +} + +impl Observation { + /// Look a timing up by label. + #[must_use] + pub fn get(&self, label: &str) -> Option { + self.timings + .iter() + .find(|t| t.label == label) + .map(|t| t.nanos_per_op) + } + + /// One doorbell cycle as a fraction of one **empty** `SubmitIoRing`. + /// + /// **This is not the number the design turns on, and it should not be read + /// as one.** An empty submit carries no work, so this ratio has a + /// denominator that measures nothing the design cares about. It is exposed + /// because the raw fact is worth recording across hosts -- a machine where + /// the empty submit is *expensive* would itself be a finding -- not because + /// dividing by it answers anything. + /// + /// The argument rests on *carries no work*, which holds everywhere, and no + /// longer on *does not enter the kernel*, which does not. That read "an + /// empty submit does not appear to enter the kernel, so this ratio has a + /// denominator that is not a syscall" -- a reading from the Snapdragon X2 + /// (ARM64) development machine (~79 ns) stated as a general fact. The + /// binary decides it per host, and on an x86_64 machine measured during + /// review it printed the opposite, the + /// empty submit landing at 216 ns among that probe's own 206 ns syscalls. + #[must_use] + pub fn doorbell_over_empty_submit(&self) -> Option { + let doorbell = self.get("set_reset_event")?; + let submit = self.submit_nanos?; + (submit > 0.0).then_some(doorbell / submit) + } +} + +fn time_loop(label: &'static str, iterations: u32, mut body: impl FnMut()) -> Timing { + // Warm the path first: the first call through a syscall stub pays for + // resolution and page faults that a steady-state cost should not include. + for _ in 0..1024 { + body(); + } + let start = Instant::now(); + for _ in 0..iterations { + body(); + } + let elapsed = start.elapsed(); + Timing { + label, + iterations, + nanos_per_op: elapsed.as_nanos() as f64 / f64::from(iterations), + } +} + +/// Name a wait result, and attach an OS error only where one exists. +/// +/// `WaitForSingleObject` returns a status code rather than a `BOOL`, and only +/// `WAIT_FAILED` sets the last-error value. `WAIT_TIMEOUT` and `WAIT_ABANDONED` +/// are *successful* returns, so a code printed beside either belongs to +/// whatever call ran previously and describes something else entirely -- which +/// is worse than printing nothing, because it reads as a diagnosis. +fn describe_wait(waited: WAIT_EVENT) -> String { + match waited { + WAIT_OBJECT_0 => "WAIT_OBJECT_0 (signalled)".to_string(), + WAIT_TIMEOUT => { + "WAIT_TIMEOUT -- the event was not signalled; this is not an OS error".to_string() + } + WAIT_ABANDONED => { + "WAIT_ABANDONED -- a mutex owner exited; this is not an OS error".to_string() + } + WAIT_FAILED => format!("WAIT_FAILED: {}", std::io::Error::last_os_error()), + other => format!("unrecognised wait result {other:#010x}"), + } +} + +/// Run every timing. +/// +/// # Panics +/// +/// Panics if `CreateEventW` fails, which would mean the host cannot create a +/// manual-reset event and nothing here is measurable. +/// +/// Panics, too, if any timed call fails -- `SetEvent`, `ResetEvent`, a +/// zero-timeout wait that does not observe the event as signalled, or +/// `SubmitIoRing`. This is deliberately loud. Each of those still costs a +/// measurable transition when it fails, so a probe that swallowed the error +/// would report a plausible nanosecond figure for an operation that did not +/// happen, which is worse than reporting nothing. +#[must_use] +pub fn measure() -> Observation { + const ITERATIONS: u32 = 200_000; + + // SAFETY: a manual-reset, initially-unsignalled, unnamed event. + let event: HANDLE = unsafe { CreateEventW(std::ptr::null(), 1, 0, std::ptr::null()) }; + assert!( + !event.is_null(), + "CreateEventW failed: {}", + std::io::Error::last_os_error() + ); + + let counter = AtomicU64::new(0); + let mut timings = Vec::new(); + + timings.push(time_loop("atomic_fetch_add", ITERATIONS, || { + counter.fetch_add(1, Ordering::Relaxed); + })); + + // THE RULE: every call that returns a status has that status checked, + // inside the timed region. No exceptions, and no per-call-site argument + // about whether this one is worth it. + // + // It is a flat rule on purpose. The previous version checked only + // `SubmitIoRing`, with a well-argued note there explaining why discarding a + // status lets a failing call report a plausible time for an operation that + // never happened -- and left the three event loops above it discarding + // their `BOOL`s. The argument was correct and got applied to the one call + // that looked expensive enough to deserve it. That is how the cheap calls + // get missed: "trivial enough not to check" is not a property of the call, + // it is a property of how hard anyone looked at it. + // + // Both halves of that were measured rather than argued, on the x86_64 + // review host, by running this probe against a deliberately invalid handle + // so that every event call fails. + // + // What the unchecked version reported, in ns/op, against the true figures: + // + // set_event_already_signalled 212.7 (true 205) + // set_reset_event 422.9 (true 531) + // wait_zero_signalled 231.5 (true 280) + // + // Not one of those looks wrong. The redundant-`SetEvent` figure is within + // 4% of the real one, and a reader would have taken the whole set as + // evidence and drawn the doorbell-versus-build conclusion from a run in + // which no event operation ever succeeded. A failing syscall is not cheap + // enough to be conspicuous -- that is the entire hazard. + // + // The checks cost nothing detectable: with them in place the same host + // reports 204-206, 528-534 and 280.3-280.7 across three runs, which is the + // run-to-run spread and not a shift. If a check ever does cost enough to + // distort a figure, that will show up as data and can be tuned then, at + // that site, with the evidence in hand. Until then the rule does not bend + // to an estimate. + // + // `atomic_fetch_add` above is not an exception: `fetch_add` returns no + // status, so there is nothing to check. + + // Every message below carries `last_os_error()`. A probe that panics in CI + // is read from a log by someone who cannot rerun it under a debugger, and + // "SetEvent failed" tells them nothing they could not already see; the code + // distinguishes an invalid handle from a resource limit. The format + // arguments are evaluated only when the assertion fires, so this costs + // nothing in the timed loops. + + // Leave it signalled, so every call in the next loop is redundant. + assert!( + unsafe { SetEvent(event) } != 0, + "SetEvent failed: {}", + std::io::Error::last_os_error() + ); + timings.push(time_loop("set_event_already_signalled", ITERATIONS, || { + assert!( + unsafe { SetEvent(event) } != 0, + "SetEvent on an already-signalled event failed: {}", + std::io::Error::last_os_error() + ); + })); + + assert!( + unsafe { ResetEvent(event) } != 0, + "ResetEvent failed: {}", + std::io::Error::last_os_error() + ); + timings.push(time_loop("set_reset_event", ITERATIONS, || unsafe { + assert!( + SetEvent(event) != 0, + "SetEvent failed mid-cycle: {}", + std::io::Error::last_os_error() + ); + assert!( + ResetEvent(event) != 0, + "ResetEvent failed mid-cycle: {}", + std::io::Error::last_os_error() + ); + })); + + assert!( + unsafe { SetEvent(event) } != 0, + "SetEvent failed: {}", + std::io::Error::last_os_error() + ); + timings.push(time_loop("wait_zero_signalled", ITERATIONS, || { + // Checked against `WAIT_OBJECT_0`, not merely "did not fail". The label + // says *satisfied* wait, and `WAIT_TIMEOUT` is a successful return that + // times a different path -- an unsatisfied poll, which is the cheaper + // one and would flatter the figure. + // + // The error code is attached only to `WAIT_FAILED`, because that is the + // only return for which `GetLastError` is defined. `WaitForSingleObject` + // is not a boolean-returning call: `WAIT_TIMEOUT` and `WAIT_ABANDONED` + // are *successful* returns that set no error, so a code printed beside + // them belongs to whatever ran last and is fiction. + // + // This is the rule the previous commits arrived at -- attach an error + // only where the condition is genuinely an OS failure -- applied to the + // one call in this file that returns a status code rather than a + // `BOOL`. The sweep that added `last_os_error()` everywhere treated it + // like the others, which is how a rule about failure reporting became a + // way to report a failure that did not happen. + let waited = unsafe { WaitForSingleObject(event, 0) }; + assert!( + waited == WAIT_OBJECT_0, + "a zero-timeout wait did not observe the event as signalled: {}", + describe_wait(waited) + ); + })); + unsafe { + assert!( + ResetEvent(event) != 0, + "ResetEvent failed: {}", + std::io::Error::last_os_error() + ); + // Checked as a post-condition: a close that fails means the handle was + // already invalid, which retroactively discredits every figure above + // it. That is not theoretical -- in the bad-handle run described above, + // with every other check stripped out, this was the one that caught it. + // It is the backstop for a handle that goes bad in a way no individual + // call happens to report. + assert!( + CloseHandle(event) != 0, + "CloseHandle failed: {}", + std::io::Error::last_os_error() + ); + } + + // The syscall the doorbell would be amortised against. Far fewer + // iterations: this one is a real kernel transition. `submit_and_wait(0)` + // asks for no completions, so it returns without blocking and measures the + // transition rather than any I/O. + let submit_nanos = ioring::Ring::new().map(|ring| { + const SUBMIT_ITERATIONS: u32 = 20_000; + let timing = time_loop("submit_io_ring_empty", SUBMIT_ITERATIONS, || { + // Both halves of the answer are checked, inside the timed region. + // Discarding them let a host where `SubmitIoRing` fails produce a + // perfectly plausible timing -- a failing call still costs a + // measurable transition -- which the report then read as the cost of + // a successful empty submission. That is the failure mode this whole + // crate exists to avoid: a number that looks like evidence and is + // not. The `submitted` count is checked too, because a call that + // succeeded while submitting entries did not measure what the label + // says it measured. + // + // Inside the loop, not outside it: a check after the fact would let + // the timing be taken before anything established it was valid. + // + // Every loop above now does the same, under the flat rule stated + // there. This note came first and for a while was the only one, + // which is the whole reason the rule is now flat rather than + // argued per site. + let (hr, submitted) = ring.submit_and_wait(0); + assert!(hr >= 0, "SubmitIoRing(0) failed: {hr:#010x}"); + assert_eq!(submitted, 0, "SubmitIoRing(0) submitted entries"); + }); + timings.push(timing); + timing.nanos_per_op + }); + + Observation { + timings, + submit_nanos, + } +} + +/// Keeps the doorbell's own wake path honest: a consumer that actually parks +/// and is woken measures something the zero-timeout poll above does not. +/// +/// Reported separately because it is a two-thread measurement and therefore +/// noisier than the single-threaded loops. The number is a full **round trip** +/// -- wake the peer, park, be woken -- not a single transition, so it is an +/// upper bound on what one wakeup costs rather than the cost itself. +/// +/// # Why the handshake alternates strictly +/// +/// The obvious version -- one thread calling `SetEvent` in a loop while the +/// other calls `WaitForSingleObject` -- **deadlocks**, and did when this probe +/// was first written. An auto-reset event does not count signals: two arriving +/// before one wait collapse into one, the waiter's count never catches up, and +/// it blocks on `INFINITE` for ever. Two events used as ping and pong force +/// strict alternation, so no signal can be lost. +/// +/// Every wait is nevertheless bounded. A probe that can hang is a probe that +/// can hang a build, and the deadlock above is exactly how that happens; a +/// timeout turns it into a reported anomaly instead. +/// +/// Returns `None` if the handshake ever timed out, because a partial run's +/// average would be meaningless -- and for the same reason if `rounds` is zero, +/// which has no average at all rather than an average of nothing. +#[must_use] +pub fn measure_park_and_wake(rounds: u32) -> Option { + const WAIT_TIMEOUT_MS: u32 = 5_000; + + // An empty sample has no average, and the arithmetic below would not say + // so: no round runs, so the elapsed time is zero, and `0.0 / 0.0` is `NaN` + // wrapped in the `Some` this function documents as a meaningful number. A + // caller comparing that against a threshold gets `false` from every + // comparison and no indication why. + if rounds == 0 { + return None; + } + + // Created and checked ONE AT A TIME, which the combined assertion this + // replaces could not do. That assertion leaked: with `ping` created and + // `pong` failing, it panicked without closing `ping`. Worse, it misreported + // -- `last_os_error()` was read after *both* calls, so the failure of the + // first was overwritten by the success of the second, and the message could + // read "CreateEventW failed: The operation completed successfully". + // + // That is a defect introduced by the previous commit, which added + // `last_os_error()` to every assertion in this file for diagnosability. + // Attaching an error code to a condition spanning two calls does not improve + // the diagnosis, it fabricates one: the code belongs to whichever call ran + // last, not to whichever failed. **An error code is only meaningful read + // immediately after the single call whose failure is being reported**, which + // is why the close below reads its own separately rather than reusing this. + + // SAFETY: an auto-reset, initially-unsignalled, unnamed event. + let ping: HANDLE = unsafe { CreateEventW(std::ptr::null(), 0, 0, std::ptr::null()) }; + assert!( + !ping.is_null(), + "CreateEventW(ping) failed: {}", + std::io::Error::last_os_error() + ); + + // SAFETY: as above. + let pong: HANDLE = unsafe { CreateEventW(std::ptr::null(), 0, 0, std::ptr::null()) }; + if pong.is_null() { + // Read before the close, which would overwrite it. + let error = std::io::Error::last_os_error(); + // SAFETY: `ping` was created above and nothing else holds it. + let closed = unsafe { CloseHandle(ping) }; + assert!( + closed != 0, + "CreateEventW(pong) failed ({error}), and closing ping then also failed: {}", + std::io::Error::last_os_error() + ); + panic!("CreateEventW(pong) failed: {error}"); + } + + // A named `Send` carrier, where this used to round-trip the handles through + // `usize` and cast them back inside the thread. + // + // `HANDLE` is `*mut c_void`, so it is `!Send` and `thread::spawn` refuses + // it -- capturing the handles directly does not compile. Some carrier is + // therefore required, and the question is only which one says what it is + // doing. The `usize` cast worked but laundered the claim: it asserts "these + // are safe to move across a thread boundary" with no `unsafe` anywhere near + // the assertion, so nothing prompts a reader to check it. Naming the type + // puts the `unsafe impl` and its justification at the point the claim is + // actually made. + // + // SAFETY: a Win32 event `HANDLE` is a process-wide kernel object reference, + // not thread-affine -- `SetEvent`/`WaitForSingleObject` may be called on it + // from any thread. These two are created above, are used by this thread + // only until the join below, and are closed only after that join, so the + // reference stays valid for the whole of the peer's life. + struct SendHandles { + ping: HANDLE, + pong: HANDLE, + } + // SAFETY: as argued directly above. + unsafe impl Send for SendHandles {} + + impl SendHandles { + /// Take both handles, consuming the carrier. + /// + /// This exists to force the closure below to capture the carrier *as a + /// whole*, and it is not decoration. Under disjoint closure capture + /// (RFC 2229, introduced in edition 2021 and in force here in 2024) a + /// closure captures the individual **fields** it mentions, so writing + /// `carriers.ping` inside the closure captures a bare `HANDLE` -- which + /// is `!Send` -- and the wrapper's `unsafe impl Send` never enters the + /// picture. The first version of this did exactly that and failed to + /// compile with the same error the `usize` cast was replacing. + /// + /// A method call needs the whole receiver, so the capture is the carrier + /// and the `Send` impl applies. Anyone "simplifying" this back to field + /// access will be told by the compiler, which is the good outcome; this + /// note is here so they know why rather than reaching for the cast. + fn take(self) -> (HANDLE, HANDLE) { + (self.ping, self.pong) + } + } + + let carriers = SendHandles { ping, pong }; + + let peer = std::thread::spawn(move || { + let (ping, pong) = carriers.take(); + for _ in 0..rounds { + // SAFETY: both handles outlive this thread, which is joined below. + let waited = unsafe { WaitForSingleObject(ping, WAIT_TIMEOUT_MS) }; + if waited != WAIT_OBJECT_0 { + return false; + } + // Reported rather than asserted: a panic here would cross a thread + // boundary into `join`, which turns it into the same `false` with + // the message lost. Failing the handshake is the honest handling. + if unsafe { SetEvent(pong) } == 0 { + return false; + } + } + true + }); + + let mut ok = true; + let start = Instant::now(); + for _ in 0..rounds { + // SAFETY: both handles are live for the whole loop. + // + // A failing `SetEvent` would eventually be caught by the peer's wait + // timing out, so this is not the difference between a wrong answer and + // a right one -- it is the difference between failing in 5 ms and + // failing after `rounds` timeouts of WAIT_TIMEOUT_MS each, under a + // diagnosis ("the peer never woke") that names the symptom rather than + // the cause. + if unsafe { SetEvent(ping) } == 0 { + ok = false; + break; + } + if unsafe { WaitForSingleObject(pong, WAIT_TIMEOUT_MS) } != WAIT_OBJECT_0 { + ok = false; + break; + } + } + let elapsed = start.elapsed(); + + let peer_ok = peer.join().unwrap_or(false); + // SAFETY: the peer has been joined, so nothing else holds these. + unsafe { + assert!( + CloseHandle(ping) != 0, + "CloseHandle(ping) failed: {}", + std::io::Error::last_os_error() + ); + assert!( + CloseHandle(pong) != 0, + "CloseHandle(pong) failed: {}", + std::io::Error::last_os_error() + ); + } + + (ok && peer_ok).then(|| elapsed.as_nanos() as f64 / f64::from(rounds)) +} diff --git a/crates/windows-platform-probes/src/lib.rs b/crates/windows-platform-probes/src/lib.rs index dbc16f560..12a62bd8b 100644 --- a/crates/windows-platform-probes/src/lib.rs +++ b/crates/windows-platform-probes/src/lib.rs @@ -106,7 +106,9 @@ //! | [`cancel_io::cancel_against_busy_thread`] | binary only | it can block indefinitely against a thread re-entering synchronous I/O | //! | [`long_path::measure`] | binary only | whether the `longPathAware` manifest opt-in lifts `MAX_PATH` for a *relative* path -- binary only because the answer is the difference between two differently-manifested executables, which no single in-process test can observe | //! | [`topology::measure`] | asserted | that `windows-topology-sys`' parse of `GetLogicalProcessorInformationEx` agrees with `GetActiveProcessorCount`, `GetActiveProcessorGroupCount` and `GetNumaHighestNodeNumber` read independently -- asserted because the invariants hold on any machine even though every value is host-specific, and the binary prints the shape so CI doubles as a fleet survey | - +//! | [`doorbell_cost::measure`] | binary only | the absolute cost of `SetEvent`, a set/reset cycle and a satisfied wait against an uncontended atomic, and how much batching drives the doorbell below the push it accompanies | +//! | [`doorbell_cost::measure_park_and_wake`] | asserted | that the park-and-wake handshake completes rather than deadlocking, which its first implementation did | +//! | [`request_cost::measure`] | binary only | the absolute cost of preparing a path, building an owned `OpenFile`, and duplicating a handle | #![cfg(windows)] #![forbid(unsafe_op_in_unsafe_fn)] #![warn(missing_docs)] @@ -114,6 +116,7 @@ pub mod cancel_io; pub mod completion_port; pub mod device_map; +pub mod doorbell_cost; pub mod error_mode; pub mod handle_state; pub mod ioring; @@ -121,6 +124,7 @@ pub mod long_path; pub mod long_path_report; pub mod pool_growth; pub mod report; +pub mod request_cost; pub mod topology; pub mod topology_report; pub mod worker_context; diff --git a/crates/windows-platform-probes/src/request_cost.rs b/crates/windows-platform-probes/src/request_cost.rs new file mode 100644 index 000000000..1f7bedf52 --- /dev/null +++ b/crates/windows-platform-probes/src/request_cost.rs @@ -0,0 +1,352 @@ +// Copyright (c) Mike Grier. + +//! What does it cost to build a namespace request, against the queue that would +//! carry it? +//! +//! **An experiment, not a component.** These probes measure platform behaviour +//! and are not for production use. Do not call them from production code, and +//! do not lift a technique out of here. See this crate's DESIGN-NOTES.md. +//! +//! # The decision this exists to inform +//! +//! The two-layer ring's submission queue was specified to carry **POD +//! descriptors with no allocation on push**. A deferred `CreateFileW` carries a +//! path, and a path is neither fixed-size nor POD, so that requirement and the +//! namespace plane's needs cannot both hold as written. +//! +//! `windows-namespace-request-sys` already solves the hard part: an `OpenFile` +//! is an *owned, `Send`* parameter set, built on one thread and performed +//! faithfully on another. So the queue can carry a request by value and the +//! lifetime hazard disappears. What remains is a cost question about **this +//! operation type**: how does building one compare with the doorbell that would +//! carry it (~165 ns as recorded on the Snapdragon X2 (ARM64) development +//! machine -- run `probe-doorbell-cost` on the host in front of you for a local +//! figure, which CI does in the same job)? +//! +//! # What this does not measure, stated because the number invites over-reading +//! +//! **This says nothing about whether the queue is efficient.** It measures the +//! construction cost of the queue's *heaviest* payload. Two distinctions the +//! result must not be stretched across: +//! +//! - **Operation type.** A namespace open resolves a path through Win32 and +//! may duplicate a handle. A registered-buffer read -- the hot path -- does +//! neither: its descriptor is a slot index and an offset, and there the +//! queue's own mechanics are the whole per-operation cost. +//! - **Overhead against efficiency.** Throughput under contention, the ring's +//! cache behaviour, batching amortization, and backpressure under load are +//! what make a queue good or bad. A single uncontended construction time +//! measures none of them. +//! +//! What it supports is a **comparison**, not a verdict: build cost against the +//! doorbell that would carry it. Which of the two is the larger half is a +//! question about one host, and this probe measures only one side of it -- +//! read `probe-doorbell-cost`'s `set_reset_event` from the same run for the +//! other. The comparison inverts between machines: the Snapdragon X2 (ARM64) +//! development machine had the doorbell at roughly a third of a build, and an +//! x86_64 host measured during review had it at roughly two and a half times +//! one. A sentence naming a small half would therefore be wrong on one of them. +//! # Handle duplication is the part that is easy to under-count +//! +//! A request that carries a handle -- a template handle for an open, or the +//! subject of a query -- must **duplicate** it, because the submitting thread +//! may close its own copy the moment it returns. `CapturedHandle::capture` does +//! that with `DuplicateHandle`, which is a kernel transition, not a memory +//! copy. So "what does a request cost" is not only an allocation question, and +//! measuring only the path would understate it. +//! +//! # Preparing a path is a Win32 call, not an allocation +//! +//! This probe was written expecting `prepare` to be an allocation and a copy. +//! It is not: it calls **`GetFullPathNameW`** to resolve the path against the +//! process working directory, because [the namespace session] settled that the +//! path is resolved at submission -- the process CWD is mutable by any thread, +//! so even perfect remoting would be racy. +//! +//! That work reads **process state**: it resolves against the current +//! directory, and for a drive-relative path against the per-drive current +//! directory held in the `=C:` environment variables. So the measured remainder +//! is path resolution, not allocation -- and naming a *mechanism* for it has +//! now been got wrong twice. Calling it a *syscall cost* claimed a kernel +//! transition a timing loop cannot establish; calling it *lexical*, which +//! replaced it, claimed pure string work it equally is not. A genuinely lexical +//! canonicalizer is a different call (`PathCchCanonicalizeEx`) and is +//! deliberately not the one wanted here, because resolving against the CWD at +//! submission is the property being bought. What survives either way is the +//! part that matters: an allocator cannot remove it. +//! +//! The two schemes that might reduce it recover different halves. **Inline +//! storage** removes the allocation and copy, which is what +//! `clone_prepared_units` measures, and cannot touch the resolution at all. +//! **Recycling** a resolved path skips the resolution, paying the clone in +//! place of the whole build, so it recovers the difference between them. Naming +//! one figure for both -- as this did -- credits an allocator with work it +//! cannot remove. Knowing which half is which is the point of measuring both. +//! [the namespace session]: ../../../design-sessions/DESIGN-SESSION-2026-08-27-pseudo-async-namespace-operations.md +//! +//! Each timing is reported per operation. Absolute values are host-specific; +//! the **ratios against the doorbell and the atomic** are the finding. + +use std::time::Instant; + +use wtf_string::Wtf16String; + +use windows_namespace_request_sys::{CapturedHandle, OpenFile, prepare}; +use windows_sys::Win32::Foundation::GENERIC_READ; +use windows_sys::Win32::Storage::FileSystem::{FILE_SHARE_READ, OPEN_EXISTING}; +use windows_sys::Win32::System::SystemInformation::GetSystemDirectoryW; + +/// Nanoseconds per operation for one timed loop. +#[derive(Debug, Clone, Copy, PartialEq)] +pub struct Timing { + /// What was timed. + pub label: &'static str, + /// Iterations executed. + pub iterations: u32, + /// Nanoseconds per iteration. + pub nanos_per_op: f64, +} + +/// Every timing taken by [`measure`]. +#[derive(Debug, Clone)] +pub struct Observation { + /// Each timed loop, in the order run. + pub timings: Vec, +} + +impl Observation { + /// Look a timing up by label. + #[must_use] + pub fn get(&self, label: &str) -> Option { + self.timings + .iter() + .find(|t| t.label == label) + .map(|t| t.nanos_per_op) + } +} + +/// Time `body`, including the drop of whatever it returns. +/// +/// **The drop is inside the timed region, and for the heap-owning values below +/// that is a construct-and-destroy cycle rather than a construction cost.** +/// `black_box` takes the value and it falls at the end of the statement, so +/// `prepare_*`, `build_open_request` and `clone_prepared_units` each include +/// freeing the `Wtf16String` they built. On a clone measured near 50 ns a free +/// is a visible share of the figure. +/// +/// It is reported this way rather than restructured, and the reason is that the +/// obvious alternative is not more truthful. Retaining each value -- what the +/// captured-handle loop below does, for a reason that does not apply here -- +/// would hold 100_000 live allocations, which measures an allocator that never +/// reuses a block instead of one that does. A queue holds a bounded number of +/// requests, so neither regime is the shipping one, and the honest course is to +/// say which one this is. +/// +/// The captured-handle loop is different in kind and is genuinely restructured: +/// dropping a `CapturedHandle` calls `CloseHandle`, so leaving it in the timed +/// region reports two kernel transitions as one number. A free is not a +/// syscall. +fn time_loop(label: &'static str, iterations: u32, mut body: impl FnMut() -> T) -> Timing { + // Warm the path: the first pass pays for lazily resolved syscall stubs and + // for the allocator's first touch of a fresh size class. + for _ in 0..256 { + std::hint::black_box(body()); + } + let start = Instant::now(); + for _ in 0..iterations { + std::hint::black_box(body()); + } + let elapsed = start.elapsed(); + Timing { + label, + iterations, + nanos_per_op: elapsed.as_nanos() as f64 / f64::from(iterations), + } +} + +/// Time request construction, path preparation, and handle duplication. +/// +/// # Panics +/// +/// Panics if the fixed test paths fail to prepare, which would mean +/// `prepare` rejects an ordinary absolute path and nothing here is meaningful. +#[must_use] +pub fn measure() -> Observation { + const ITERATIONS: u32 = 100_000; + const HANDLE_ITERATIONS: u32 = 50_000; + + // Resolved, not assumed. Windows is not always on `C:` -- a valid + // installation can sit on any volume -- and hard-coding it made this probe + // panic on such a machine rather than measure it. The same path is used for + // the prepared request and the real open below, so the two stay consistent. + // Wide the whole way, with no UTF-8 in the middle. `Wtf16String` exists + // precisely to carry what Windows hands back, and routing a Windows path + // through `str` gives up that property twice over: `to_str` panics on a + // path that is not valid UTF-8, and the `from_utf16_lossy` this once used + // inside `system_directory` silently replaced any unpaired surrogate before + // it ever got here. Neither is reachable on a normal install, and neither + // has any business being on the path from a Win32 call to a WTF-16 string. + let system_dll = system_directory().join("kernel32.dll"); + let short = Wtf16String::from_os_str(system_dll.as_os_str()); + // Synthetic, and hard-coded on purpose -- the opposite requirement to the + // path above, which is why the two do not match and must not be made to. + // `short` names a file that is really opened, so it has to exist and is + // resolved. This one is only ever normalized, so it must NOT need to exist: + // a fixed 24-component path keeps the length identical on every host, and a + // length that varied with the local system directory would make the figure + // incomparable between the machines the report asks a reader to compare. + // + // The `C:` is safe for the same reason the probe's own conclusion is: a + // fully-qualified path is normalized without consulting a device, so no + // volume is needed behind the letter. Two review passes read this as the + // portability bug fixed above, so it is now measured rather than argued -- + // see `preparing_a_path_needs_no_volume_behind_its_drive_letter`. + let long_text = format!(r"C:\{}\file.txt", vec!["directory"; 24].join("\\")); + let long = Wtf16String::from(long_text.as_str()); + + let mut timings = Vec::new(); + + // The allocation and normalization a path costs, at two lengths, because + // the common case and the worst case allocate differently. + timings.push(time_loop("prepare_short_path", ITERATIONS, || { + prepare(&short).expect("an absolute path prepares") + })); + timings.push(time_loop("prepare_long_path", ITERATIONS, || { + prepare(&long).expect("an absolute path prepares") + })); + + // A whole request, which is a prepared path plus the builder chain. This is + // what the queue would actually carry. + timings.push(time_loop("build_open_request", ITERATIONS, || { + let path = prepare(&short).expect("an absolute path prepares"); + OpenFile::new(path) + .with_desired_access(GENERIC_READ) + .with_share_mode(FILE_SHARE_READ) + .with_creation_disposition(OPEN_EXISTING) + })); + + // Cloning the prepared path alone, which is what a request-recycling scheme + // would avoid paying. + let prepared_units = prepare(&short) + .expect("an absolute path prepares") + .into_wtf16(); + timings.push(time_loop("clone_prepared_units", ITERATIONS, || { + prepared_units.clone() + })); + + // The kernel transition a captured handle costs. Measured against a handle + // this process already owns, so nothing here depends on the filesystem. + // + // Capture and close are timed SEPARATELY, and that separation is the whole + // point. `time_loop` black-boxes its closure's return value and drops it at + // the end of the statement, so a loop that captures and returns a + // `CapturedHandle` -- which owns an `OwnedHandle` -- also calls + // `CloseHandle` inside the timed region. That is two kernel transitions + // reported as one number, and the report reads that number as the cost of + // duplication alone, so it overstated it by however much a close costs. + // + // Retaining every duplicate in a pre-sized `Vec` keeps the close out of the + // capture loop, and timing the drop of that same `Vec` recovers the close as + // its own figure rather than discarding it. The `push` is a pointer bump + // into reserved capacity, which is not free but is nowhere near a syscall. + let file = std::fs::File::open(&system_dll).expect("kernel32.dll is readable"); + let borrowed = std::os::windows::io::AsHandle::as_handle(&file); + + // Warmed the same way `time_loop` warms, and for the same reason: the first + // pass pays for lazily resolved syscall stubs and the allocator's first + // touch of a fresh size class. + for _ in 0..256 { + let _ = + std::hint::black_box(CapturedHandle::capture(borrowed).expect("duplicating a handle")); + } + + let mut captured = Vec::with_capacity(HANDLE_ITERATIONS as usize); + let start = Instant::now(); + for _ in 0..HANDLE_ITERATIONS { + captured.push(CapturedHandle::capture(borrowed).expect("duplicating an owned handle")); + } + let capture_elapsed = start.elapsed(); + timings.push(Timing { + label: "capture_handle", + iterations: HANDLE_ITERATIONS, + nanos_per_op: capture_elapsed.as_nanos() as f64 / f64::from(HANDLE_ITERATIONS), + }); + + let start = Instant::now(); + drop(captured); + let close_elapsed = start.elapsed(); + timings.push(Timing { + label: "close_handle", + iterations: HANDLE_ITERATIONS, + nanos_per_op: close_elapsed.as_nanos() as f64 / f64::from(HANDLE_ITERATIONS), + }); + + Observation { timings } +} + +/// Where Windows is actually installed, rather than where it usually is. +/// +/// A short buffer is retried at the size the call asks for, so a long system +/// directory is read rather than guessed at. +/// +/// # Panics +/// +/// Panics if `GetSystemDirectoryW` will not report a directory. +/// +/// This used to fall back to `C:\Windows\System32`, under a doc comment +/// claiming the fallback kept the failure visible. It did the opposite: it +/// substituted a guess for an answer the system declined to give, and the probe +/// then measured whatever happened to be at the guessed path -- on a non-`C:` +/// install, something that is not there at all. That is the same defect as +/// discarding a status: a plausible result standing in for one that was never +/// obtained. A probe that cannot locate the file it is timing has nothing to +/// say, and says so here rather than several frames later. +fn system_directory() -> std::path::PathBuf { + // The common case, off the stack. + let mut buffer = [0_u16; 260]; + // SAFETY: writes at most `buffer.len()` units into a buffer of that size. + let written = unsafe { GetSystemDirectoryW(buffer.as_mut_ptr(), buffer.len() as u32) } as usize; + + assert!( + written != 0, + "GetSystemDirectoryW failed: {}", + std::io::Error::last_os_error() + ); + + // `>=`, not `>`. On success the count excludes the terminator, so it can + // reach at most `buffer.len() - 1`; when the buffer is too small it is the + // required size *including* the terminator, so it is at least + // `buffer.len() + 1`. Exactly `buffer.len()` is therefore unreachable from + // either branch -- and treating it as too-small costs one wasted retry + // while removing the need for the next reader to redo that analysis before + // trusting a possibly-unterminated buffer. + if written >= buffer.len() { + // `written` is the required size including the terminator, so a buffer + // of exactly that length is enough and the retry cannot ask again. + let mut heap = vec![0_u16; written]; + // SAFETY: writes at most `heap.len()` units into a buffer of that size. + let retried = unsafe { GetSystemDirectoryW(heap.as_mut_ptr(), heap.len() as u32) } as usize; + + // Two conditions, two assertions, because only one of them is an OS + // failure and an error code attached to the other would be fiction -- + // `GetLastError` is not meaningful for a call that returned a size. + assert!( + retried != 0, + "GetSystemDirectoryW failed at the size it asked for ({written}): {}", + std::io::Error::last_os_error() + ); + assert!( + retried < heap.len(), + "GetSystemDirectoryW asked for {written} units, then wanted {retried} \ + at that size -- the system directory changed between the two calls" + ); + return std::path::PathBuf::from(os_string(&heap[..retried])); + } + + std::path::PathBuf::from(os_string(&buffer[..written])) +} + +/// Losslessly, because a Windows path is UTF-16 and not necessarily Unicode. +fn os_string(units: &[u16]) -> std::ffi::OsString { + std::os::windows::ffi::OsStringExt::from_wide(units) +} diff --git a/crates/windows-platform-probes/src/tests.rs b/crates/windows-platform-probes/src/tests.rs index b4fb5f734..e95abd376 100644 --- a/crates/windows-platform-probes/src/tests.rs +++ b/crates/windows-platform-probes/src/tests.rs @@ -4296,3 +4296,149 @@ fn a_named_level_with_no_summary_is_not_also_called_missing() { "and still says which absent case it is: {text}" ); } + +// --- the doorbell's park-and-wake handshake --------------------------------- +// +// Its own documentation records that the first implementation DEADLOCKED: one +// thread setting an auto-reset event while the other waited, two signals +// collapsing into one, and the waiter blocking on INFINITE for ever. Nothing +// tested it, so the rewrite that fixed it could have been undone silently. +// +// Both tests are bounded by construction. A test that can hang is worse than +// the defect it guards, because it takes the whole suite with it: the handshake +// itself waits with a 5-second timeout and reports `None` rather than blocking, +// so a reintroduced deadlock surfaces here as a failed assertion within seconds +// rather than as a suite that never finishes. + +#[test] +fn a_zero_round_handshake_has_no_average_rather_than_a_meaningless_one() { + // The deterministic half of the contract, and the one a caller is most + // likely to break by "simplifying". With no rounds the elapsed time is zero + // and the average would be `0.0 / 0.0` -- NaN, wrapped in the `Some` this + // function documents as a meaningful number, against which every comparison + // a caller makes returns false with no indication why. + assert_eq!( + crate::doorbell_cost::measure_park_and_wake(0), + None, + "zero rounds has no average, and must not report one" + ); +} + +#[test] +fn a_small_handshake_completes_and_reports_a_positive_round_trip() { + // The liveness half: the two-event alternation actually runs to completion + // and produces a number. Deliberately few rounds -- this is a real + // cross-thread measurement, and the assertion is that it terminates and is + // sane, not that it is fast. + // + // The tolerance for a loaded machine is large but **bounded**, and this once + // said "arbitrarily slow without making it wrong", which is not true of the + // code it describes. Each wait inside the handshake carries a 5-second + // timeout; a round that exceeds it makes `measure_park_and_wake` return + // `None` and fails the `expect` below. The section header above states that + // bound correctly and the `expect` message names it outright, so the claim + // was contradicted twice within a few lines of making it. + // + // Bounded is the deliberate choice, for the reason in that header: a test + // that can hang takes the whole suite with it, which is worse than the + // defect it guards against. The margin is enormous -- a round trip is + // sub-microsecond in practice against a 5-second ceiling -- so a failure + // here means the machine stalled for seconds, which is worth a red test + // rather than a silently slow pass. + let average = crate::doorbell_cost::measure_park_and_wake(64) + .expect("a bounded handshake of 64 rounds must complete rather than time out"); + + assert!( + average.is_finite() && average > 0.0, + "a completed handshake must report a positive finite round trip, got {average}" + ); +} + +// --- what `prepare` needs from a drive letter ------------------------------- +// +// `request_cost::measure` builds its long-path sample on a hard-coded `C:`, and +// two review passes read that as a portability bug: a machine with no `C:` +// volume would panic on the `expect` rather than measure. It would not, and the +// reason is the same fact the probe's own headline conclusion rests on -- that +// `GetFullPathNameW` resolves a fully-qualified path without touching the +// filesystem. A volume that does not exist is therefore not consulted. +// +// That was an argument, and an argument is what a reviewer had to disbelieve. +// This is the measurement. It also pins the "touches no filesystem" claim +// itself, which nothing else here does: if that claim ever stops holding, the +// probe's account of where its nanoseconds go is wrong, and this fails first. + +#[test] +fn preparing_a_path_needs_no_volume_behind_its_drive_letter() { + // A bitmask, not 23 `Path::exists()` calls. Probing each root touches real + // devices: an offline mapped network drive makes `exists()` block until the + // redirector times out, so the original form could stall this test for + // minutes on exactly the CI machine most likely to have one. + // `GetLogicalDrives` answers from a snapshot without going near a device, + // and answers the sharper question too -- a letter absent from the mask has + // no volume, where `exists()` also returns false for a drive that is + // present but has no media. + // + // SAFETY: no preconditions. + let used = unsafe { windows_sys::Win32::Storage::FileSystem::GetLogicalDrives() }; + + // `GetLogicalDrives` returns 0 on failure, which is also a perfectly valid + // mask meaning "no drives at all" -- so an unchecked zero would be read as + // "every letter is free", and the search would pick a letter that may well + // be mounted. The test would then prepare a path on a REAL volume and pass, + // proving nothing, which is worse than failing. + // + // That this test in particular could go vacuous is the sharp edge: it is + // the one pinning the claim that no volume is needed. It is also a plain + // instance of the workspace standard -- a failable call has its failure + // handled -- introduced by the switch away from `Path::exists()`, which + // could not fail this way. + assert!( + used != 0, + "GetLogicalDrives failed: {}", + std::io::Error::last_os_error() + ); + + // The whole alphabet. The mask already excludes anything mounted, so there + // is no letter worth reserving by hand: starting at `D` only narrowed the + // search on a machine with many mapped drives, for no benefit, since `C` + // being in use is exactly what the mask reports. + // Fails rather than skips when no letter is free, which is deliberate and + // has been raised in review, so the reasoning is recorded here. + // + // libtest has no runtime skip: a test that "skips" is a test that PASSES. + // This is the test pinning the claim that `prepare` needs no volume, so a + // pass that established nothing is the one outcome worth avoiding -- the + // same vacuous-green hazard as the unchecked `GetLogicalDrives` above, which + // is what made the explicit check necessary in the first place. + // + // It also matches how this crate already handles the identical condition: + // `impersonation_changes_which_device_map_a_drive_letter_resolves_in` and + // its sibling both `panic!("no free drive letter on this host, so the probe + // cannot run")`, and they search only `H..=Z`. This search covers all 26, so + // it fails strictly less often than sites that already chose to fail. + // + // The condition needs every letter mounted including `A` and `B`, which are + // floppy-era and essentially never assigned. A host in that state is worth + // hearing about loudly, and the message says plainly that it is the + // environment rather than the code. + let absent = (b'A'..=b'Z') + .find(|&byte| used & (1 << u32::from(byte - b'A')) == 0) + .map(char::from) + .expect( + "every drive letter A-Z is mounted on this host, so no unmounted \ + letter exists to test against -- an environment limitation, not a \ + failure of the behaviour under test", + ); + + let text = format!(r"{absent}:\{}\file.txt", vec!["directory"; 24].join("\\")); + let path = wtf_string::Wtf16String::from(text.as_str()); + + assert!( + windows_namespace_request_sys::prepare(&path).is_ok(), + "preparing {text} must succeed with no {absent}: volume mounted -- \ + a fully-qualified path is normalized, not resolved against a device, \ + and `request_cost` depends on that both for its long-path sample and \ + for its claim about where the measured time goes" + ); +}