From b559486057efe740f956b8a0fbe5f1beb7934657 Mon Sep 17 00:00:00 2001 From: Mike Grier Date: Wed, 9 Sep 2026 18:15:11 -0400 Subject: [PATCH 1/5] feat(platform-probes): add LineSink, the fmt::Write sink a renderer can stream into Completed item: M1.1: Decide how a formatted line reaches the sink, because that choice is what makes the rest mechanical. Option (b) of the three the item offered: `LineSink`, an adapter implementing `std::fmt::Write` over a `&mut dyn Report`. The item's own estimate decided the question once it was re-measured. It said "upwards of 160" `writeln!` sites; there are 504 across the production renderers, written into the `&mut String` of about twenty functions. Option (a), a `Report` method taking `fmt::Arguments` plus a macro, is the most explicit and would have rewritten every one of those 504 -- affordable at 160, not at 504. Option (b) moves the twenty signatures and leaves the 504 untouched, because `String` implements `fmt::Write` too and a call site cannot tell the difference. Option (c) was declined as a half-measure that keeps two buffers. The cost the item predicted for (b) is real and is paid here rather than deferred. `fmt::Write` is line-agnostic -- `write_str` receives fragments, multiple lines, or a bare newline -- while `Report` speaks in lines and `Captured` is addressable by line, so the sink holds a partial line and emits only completed ones. Seven tests pin that, and the two properties easiest to get wrong were verified by sabotage rather than by reading: - A report whose final call is `write!` rather than `writeln!` must still emit that line; `finish` does it. Removing it fails two tests. Without it a report loses exactly its last row, which is invisible except as an absence. - `split('\n')`, not `lines()`: only the former distinguishes text that ended on a newline from text that did not, which is what decides whether the tail is a finished line or a partial one. Substituting `lines()` fails three tests. One test asserts the correspondence M1.2 will depend on -- that writing through the sink gives a reader exactly what composing a `String` and handing it to `emit` gives today -- so the conversion can be mechanical rather than a silent change to every report. No renderer is converted yet; that is M1.2, and the buffering decision is marked as being superseded rather than rewritten, because it still describes the code until then. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- crates/windows-platform-probes/CHECKLIST.md | 32 +++-- .../windows-platform-probes/DESIGN-NOTES.md | 54 ++++++++ crates/windows-platform-probes/src/report.rs | 72 ++++++++++ .../src/report/tests.rs | 129 +++++++++++++++++- 4 files changed, 273 insertions(+), 14 deletions(-) diff --git a/crates/windows-platform-probes/CHECKLIST.md b/crates/windows-platform-probes/CHECKLIST.md index f7b33dbc6..58acf4c00 100644 --- a/crates/windows-platform-probes/CHECKLIST.md +++ b/crates/windows-platform-probes/CHECKLIST.md @@ -27,19 +27,25 @@ See [DESIGN-NOTES.md](DESIGN-NOTES.md) -> [The report is buffered, and what that costs](DESIGN-NOTES.md#d-buffered-report) for why it was built this way and why the fix is a separate piece of work rather than a correction to that one. -- [ ] **M1.1** -- Decide how a formatted line reaches the sink, because that choice is what makes the - rest mechanical. Every renderer today writes through `let _ = writeln!(out, ...)` against a - `String`'s `fmt::Write` -- upwards of 160 sites across the probes -- so the sink must accept - *formatted* output, not just `&str`, or every site grows a `format!` and an allocation per line. - The options differ in what they cost callers, and the choice is the engineer's: - (a) give `Report` a method taking `fmt::Arguments` plus a `report_line!` macro, so a call site stays - one line and reads almost as it does now; - (b) implement `fmt::Write` for the sink types, so `writeln!(out, ...)` keeps working verbatim against - a `&mut dyn Report` -- smallest diff at the call sites, but `fmt::Write` is line-agnostic, so the sink - must split on newlines internally and `Captured`'s one-line-per-entry guarantee has to be re-established - rather than assumed; - (c) leave the renderers writing to a `String` and flush it to the sink at each line boundary, which - streams without touching the call sites but keeps two buffers. +- [x] **M1.1** -- Decide how a formatted line reaches the sink, and build it. **Option (b): `LineSink`, + an adapter implementing `std::fmt::Write` over a `&mut dyn Report`.** Decision and reasoning in + [DESIGN-NOTES.md](DESIGN-NOTES.md#d-streaming-report). + + **The estimate in this item was wrong, and re-measuring it decided the question.** It said "upwards + of 160" `writeln!` sites; there are **504** across the production renderers, written into the `&mut + String` of about twenty functions. Option (a) -- a `Report` method taking `fmt::Arguments` plus a + macro -- is the most explicit and would have rewritten all 504; that is affordable at 160 and is not + at 504. Option (b) moves the twenty signatures and leaves the 504 untouched, because `String` + implements `fmt::Write` too and a call site cannot tell the difference. Option (c) was declined as a + half-measure that keeps two buffers. + + The cost this item predicted for (b) is real and is now paid: `fmt::Write` is line-agnostic, so + `LineSink` holds a partial line and emits completed ones, and `Captured`'s one-line-per-entry + guarantee is re-established by test rather than assumed. Seven tests pin it, including the two + properties that are easy to get wrong -- a final `write!` with no trailing newline still emits its + line, and `split('\n')` rather than `lines()` because only the former distinguishes a finished line + from a partial one. Both were verified by sabotage (failing three tests and two respectively), not + by reading. - [ ] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify `emit_report` accordingly: once lines leave as they are produced, catching the unwind is no longer diff --git a/crates/windows-platform-probes/DESIGN-NOTES.md b/crates/windows-platform-probes/DESIGN-NOTES.md index fa66244c9..5e67b4993 100644 --- a/crates/windows-platform-probes/DESIGN-NOTES.md +++ b/crates/windows-platform-probes/DESIGN-NOTES.md @@ -485,6 +485,11 @@ comparison exists to classify correctly: a red build that is **not** a finding. +**Being superseded by [A renderer writes into the sink through +`fmt::Write`](#d-streaming-report).** The mechanism is decided and built (M1.1); +the renderers still buffer until M1.2 converts them, so what follows remains an +accurate description of the code today. + Every probe's output goes through one sink: the renderer composes its report into a `String` and `emit_report` hands it to a [`Report`]. That is what the repository's architectural pre-step asks for -- the real stream is named in @@ -520,6 +525,55 @@ The ordering was deliberate. The sink had to exist before the probes could be peeled off their originating branch in reviewable stages, and a design that streams is a different design, not a later revision of this one. +## A renderer writes into the sink through `fmt::Write`, not through a sink method + + + +**Superseding the buffering above**, as M1 said it would: the mechanism by which +a formatted line reaches a [`Report`] is +[`LineSink`](src/report.rs), an adapter implementing `std::fmt::Write`. + +The choice was between giving `Report` a method taking `fmt::Arguments` (with a +`report_line!` macro), implementing `fmt::Write` on a sink so existing +`writeln!` calls keep working, and keeping the `String` while flushing it at +line boundaries. **It was decided by counting rather than by taste.** Every +renderer already writes through `writeln!(out, ...)` against a `String`'s +`fmt::Write`, at **504 sites**; only about twenty functions take the `&mut +String` those sites write into. A sink method would have been the most explicit +option and would have rewritten all 504; `fmt::Write` moves the twenty and +leaves the 504 untouched, because `String` implements `fmt::Write` too and the +call sites cannot tell the difference. + +Worth recording that M1 estimated "upwards of 160" of those sites. The real +figure is three times that, and it is the whole of the argument -- an option +whose cost is "rewrite every call site" is affordable at 160 and is not at 504. +A plan's estimate is worth re-measuring at the moment it becomes a decision. + +### What the adapter has to reassemble, and why that is not a detail + +`fmt::Write` is **line-agnostic**: `write_str` receives whatever slices the +formatting machinery produces -- a fragment below a line, several lines at once, +a bare `"\n"` -- while [`Report`] speaks in whole lines and [`Captured`] is +addressable by line, which is what lets a test name a row. So `LineSink` holds a +partial line and emits only completed ones. + +Two properties are easy to get wrong and are pinned by tests rather than by +this paragraph: + +- **A report whose last write is a `write!` rather than a `writeln!` must still + emit that line.** `LineSink::finish` does it. Without it a report loses + exactly its final row, which is invisible except as an absence. +- **`split('\n')`, not `lines()`.** `lines()` cannot distinguish text that ended + on a newline from text that did not, and that distinction is precisely what + decides whether the tail is a finished line or a partial one. Sabotaging each + of these in turn fails three tests and two tests respectively, so the + distinction is measured rather than asserted here. + +The remaining conversion -- pointing the twenty renderers at the sink and +removing the `catch_unwind`/`resume_unwind` pair, which stops being what makes +partial output work once lines leave as they are produced -- is +[CHECKLIST.md](CHECKLIST.md) M1.2, and the interruption check is M1.3. + ## The long-path probe: a pair of binaries, and a second declined hardening diff --git a/crates/windows-platform-probes/src/report.rs b/crates/windows-platform-probes/src/report.rs index d2402a19c..eabb24685 100644 --- a/crates/windows-platform-probes/src/report.rs +++ b/crates/windows-platform-probes/src/report.rs @@ -92,6 +92,78 @@ impl Captured { } } +/// A [`Report`] a renderer can `writeln!` into directly. +/// +/// This is the answer to "how does a formatted line reach the sink", and the +/// reason it is a [`std::fmt::Write`] adapter rather than a method on [`Report`] +/// is arithmetic. Every renderer writes through `writeln!(out, ...)` against a +/// `String`, at **504 sites** across this crate; a sink method taking +/// `fmt::Arguments` would have been explicit but would have rewritten every one +/// of them, while `String` already implements `fmt::Write`, so a sink that does +/// too lets those sites stand untouched and moves only the ~20 renderer +/// signatures. The recorded reasoning is in +/// [DESIGN-NOTES.md](../DESIGN-NOTES.md#d-streaming-report). +/// +/// # Lines are reassembled here, because `fmt::Write` does not speak in them +/// +/// `write_str` receives whatever slices the formatting machinery hands it: a +/// fragment of a line, several lines at once, or a bare `"\n"`. [`Report`] +/// speaks in whole lines and [`Captured`] is addressable by line, so this holds +/// a partial line until a `\n` arrives and emits exactly the completed ones. +/// +/// **A renderer that ends without a trailing newline still has its last line +/// emitted**, by [`LineSink::finish`], which `emit_report_to` calls. Dropping +/// that trailing fragment would silently truncate any report whose final +/// `write!` was not a `writeln!` -- a defect that would show only as a missing +/// last row. +pub struct LineSink<'a> { + report: &'a mut dyn Report, + partial: String, +} + +impl<'a> LineSink<'a> { + /// Wrap a [`Report`] so renderers can write formatted text into it. + pub fn new(report: &'a mut dyn Report) -> Self { + Self { + report, + partial: String::new(), + } + } + + /// Emit any text written since the last newline. + /// + /// Idempotent: a second call with nothing buffered emits nothing, so a + /// caller that finishes a sink twice does not add a stray empty line. + pub fn finish(&mut self) { + if !self.partial.is_empty() { + self.report.line(&self.partial); + self.partial.clear(); + } + } +} + +impl std::fmt::Write for LineSink<'_> { + fn write_str(&mut self, text: &str) -> std::fmt::Result { + // `split('\n')`, not `lines()`. `lines()` cannot distinguish "ends with + // a newline" from "does not", which is exactly the distinction that + // decides whether the tail is a completed line or a partial one still + // being written. `split` always yields one more piece than there are + // newlines, so the final piece is the remainder by construction -- + // empty when the text ended on a newline. + let mut pieces = text.split('\n'); + let first = pieces.next().unwrap_or_default(); + self.partial.push_str(first); + + for piece in pieces { + let line = std::mem::take(&mut self.partial); + self.report.line(&line); + self.partial.push_str(piece); + } + + Ok(()) + } +} + /// Write a rendered block to `report`, one line at a time. /// /// A `render_*` function produces a whole block with embedded newlines and a diff --git a/crates/windows-platform-probes/src/report/tests.rs b/crates/windows-platform-probes/src/report/tests.rs index 384490c0f..66ce40d37 100644 --- a/crates/windows-platform-probes/src/report/tests.rs +++ b/crates/windows-platform-probes/src/report/tests.rs @@ -9,7 +9,134 @@ use std::fmt::Write as _; use std::panic::{AssertUnwindSafe, catch_unwind}; -use super::{Captured, Report, emit, emit_report_to}; +use super::{Captured, LineSink, Report, emit, emit_report_to}; + +// --- the fmt::Write sink ---------------------------------------------------- +// +// `LineSink` exists so a renderer can `writeln!` straight into a `Report`, and +// the whole of its difficulty is that `fmt::Write` does not speak in lines +// while `Report` does. `write_str` receives whatever slices the formatting +// machinery happens to produce, so these pin the reassembly rather than the +// happy path: fragments below a line, several lines in one call, and the tail +// that arrives without a newline behind it. + +#[test] +fn a_line_sink_emits_one_line_per_newline() { + // The ordinary case, and the one every renderer relies on. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + writeln!(sink, "header").expect("writing to a line sink cannot fail"); + writeln!(sink, "row {}", 1).expect("writing to a line sink cannot fail"); + writeln!(sink, "row {}", 2).expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(captured.lines, ["header", "row 1", "row 2"]); +} + +#[test] +fn a_line_sink_joins_fragments_written_below_a_line() { + // `write!` without a newline, repeatedly, is how a renderer builds a row + // from parts -- and it is what `fmt::Arguments` does internally for a + // format string with interpolations. Each fragment must accumulate rather + // than becoming a line of its own. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + write!(sink, "one ").expect("writing to a line sink cannot fail"); + write!(sink, "two ").expect("writing to a line sink cannot fail"); + writeln!(sink, "three").expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(captured.lines, ["one two three"]); +} + +#[test] +fn a_line_sink_splits_a_multi_line_write() { + // One `write_str` carrying several newlines must still produce several + // lines, because a renderer may hand over a pre-composed block. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + write!(sink, "a\nb\nc\n").expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(captured.lines, ["a", "b", "c"]); +} + +#[test] +fn a_line_sink_emits_a_final_line_that_has_no_newline() { + // The case that decides whether this adapter can be trusted at all. A + // renderer whose last call is `write!` rather than `writeln!` has a + // complete line sitting in the buffer with nothing to flush it, and + // dropping it would truncate the report by exactly one row -- a defect + // visible only as a missing last line. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + writeln!(sink, "kept").expect("writing to a line sink cannot fail"); + write!(sink, "also kept").expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(captured.lines, ["kept", "also kept"]); +} + +#[test] +fn finishing_a_line_sink_twice_adds_nothing() { + // `emit_report_to` finishes the sink, and a renderer may reasonably finish + // its own; the second call must not invent an empty line. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + writeln!(sink, "only").expect("writing to a line sink cannot fail"); + sink.finish(); + sink.finish(); + } + + assert_eq!(captured.lines, ["only"]); +} + +#[test] +fn a_line_sink_preserves_a_blank_line() { + // Blank lines are structure in these reports -- they separate a table from + // the prose reading it -- so an empty line between two newlines is content, + // not noise to collapse. + let mut captured = Captured::default(); + { + let mut sink = LineSink::new(&mut captured); + writeln!(sink, "section").expect("writing to a line sink cannot fail"); + writeln!(sink).expect("writing to a line sink cannot fail"); + writeln!(sink, "next").expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(captured.lines, ["section", "", "next"]); +} + +#[test] +fn a_line_sink_matches_what_emit_produces_for_the_same_text() { + // The correspondence that lets M1.2 be a mechanical conversion: writing + // through the sink must give a reader exactly what composing a `String` and + // handing it to `emit` gives today. If these disagreed, converting a + // renderer would silently change its report. + let block = "header\n\nrow 1\nrow 2\ntrailing"; + + let mut through_emit = Captured::default(); + emit(&mut through_emit, block); + + let mut through_sink = Captured::default(); + { + let mut sink = LineSink::new(&mut through_sink); + write!(sink, "{block}").expect("writing to a line sink cannot fail"); + sink.finish(); + } + + assert_eq!(through_sink.lines, through_emit.lines); +} #[test] fn a_captured_report_keeps_its_lines_in_order() { From e833152c79eb4fa43f1b80e93718dd7e498dd22e Mon Sep 17 00:00:00 2001 From: Mike Grier Date: Wed, 9 Sep 2026 18:51:31 -0400 Subject: [PATCH 2/5] feat(platform-probes): stream every probe's report, and delete the catch-and-resume Completed item: M1.2: Convert every renderer to write into the sink as it measures, and simplify `emit_report` accordingly. All sixteen probes now take `out: &mut dyn std::fmt::Write` and their lines reach the `Report` as they are composed. The `catch_unwind`/`resume_unwind` pair is deleted rather than kept: with lines leaving as they are produced there is no buffer to rescue, so it would have been machinery that no longer earned its place -- and it would have kept implying that partial output depends on the panic unwinding, which is the limitation this milestone removes. `Captured` is untouched and its tests pass unchanged. The 504 `writeln!` call sites are untouched, which is what M1.1 chose option (b) for. Three probes needed more than a signature change, because they never went through `emit_report` at all: `core_affinity`, `peer_index_cache` and `queue_contention` each composed a `String` and called `emit` directly. They are branch-local and so missed the round that fixed the same bypass in the peeled probes, which means this crate's "every probe routes through this, with no exceptions" claim was false in three places. `core_affinity` additionally measured in `main`'s argument list, ahead of the renderer, so a topology read that failed produced no banner and no indication of which probe had died; it now measures after the banner and reports that failure as a failure to observe the host rather than as a finding about it. **Verifying that no report changed needed a control, and that is the part worth keeping.** A direct before/after comparison flagged nine of fifteen reports -- which is not evidence, because these probes print measured nanoseconds and branch their verdicts on them. Running the same build twice differed by as much or more: `peer-index-cache` differs on 22 lines between two runs of one build, against 20 across the conversion. The twelve deterministic reports were structurally identical before and after. A before/after diff on a probe means nothing without that control, and it would have been easy to read the raw differences as either a regression or noise without measuring which. The panic test's assertions are unchanged, which is the point: the property held by machinery before and holds by construction now. Its explanation is rewritten, because it named a `resume_unwind` that no longer exists. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- crates/windows-platform-probes/CHECKLIST.md | 25 ++++- .../windows-platform-probes/DESIGN-NOTES.md | 53 +++++++++-- .../src/bin/cancel_io.rs | 3 +- .../src/bin/completion_port.rs | 7 +- .../src/bin/device_map.rs | 5 +- .../src/bin/doorbell_cost.rs | 3 +- .../src/bin/error_mode.rs | 4 +- .../src/bin/handle_state.rs | 3 +- .../windows-platform-probes/src/bin/ioring.rs | 3 +- .../src/bin/pool_growth.rs | 11 ++- .../src/bin/request_cost.rs | 3 +- .../src/bin/topology.rs | 4 +- .../src/bin/worker_context.rs | 3 +- .../src/long_path_report.rs | 8 +- crates/windows-platform-probes/src/report.rs | 93 +++++++++---------- .../src/report/tests.rs | 16 +++- 16 files changed, 144 insertions(+), 100 deletions(-) diff --git a/crates/windows-platform-probes/CHECKLIST.md b/crates/windows-platform-probes/CHECKLIST.md index 58acf4c00..147a5bc90 100644 --- a/crates/windows-platform-probes/CHECKLIST.md +++ b/crates/windows-platform-probes/CHECKLIST.md @@ -47,11 +47,26 @@ piece of work rather than a correction to that one. from a partial one. Both were verified by sabotage (failing three tests and two respectively), not by reading. -- [ ] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify - `emit_report` accordingly: once lines leave as they are produced, catching the unwind is no longer - what makes partial output work, and the `catch_unwind`/`resume_unwind` pair should be removed rather - than left as machinery that no longer earns its place. Keep `Captured` working -- it is what every - in-process test asserts against. +- [x] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify + `emit_report` accordingly. All sixteen probes now take `out: &mut dyn std::fmt::Write`; the + `catch_unwind`/`resume_unwind` pair is deleted, because with lines leaving as they are produced + there is no buffer to rescue and keeping it would imply partial output still depends on the panic + unwinding. `Captured` is unchanged and its tests pass untouched. + + **Three probes needed more than a signature change**, because they never went through + `emit_report` at all -- `core_affinity`, `peer_index_cache` and `queue_contention` each composed a + `String` and called `emit` directly. They are branch-local and so missed the round that fixed the + same bypass in the peeled probes, which means the crate's "every probe routes through this" claim + was false in three places. `core_affinity` additionally measured in `main`'s argument list, ahead + of the renderer, so a topology read that failed produced no banner at all; it now measures after + the banner and reports the failure as a failure to observe rather than as a finding. + + **Verified with a control, because these probes are not deterministic.** A direct before/after + comparison flagged nine of fifteen reports, which is not evidence -- they print measured + nanoseconds and branch their verdicts on them. Running the *same* build twice differed by as much + or more (`peer-index-cache`: 22 lines between two runs of one build, against 20 across the + conversion), and the twelve deterministic reports were structurally identical. A before/after diff + on a probe means nothing without that control. - [ ] **M1.3** -- Verify by interruption, not by reasoning. Sending Ctrl-C to a probe part-way through must leave the already-measured lines on the terminal; today it leaves nothing. Assert the in-process diff --git a/crates/windows-platform-probes/DESIGN-NOTES.md b/crates/windows-platform-probes/DESIGN-NOTES.md index 5e67b4993..e035506a9 100644 --- a/crates/windows-platform-probes/DESIGN-NOTES.md +++ b/crates/windows-platform-probes/DESIGN-NOTES.md @@ -485,10 +485,12 @@ comparison exists to classify correctly: a red build that is **not** a finding. -**Being superseded by [A renderer writes into the sink through -`fmt::Write`](#d-streaming-report).** The mechanism is decided and built (M1.1); -the renderers still buffer until M1.2 converts them, so what follows remains an -accurate description of the code today. +**Superseded by [A renderer writes into the sink through +`fmt::Write`](#d-streaming-report).** The renderers stream as of M1.2, and the +`catch_unwind`/`resume_unwind` pair described below no longer exists. Kept +because the cost it records is what motivated the replacement, and because the +ordering argument at the end is still the reason the sink was built this way +first. Every probe's output goes through one sink: the renderer composes its report into a `String` and `emit_report` hands it to a [`Report`]. That is what the @@ -569,13 +571,46 @@ this paragraph: of these in turn fails three tests and two tests respectively, so the distinction is measured rather than asserted here. -The remaining conversion -- pointing the twenty renderers at the sink and -removing the `catch_unwind`/`resume_unwind` pair, which stops being what makes -partial output work once lines leave as they are produced -- is -[CHECKLIST.md](CHECKLIST.md) M1.2, and the interruption check is M1.3. +### Every renderer now writes into the sink, and the catch-and-resume is gone + +M1.2 pointed all sixteen probes at the sink. Two things about that conversion are +worth keeping. + +**The `catch_unwind`/`resume_unwind` pair was deleted rather than left in place.** +Once lines leave as they are produced there is no buffer to rescue, so the pair +would have been machinery that no longer earned its place -- and worse, it would +have kept implying that partial output depends on the panic unwinding, which was +precisely the limitation this milestone removed. The test that guarded it is +unchanged and still passes: the property held by machinery before and holds by +construction now. + +**A panic still loses at most a partial final line** -- one on which a renderer +called `write!` without a newline. Flushing it would need a `Drop` on `LineSink`, +and a `Drop` that writes can panic while unwinding, which aborts and replaces a +diagnosable failure with one that explains nothing. An unterminated fragment is +not a finding, so the trade is one-sided. + +Three probes needed more than a signature change, because they were composing a +`String` and calling `emit` directly rather than going through `emit_report` at +all: `core_affinity`, `peer_index_cache` and `queue_contention`. They are the +branch-local probes, and they had never been through the round that fixed the +same bypass in the peeled ones -- the crate's "every probe routes through this" +claim was false in three places until now. `core_affinity` also measured in +`main`'s argument list, so a failure to read the topology produced no banner and +no indication of which probe had died; it now measures inside the renderer, +after the banner, and reports a failed read as a failure to observe rather than +as a finding. + +**Verifying that no report changed needed a control, because most of these +probes are not deterministic.** Comparing before and after directly showed +differences in nine of fifteen reports -- which proves nothing on its own, since +these probes print measured nanoseconds and render verdicts branching on them. +Running the *same* build twice showed differences of the same size or larger +(`peer-index-cache` 22 lines between two runs of one build, against 20 across +the conversion). The twelve deterministic reports were structurally identical. +A before/after diff on a probe is not evidence without that control. ## The long-path probe: a pair of binaries, and a second declined hardening - The `longPathAware` opt-in has two halves and neither is a runtime switch: a diff --git a/crates/windows-platform-probes/src/bin/cancel_io.rs b/crates/windows-platform-probes/src/bin/cancel_io.rs index cbf1c88be..8a17570fa 100644 --- a/crates/windows-platform-probes/src/bin/cancel_io.rs +++ b/crates/windows-platform-probes/src/bin/cancel_io.rs @@ -11,7 +11,6 @@ //! is a call that can fail to return, so every case here runs behind a //! watchdog; a wedged `#[test]` would take the whole suite with it. -use std::fmt::Write as _; use windows_platform_probes::cancel_io::{ CancelOutcome, WATCHDOG, cancel_against_busy_thread, cancel_against_idle_thread, }; @@ -35,7 +34,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/completion_port.rs b/crates/windows-platform-probes/src/bin/completion_port.rs index 2b3a9977e..7168f85a6 100644 --- a/crates/windows-platform-probes/src/bin/completion_port.rs +++ b/crates/windows-platform-probes/src/bin/completion_port.rs @@ -13,12 +13,11 @@ //! completion arrived, and so read a clean failure -- result code //! `ERROR_INVALID_PARAMETER`, zero bytes -- as a success. -use std::fmt::Write as _; use windows_platform_probes::completion_port::{CompletionPortFinding, ReadAttempt, measure}; use windows_platform_probes::ioring::IoRingSupport; use windows_platform_probes::report::emit_report; -fn describe(out: &mut String, label: &str, attempt: ReadAttempt) { +fn describe(out: &mut dyn std::fmt::Write, label: &str, attempt: ReadAttempt) { let _ = writeln!( out, " {label:<46} result={:#010x} bytes={} first={:#04x} [{}]", @@ -29,7 +28,7 @@ fn describe(out: &mut String, label: &str, attempt: ReadAttempt) { ); } -fn report(out: &mut String, finding: CompletionPortFinding) { +fn report(out: &mut dyn std::fmt::Write, finding: CompletionPortFinding) { let _ = writeln!( out, "a PASS needs all three: success code, full byte count, and the fill byte.\n" @@ -155,7 +154,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/device_map.rs b/crates/windows-platform-probes/src/bin/device_map.rs index f087a0688..bb11ba70f 100644 --- a/crates/windows-platform-probes/src/bin/device_map.rs +++ b/crates/windows-platform-probes/src/bin/device_map.rs @@ -13,7 +13,6 @@ //! path resolved on a submitting thread and opened on a worker under a captured //! token can name a different device. -use std::fmt::Write as _; use windows_platform_probes::device_map::{SubstDrive, measure_with_subst}; use windows_platform_probes::report::emit_report; @@ -25,7 +24,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 @@ -65,7 +64,7 @@ fn render(out: &mut String) { // stays available to the lines below. A closure capturing it mutably would // hold the borrow across every later write. fn describe( - out: &mut String, + out: &mut dyn std::fmt::Write, label: &str, observation: &windows_platform_probes::device_map::MapObservation, ) { diff --git a/crates/windows-platform-probes/src/bin/doorbell_cost.rs b/crates/windows-platform-probes/src/bin/doorbell_cost.rs index 382495ab4..543d9e67e 100644 --- a/crates/windows-platform-probes/src/bin/doorbell_cost.rs +++ b/crates/windows-platform-probes/src/bin/doorbell_cost.rs @@ -12,7 +12,6 @@ //! 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; @@ -25,7 +24,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/error_mode.rs b/crates/windows-platform-probes/src/bin/error_mode.rs index 71078ef33..3eaea5ba2 100644 --- a/crates/windows-platform-probes/src/bin/error_mode.rs +++ b/crates/windows-platform-probes/src/bin/error_mode.rs @@ -13,8 +13,6 @@ //! the one observation a test must not: the alignment bit's process-scope //! stickiness is irreversible, so it is demonstrated here and nowhere else. -use std::fmt::Write as _; - use windows_platform_probes::error_mode::{ alignment_bit_is_sticky_at_process_scope, bits, combined_invalid_installs_nothing, probe_bit, settable_bits, thread_mode_independent_of_process, @@ -46,7 +44,7 @@ fn main() { /// which the observations are taken is part of what is being reported. Splitting /// measurement from rendering would invite a later reordering that silently /// changes the result. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/handle_state.rs b/crates/windows-platform-probes/src/bin/handle_state.rs index c7570ec9b..a3608ebce 100644 --- a/crates/windows-platform-probes/src/bin/handle_state.rs +++ b/crates/windows-platform-probes/src/bin/handle_state.rs @@ -11,7 +11,6 @@ //! observations themselves -- the actual file names each handle returned -- //! which is what makes a surprising result diagnosable rather than merely red. -use std::fmt::Write as _; use windows_platform_probes::handle_state::{ Fixture, SingleShot, closing_duplicate_preserves_source, duplicate_shares_cursor, ground_truth, query_disturbs_cursor, separate_opens_are_independent, @@ -26,7 +25,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/ioring.rs b/crates/windows-platform-probes/src/bin/ioring.rs index 862490b7f..b9e3041d5 100644 --- a/crates/windows-platform-probes/src/bin/ioring.rs +++ b/crates/windows-platform-probes/src/bin/ioring.rs @@ -11,7 +11,6 @@ //! this reports "cannot measure" rather than a false negative on a host that //! has no ring. -use std::fmt::Write as _; use windows_platform_probes::ioring::{ IoRingSupport, is_available, measure_registration, measure_thread_agnosticism, }; @@ -25,7 +24,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/pool_growth.rs b/crates/windows-platform-probes/src/bin/pool_growth.rs index 7d73e1ae1..c99646045 100644 --- a/crates/windows-platform-probes/src/bin/pool_growth.rs +++ b/crates/windows-platform-probes/src/bin/pool_growth.rs @@ -11,7 +11,6 @@ //! exceed it, and gets there promptly); this binary prints the numbers, which //! is what a new architecture actually needs to be re-measured against. -use std::fmt::Write as _; use windows_platform_probes::pool_growth::{measure_growth, measure_raise_while_saturated}; use windows_platform_probes::report::emit_report; @@ -20,7 +19,13 @@ use windows_platform_probes::report::emit_report; /// Takes the buffer rather than printing: a helper that wrote to stdout while /// its caller composed a string would emit its lines *before* the caller's, /// reordering the report even though every line still appeared. -fn report(out: &mut String, label: &str, maximum: u32, submissions: usize, runs_long: bool) { +fn report( + out: &mut dyn std::fmt::Write, + label: &str, + maximum: u32, + submissions: usize, + runs_long: bool, +) { let observed = measure_growth(maximum, submissions, runs_long); let _ = writeln!(out, "{label}"); @@ -50,7 +55,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/request_cost.rs b/crates/windows-platform-probes/src/bin/request_cost.rs index 558fb2a91..6a2f45edf 100644 --- a/crates/windows-platform-probes/src/bin/request_cost.rs +++ b/crates/windows-platform-probes/src/bin/request_cost.rs @@ -10,7 +10,6 @@ //! 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; @@ -49,7 +48,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/bin/topology.rs b/crates/windows-platform-probes/src/bin/topology.rs index 1b1191cac..d908c00ff 100644 --- a/crates/windows-platform-probes/src/bin/topology.rs +++ b/crates/windows-platform-probes/src/bin/topology.rs @@ -28,7 +28,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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`. // @@ -55,5 +55,5 @@ fn render(out: &mut String) { Ok(observation) => report(&banner, &observation), Err(error) => report_unmeasured(&banner, &error), }; - out.push_str(&text); + let _ = write!(out, "{text}"); } diff --git a/crates/windows-platform-probes/src/bin/worker_context.rs b/crates/windows-platform-probes/src/bin/worker_context.rs index b1352d729..24509332b 100644 --- a/crates/windows-platform-probes/src/bin/worker_context.rs +++ b/crates/windows-platform-probes/src/bin/worker_context.rs @@ -12,7 +12,6 @@ //! measurement can be eyeballed on a new host or a new Windows build without //! reading a test's output. -use std::fmt::Write as _; use windows_platform_probes::report::emit_report; use windows_platform_probes::worker_context::{ observe_on_worker, observe_on_worker_while_impersonating, @@ -26,7 +25,7 @@ fn main() { } /// The probe's whole report, as text. -fn render(out: &mut String) { +fn render(out: &mut dyn std::fmt::Write) { // 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 diff --git a/crates/windows-platform-probes/src/long_path_report.rs b/crates/windows-platform-probes/src/long_path_report.rs index 614fec759..6d772eba2 100644 --- a/crates/windows-platform-probes/src/long_path_report.rs +++ b/crates/windows-platform-probes/src/long_path_report.rs @@ -6,8 +6,6 @@ //! **An experiment, not a component.** These probes measure platform behaviour //! and are not for production use. See this crate's DESIGN-NOTES.md. -use std::fmt::Write as _; - use crate::long_path::{MAX_PATH_CONTENT, Observation, Shape, is_refusal}; #[cfg(test)] @@ -26,7 +24,7 @@ mod tests; /// nothing at all, not even the banner that every captured report is supposed to /// carry. Composing the banner and the header first makes the buffer worth /// emitting from the moment measurement begins. -pub fn render(out: &mut String, manifest_aware: bool) { +pub fn render(out: &mut dyn std::fmt::Write, manifest_aware: bool) { preamble(out); // Everything above is already in `out`, so the report survives whatever this // does. @@ -38,7 +36,7 @@ pub fn render(out: &mut String, manifest_aware: bool) { /// Split out so [`body`] can be tested. The ordering is the point rather than an /// artefact: this must reach `out` before [`crate::long_path::measure`] is /// called, or a panic inside the measurement prints nothing at all. -fn preamble(out: &mut String) { +fn preamble(out: &mut dyn std::fmt::Write) { // First line of the report, and part of the composed 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. @@ -62,7 +60,7 @@ fn preamble(out: &mut String) { /// it is the length-refusal gating, the ceiling the column compares against, the /// registry warning, and the apparatus-error early return, two of which are /// fixes for defects a review round had to find by reading output. -fn body(out: &mut String, observation: &Observation) { +fn body(out: &mut dyn std::fmt::Write, observation: &Observation) { let _ = writeln!( out, "manifest longPathAware : {}", diff --git a/crates/windows-platform-probes/src/report.rs b/crates/windows-platform-probes/src/report.rs index eabb24685..7357e1621 100644 --- a/crates/windows-platform-probes/src/report.rs +++ b/crates/windows-platform-probes/src/report.rs @@ -51,8 +51,6 @@ //! identical -- it passed three genuinely broken probes here before the //! comparison was redone line-by-line. -use std::panic::{AssertUnwindSafe, catch_unwind, resume_unwind}; - /// Somewhere a probe's report can go. pub trait Report { /// Emit one line. @@ -181,65 +179,58 @@ pub fn emit(report: &mut impl Report, block: &str) { } } -/// Compose a report and emit it, **including when composing it panics**. +/// Render a report straight to the sink, a line at a time as it is produced. +/// +/// Every probe's `main` is one call to this. The renderer writes into a +/// [`LineSink`], so each completed line reaches the [`Report`] as it is +/// composed rather than when the renderer returns. /// -/// Every probe's `main` is one call to this. The buffer is owned here rather -/// than inside the renderer so that a measurement which aborts part-way still -/// prints what it had already established. +/// That matters because these renderers **interleave measurement with output**. +/// `probe-cancel-io` writes a heading, runs an attempt against a five-second +/// watchdog, writes its outcome, and repeats -- so with a buffered report a +/// reader who interrupts a run gets nothing, and a run is slowest to finish in +/// exactly the case it was hunting for. Streaming makes the finished lines a +/// reader's regardless of how the process ends. /// -/// That is not hypothetical bookkeeping. These probes call into measurements -/// documented to panic -- `worker_context`'s impersonating observation panics if -/// the token cannot be duplicated or applied, or if the worker never reports -- -/// and each renderer composes several completed findings *before* reaching one. -/// Printing line-by-line used to make that automatic: whatever had been measured -/// was already on the terminal. Buffering the whole report to hand it to a -/// [`Report`] silently gave that up, and for an instrument the point of which is -/// that a failure be diagnosable, how far it got is exactly the information -/// worth keeping. +/// # What replaced the catch-and-resume /// -/// The panic is resumed afterwards, so the exit status and the message are -/// unchanged; the partial report is added to them, not substituted for them. +/// This used to compose the whole report into a `String` inside `catch_unwind`, +/// emit the buffer, and resume the panic, which recovered the finished lines +/// for an unwinding panic **and only for that**. A Ctrl-C, which the default +/// Windows console handler serves by terminating the process, or an abort from +/// a panic raised while already unwinding, both discarded the buffer. /// -/// **This restores the streaming property for unwinding panics only, and that -/// bound is known rather than overlooked.** A termination that does not unwind -/// still loses the buffer, where printing line-by-line would have kept it: Ctrl-C -/// (the default Windows console handler terminates the process outright), and an -/// abort from a panic raised during unwinding. The case that costs most is -/// `probe-cancel-io`, which can run four attempts at a five-second watchdog -- -/// so about twenty seconds, precisely when the wedge it hunts for occurs, which -/// is precisely when a reader interrupts it. +/// Streaming makes that machinery unnecessary rather than merely redundant: the +/// lines are already out, so there is no buffer to rescue and nothing for a +/// `catch_unwind` to do. Keeping it would have been machinery that no longer +/// earned its place -- and would have kept the misleading implication that +/// partial output depends on the panic unwinding. /// -/// Fixing it properly means the renderers writing into a [`Report`] as they go -/// rather than into a `String`, which keeps [`Captured`] working for tests and -/// streams for real runs. That is a different design rather than an oversight in -/// this one -- it changes every renderer -- so it is queued as its own work: -/// milestone `M1` of [CHECKLIST.md](../CHECKLIST.md), with the reasoning in -/// [DESIGN-NOTES.md](../DESIGN-NOTES.md#d-buffered-report). -pub fn emit_report(render: impl FnOnce(&mut String)) { +/// **A panic still loses at most a partial final line**, meaning one on which a +/// renderer had called `write!` without a newline. That is deliberate: flushing +/// it would require a `Drop` on [`LineSink`], and a `Drop` that writes can panic +/// while unwinding, which aborts -- replacing a diagnosable failure with one +/// that explains nothing, the same hazard `Impersonation::drop` documents above. +/// An unterminated fragment is not a finding, so the trade is one-sided. +pub fn emit_report(render: impl FnOnce(&mut dyn std::fmt::Write)) { emit_report_to(&mut Stdout, render); } /// [`emit_report`] against an arbitrary sink. /// -/// Exists so the catch-emit-resume logic is what a test executes, rather than a -/// second copy of that shape written in the test. The first version of the test -/// re-implemented it against a [`Captured`] and so would have passed with the -/// `resume_unwind` below deleted -- which would leave a probe printing a partial -/// report and exiting **0**, the failure that looks most like success. -pub fn emit_report_to(report: &mut impl Report, render: impl FnOnce(&mut String)) { - let mut out = String::new(); - - // `AssertUnwindSafe` because the only state crossing the boundary is this - // buffer, and a partially written report is precisely what is wanted here - // rather than a hazard to be guarded against. - let outcome = catch_unwind(AssertUnwindSafe(|| render(&mut out))); - - emit(report, &out); - - if let Err(payload) = outcome { - resume_unwind(payload); - } +/// Exists so the streaming behaviour is what a test executes, rather than a +/// second copy of that shape written in the test. That mattered more when this +/// wrapped a `catch_unwind`: the first version of the test re-implemented the +/// catch-emit-resume itself and so would have passed with the `resume_unwind` +/// deleted, leaving a probe printing a partial report and exiting **0** -- the +/// failure that looks most like success. The shape is simpler now, and the +/// reason to share it is unchanged. +pub fn emit_report_to(report: &mut impl Report, render: impl FnOnce(&mut dyn std::fmt::Write)) { + let mut sink = LineSink::new(report); + render(&mut sink); + // Emits a final line the renderer left without a newline. Not reached when + // `render` panics, which costs at most that fragment -- see `emit_report`. + sink.finish(); } - #[cfg(test)] mod tests; diff --git a/crates/windows-platform-probes/src/report/tests.rs b/crates/windows-platform-probes/src/report/tests.rs index 66ce40d37..7e509f88e 100644 --- a/crates/windows-platform-probes/src/report/tests.rs +++ b/crates/windows-platform-probes/src/report/tests.rs @@ -199,6 +199,12 @@ fn a_renderer_that_panics_still_has_its_finished_lines_emitted() { // would print a partial report and exit **0**, which is the failure that // looks most like success. Hence `emit_report_to`: same logic, injectable // sink. + // + // **That catch-emit-resume no longer exists**, and this test is why it could + // go. Lines now reach the sink as they are written, so a panic leaves the + // finished ones already emitted and there is no buffer for a `catch_unwind` + // to rescue. The assertions below are unchanged -- which is the point: the + // property held by machinery before and holds by construction now. let mut captured = Captured::default(); let outcome = catch_unwind(AssertUnwindSafe(|| { @@ -208,9 +214,13 @@ fn a_renderer_that_panics_still_has_its_finished_lines_emitted() { }); })); - // Both halves matter, and each fails a different mutation. Without the - // first, deleting the `emit` leaves the test green; without the second, - // deleting the `resume_unwind` does. + // Both halves still matter, and each still fails a different mutation -- + // but what breaks the first has changed with the mechanism. It used to be + // deleting the `emit` after the catch; now it is anything that stops lines + // reaching the sink as they are written, because there is no buffer left to + // rescue. The second half is unchanged in what it guards and stronger in how + // it holds: nothing catches the panic any more, so it propagates by default + // rather than by remembering to re-raise it. assert_eq!( captured.lines, ["measured before the failure"], From f523f6cab8fe1e012ae41a46f8af32fc9c481479 Mon Sep 17 00:00:00 2001 From: Mike Grier Date: Wed, 9 Sep 2026 19:01:45 -0400 Subject: [PATCH 3/5] test(platform-probes): pin streaming by observation, and measure an interrupted probe Completed item: M1.3: Verify by interruption, not by reasoning. Completes M1, which is archived to COMPLETED-CHECKLIST.md and its PLANS.md row updated. **The unit test this item specified would not have caught a regression.** It asked for "a renderer that panics mid-report still has its finished lines in a `Captured`", and that passes under a buffered report too -- emit the buffer after catching the unwind and it holds, which is exactly what the pre-M1.2 code did. What distinguishes streaming is not what a reader has at the end but WHEN the sink receives it. So `a_line_reaches_the_sink_before_the_renderer_returns` observes the sink from inside the renderer, through an `Rc>` shared with a `Report` impl, and asserts a completed line is already there while rendering continues. Restoring the old buffered `emit_report_to` fails it with its own message. **The interruption half is measured, with a control.** `probe-queue-contention` takes about 65 seconds; started with stdout redirected and killed at 8 seconds, the streaming build had 114 bytes on disk -- the host banner and the heading -- and the pre-M1.2 build, built from `246687e` and run through the identical sequence, had 0. The control is what makes it evidence. Reading 114 bytes from the new build shows only that something was written; reading zero from the old one shows the change caused it. `TerminateProcess` was used rather than Ctrl-C, deliberately and as the stronger case: Ctrl-C runs the default console handler and lets the runtime unwind its exit path, while `TerminateProcess` runs nothing at all, so anything still in a userspace buffer is lost outright. A report that survives it survives a Ctrl-C. Recorded in DESIGN-NOTES with the reason it works at all: Rust's `Stdout` wraps a `LineWriter` and flushes at each newline even when redirected, so a line has reached the OS before the next is composed. Had stdout been block-buffered this milestone would have needed a per-line flush as well. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PLANS.md | 2 +- crates/windows-platform-probes/CHECKLIST.md | 71 --------------- .../COMPLETED-CHECKLIST.md | 91 +++++++++++++++++++ .../windows-platform-probes/DESIGN-NOTES.md | 36 ++++++++ 4 files changed, 128 insertions(+), 72 deletions(-) create mode 100644 crates/windows-platform-probes/COMPLETED-CHECKLIST.md diff --git a/PLANS.md b/PLANS.md index 3d9617bae..0fb2ce45d 100644 --- a/PLANS.md +++ b/PLANS.md @@ -20,7 +20,7 @@ plans tracker: [crates/windows-file-enumeration-sys/PLANS.md](crates/windows-fil | [CHECKLIST-thread-ambient.md](CHECKLIST-thread-ambient.md) | in progress | M22-M23: extract the captured-context composite into `windows-thread-ambient-sys`, a standalone platform layer that captures a thread's ambient state and applies it on another thread. M24-M26: `windows-namespace-request-sys`, marshalable Win32 namespace call parameter sets, over a round-one entry list audited from three real consumers (this repository's watcher and enumeration crates, and `MikeGrier/Globazog-rs`) rather than guessed. M27: `windows-platform-probes`, a durable home for the measurements this workspace's designs rest on, under a three-tier scheme (asserted / ignored / binary-only) where every tier is compiled by an ordinary build. Feature-scoped and deleted when complete; it is the whole of the `mikegrier/thread-ambient` branch's work, and is deliberately separate from the deferred namespace-facility items in [CHECKLIST.md](CHECKLIST.md). | [crates/windows-thread-ambient-sys/DESIGN-NOTES.md](crates/windows-thread-ambient-sys/DESIGN-NOTES.md) | | [crates/windows-overlapped-io-sys/CHECKLIST.md](crates/windows-overlapped-io-sys/CHECKLIST.md) | not started | M14: finish the contract audit -- categories 1, 2, 6, 8, 9 were not examined -- and sweep `outstanding()` for the advisory-predicate hazard. | [crates/windows-overlapped-io-sys/DESIGN-NOTES.md](crates/windows-overlapped-io-sys/DESIGN-NOTES.md) | | [crates/windows-ioring-sys/CHECKLIST.md](crates/windows-ioring-sys/CHECKLIST.md) | in progress | Memory-safe Rust over the Windows `IoRing` submission/completion ring, as a new crate. M1-M7 (ring lifecycle through the `ring-copy` topology-aligned sample) are complete and archived. The parked, pinned-thread `M6+` work and the new M10 contract audit remain. | [crates/windows-ioring-sys/DESIGN-NOTES.md](crates/windows-ioring-sys/DESIGN-NOTES.md) | -| [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md) | not started | M1: stream a probe's report as it is measured. The one-sink refactor has each renderer compose its report into a `String`, which buys the seam that lets a probe's findings be asserted rather than eyeballed, and gives up output appearing as it is measured. `emit_report` recovers that for an unwinding panic only; Ctrl-C and an abort during unwinding still discard the buffer. Costs most on `probe-cancel-io`, which runs about twenty seconds precisely when the wedge it hunts for occurs -- precisely when a reader interrupts. | [crates/windows-platform-probes/DESIGN-NOTES.md](crates/windows-platform-probes/DESIGN-NOTES.md#d-buffered-report) | +| [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md) | in progress | M1 (streaming reports) is done and archived: every probe now writes into the sink as it measures, through a `fmt::Write` adapter that left all 504 `writeln!` call sites untouched, and the `catch_unwind`/`resume_unwind` pair is gone because there is no longer a buffer to rescue. Measured with a control -- a probe killed 8 s into a 65 s run keeps its banner and heading where the previous build kept nothing. M2 remains: check correspondence *between* a report's parts, which is the defect class no per-part instrument in this crate can see. | [crates/windows-platform-probes/DESIGN-NOTES.md](crates/windows-platform-probes/DESIGN-NOTES.md#d-streaming-report) | | [CHECKLIST-mutation-survivors.md](CHECKLIST-mutation-survivors.md) | not started | Work queued from the workspace-wide cargo-mutants sweep of 2026-09-02, whose findings are kept in [mutation-sweeps/2026-09-02/](mutation-sweeps/2026-09-02/README.md) rather than re-derived -- the run took roughly fourteen hours. 2,792 caught, 1,112 survived, 198 timed out. **The headline numbers mislead in three ways and the README says how**: a timeout in a blocking-API crate is usually a detection that lost its name rather than a gap (measured: one of `windows-waitable-queues`' 120 timeouts fails four tests in 0.00s when re-injected alone), a low score on an executable probe crate is measuring the wrong thing, and three kinds of survivor -- equivalent mutants, unreachable code, and constants that want a `const` assertion -- are not missing tests at all. M1 covers the shipping crates; M2 holds the two crates that are not libraries and whose scope is an engineer's decision; M3 re-runs and prunes rather than hand-editing the tool's output into a second source of truth. | [mutation-sweeps/2026-09-02/README.md](mutation-sweeps/2026-09-02/README.md) | Add a row here when new work is planned, against [CHECKLIST.md](CHECKLIST.md) or any crate's. diff --git a/crates/windows-platform-probes/CHECKLIST.md b/crates/windows-platform-probes/CHECKLIST.md index 147a5bc90..e7360a478 100644 --- a/crates/windows-platform-probes/CHECKLIST.md +++ b/crates/windows-platform-probes/CHECKLIST.md @@ -5,77 +5,6 @@ separately, in the workspace [CHECKLIST-thread-ambient.md](../../CHECKLIST-threa M27; that file is feature-scoped and is deleted when its feature completes, so durable follow-up work for the crate belongs here instead. -## M1 -- Stream a probe's report as it is measured - -The report sink introduced with [src/report.rs](src/report.rs) has each renderer compose its whole -report into a `String`, which `emit_report` then hands to a [`Report`]. That buys the seam the crate -wanted -- a probe's findings can be asserted rather than eyeballed -- and it gave up a property the -previous line-by-line `println!` had for free: output appearing as it is measured. - -`emit_report` recovers it for an **unwinding panic** only, by catching, emitting what was composed, and -resuming. A termination that does not unwind still discards the buffer: - -- **Ctrl-C.** The default Windows console handler terminates the process; no unwind runs. -- **Abort from a panic raised while already unwinding.** - -The case that costs most is `probe-cancel-io`: four attempts against a five-second watchdog, so about -twenty seconds, and it runs that long *precisely when the wedge it hunts for occurs* -- which is -precisely when a reader gives up and interrupts. The measurement most worth having is the one most -likely to be thrown away. - -See [DESIGN-NOTES.md](DESIGN-NOTES.md) -> [The report is buffered, and what that -costs](DESIGN-NOTES.md#d-buffered-report) for why it was built this way and why the fix is a separate -piece of work rather than a correction to that one. - -- [x] **M1.1** -- Decide how a formatted line reaches the sink, and build it. **Option (b): `LineSink`, - an adapter implementing `std::fmt::Write` over a `&mut dyn Report`.** Decision and reasoning in - [DESIGN-NOTES.md](DESIGN-NOTES.md#d-streaming-report). - - **The estimate in this item was wrong, and re-measuring it decided the question.** It said "upwards - of 160" `writeln!` sites; there are **504** across the production renderers, written into the `&mut - String` of about twenty functions. Option (a) -- a `Report` method taking `fmt::Arguments` plus a - macro -- is the most explicit and would have rewritten all 504; that is affordable at 160 and is not - at 504. Option (b) moves the twenty signatures and leaves the 504 untouched, because `String` - implements `fmt::Write` too and a call site cannot tell the difference. Option (c) was declined as a - half-measure that keeps two buffers. - - The cost this item predicted for (b) is real and is now paid: `fmt::Write` is line-agnostic, so - `LineSink` holds a partial line and emits completed ones, and `Captured`'s one-line-per-entry - guarantee is re-established by test rather than assumed. Seven tests pin it, including the two - properties that are easy to get wrong -- a final `write!` with no trailing newline still emits its - line, and `split('\n')` rather than `lines()` because only the former distinguishes a finished line - from a partial one. Both were verified by sabotage (failing three tests and two respectively), not - by reading. - -- [x] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify - `emit_report` accordingly. All sixteen probes now take `out: &mut dyn std::fmt::Write`; the - `catch_unwind`/`resume_unwind` pair is deleted, because with lines leaving as they are produced - there is no buffer to rescue and keeping it would imply partial output still depends on the panic - unwinding. `Captured` is unchanged and its tests pass untouched. - - **Three probes needed more than a signature change**, because they never went through - `emit_report` at all -- `core_affinity`, `peer_index_cache` and `queue_contention` each composed a - `String` and called `emit` directly. They are branch-local and so missed the round that fixed the - same bypass in the peeled probes, which means the crate's "every probe routes through this" claim - was false in three places. `core_affinity` additionally measured in `main`'s argument list, ahead - of the renderer, so a topology read that failed produced no banner at all; it now measures after - the banner and reports the failure as a failure to observe rather than as a finding. - - **Verified with a control, because these probes are not deterministic.** A direct before/after - comparison flagged nine of fifteen reports, which is not evidence -- they print measured - nanoseconds and branch their verdicts on them. Running the *same* build twice differed by as much - or more (`peer-index-cache`: 22 lines between two runs of one build, against 20 across the - conversion), and the twelve deterministic reports were structurally identical. A before/after diff - on a probe means nothing without that control. - -- [ ] **M1.3** -- Verify by interruption, not by reasoning. Sending Ctrl-C to a probe part-way through - must leave the already-measured lines on the terminal; today it leaves nothing. Assert the in-process - half (a renderer that panics mid-report still has its finished lines in a `Captured`) as a unit test, - and record the Ctrl-C observation in [DESIGN-NOTES.md](DESIGN-NOTES.md) -- an interactive signal is not - something to assert in CI, but it is the property the milestone exists for, so it must be measured - once rather than assumed. - - ## M2 -- Check correspondence between the report's parts, not just each part A pull-request review found a state where [src/topology_report.rs](src/topology_report.rs) printed diff --git a/crates/windows-platform-probes/COMPLETED-CHECKLIST.md b/crates/windows-platform-probes/COMPLETED-CHECKLIST.md new file mode 100644 index 000000000..9b635e6ba --- /dev/null +++ b/crates/windows-platform-probes/COMPLETED-CHECKLIST.md @@ -0,0 +1,91 @@ +# Completed checklists: windows-platform-probes + +Append-only. Newest groups at the bottom. + +## Moved 2026-09-09 19:00:17 -04:00 -- M1: a probe's report streams as it is measured + +## M1 -- Stream a probe's report as it is measured + +The report sink introduced with [src/report.rs](src/report.rs) has each renderer compose its whole +report into a `String`, which `emit_report` then hands to a [`Report`]. That buys the seam the crate +wanted -- a probe's findings can be asserted rather than eyeballed -- and it gave up a property the +previous line-by-line `println!` had for free: output appearing as it is measured. + +`emit_report` recovers it for an **unwinding panic** only, by catching, emitting what was composed, and +resuming. A termination that does not unwind still discards the buffer: + +- **Ctrl-C.** The default Windows console handler terminates the process; no unwind runs. +- **Abort from a panic raised while already unwinding.** + +The case that costs most is `probe-cancel-io`: four attempts against a five-second watchdog, so about +twenty seconds, and it runs that long *precisely when the wedge it hunts for occurs* -- which is +precisely when a reader gives up and interrupts. The measurement most worth having is the one most +likely to be thrown away. + +See [DESIGN-NOTES.md](DESIGN-NOTES.md) -> [The report is buffered, and what that +costs](DESIGN-NOTES.md#d-buffered-report) for why it was built this way and why the fix is a separate +piece of work rather than a correction to that one. + +- [x] **M1.1** -- Decide how a formatted line reaches the sink, and build it. **Option (b): `LineSink`, + an adapter implementing `std::fmt::Write` over a `&mut dyn Report`.** Decision and reasoning in + [DESIGN-NOTES.md](DESIGN-NOTES.md#d-streaming-report). + + **The estimate in this item was wrong, and re-measuring it decided the question.** It said "upwards + of 160" `writeln!` sites; there are **504** across the production renderers, written into the `&mut + String` of about twenty functions. Option (a) -- a `Report` method taking `fmt::Arguments` plus a + macro -- is the most explicit and would have rewritten all 504; that is affordable at 160 and is not + at 504. Option (b) moves the twenty signatures and leaves the 504 untouched, because `String` + implements `fmt::Write` too and a call site cannot tell the difference. Option (c) was declined as a + half-measure that keeps two buffers. + + The cost this item predicted for (b) is real and is now paid: `fmt::Write` is line-agnostic, so + `LineSink` holds a partial line and emits completed ones, and `Captured`'s one-line-per-entry + guarantee is re-established by test rather than assumed. Seven tests pin it, including the two + properties that are easy to get wrong -- a final `write!` with no trailing newline still emits its + line, and `split('\n')` rather than `lines()` because only the former distinguishes a finished line + from a partial one. Both were verified by sabotage (failing three tests and two respectively), not + by reading. + +- [x] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify + `emit_report` accordingly. All sixteen probes now take `out: &mut dyn std::fmt::Write`; the + `catch_unwind`/`resume_unwind` pair is deleted, because with lines leaving as they are produced + there is no buffer to rescue and keeping it would imply partial output still depends on the panic + unwinding. `Captured` is unchanged and its tests pass untouched. + + **Three probes needed more than a signature change**, because they never went through + `emit_report` at all -- `core_affinity`, `peer_index_cache` and `queue_contention` each composed a + `String` and called `emit` directly. They are branch-local and so missed the round that fixed the + same bypass in the peeled probes, which means the crate's "every probe routes through this" claim + was false in three places. `core_affinity` additionally measured in `main`'s argument list, ahead + of the renderer, so a topology read that failed produced no banner at all; it now measures after + the banner and reports the failure as a failure to observe rather than as a finding. + + **Verified with a control, because these probes are not deterministic.** A direct before/after + comparison flagged nine of fifteen reports, which is not evidence -- they print measured + nanoseconds and branch their verdicts on them. Running the *same* build twice differed by as much + or more (`peer-index-cache`: 22 lines between two runs of one build, against 20 across the + conversion), and the twelve deterministic reports were structurally identical. A before/after diff + on a probe means nothing without that control. + +- [x] **M1.3** -- Verify by interruption, not by reasoning. Both halves done, and the in-process half + needed a test this item did not describe. + + **The unit test as specified would not have caught a regression.** "A renderer that panics + mid-report still has its finished lines in a `Captured`" passes under a *buffered* report too -- + emit the buffer after catching the unwind and it holds, which is exactly what the pre-M1.2 code + did. What distinguishes streaming is not what a reader has at the end but **when** the sink + receives it, so `a_line_reaches_the_sink_before_the_renderer_returns` observes the sink from + *inside* the renderer through a shared `Rc>`. Restoring the old buffered + `emit_report_to` fails it with its own message; the panic test alone would have stayed green on + the mechanism and gone red only on the missing catch. + + **The interruption half is measured, with a control**, and recorded in + [DESIGN-NOTES.md](DESIGN-NOTES.md). `probe-queue-contention` (~65 s), stdout redirected, killed at + 8 s: the streaming build had **114 bytes** on disk (banner and heading), the pre-M1.2 build built + from `246687e` had **0**. The control is what makes it evidence rather than an observation. + + `TerminateProcess` was used rather than Ctrl-C deliberately: it runs no handler at all, where + Ctrl-C still lets the runtime unwind its exit path, so surviving it subsumes the interactive case. + The reason any of it works is that Rust's `Stdout` wraps a `LineWriter` and flushes at each + newline even when redirected -- had stdout been block-buffered this milestone would have needed a + per-line flush too. diff --git a/crates/windows-platform-probes/DESIGN-NOTES.md b/crates/windows-platform-probes/DESIGN-NOTES.md index e035506a9..7e7f650e2 100644 --- a/crates/windows-platform-probes/DESIGN-NOTES.md +++ b/crates/windows-platform-probes/DESIGN-NOTES.md @@ -610,6 +610,42 @@ Running the *same* build twice showed differences of the same size or larger the conversion). The twelve deterministic reports were structurally identical. A before/after diff on a probe is not evidence without that control. +### Measured: an interrupted probe keeps what it had already measured + +M1.3 asked for this to be measured once rather than assumed, because it is the +property the whole milestone exists for and no unit test reaches it -- a test +cannot terminate its own process without taking the harness with it. + +`probe-queue-contention` takes about 65 seconds on the x86_64 review host, which +makes it the natural subject. Started with stdout redirected to a file, left for +8 seconds, then terminated: + +| build | bytes on disk at 8 s | content | +|---|---|---| +| streaming (M1.2) | **114** | the host banner and the heading | +| buffered (pre-M1.2, built from `246687e`) | **0** | nothing at all | + +The control is the point. Reading 114 bytes from the streaming build shows only +that something was written; running the *previous* build through the identical +sequence and reading zero is what shows the change caused it. Both binaries were +release builds of the same crate, killed at the same elapsed time, by the same +command. + +**`TerminateProcess` was used rather than Ctrl-C, and it is the stronger case.** +Ctrl-C on Windows runs the default console handler, which terminates the process +but still lets the runtime unwind its exit path; `TerminateProcess` -- what +`Stop-Process -Force` issues -- runs nothing at all, so any bytes still sitting +in a userspace buffer are lost outright. A report that survives it survives a +Ctrl-C, so the interactive case is covered by the measurement rather than left +untested. + +**Why the bytes are already safe** is worth naming, since it is what makes the +whole design work: Rust's `std::io::Stdout` wraps a `LineWriter`, which flushes +at each newline whether stdout is a terminal or a redirected file. So a line +handed to `println!` has reached the OS before the next one is composed, and no +process-level termination can take it back. Had stdout been block-buffered, this +milestone would have needed an explicit flush per line as well. + ## The long-path probe: a pair of binaries, and a second declined hardening From a36ad75b2085a437fe006523f9f8e44b48f57a16 Mon Sep 17 00:00:00 2001 From: Mike Grier Date: Wed, 9 Sep 2026 22:08:19 -0400 Subject: [PATCH 4/5] docs(platform-probes): re-measure M1's evidence against this crate's probes Every figure M1 recorded was measured on a branch carrying sixteen probes, three of which are not in this crate. Carried over unchanged, the numbers would describe a build a reader of this history cannot produce, and cite probes they cannot find. So each was measured again here. - Call sites: 332 across 18 renderer signatures, not 504 across twenty. The argument is unchanged and the conclusion is the same -- an option costing "rewrite every call site" is affordable at 160 and is not at 332 -- but the estimate this crate can check is 332. - Interruption: the 65-second subject does not exist here, and the longest probe in this crate runs 0.8 s. Re-measured on `probe-doorbell-cost` at a 300 ms kill, six runs per build, each run recording whether the process was still alive when killed rather than inferring it from the byte count: streaming captured 129 characters on six of six, the pre-conversion build 0 on six of six. - Determinism control: 4 of 13 reports differ across the change, while the same-build-twice control differs in 5, by the same amount or more in every case. `probe-cancel-io` is the sharpest: not deterministic, yet it matched across the change, so a before/after diff read alone would have counted it as evidence from a probe that varies run to run. Also corrects the claim that three probes bypassed `emit_report`. That is true of three branch-local probes and false of every probe here, where the one-sink refactor already holds -- which is precisely why converting this crate is one function plus one line per renderer. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PLANS.md | 2 +- .../COMPLETED-CHECKLIST.md | 48 ++++----- .../windows-platform-probes/DESIGN-NOTES.md | 99 ++++++++++++------- 3 files changed, 88 insertions(+), 61 deletions(-) diff --git a/PLANS.md b/PLANS.md index 0fb2ce45d..8eb8844b4 100644 --- a/PLANS.md +++ b/PLANS.md @@ -20,7 +20,7 @@ plans tracker: [crates/windows-file-enumeration-sys/PLANS.md](crates/windows-fil | [CHECKLIST-thread-ambient.md](CHECKLIST-thread-ambient.md) | in progress | M22-M23: extract the captured-context composite into `windows-thread-ambient-sys`, a standalone platform layer that captures a thread's ambient state and applies it on another thread. M24-M26: `windows-namespace-request-sys`, marshalable Win32 namespace call parameter sets, over a round-one entry list audited from three real consumers (this repository's watcher and enumeration crates, and `MikeGrier/Globazog-rs`) rather than guessed. M27: `windows-platform-probes`, a durable home for the measurements this workspace's designs rest on, under a three-tier scheme (asserted / ignored / binary-only) where every tier is compiled by an ordinary build. Feature-scoped and deleted when complete; it is the whole of the `mikegrier/thread-ambient` branch's work, and is deliberately separate from the deferred namespace-facility items in [CHECKLIST.md](CHECKLIST.md). | [crates/windows-thread-ambient-sys/DESIGN-NOTES.md](crates/windows-thread-ambient-sys/DESIGN-NOTES.md) | | [crates/windows-overlapped-io-sys/CHECKLIST.md](crates/windows-overlapped-io-sys/CHECKLIST.md) | not started | M14: finish the contract audit -- categories 1, 2, 6, 8, 9 were not examined -- and sweep `outstanding()` for the advisory-predicate hazard. | [crates/windows-overlapped-io-sys/DESIGN-NOTES.md](crates/windows-overlapped-io-sys/DESIGN-NOTES.md) | | [crates/windows-ioring-sys/CHECKLIST.md](crates/windows-ioring-sys/CHECKLIST.md) | in progress | Memory-safe Rust over the Windows `IoRing` submission/completion ring, as a new crate. M1-M7 (ring lifecycle through the `ring-copy` topology-aligned sample) are complete and archived. The parked, pinned-thread `M6+` work and the new M10 contract audit remain. | [crates/windows-ioring-sys/DESIGN-NOTES.md](crates/windows-ioring-sys/DESIGN-NOTES.md) | -| [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md) | in progress | M1 (streaming reports) is done and archived: every probe now writes into the sink as it measures, through a `fmt::Write` adapter that left all 504 `writeln!` call sites untouched, and the `catch_unwind`/`resume_unwind` pair is gone because there is no longer a buffer to rescue. Measured with a control -- a probe killed 8 s into a 65 s run keeps its banner and heading where the previous build kept nothing. M2 remains: check correspondence *between* a report's parts, which is the defect class no per-part instrument in this crate can see. | [crates/windows-platform-probes/DESIGN-NOTES.md](crates/windows-platform-probes/DESIGN-NOTES.md#d-streaming-report) | +| [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md) | in progress | M1 (streaming reports) is done and archived: every probe now writes into the sink as it measures, through a `fmt::Write` adapter that left all 332 `writeln!` call sites untouched, and the `catch_unwind`/`resume_unwind` pair is gone because there is no longer a buffer to rescue. Measured with a control -- a probe killed 300 ms into a 0.8 s run keeps its banner and heading on six runs of six, where the previous build kept nothing on six of six. M2 remains: check correspondence *between* a report's parts, which is the defect class no per-part instrument in this crate can see. | [crates/windows-platform-probes/DESIGN-NOTES.md](crates/windows-platform-probes/DESIGN-NOTES.md#d-streaming-report) | | [CHECKLIST-mutation-survivors.md](CHECKLIST-mutation-survivors.md) | not started | Work queued from the workspace-wide cargo-mutants sweep of 2026-09-02, whose findings are kept in [mutation-sweeps/2026-09-02/](mutation-sweeps/2026-09-02/README.md) rather than re-derived -- the run took roughly fourteen hours. 2,792 caught, 1,112 survived, 198 timed out. **The headline numbers mislead in three ways and the README says how**: a timeout in a blocking-API crate is usually a detection that lost its name rather than a gap (measured: one of `windows-waitable-queues`' 120 timeouts fails four tests in 0.00s when re-injected alone), a low score on an executable probe crate is measuring the wrong thing, and three kinds of survivor -- equivalent mutants, unreachable code, and constants that want a `const` assertion -- are not missing tests at all. M1 covers the shipping crates; M2 holds the two crates that are not libraries and whose scope is an engineer's decision; M3 re-runs and prunes rather than hand-editing the tool's output into a second source of truth. | [mutation-sweeps/2026-09-02/README.md](mutation-sweeps/2026-09-02/README.md) | Add a row here when new work is planned, against [CHECKLIST.md](CHECKLIST.md) or any crate's. diff --git a/crates/windows-platform-probes/COMPLETED-CHECKLIST.md b/crates/windows-platform-probes/COMPLETED-CHECKLIST.md index 9b635e6ba..02129fa4a 100644 --- a/crates/windows-platform-probes/COMPLETED-CHECKLIST.md +++ b/crates/windows-platform-probes/COMPLETED-CHECKLIST.md @@ -31,10 +31,10 @@ piece of work rather than a correction to that one. [DESIGN-NOTES.md](DESIGN-NOTES.md#d-streaming-report). **The estimate in this item was wrong, and re-measuring it decided the question.** It said "upwards - of 160" `writeln!` sites; there are **504** across the production renderers, written into the `&mut - String` of about twenty functions. Option (a) -- a `Report` method taking `fmt::Arguments` plus a - macro -- is the most explicit and would have rewritten all 504; that is affordable at 160 and is not - at 504. Option (b) moves the twenty signatures and leaves the 504 untouched, because `String` + of 160" `writeln!` sites; there are **332** across this crate's production renderers, written into + the `&mut String` of 18 functions. Option (a) -- a `Report` method taking `fmt::Arguments` plus a + macro -- is the most explicit and would have rewritten all 332; that is affordable at 160 and is not + at 332. Option (b) moves the 18 signatures and leaves the 332 untouched, because `String` implements `fmt::Write` too and a call site cannot tell the difference. Option (c) was declined as a half-measure that keeps two buffers. @@ -47,25 +47,27 @@ piece of work rather than a correction to that one. by reading. - [x] **M1.2** -- Convert every renderer to write into the sink as it measures, and simplify - `emit_report` accordingly. All sixteen probes now take `out: &mut dyn std::fmt::Write`; the + `emit_report` accordingly. All thirteen probes now take `out: &mut dyn std::fmt::Write`; the `catch_unwind`/`resume_unwind` pair is deleted, because with lines leaving as they are produced there is no buffer to rescue and keeping it would imply partial output still depends on the panic unwinding. `Captured` is unchanged and its tests pass untouched. - **Three probes needed more than a signature change**, because they never went through - `emit_report` at all -- `core_affinity`, `peer_index_cache` and `queue_contention` each composed a - `String` and called `emit` directly. They are branch-local and so missed the round that fixed the - same bypass in the peeled probes, which means the crate's "every probe routes through this" claim - was false in three places. `core_affinity` additionally measured in `main`'s argument list, ahead - of the renderer, so a topology read that failed produced no banner at all; it now measures after - the banner and reports the failure as a failure to observe rather than as a finding. - - **Verified with a control, because these probes are not deterministic.** A direct before/after - comparison flagged nine of fifteen reports, which is not evidence -- they print measured - nanoseconds and branch their verdicts on them. Running the *same* build twice differed by as much - or more (`peer-index-cache`: 22 lines between two runs of one build, against 20 across the - conversion), and the twelve deterministic reports were structurally identical. A before/after diff - on a probe means nothing without that control. + **Every probe in this crate needed only the signature change**, because each already went through + `emit_report` rather than composing a `String` and calling `emit` itself. That is what the + one-sink refactor bought, and it is why converting thirteen probes is one function plus one line + per renderer. Three further probes under development on a branch do not hold that property and + are converted where they land, since they are not in this crate yet. + + **Verified with a control, because several of these probes are not deterministic.** A direct + before/after comparison flagged four of the thirteen reports, which is not evidence -- they print + measured nanoseconds and branch their verdicts on them. Running the *same* build twice differs in + **five**, by the same amount or more in every case: `probe-doorbell-cost` 34 lines against 30, + `probe-request-cost` 32 against 32, `probe-pool-growth` 14 against 14, `probe-device-map` 4 + against 4, and `probe-cancel-io` 2 against **0** -- that last one being the sharpest, since a + probe whose output varies run to run happened to match across the change and would have counted + as evidence of no change had the control not existed. The eight reports the control showed to be + genuinely deterministic were byte-identical. A before/after diff on a probe means nothing without + that control. - [x] **M1.3** -- Verify by interruption, not by reasoning. Both halves done, and the in-process half needed a test this item did not describe. @@ -80,9 +82,11 @@ piece of work rather than a correction to that one. the mechanism and gone red only on the missing catch. **The interruption half is measured, with a control**, and recorded in - [DESIGN-NOTES.md](DESIGN-NOTES.md). `probe-queue-contention` (~65 s), stdout redirected, killed at - 8 s: the streaming build had **114 bytes** on disk (banner and heading), the pre-M1.2 build built - from `246687e` had **0**. The control is what makes it evidence rather than an observation. + [DESIGN-NOTES.md](DESIGN-NOTES.md). `probe-doorbell-cost` (~0.8 s, the longest-running probe + here), stdout redirected, killed at 300 ms, six runs of each build with every run confirmed still + alive at the kill: the streaming build captured **129 characters** (banner and heading) on all + six, the pre-conversion build **0** on all six. The control is what makes it evidence rather than + an observation. `TerminateProcess` was used rather than Ctrl-C deliberately: it runs no handler at all, where Ctrl-C still lets the runtime unwind its exit path, so surviving it subsumes the interactive case. diff --git a/crates/windows-platform-probes/DESIGN-NOTES.md b/crates/windows-platform-probes/DESIGN-NOTES.md index 7e7f650e2..eb3149cd4 100644 --- a/crates/windows-platform-probes/DESIGN-NOTES.md +++ b/crates/windows-platform-probes/DESIGN-NOTES.md @@ -540,16 +540,16 @@ The choice was between giving `Report` a method taking `fmt::Arguments` (with a `writeln!` calls keep working, and keeping the `String` while flushing it at line boundaries. **It was decided by counting rather than by taste.** Every renderer already writes through `writeln!(out, ...)` against a `String`'s -`fmt::Write`, at **504 sites**; only about twenty functions take the `&mut +`fmt::Write`, at **332 sites** in this crate; only 18 functions take the `&mut String` those sites write into. A sink method would have been the most explicit -option and would have rewritten all 504; `fmt::Write` moves the twenty and -leaves the 504 untouched, because `String` implements `fmt::Write` too and the -call sites cannot tell the difference. +option and would have rewritten all 332; `fmt::Write` moves the 18 and leaves +the 332 untouched, because `String` implements `fmt::Write` too and the call +sites cannot tell the difference. Worth recording that M1 estimated "upwards of 160" of those sites. The real -figure is three times that, and it is the whole of the argument -- an option -whose cost is "rewrite every call site" is affordable at 160 and is not at 504. -A plan's estimate is worth re-measuring at the moment it becomes a decision. +figure is twice that, and it is the whole of the argument -- an option whose +cost is "rewrite every call site" is affordable at 160 and is not at 332. A +plan's estimate is worth re-measuring at the moment it becomes a decision. ### What the adapter has to reassemble, and why that is not a detail @@ -573,7 +573,7 @@ this paragraph: ### Every renderer now writes into the sink, and the catch-and-resume is gone -M1.2 pointed all sixteen probes at the sink. Two things about that conversion are +M1.2 pointed all thirteen probes at the sink. Two things about that conversion are worth keeping. **The `catch_unwind`/`resume_unwind` pair was deleted rather than left in place.** @@ -590,24 +590,40 @@ and a `Drop` that writes can panic while unwinding, which aborts and replaces a diagnosable failure with one that explains nothing. An unterminated fragment is not a finding, so the trade is one-sided. -Three probes needed more than a signature change, because they were composing a -`String` and calling `emit` directly rather than going through `emit_report` at -all: `core_affinity`, `peer_index_cache` and `queue_contention`. They are the -branch-local probes, and they had never been through the round that fixed the -same bypass in the peeled ones -- the crate's "every probe routes through this" -claim was false in three places until now. `core_affinity` also measured in -`main`'s argument list, so a failure to read the topology produced no banner and -no indication of which probe had died; it now measures inside the renderer, -after the banner, and reports a failed read as a failure to observe rather than -as a finding. - -**Verifying that no report changed needed a control, because most of these -probes are not deterministic.** Comparing before and after directly showed -differences in nine of fifteen reports -- which proves nothing on its own, since +Every probe in this crate needed only the signature change, because each already +went through `emit_report` rather than composing a `String` and calling `emit` +itself. That is worth stating because it was not free: it is what the one-sink +refactor bought, and it is why converting thirteen probes to stream is a +mechanical change to one function plus one line per renderer. + +Three further probes are being developed on a branch and do **not** hold that +property -- they compose a `String` and call `emit` directly, so the crate's +"every probe routes through this" claim is false for them. They are converted +where they land rather than here, since they do not exist in this crate yet. + +**Verifying that no report changed needed a control, because several of these +probes are not deterministic.** Comparing before and after directly showed four +of the thirteen reports differing -- which proves nothing on its own, since these probes print measured nanoseconds and render verdicts branching on them. -Running the *same* build twice showed differences of the same size or larger -(`peer-index-cache` 22 lines between two runs of one build, against 20 across -the conversion). The twelve deterministic reports were structurally identical. + +Running the *same* build twice is the control, and it differs in **five**, by +the same amount or more in every case: + +| probe | lines differing, same build twice | lines differing, across the change | +|---|---|---| +| `probe-doorbell-cost` | 34 | 30 | +| `probe-request-cost` | 32 | 32 | +| `probe-pool-growth` | 14 | 14 | +| `probe-device-map` | 4 | 4 | +| `probe-cancel-io` | 2 | **0** | + +`probe-cancel-io` is the one that makes the point sharpest: it is *not* +deterministic, yet it happened to match across the change. Had the before/after +diff been read on its own, that would have counted as evidence of no change -- +from a probe whose output varies run to run regardless. The eight reports the +control showed to be genuinely deterministic were byte-identical across the +conversion, and those are the eight that carry the argument. + A before/after diff on a probe is not evidence without that control. ### Measured: an interrupted probe keeps what it had already measured @@ -616,25 +632,32 @@ M1.3 asked for this to be measured once rather than assumed, because it is the property the whole milestone exists for and no unit test reaches it -- a test cannot terminate its own process without taking the harness with it. -`probe-queue-contention` takes about 65 seconds on the x86_64 review host, which -makes it the natural subject. Started with stdout redirected to a file, left for -8 seconds, then terminated: +`probe-doorbell-cost` is the longest-running probe in this crate at about 0.8 +seconds, which makes it the subject. Started with stdout redirected, left for +300 milliseconds, then terminated -- **six runs of each build**, with every run +confirmed to have still been alive at the moment it was killed, since a probe +that had already exited would be measuring nothing: -| build | bytes on disk at 8 s | content | -|---|---|---| -| streaming (M1.2) | **114** | the host banner and the heading | -| buffered (pre-M1.2, built from `246687e`) | **0** | nothing at all | +| build | characters captured | runs | content | +|---|---|---|---| +| streaming | **129** | 6 of 6 identical | the host banner and the heading | +| buffered (built from the `LineSink` commit, before the conversion) | **0** | 6 of 6 identical | nothing at all | + +The control is the point. Reading 129 characters from the streaming build shows +only that something was written; running the *previous* build through the +identical sequence and reading zero is what shows the change caused it. Both +binaries were release builds of the same crate, killed at the same elapsed time, +by the same code. -The control is the point. Reading 114 bytes from the streaming build shows only -that something was written; running the *previous* build through the identical -sequence and reading zero is what shows the change caused it. Both binaries were -release builds of the same crate, killed at the same elapsed time, by the same -command. +The margin is narrower than it looks and deliberately so. 300 ms against an +800 ms probe leaves no room for a slow start to be mistaken for buffering, which +is why each run records whether the process was still running when killed rather +than inferring it from the byte count. **`TerminateProcess` was used rather than Ctrl-C, and it is the stronger case.** Ctrl-C on Windows runs the default console handler, which terminates the process but still lets the runtime unwind its exit path; `TerminateProcess` -- what -`Stop-Process -Force` issues -- runs nothing at all, so any bytes still sitting +.NET's `Process.Kill` issues -- runs nothing at all, so any bytes still sitting in a userspace buffer are lost outright. A report that survives it survives a Ctrl-C, so the interactive case is covered by the measurement rather than left untested. From 3827dc32f103698651b79f983b89b64dc34779ec Mon Sep 17 00:00:00 2001 From: Mike Grier Date: Wed, 9 Sep 2026 22:22:16 -0400 Subject: [PATCH 5/5] Update comments in report.rs for better clarity Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- crates/windows-platform-probes/src/report.rs | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/crates/windows-platform-probes/src/report.rs b/crates/windows-platform-probes/src/report.rs index 7357e1621..781e09834 100644 --- a/crates/windows-platform-probes/src/report.rs +++ b/crates/windows-platform-probes/src/report.rs @@ -92,13 +92,11 @@ impl Captured { /// A [`Report`] a renderer can `writeln!` into directly. /// -/// This is the answer to "how does a formatted line reach the sink", and the -/// reason it is a [`std::fmt::Write`] adapter rather than a method on [`Report`] /// is arithmetic. Every renderer writes through `writeln!(out, ...)` against a -/// `String`, at **504 sites** across this crate; a sink method taking +/// `String`, at **332 sites** across this crate; a sink method taking /// `fmt::Arguments` would have been explicit but would have rewritten every one /// of them, while `String` already implements `fmt::Write`, so a sink that does -/// too lets those sites stand untouched and moves only the ~20 renderer +/// too lets those sites stand untouched and moves only 18 renderer signatures. /// signatures. The recorded reasoning is in /// [DESIGN-NOTES.md](../DESIGN-NOTES.md#d-streaming-report). ///