From c3c282f4aee033caf1b5686bcd1a3a3dcf95b812 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 09:14:36 -0400 Subject: [PATCH 1/3] energy tests: assert what the probe reports, not what the host's scheduler allows MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two tests on the macOS runner failed on load rather than on behaviour. The runner is the dev Mac, so "load" means other sessions' work, and both tests asserted a threshold on something the scheduler controls. **eoc-meter — `the_probe_burns_its_tick_of_thread_cpu_between_samples`.** It required each inter-sample gap to carry at least half the 25 ms tick of thread CPU, on the reasoning that the tick spins on the *thread's* clock and so "host load cannot fail it". That reasoning was wrong, and the test's own failure message said why: a tick also stops at `PROBE_TICK_WALL_CAP`, so a host giving this thread a sliver of a core caps the tick with little CPU to show. That is how it failed in CI. No CPU threshold can replace it, because the two outcomes that matter are not separable by time: a spin the host starved into the cap and a tick that simply *slept* both show a long wall span against little CPU. I first tried a per-turn CPU floor, reasoning that a turn is fixed work so starvation lowers turns per second and not the cost of a turn. Measuring it refuted that — a turn that sleeps 1 ms costs 13.3-15.8 µs of thread CPU against a real turn's 2.13-2.92 µs, because a blocking body's context switch is charged to the thread. Even the direction of the threshold was wrong, so the assertion came back out rather than staying in as a number that reads like a guarantee while discriminating nothing. The information has to come from the thing under test. `spin_for_cpu` now returns a `TickOutcome` — the CPU it saw itself burn, and how many turns of the spin loop it ran — and `probe_with` collects one per tick. Per tick the test requires that the loop ran at all (a tick that never span did not burn CPU, at any load) and that it stopped for one of its two stated reasons rather than early; the gaps measured by the tests' own clocks still bound it from above and keep CPU under wall. `SampleCall` gains absolute wall readings beside its CPU pair so the inter-sample gap is derivable in both clocks from one source. Falsified: a tick that sleeps instead of spinning, and a tick skipped altogether, are both caught now — the sleeping one was **not** caught by the weaker intermediate version I tried, which is how I found that version was wrong. Stated in the test's doc comment: this does not establish that the spin body is CPU-bound rather than blocking, because nothing the probe reports separates those. **jouleclaw-energy — `the_process_counter_meters_this_process_and_nothing_else`.** It required a child process to burn ≥ 0.2 J in a 300 ms wall window. The child is an ordinary-priority shell loop competing for a core, so a busy host starves it below the line — 0.147 J at load average 149. How much work a *competing* process gets done in a fixed wall window is the scheduler talking, not this counter. The test's claim is attribution, so that is what it now asserts: the child's burn against this process's window. The old pair gave a factor of two (0.2 J against 0.1 J); attribution either holds by orders of magnitude or does not hold at all, and in the starved run above it held by a factor of about 1 070. The absolute floor stays an order of magnitude lower, only to keep the check from being vacuous if the child never ran. Verified under the load that broke them: both pass three times each at load average ~190. eoc-rs workspace 717 passed; jouleclaw-energy 57 passed. The two clippy warnings in eoc-meter predate this change (checked against the stashed baseline). Co-Authored-By: Claude Opus 5 --- eoc/eoc-rs/crates/eoc-meter/src/lib.rs | 242 +++++++++++++----- .../jouleclaw-energy/tests/process_cpu.rs | 32 ++- 2 files changed, 214 insertions(+), 60 deletions(-) diff --git a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs index 33d01e17e..1ab93a2bc 100644 --- a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs +++ b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs @@ -361,9 +361,9 @@ mod rail_liveness { /// could be taken; each one taken is handed to the rule with the wall /// clock `now` read as it returns. [`probe_with`] runs it with the /// sampler, tick and wall clock it is given, and records each sample call. - pub(crate) fn watch( + pub(crate) fn watch( sample: impl FnMut() -> Option>, - tick: impl FnMut(), + tick: impl FnMut() -> T, now: impl Fn() -> Duration, budget: Duration, ) -> RailWatch { @@ -372,10 +372,10 @@ mod rail_liveness { /// [`watch`], folding samples into the watch `w` it is given (so a /// single vendor counter's probe watches every channel). - pub(crate) fn watch_from( + pub(crate) fn watch_from( mut w: RailWatch, mut sample: impl FnMut() -> Option>, - mut tick: impl FnMut(), + mut tick: impl FnMut() -> T, now: impl Fn() -> Duration, budget: Duration, ) -> RailWatch { @@ -401,20 +401,40 @@ mod rail_liveness { /// clock stands still, and the tick simply takes longer. Only the wall cap /// can cut a tick short, on a host that gives this thread less than /// `want / wall_cap` of a core (5% for the probe's 25 ms in 500 ms). + /// What one tick of the CPU-burning spin did. + /// + /// `spins` is the point of this type. A tick ends on either of two + /// conditions — the CPU target, or the wall cap — and from the outside the + /// two outcomes that matter are indistinguishable by time alone: a spin the + /// host starved into the cap and a tick that simply *slept* both show a + /// full wall span against little CPU. The only honest separator is whether + /// the spin loop ran at all, which only the spin can report. A test that + /// infers it from a CPU threshold is choosing a number the host can defeat + /// in either direction. + #[derive(Debug, Clone, Copy, PartialEq, Eq)] + pub(crate) struct TickOutcome { + /// The thread CPU the spin saw itself burn. + pub(crate) cpu: Duration, + /// Turns of the spin loop. Zero means the tick never span. + pub(crate) spins: u64, + } + pub(crate) fn spin_for_cpu( thread_cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration, want: Duration, wall_cap: Duration, - ) -> Duration { + ) -> TickOutcome { let (cpu0, wall0) = (thread_cpu(), wall()); let mut acc: u64 = 0; + let mut spins: u64 = 0; loop { let used = thread_cpu().saturating_sub(cpu0); if used >= want || wall().saturating_sub(wall0) >= wall_cap { std::hint::black_box(acc); - return used; + return TickOutcome { cpu: used, spins }; } + spins += 1; for _ in 0..256 { acc = std::hint::black_box(acc.wrapping_add(1)); } @@ -443,6 +463,16 @@ mod rail_liveness { /// another process's all-channel sample can hold IOReport for hundreds /// of milliseconds, and this call waits for it. pub(crate) wall: Duration, + /// The wall clock just before and just after the call, absolute. + /// + /// Recorded as a pair, like the CPU readings below, so the gap *between* + /// two calls is derivable in both clocks from the same source. A tick is + /// bounded by 25 ms of thread CPU **or** a 500 ms wall cap, so a test + /// holding only the CPU gap cannot tell a tick that burned its CPU from + /// one the host starved into the cap — see + /// `the_probe_burns_its_tick_of_thread_cpu_between_samples`. + pub(crate) wall_before: Duration, + pub(crate) wall_after: Duration, /// The probing thread's CPU clock just before and just after the call. pub(crate) cpu_before: Duration, pub(crate) cpu_after: Duration, @@ -463,6 +493,8 @@ mod rail_liveness { pub(crate) opened: bool, /// Ticks run between samples. pub(crate) ticks: u32, + /// What each of those ticks did, in order. `ticks` is its length. + pub(crate) tick_outcomes: Vec, /// Every sample call, in order. pub(crate) calls: Vec, /// The rule, folded over every sample that was taken. @@ -484,7 +516,7 @@ mod rail_liveness { /// the rule in [`watch`] for `budget`, and records every sample call. pub(crate) fn probe_with( open: impl FnOnce() -> Option, - mut tick: impl FnMut(), + mut tick: impl FnMut() -> TickOutcome, thread_cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration, budget: Duration, @@ -493,9 +525,15 @@ mod rail_liveness { S: FnMut() -> Option, { let Some(mut sampler) = open() else { - return ProbeRun { opened: false, ticks: 0, calls: Vec::new(), watch: RailWatch::default() }; + return ProbeRun { + opened: false, + ticks: 0, + tick_outcomes: Vec::new(), + calls: Vec::new(), + watch: RailWatch::default(), + }; }; - let (mut calls, mut ticks) = (Vec::new(), 0u32); + let (mut calls, mut ticks, mut tick_outcomes) = (Vec::new(), 0u32, Vec::new()); let watch = watch( || { let (cpu_before, started) = (thread_cpu(), wall()); @@ -503,6 +541,8 @@ mod rail_liveness { let (ended, cpu_after) = (wall(), thread_cpu()); calls.push(SampleCall { wall: ended.saturating_sub(started), + wall_before: started, + wall_after: ended, cpu_before, cpu_after, shape: sample.as_ref().map(|s| (s.channels, s.group_only)), @@ -512,12 +552,12 @@ mod rail_liveness { }, || { ticks += 1; - tick(); + tick_outcomes.push(tick()); }, &wall, budget, ); - ProbeRun { opened: true, ticks, calls, watch } + ProbeRun { opened: true, ticks, tick_outcomes, calls, watch } } /// The status a probe verdict gives this host. No verdict — no @@ -551,10 +591,10 @@ mod rail_liveness { /// over each part so the tests drive this very function with a scripted /// counter, tick and clock; each rung's cached probe passes the real ones. #[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter - pub(crate) fn probe_counter( + pub(crate) fn probe_counter( open: impl FnOnce() -> Option, mut sample: impl FnMut(&C) -> Option>, - tick: impl FnMut(), + tick: impl FnMut() -> T, now: impl Fn() -> Duration, budget: Duration, ) -> Option { @@ -1131,6 +1171,9 @@ mod rail_liveness { ticked.set(ticked.get() + 1); wall.set(wall.get() + step); cpu.set(cpu.get() + TICK); + // A scripted tick that reaches its CPU target: it reports a + // spin so a consumer can tell it apart from one that waited. + TickOutcome { cpu: TICK, spins: 1 } }, || cpu.get(), || wall.get(), @@ -1292,7 +1335,7 @@ mod rail_liveness { want, cap, ); - (used, cpu_reads.get()) + (used.cpu, cpu_reads.get()) } /// The tick spins until this thread's CPU clock has advanced by the @@ -1509,8 +1552,8 @@ mod clocks { /// One tick of a CPU-burning probe: spin until this thread's CPU clock has /// advanced [`PROBE_TICK`], or [`PROBE_TICK_WALL_CAP`] of wall time has /// passed. - pub(crate) fn cpu_burn_tick() { - crate::rail_liveness::spin_for_cpu(thread_cpu_time, wall_now, PROBE_TICK, PROBE_TICK_WALL_CAP); + pub(crate) fn cpu_burn_tick() -> crate::rail_liveness::TickOutcome { + crate::rail_liveness::spin_for_cpu(thread_cpu_time, wall_now, PROBE_TICK, PROBE_TICK_WALL_CAP) } } @@ -1818,8 +1861,8 @@ mod macos_ioreport { } /// One tick of the probe: [`crate::clocks::cpu_burn_tick`]. - fn probe_tick() { - crate::clocks::cpu_burn_tick(); + fn probe_tick() -> crate::rail_liveness::TickOutcome { + crate::clocks::cpu_burn_tick() } /// How many times [`host_status`] — the probe behind the cached @@ -3089,19 +3132,41 @@ mod macos_ioreport { } } - /// The production probe burns CPU between samples, and exactly its tick - /// of it, pinned per tick on the probe's own records of this thread's - /// CPU clock (identified as such by the thread-clock test) so host load - /// cannot fail it: the CPU the thread consumed between the end of one - /// sample call and the start of the next must be at least half the - /// 25 ms tick (a probe that sleeps, or does nothing, between samples - /// burns ~0) and at most twice it (a slower cadence, e.g. a 100 ms tick, - /// burns more). And the tick CPU the probe recorded is checked against - /// the tests' own reading of the thread's CPU clock over the whole probe, - /// and every thread-clock reading the probe recorded must lie between the - /// tests' own readings of this thread's CPU clock just before and just - /// after it: the clock the production composition hands the probe is - /// this thread's CPU clock, not the wall clock or the process's. + /// The production probe burns CPU between samples rather than waiting or + /// skipping, pinned per tick. + /// + /// This test used to require that each inter-sample gap carry at least + /// half the 25 ms tick of thread CPU, on the reasoning that a tick spins + /// on the *thread's* clock and so "host load cannot fail it". That + /// reasoning was wrong, and its own failure message said why: a tick also + /// stops at [`crate::clocks::PROBE_TICK_WALL_CAP`], so a host that gives + /// this thread a sliver of a core caps the tick with little CPU to show. + /// It failed on the macOS CI runner — which is the dev Mac, under other + /// work — exactly that way. + /// + /// No CPU threshold can replace it, because the two outcomes that matter + /// are not separable by time: a spin the host starved into the cap and a + /// tick that simply *slept* both show a long wall span against little + /// CPU. Measured here, a sleeping tick's turns cost *more* thread CPU + /// than real ones (13.3-15.8 µs against 2.13-2.92 µs), because a blocking + /// body's context switch is charged to the thread — so even the direction + /// of a threshold is wrong. + /// + /// So the tick reports what it did: [`rail_liveness::TickOutcome`] carries + /// the CPU it saw itself burn and how many turns of the spin loop it ran. + /// Per tick this test then requires that the loop ran at all (`spins > 0` + /// — a tick that never span did not burn CPU, at any load) and that the + /// tick stopped for one of its two stated reasons rather than early. The + /// gaps measured by the tests' own clocks bound it from above (a slower + /// cadence burns more) and keep CPU under wall. + /// + /// What this does **not** establish: that the spin body is CPU-bound + /// rather than blocking. Nothing the probe reports separates those. + /// + /// Also pinned here, unchanged: every thread-clock reading the probe + /// recorded lies between the tests' own readings around it, so the clock + /// the production composition hands the probe is this thread's CPU clock + /// and not the wall clock or the process's. #[test] fn the_probe_burns_its_tick_of_thread_cpu_between_samples() { let own0 = own_thread_cpu(); @@ -3127,38 +3192,99 @@ mod macos_ioreport { assert!(run.calls.is_empty() && run.ticks == 0, "{run:?}"); return; } - let ticks: Vec = - run.calls.windows(2).map(|w| w[1].cpu_before.saturating_sub(w[0].cpu_after)).collect(); - let recorded: Duration = ticks.iter().sum(); + // Each inter-sample gap in the tests' own clocks: the CPU gap as + // before, and the wall gap beside it, from the same pair of calls. + // Both are needed, because a tick stops on EITHER the CPU target or + // the 500 ms wall cap. + let gaps: Vec<(Duration, Duration)> = run + .calls + .windows(2) + .map(|w| { + ( + w[1].cpu_before.saturating_sub(w[0].cpu_after), + w[1].wall_before.saturating_sub(w[0].wall_after), + ) + }) + .collect(); + let cpus: Vec = gaps.iter().map(|(c, _)| *c).collect(); + let recorded: Duration = cpus.iter().sum(); + let capped = run.tick_outcomes.iter().filter(|t| t.cpu < TICK).count(); eprintln!( - "ioreport probe tick: {} ticks of this thread's CPU between {} sample calls: min {:?}, median {:?}, \ - max {:?} (specified 25 ms); the tests' own reading of the thread's CPU clock over the whole \ - probe: {own:?} in {took:?} of wall time", - ticks.len(), + "ioreport probe tick: {} ticks of this thread's CPU between {} sample calls: min {:?}, \ + median {:?}, max {:?} (specified 25 ms of CPU, or a 500 ms wall cap); {capped} of them \ + reached the cap instead, each reporting its own spin count; the tests' own reading of the \ + thread's CPU clock over the whole probe: {own:?} in {took:?} of wall time", + gaps.len(), run.calls.len(), - ticks.iter().min(), - (!ticks.is_empty()).then(|| median(&ticks)), - ticks.iter().max() + cpus.iter().min(), + (!cpus.is_empty()).then(|| median(&cpus)), + cpus.iter().max() ); - assert!(ticks.len() >= 2, "the probe made only {} sample calls", run.calls.len()); - assert_eq!(run.ticks as usize, ticks.len(), "every tick runs between two sample calls"); - for (i, t) in ticks.iter().enumerate() { + assert!(gaps.len() >= 2, "the probe made only {} sample calls", run.calls.len()); + assert_eq!(run.ticks as usize, gaps.len(), "every tick runs between two sample calls"); + assert_eq!(run.tick_outcomes.len(), gaps.len(), "every tick reported an outcome"); + + for (i, (&(cpu, wall), out)) in gaps.iter().zip(&run.tick_outcomes).enumerate() { + // The claim is that the probe BURNS CPU between samples rather + // than waiting or skipping, and that claim cannot be checked with + // a CPU threshold. A tick stops on the CPU target or on the wall + // cap; a host that gives this thread a sliver of a core caps it + // with little CPU to show, and a tick that merely *slept* looks + // the same in both clocks. A threshold between those two is a + // number the host can defeat in either direction — too low and a + // sleeping tick passes, too high and a starved one fails. So the + // tick reports its own spin count, and that is the separator: a + // tick that never span did not burn CPU, at any load. assert!( - *t >= TICK / 2, - "tick {i} burned only {t:?} of this thread's CPU (every tick: {ticks:?}): the probe must burn \ - CPU between samples, not wait or skip. A tick spins until the thread's CPU clock has \ - advanced 25 ms, so host load cannot shorten it; only its 500 ms wall cap can, on a host \ - that gives this thread under 5% of a core" + out.spins > 0, + "tick {i} reported {} turns of its spin loop: it did not burn CPU between samples, it \ + waited or was skipped (outcome {out:?}, gap {cpu:?} of CPU in {wall:?} of wall time)", + out.spins + ); + // And it stopped for one of the two stated reasons, not early. + assert!( + out.cpu >= crate::clocks::PROBE_TICK + || wall + CLOCK_STEP >= crate::clocks::PROBE_TICK_WALL_CAP, + "tick {i} stopped after {:?} of CPU without reaching the 25 ms target, and only {wall:?} \ + of wall time had passed — short of the 500 ms cap, so neither stopping condition had \ + been met (outcome {out:?})", + out.cpu ); assert!( - *t <= TICK * 2, - "tick {i} burned {t:?} of this thread's CPU (every tick: {ticks:?}): the tick is 25 ms of CPU" + cpu <= TICK * 2, + "tick {i} burned {cpu:?} of this thread's CPU (every gap: {gaps:?}): the tick is 25 ms of CPU" + ); + assert!( + cpu <= wall + CLOCK_STEP, + "tick {i}: {cpu:?} of this thread's CPU in only {wall:?} of wall time" + ); + // Deliberately NOT asserted: that each turn burned a minimum of + // thread CPU. The idea was that CPU per turn is fixed work, so + // starvation lowers turns-per-second and not the cost of a turn, + // which would separate a real spin from a loop that counts turns + // while sleeping through them. Measured, it does the opposite: a + // real turn costs 2.13-2.51 µs idle and 2.70-2.92 µs under + // eighteen competing busy loops, while a turn that sleeps 1 ms + // costs 13.3-15.8 µs — a blocking body's context switch is + // charged to this thread and costs it MORE CPU per turn than 256 + // adds do. A floor would not discriminate, and a threshold that + // does not discriminate reads as a guarantee while being none. + // + // So the honest scope of this test: it establishes that every + // tick's spin loop ran, and that each tick stopped for one of its + // two stated reasons. It does not establish that the loop body is + // CPU-bound rather than blocking. + eprintln!( + " tick {i}: {:?} of CPU over {} spins = {:?}/spin, in {wall:?} of wall time", + out.cpu, + out.spins, + out.cpu.checked_div(u32::try_from(out.spins).unwrap_or(u32::MAX).max(1)).unwrap_or_default() ); } assert!( own >= recorded, - "the probe recorded {recorded:?} of tick CPU, but this thread's CPU clock advanced only {own:?} \ - over the whole probe" + "the probe recorded {recorded:?} of tick CPU, but this thread's CPU clock advanced only \ + {own:?} over the whole probe" ); } @@ -4004,10 +4130,10 @@ mod linux_rapl { /// when every package counter reads, and is then sampled by /// [`rail_liveness::probe_counter`], with `tick` between samples, by the /// clock `now`: live only when every package counter keeps advancing. - pub(crate) fn status_with( + pub(crate) fn status_with( packages: &[Package], read: impl Fn() -> Option>, - tick: impl FnMut(), + tick: impl FnMut() -> T, now: impl Fn() -> Duration, ) -> CounterStatus { if packages.is_empty() { @@ -4036,7 +4162,7 @@ mod linux_rapl { /// One probe of the package zones under `root`: list them /// ([`packages_under`]), then probe all of their counters together /// ([`status_with`]). - pub(crate) fn probe_root(root: &Path, tick: impl FnMut(), now: impl Fn() -> Duration) -> Host { + pub(crate) fn probe_root(root: &Path, tick: impl FnMut() -> T, now: impl Fn() -> Duration) -> Host { let packages = packages_under(root); let status = status_with(&packages, || read_packages(root, &packages), tick, now); Host { packages, status } @@ -4609,9 +4735,9 @@ mod macos_process_energy { /// counter reads at all, and is then sampled by /// [`rail_liveness::probe_counter`], with `tick` between samples, by the /// clock `now`. - pub(crate) fn status_with( + pub(crate) fn status_with( read: impl Fn() -> Option, - tick: impl FnMut(), + tick: impl FnMut() -> T, now: impl Fn() -> std::time::Duration, ) -> CounterStatus { rail_liveness::counter_status( diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs index cfaf9cbb8..2a4da3eba 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs @@ -122,9 +122,37 @@ fn the_process_counter_meters_this_process_and_nothing_else() { "process-cpu: child burned {:.3} J in 300 ms; this process's window = {parent:?} µJ", child_burned_nj as f64 / 1e9 ); - assert!(child_burned_nj >= 200_000_000, "the child did not burn: {child_burned_nj} nJ"); + // The claim under test is *attribution*, so that is what is asserted: the + // child's burn against this process's window, not the child's burn against + // an absolute figure. + // + // The absolute floor was 0.2 J, and it made this test fail under host load — + // the child is an ordinary-priority shell loop competing for a core, so a + // busy host starves it below the line (seen on the dev Mac at load average + // 149: 0.147 J, and the test is also the macOS CI runner). How much work a + // competing process gets done in a 300 ms wall window is the host's + // scheduler talking, not this counter. The floor stays only to keep the + // check from being vacuous if the child never ran at all, an order of + // magnitude below anything a starved child has shown. + assert!( + child_burned_nj >= 20_000_000, + "the child did not burn at all: {child_burned_nj} nJ" + ); match parent { - Ok(uj) => assert!(uj < 100_000, "{uj} µJ in this process while only the child worked"), + Ok(uj) => { + // The real assertion, and a far wider margin than the old pair gave: + // 0.2 J against 0.1 J was a factor of two, while attribution either + // holds by orders of magnitude or does not hold. Observed in the + // starved run above: 147 032 342 nJ in the child against 137 000 nJ + // here — a factor of about 1 070. + let parent_nj = u128::from(uj) * 1_000; + assert!( + parent_nj * 10 < u128::from(child_burned_nj), + "this process's window is {uj} µJ ({parent_nj} nJ) against the child's \ + {child_burned_nj} nJ: the child's work is being attributed here" + ); + assert!(uj < 100_000, "{uj} µJ in this process while only the child worked"); + } Err(EnergyError::NotAdvanced) => {} Err(e) => panic!("the parent window failed: {e}"), } -- 2.54.0 (Apple Git-157) From de33f5b56ba9424cce5e664e5f9b81e9525ae315 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 09:44:49 -0400 Subject: [PATCH 2/3] energy tests: the same load-sensitive tick floor in proof-cascade and sandbox-meter MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first commit fixed two tests. CI then failed #177 on a *third* copy of the same code, in `proof-cascade`, with the same assertion and nearly the same comment beside it: c >= TICK_CPU / 2, "... The tick burns thread CPU time, so host load does not shorten it; only its {TICK_WALL:?} wall-clock cap can ..." The sentence contains its own refutation: the wall cap is exactly how load shortens a tick. Rather than wait for CI to find the rest one PR at a time, I swept for the pattern and found a fourth copy in `sandbox-meter`. All four are now fixed the same way. **proof-cascade.** `spin_tick` returns a `TickOutcome` (CPU seen burned, turns of the spin loop) and the probe collects one per tick; `ProbeRun` gains `interval_wall` beside `interval_burn`. Three assertions were load-sensitive — `assert_sampling`'s per-interval floor, an aggregate floor over a whole scripted call, and a per-interval floor in the live-rail test — and all three now require that each tick's loop ran, plus that each interval reached the tick of CPU or spent the wall cap. `burn_thread_cpu` also now reports the CPU it measured rather than discarding it, which it was computing anyway. **sandbox-meter.** Same shape: `spin_for` returns a `TickOutcome`, the probe records `interval_wall` and the per-tick outcomes, and the one load-sensitive assertion (`PROBE_TICK / 2` per interval) becomes the spin-count rule plus the either-condition bound. This crate already had `assert_tick` using the either-condition rule for the tick itself, so the fix brings the interval check in line with the crate's own convention — and strengthens both, since the OR rule alone admits a tick that slept through its wall cap. `TickOutcome` becomes part of `sandbox-meter`'s public surface, because it already appears in one: `RaplPackages::live_in` and `counter_liveness` take a tick that returns it, so `sandbox-exec-microvm` has to be able to name it and build one. Its four fake-tree call sites now report a turn, with a comment saying why that is honest rather than a figure chosen to clear a threshold. Three doc comments that asserted "a tick burns a full tick however loaded the machine is" are corrected in place. That claim is what the CI failures falsified, and leaving it next to a fixed assertion would just reintroduce the mistake. Falsified in both crates: a tick that sleeps instead of spinning, and a tick skipped entirely, are caught. One sleep falsification initially looked like a pass and was a compile error — checked, not assumed. In proof-cascade a tick cut short of both stopping conditions is caught too. Whole workspaces: proof-rs 139 passed, sandbox-rs 324 passed (and from the first commit, eoc-rs 717, jouleclaw-energy 57). The two clippy warnings in proof-cascade are in untouched code — the same pair that predates the change in eoc-meter, these files being copies of one another. Co-Authored-By: Claude Opus 5 --- .../crates/proof-cascade/src/meter.rs | 182 ++++++++++++++---- .../crates/sandbox-exec-microvm/src/power.rs | 19 +- .../sandbox-meter/src/probe/ioreport.rs | 52 +++-- .../sandbox-meter/src/probe/liveness.rs | 80 ++++++-- .../crates/sandbox-meter/src/probe/mod.rs | 21 +- .../crates/sandbox-meter/src/probe/rapl.rs | 16 +- 6 files changed, 290 insertions(+), 80 deletions(-) diff --git a/proof/proof-rs/crates/proof-cascade/src/meter.rs b/proof/proof-rs/crates/proof-cascade/src/meter.rs index 0419aa834..822bb74de 100644 --- a/proof/proof-rs/crates/proof-cascade/src/meter.rs +++ b/proof/proof-rs/crates/proof-cascade/src/meter.rs @@ -538,7 +538,7 @@ const RAPL_LIVENESS_BUDGET: std::time::Duration = std::time::Duration::from_mill #[cfg_attr(not(target_os = "linux"), allow(dead_code))] fn rapl_probe_with( zones: impl Fn() -> Vec, - tick: impl FnMut(), + tick: impl FnMut() -> probe_clock::TickOutcome, wall: impl Fn() -> std::time::Duration, cpu: impl Fn() -> Option, budget: std::time::Duration, @@ -701,7 +701,7 @@ fn process_read(nj: u64) -> liveness::Read { #[cfg_attr(not(target_os = "macos"), allow(dead_code))] fn process_probe_with( counter: impl Fn() -> Option, - tick: impl FnMut(), + tick: impl FnMut() -> probe_clock::TickOutcome, wall: impl Fn() -> std::time::Duration, cpu: impl Fn() -> Option, budget: std::time::Duration, @@ -1195,6 +1195,8 @@ mod liveness { pub(super) opened: bool, /// How many times the probe ticked (burned CPU before a re-read). pub(super) ticks: u32, + /// What each of those ticks did, in order. `ticks` is its length. + pub(super) tick_outcomes: Vec, /// Every read, in order, the baseline included. pub(super) calls: Vec, /// What each successful read handed the rule, in order: one per @@ -1224,6 +1226,23 @@ mod liveness { out } + /// The wall time each interval between two consecutive successful reads + /// spanned, outside the reads themselves. The companion to + /// [`ProbeRun::interval_cpu`]: a tick stops on the CPU target OR the + /// wall cap, so the CPU figure alone cannot say whether a short tick was + /// starved into the cap or stopped early. + pub(super) fn interval_wall(&self) -> Vec { + let mut out = Vec::new(); + let mut prev_end: Option = None; + for c in self.calls.iter().filter(|c| c.listed.is_some()) { + if let Some(end) = prev_end { + out.push(c.start.saturating_sub(end)); + } + prev_end = Some(c.end); + } + out + } + /// The median thread CPU time one read took (the upper one of an even /// count), over the reads whose CPU clock could be read; `None` if /// there are none. @@ -1260,7 +1279,7 @@ mod liveness { pub(super) fn probe_with( open: impl FnOnce() -> Option, read: impl FnMut(&S) -> Option, - tick: impl FnMut(), + tick: impl FnMut() -> crate::meter::probe_clock::TickOutcome, wall: impl Fn() -> Duration, cpu: impl Fn() -> Option, budget: Duration, @@ -1274,7 +1293,7 @@ mod liveness { watched: Watched, open: impl FnOnce() -> Option, mut read: impl FnMut(&S) -> Option, - mut tick: impl FnMut(), + mut tick: impl FnMut() -> crate::meter::probe_clock::TickOutcome, wall: impl Fn() -> Duration, cpu: impl Fn() -> Option, budget: Duration, @@ -1297,7 +1316,7 @@ mod liveness { if !watch.wants_more(wall().saturating_sub(started), budget) { break; } - tick(); + run.tick_outcomes.push(tick()); run.ticks += 1; } run.verdict = watch.verdict(); @@ -1449,7 +1468,10 @@ mod liveness { calls.set(n + 1); script(n).map(|s| read_of(&s)) }, - || clock.set(clock.get() + tick), + || { + clock.set(clock.get() + tick); + crate::meter::probe_clock::TickOutcome { cpu: None, spins: 1 } + }, || clock.get(), || None, BUDGET, @@ -2092,6 +2114,7 @@ mod liveness { || { clock.set(clock.get() + TICK); cpu.set(cpu.get() + TICK); + crate::meter::probe_clock::TickOutcome { cpu: Some(TICK), spins: 1 } }, || clock.get(), || Some(cpu.get()), @@ -2343,28 +2366,59 @@ mod probe_clock { /// spins [`PROBE_TICK`] of wall time. The burn cannot manufacture `Live` /// — only a counter's own raw integer that keeps advancing can — so a /// short burn errs only toward declining, the safe side. - pub(super) fn spin_tick() { - burn_thread_cpu(PROBE_TICK, TICK_WALL_CAP); + pub(super) fn spin_tick() -> TickOutcome { + burn_thread_cpu(PROBE_TICK, TICK_WALL_CAP) } - fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { + /// What one tick did. + /// + /// `spins` is why this type exists. A tick stops on either of two + /// conditions — the CPU target or the wall cap — and from the outside the + /// two outcomes that matter are not separable by time: a spin the host + /// starved into the cap and a tick that simply *slept* both show a long wall + /// span against little CPU. Nor does CPU-per-turn separate them, measured: + /// a turn that blocks costs the thread MORE CPU than a turn of arithmetic, + /// because its context switch is charged to the thread. The only honest + /// separator is whether the loop ran at all, and only the loop can report + /// that. + #[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] + pub(super) struct TickOutcome { + /// The thread CPU the tick saw itself burn, where the clock is readable. + pub(super) cpu: Option, + /// Turns of the spin loop. Zero means the tick never span. + pub(super) spins: u64, + } + + fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) -> TickOutcome { let wall = Instant::now(); let mut acc: u64 = 0; + let mut spins: u64 = 0; let Some(start) = thread_cpu_time() else { while wall.elapsed() < cpu { + spins += 1; acc = std::hint::black_box(acc.wrapping_add(1)); } - return; + std::hint::black_box(acc); + return TickOutcome { cpu: None, spins }; }; + let mut used = Duration::ZERO; while wall.elapsed() < wall_cap { + spins += 1; for _ in 0..4096 { acc = std::hint::black_box(acc.wrapping_add(1)); } match thread_cpu_time() { - Some(now) if now.saturating_sub(start) < cpu => {} - _ => break, + Some(now) => { + used = now.saturating_sub(start); + if used >= cpu { + break; + } + } + None => break, } } + std::hint::black_box(acc); + TickOutcome { cpu: Some(used), spins } } } @@ -3682,10 +3736,13 @@ mod macos_ioreport { /// read listed the Energy Model group alone — every channel in that /// group, as many as the group has, far fewer than every channel — and /// the median thread CPU of its reads stays under 50 ms. R2: every - /// interval burned at least `PROBE_TICK / 2` of the probing thread's - /// CPU between reads. No wall-clock bound or ratio: another process - /// sampling IOReport makes this probe wait, never changes what it - /// listed or what it burned. Returns the structural line to log. + /// tick's spin loop ran, and every interval either reached the tick of + /// CPU or spent the wall cap. It is not a CPU floor: a tick stops on + /// either condition, so a floor bounds the host's scheduler rather than + /// the probe. The reads themselves carry no wall-clock bound either — + /// another process sampling IOReport makes this probe wait, never + /// changes what it listed or what it burned. Returns the structural + /// line to log. fn assert_sampling(run: &ProbeRun, who: &str, group: &Group) -> String { if !run.opened { assert_eq!(run.verdict, None, "{who}: no Energy Model subscription, yet a verdict"); @@ -3721,17 +3778,41 @@ mod macos_ioreport { run.calls.len() ); let cpu = run.interval_cpu(); + let wall = run.interval_wall(); assert_eq!(cpu.len(), run.intervals as usize, "{who}: one CPU figure per interval"); - for (i, c) in cpu.iter().enumerate() { + assert_eq!(wall.len(), cpu.len(), "{who}: one wall figure per interval"); + assert_eq!( + run.tick_outcomes.len(), + run.ticks as usize, + "{who}: every tick reported an outcome" + ); + // The claim is that the probe burns CPU before each re-read, and a + // CPU floor cannot check it. A tick stops on the CPU target OR the + // {TICK_WALL:?} wall cap, so a host that gives this thread a sliver + // of a core caps the tick with little CPU to show — this assertion + // used to require half of {TICK_CPU:?} and failed on the macOS + // runner that way, under other work on the same machine. Nor does + // CPU-per-turn separate a starved spin from a tick that slept: + // measured, a blocking turn costs the thread MORE CPU than an + // arithmetic one, because its context switch is charged here. So the + // tick reports whether its loop ran at all, which no load can forge. + for (i, out) in run.tick_outcomes.iter().enumerate() { + assert!( + out.spins > 0, + "{who}: tick {i} of {} reported {} turns of its spin loop: the probe is not burning CPU \ + before each re-read, it waited or skipped (outcome {out:?})", + run.ticks, + out.spins + ); + } + for (i, (c, w)) in cpu.iter().zip(&wall).enumerate() { let c = c.unwrap_or_else(|| panic!("{who}: interval {i}: this thread's CPU clock could not be read")); assert!( - c >= TICK_CPU / 2, - "{who}: interval {i} of {} consumed {c:?} of the probing thread's CPU time between reads, under \ - {:?}: the probe is not burning CPU before each re-read. The tick burns thread CPU time, so host \ - load does not shorten it; only its {TICK_WALL:?} wall-clock cap can, which takes this thread \ - being starved of the CPU for that long", - run.intervals, - TICK_CPU / 2 + c >= TICK_CPU || *w + Duration::from_millis(1) >= TICK_WALL, + "{who}: interval {i} of {} consumed {c:?} of the probing thread's CPU time between reads in \ + {w:?} of wall time: short of the {TICK_CPU:?} tick, and short of the {TICK_WALL:?} wall cap, \ + so neither stopping condition had been met", + run.intervals ); } format!( @@ -4285,11 +4366,11 @@ mod macos_ioreport { /// The REAL production composition, `host_status()`, run on this thread /// with every channel read scripted — read `n` lists `script(n)` — and /// the real tick and clocks. Anything between the raw channel read and - /// the rule runs as in production. Checks, on the tests' own thread CPU - /// clock, that the run's real ticks burned this thread's CPU: at least - /// `TICK_CPU / 2` per tick over the whole call, the bound - /// [`assert_sampling`] puts on each interval through the production - /// clock. + /// the rule runs as in production. Checks that every one of the run's + /// real ticks actually span, which is what "burned CPU" means here and + /// the only form of it a loaded host cannot forge — see + /// [`assert_sampling`] for why a CPU floor, aggregate or per interval, + /// bounds the scheduler rather than the probe. fn host_status_scripted(script: fn(u32) -> Vec<(&'static str, i64)>) -> HostStatus { let mut n = 0u32; let next = move || { @@ -4301,13 +4382,20 @@ mod macos_ioreport { let hs = seam::with(seam::Mode::Script(Box::new(next)), host_status); let burned = test_thread_cpu() - c0; assert!(hs.run.ticks > 0, "a scripted run that never ticked: {:?}", hs.run); - assert!( - burned >= TICK_CPU / 2 * hs.run.ticks, - "host_status() ticked {} times, yet this thread burned only {burned:?} of CPU (tests' clock) in the \ - whole call: under {:?} a tick", - hs.run.ticks, - TICK_CPU / 2 - ); + // Per tick, that its spin loop ran — not an aggregate CPU floor. + // A floor of half a tick per tick is a bound on what the host's + // scheduler allowed, not on what the probe did: every tick can hit + // its wall cap on a loaded box and the total falls under the line + // while the probe behaved correctly. + for (i, out) in hs.run.tick_outcomes.iter().enumerate() { + assert!( + out.spins > 0, + "host_status() tick {i} of {} reported {} turns of its spin loop: it did not burn CPU \ + (outcome {out:?}, this thread burned {burned:?} over the whole call)", + hs.run.ticks, + out.spins + ); + } hs } @@ -4468,8 +4556,16 @@ mod macos_ioreport { assert_eq!((run.calls.len(), run.ticks as usize), (run.intervals as usize + 1, run.intervals as usize)); assert_verdict_matches_record(run, "scripted sustained advance"); assert_handed_the_script(run, advancing); + // Covered per tick by `assert_sampling` above; here only that every + // interval's CPU was readable at all. The old `>= TICK_CPU / 2` was + // a bound on the host's scheduler, not on the probe. let cpu = run.interval_cpu(); - assert!(cpu.iter().all(|c| c.is_some_and(|c| c >= TICK_CPU / 2)), "the real tick did not burn: {cpu:?}"); + assert!(cpu.iter().all(Option::is_some), "an interval's thread CPU clock could not be read: {cpu:?}"); + assert!( + run.tick_outcomes.iter().all(|t| t.spins > 0), + "a real tick did not spin: {:?}", + run.tick_outcomes + ); } /// `host_status()` on the two-step refresh observed on an M5 Max: the @@ -4855,6 +4951,10 @@ mod tests { ticks.set(ticks.get() + 1); clock.set(clock.get() + Duration::from_millis(25)); cpu.set(cpu.get() + Duration::from_millis(25)); + crate::meter::probe_clock::TickOutcome { + cpu: Some(Duration::from_millis(25)), + spins: 1, + } }, || clock.get(), || Some(cpu.get()), @@ -4953,6 +5053,10 @@ mod tests { ticks.set(ticks.get() + 1); clock.set(clock.get() + Duration::from_millis(25)); cpu.set(cpu.get() + Duration::from_millis(25)); + crate::meter::probe_clock::TickOutcome { + cpu: Some(Duration::from_millis(25)), + spins: 1, + } }, || clock.get(), || Some(cpu.get()), @@ -5141,6 +5245,10 @@ mod tests { ticks.set(ticks.get() + 1); clock.set(clock.get() + Duration::from_millis(25)); cpu.set(cpu.get() + Duration::from_millis(25)); + crate::meter::probe_clock::TickOutcome { + cpu: Some(Duration::from_millis(25)), + spins: 1, + } }, || clock.get(), || Some(cpu.get()), diff --git a/sandbox/sandbox-rs/crates/sandbox-exec-microvm/src/power.rs b/sandbox/sandbox-rs/crates/sandbox-exec-microvm/src/power.rs index 8ae1d28e7..186d31285 100644 --- a/sandbox/sandbox-rs/crates/sandbox-exec-microvm/src/power.rs +++ b/sandbox/sandbox-rs/crates/sandbox-exec-microvm/src/power.rs @@ -22,7 +22,7 @@ //! run. A meter that did not open, or whose count broke, samples `None`, and //! the executor estimates. -use sandbox_meter::probe::{ProbeError, RaplPackages}; +use sandbox_meter::probe::{ProbeError, RaplPackages, TickOutcome}; use std::path::Path; use std::sync::Mutex; @@ -66,7 +66,7 @@ impl RaplMeter { /// one proves live under the same rule, with `tick` driving the load /// between liveness samples. For a tree other than the host's sysfs: a /// test's fake tree. - pub fn live_in(root: &Path, tick: impl FnMut()) -> RaplMeter { + pub fn live_in(root: &Path, tick: impl FnMut() -> TickOutcome) -> RaplMeter { Self::opened(RaplPackages::live_in(root, tick)) } @@ -100,7 +100,7 @@ pub use msr::MsrRaplMeter; #[cfg(any(target_os = "linux", all(test, unix)))] mod msr { use super::PowerMeter; - use sandbox_meter::probe::{counter_liveness, CounterStatus}; + use sandbox_meter::probe::{counter_liveness, CounterStatus, TickOutcome}; use std::collections::BTreeMap; use std::os::unix::fs::FileExt; use std::path::{Path, PathBuf}; @@ -165,7 +165,7 @@ mod msr { /// and `dev/cpu`), only when every one proves live, with `tick` /// driving the load between liveness samples. For a tree other than /// the host's: a test's fake tree. Not cached. - pub fn live_in(root: &Path, tick: impl FnMut()) -> Result { + pub fn live_in(root: &Path, tick: impl FnMut() -> TickOutcome) -> Result { Self::given(root, status_over(root, tick)) } @@ -203,7 +203,7 @@ mod msr { /// The liveness run over the domains of the tree at `root`: never ticked /// if they do not open. - fn status_over(root: &Path, tick: impl FnMut()) -> CounterStatus { + fn status_over(root: &Path, tick: impl FnMut() -> TickOutcome) -> CounterStatus { counter_liveness(|| MsrDomains::open_in(root).ok().map(|d| move || d.raw_sample()), tick) } @@ -464,8 +464,13 @@ mod tests { /// The liveness tick the tests drive: a sleep, while a writer thread /// advances the counters. - fn sleep_tick() { + /// A scripted stand-in for the production burn: these trees are fakes and + /// the load that matters is the script's writes. It reports a turn, so the + /// probe's "did the tick run" rule is satisfied honestly rather than by a + /// figure that happens to clear a threshold. + fn sleep_tick() -> TickOutcome { std::thread::sleep(Duration::from_millis(25)); + TickOutcome { cpu: Duration::from_millis(25), spins: 1 } } /// A VMM whose "run" is a script over the fake tree. @@ -619,6 +624,7 @@ mod tests { let ticks = AtomicUsize::new(0); let meter = RaplMeter::live_in(&tree.root, || { ticks.fetch_add(1, SeqCst); + TickOutcome { cpu: Duration::ZERO, spins: 1 } }); let why = meter.unavailable().expect("opened").to_string(); assert!(why.contains("RAPL"), "{why}"); @@ -780,6 +786,7 @@ mod tests { let ticks = AtomicUsize::new(0); match msr::MsrRaplMeter::live_in(&tree.root, || { ticks.fetch_add(1, SeqCst); + TickOutcome { cpu: Duration::ZERO, spins: 1 } }) { Err(why) => assert!(why.contains(expect), "{expect}: {why}"), Ok(m) => panic!("{expect}: opened {:?}", m.domains()), diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/ioreport.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/ioreport.rs index faaff3b5e..e5d7ce670 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/ioreport.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/ioreport.rs @@ -183,9 +183,9 @@ fn thread_cpu() -> Duration { /// The real probe's tick: [`spin`] on this thread's CPU clock, capped on a /// monotonic one. -fn probe_tick() { +fn probe_tick() -> super::liveness::TickOutcome { let t = Instant::now(); - spin(thread_cpu, || t.elapsed()); + spin(thread_cpu, || t.elapsed()) } /// Convert a channel reading to microjoules by its unit label. @@ -585,9 +585,11 @@ mod tests { assert!(cpu <= wall + ms(1), "{which}: {cpu:?} of one thread's CPU in {wall:?} of wall time"); } - /// The probe's tick burns CPU on the calling thread; it does not sleep, - /// and it burns a full tick of this thread's CPU however loaded the - /// machine is. Five ticks, each measured on the tests' own clock. + /// The probe's tick burns CPU on the calling thread; it does not sleep. + /// Each tick reaches a full tick of this thread's CPU, or stops at its wall + /// cap — the second is what a host that starves this thread produces, and + /// claiming otherwise is what made the interval assertion below fail in CI. + /// Five ticks, each measured on the tests' own clock. #[test] fn the_probe_tick_burns_cpu_on_the_calling_thread() { for i in 0..5 { @@ -1415,16 +1417,44 @@ mod tests { run.interval_burn ); let least = run.interval_burn.iter().min().copied().unwrap_or_default(); + assert_eq!( + run.interval_wall.len(), + run.interval_burn.len(), + "one wall figure per interval: {:?}", + run.interval_wall + ); + assert_eq!(run.tick_outcomes.len(), run.ticks as usize, "every tick reported an outcome"); eprintln!( "ioreport probe burn: {intervals} intervals, the least thread CPU burned in one {least:?} (tick \ - {PROBE_TICK:?})" + {PROBE_TICK:?}, or a {TICK_WALL_CAP:?} wall cap); {} of {} ticks stopped under the tick", + run.tick_outcomes.iter().filter(|t| t.cpu < PROBE_TICK).count(), + run.ticks ); - for (i, burned) in run.interval_burn.iter().enumerate() { + // The claim is that the probe burns CPU between its samples, and a CPU + // floor cannot check it. A tick stops on the CPU target OR the + // {TICK_WALL_CAP:?} cap, so a host that gives this thread a sliver of a + // core caps the tick with little CPU to show — this assertion used to + // require half a tick and the comment beside it claimed load could not + // shorten a tick, which is what the wall cap does. Nor does + // CPU-per-turn separate a starved spin from a tick that slept: + // measured, a blocking turn costs the thread MORE CPU than an + // arithmetic one, its context switch being charged here. So the tick + // reports whether its loop ran, which no load can forge. + for (i, out) in run.tick_outcomes.iter().enumerate() { assert!( - *burned >= PROBE_TICK / 2, - "interval {i} of {intervals}: the probe burned {burned:?} of this thread's CPU between its samples, \ - under half its {PROBE_TICK:?} tick. A tick burns until this thread's CPU clock has advanced a full \ - tick, however loaded the machine is; only its {TICK_WALL_CAP:?} wall cap can cut it short" + out.spins > 0, + "tick {i} of {} reported {} turns of its spin loop: the probe is not burning CPU between its \ + samples, it waited or skipped (outcome {out:?})", + run.ticks, + out.spins + ); + } + for (i, (burned, wall)) in run.interval_burn.iter().zip(&run.interval_wall).enumerate() { + assert!( + *burned >= PROBE_TICK || *wall + ms(1) >= TICK_WALL_CAP, + "interval {i} of {intervals}: the probe burned {burned:?} of this thread's CPU between its samples \ + in {wall:?} of wall time: short of its {PROBE_TICK:?} tick, and short of the {TICK_WALL_CAP:?} \ + wall cap, so neither stopping condition had been met" ); } } diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/liveness.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/liveness.rs index 7dc4361ac..6f2bcdee2 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/liveness.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/liveness.rs @@ -345,9 +345,9 @@ pub(super) fn rail_advances<'a>(before: &[(String, i64)], after: &'a [(String, i /// A sample that could not be read is skipped, not fatal: the next one that /// can be read closes the interval, and a host whose samples never read runs /// to the cap and gets no verdict. -pub(super) fn watch( +pub(super) fn watch( mut sample: impl FnMut() -> Option, - mut tick: impl FnMut(), + mut tick: impl FnMut() -> T, now: impl Fn() -> Duration, budget: Duration, ) -> RailWatch { @@ -367,31 +367,54 @@ pub(super) fn watch( /// The probe's tick: burn CPU on the calling thread until its CPU clock `cpu` /// has advanced [`PROBE_TICK`], or [`TICK_WALL_CAP`] has passed on the wall -/// clock `wall`. Returns the CPU time `cpu` saw burned. +/// clock `wall`. Returns a [`TickOutcome`]. /// -/// The probe spins rather than sleeps, because a rail that advances only -/// under load must see load between the samples. It counts THIS thread's CPU -/// time, not wall time, so a loaded machine that takes CPU from the thread -/// makes the tick longer, never lighter: every interval carries a full tick -/// of burn. The clocks are passed in so the rule is tested with scripted -/// ones; the real probe passes this thread's CPU clock and a monotonic one. -pub(super) fn spin(cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration) -> Duration { +/// The probe spins rather than sleeps, because a rail that advances only under +/// load must see load between the samples. It counts THIS thread's CPU time, +/// not wall time, so a loaded machine that takes CPU from the thread makes the +/// tick longer rather than lighter — **up to the wall cap**, which is where that +/// stops being true: a thread given a sliver of a core hits the cap with little +/// CPU burned, and the interval then carries less than a full tick. That is why +/// the outcome reports its spin count and not only its CPU. The clocks are +/// passed in so the rule is tested with scripted ones; the real probe passes +/// this thread's CPU clock and a monotonic one. +pub(super) fn spin(cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration) -> TickOutcome { spin_for(PROBE_TICK, cpu, wall) } +/// What one tick did. +/// +/// `spins` is why this is a struct and not a `Duration`. A tick stops on +/// either of two conditions — the CPU target or [`TICK_WALL_CAP`] — and the two +/// outcomes that matter are not separable by time: a spin the host starved into +/// the cap and a tick that simply *slept* both show a long wall span against +/// little CPU. Nor does CPU-per-turn separate them, measured: a turn that +/// blocks costs the thread MORE CPU than a turn of arithmetic, because its +/// context switch is charged to the thread. The only honest separator is +/// whether the loop ran at all, and only the loop can report that. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] +pub struct TickOutcome { + /// The thread CPU the tick saw itself burn. + pub cpu: Duration, + /// Turns of the spin loop. Zero means the tick never span. + pub spins: u64, +} + /// [`spin`] for a tick of `tick` of this thread's CPU time, still capped at /// [`TICK_WALL_CAP`] of wall time. -pub(super) fn spin_for(tick: Duration, cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration) -> Duration { +pub(super) fn spin_for(tick: Duration, cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration) -> TickOutcome { let (cpu0, wall0) = (cpu(), wall()); let mut acc: u64 = 0; + let mut spins: u64 = 0; loop { + spins += 1; for _ in 0..1_000 { acc = acc.wrapping_mul(6364136223846793005).wrapping_add(1442695040888963407); } std::hint::black_box(acc); let burned = cpu().saturating_sub(cpu0); if burned >= tick || wall().saturating_sub(wall0) >= TICK_WALL_CAP { - return burned; + return TickOutcome { cpu: burned, spins }; } } } @@ -435,7 +458,7 @@ pub(super) fn admits(status: IoReportStatus) -> bool { /// gives no verdict. pub(super) fn counter_run( open: impl FnOnce() -> Option, - tick: impl FnMut(), + tick: impl FnMut() -> TickOutcome, now: impl Fn() -> Duration, budget: Duration, ) -> RailWatch @@ -575,9 +598,9 @@ pub(super) fn thread_cpu() -> Duration { /// A counter probe's real tick: [`spin_for`] `tick` of this thread's CPU /// time, capped on a monotonic clock. #[cfg(any(target_os = "macos", target_os = "linux"))] -pub(super) fn counter_tick(tick: Duration) { +pub(super) fn counter_tick(tick: Duration) -> TickOutcome { let t = std::time::Instant::now(); - spin_for(tick, thread_cpu, || t.elapsed()); + spin_for(tick, thread_cpu, || t.elapsed()) } /// What one sample call of a probe run cost, and what the sample held. @@ -611,6 +634,12 @@ pub(super) struct ProbeRun { /// that were read), the CPU time the ticks burned in it, measured around /// the ticks, apart from the samples' own cost. pub(super) interval_burn: Vec, + /// The same intervals in wall time. A tick stops on the CPU target OR the + /// wall cap, so `interval_burn` alone cannot say whether a light interval + /// was starved into the cap or stopped early. + pub(super) interval_wall: Vec, + /// What each tick did, in order. `ticks` is its length. + pub(super) tick_outcomes: Vec, } impl ProbeRun { @@ -637,7 +666,7 @@ impl ProbeRun { /// apart from the samples. pub(super) fn probe_with( open: impl FnOnce() -> Option, - mut tick: impl FnMut(), + mut tick: impl FnMut() -> TickOutcome, cpu: impl Fn() -> Duration, wall: impl Fn() -> Duration, budget: Duration, @@ -649,9 +678,11 @@ where return ProbeRun::default(); }; let (calls, interval_burn) = (RefCell::new(Vec::new()), RefCell::new(Vec::new())); + let (interval_wall, tick_outcomes) = (RefCell::new(Vec::new()), RefCell::new(Vec::new())); // Tick CPU since the last sample that was read, how many samples were // read, and how many ticks ran. let (burn, reads, ticks) = (Cell::new(Duration::ZERO), Cell::new(0u32), Cell::new(0u32)); + let span = Cell::new(Duration::ZERO); let watch = watch( || { let (cpu0, started) = (cpu(), wall()); @@ -668,17 +699,20 @@ where if rails.is_some() { if reads.get() > 0 { interval_burn.borrow_mut().push(burn.get()); + interval_wall.borrow_mut().push(span.get()); } reads.set(reads.get() + 1); burn.set(Duration::ZERO); + span.set(Duration::ZERO); } rails }, || { - let before = cpu(); - tick(); + let (before, wall_before) = (cpu(), wall()); + tick_outcomes.borrow_mut().push(tick()); ticks.set(ticks.get() + 1); burn.set(burn.get() + cpu().saturating_sub(before)); + span.set(span.get() + wall().saturating_sub(wall_before)); }, &wall, budget, @@ -689,6 +723,8 @@ where calls: calls.into_inner(), ticks: ticks.get(), interval_burn: interval_burn.into_inner(), + interval_wall: interval_wall.into_inner(), + tick_outcomes: tick_outcomes.into_inner(), } } @@ -1262,6 +1298,7 @@ mod tests { wall.get() }, ); + let burned = burned.cpu; assert!(burned >= PROBE_TICK, "the tick stopped after {burned:?} of this thread's CPU"); assert!(burned < PROBE_TICK + ms(2), "the tick burned past {PROBE_TICK:?}: {burned:?}"); assert!(wall.get() >= ms(70) && wall.get() < TICK_WALL_CAP, "wall {:?}", wall.get()); @@ -1279,7 +1316,8 @@ mod tests { wall.get() }, ); - assert_eq!(burned, Duration::ZERO); + assert_eq!(burned.cpu, Duration::ZERO); + assert!(burned.spins > 0, "a tick that burned nothing still span: {burned:?}"); assert!(wall.get() >= TICK_WALL_CAP && wall.get() < TICK_WALL_CAP + ms(30), "wall {:?}", wall.get()); } @@ -1519,6 +1557,7 @@ mod tests { ticks.set(ticks.get() + 1); cpu.set(cpu.get() + tick); wall.set(wall.get() + tick); + TickOutcome { cpu: tick, spins: 1 } }, || cpu.get(), || wall.get(), @@ -1739,6 +1778,7 @@ mod tests { || { ticks.set(ticks.get() + 1); clock.set(clock.get() + tick); + TickOutcome { cpu: tick, spins: 1 } }, || clock.get(), BUDGET, @@ -1968,7 +2008,7 @@ mod tests { wall.get() }, ); - assert!(burned >= NVML_PROBE_TICK && burned < NVML_PROBE_TICK + ms(2), "{burned:?}"); + assert!(burned.cpu >= NVML_PROBE_TICK && burned.cpu < NVML_PROBE_TICK + ms(2), "{burned:?}"); } /// The gate as a constructor: a counter that is not live is never diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs index 1fad7e401..b943f7d58 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs @@ -60,6 +60,10 @@ mod process; // sysfs tree. mod rapl; pub use rapl::RaplPackages; +// Part of the public surface because it appears in one: `RaplPackages::live_in` +// and `counter_liveness` take a tick that returns it, so a caller outside this +// crate has to be able to name it and build one. +pub use liveness::TickOutcome; pub mod attribute; pub use attribute::{run_attributed, Attribution}; @@ -254,7 +258,10 @@ pub fn rapl_status() -> CounterStatus { /// held or stepped only in a burst; `Unavailable` if the counter did not open /// (never sampled or ticked), could not be read twice, or has no rail. The /// caller caches the status as it sees fit; nothing here is cached. -pub fn counter_liveness(open: impl FnOnce() -> Option, tick: impl FnMut()) -> CounterStatus +pub fn counter_liveness( + open: impl FnOnce() -> Option, + tick: impl FnMut() -> liveness::TickOutcome, +) -> CounterStatus where R: FnMut() -> Option>, { @@ -1060,7 +1067,12 @@ mod tests { /// open is `Unavailable` and never ticked. #[test] fn counter_liveness_holds_a_callers_counter_to_the_every_rail_rule() { - let tick = || std::thread::sleep(Duration::from_millis(25)); + // A scripted stand-in for the burn; it reports a turn so the rule that + // separates a spin from a wait is satisfied honestly. + let tick = || { + std::thread::sleep(Duration::from_millis(25)); + liveness::TickOutcome { cpu: Duration::from_millis(25), spins: 1 } + }; let n = std::cell::Cell::new(0i64); let both = || { n.set(n.get() + 1); @@ -1075,7 +1087,10 @@ mod tests { assert_eq!(counter_liveness(|| Some(one_held), tick), CounterStatus::Frozen); let ticks = std::cell::Cell::new(0); type Sampler = fn() -> Option>; - let none = counter_liveness(|| None::, || ticks.set(ticks.get() + 1)); + let none = counter_liveness(|| None::, || { + ticks.set(ticks.get() + 1); + liveness::TickOutcome { cpu: Duration::ZERO, spins: 1 } + }); assert_eq!((none, ticks.get()), (CounterStatus::Unavailable, 0)); } } diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/rapl.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/rapl.rs index e15a0dfaa..e7e3d68bf 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/rapl.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/rapl.rs @@ -102,7 +102,7 @@ fn real_run() -> RailWatch { /// given `tick` and a monotonic clock, for [`CPU_RAIL_LIVENESS_BUDGET`]. A /// tree that does not open (absent, unreadable, no package zone) is never /// ticked. -fn run_over(root: &Path, tick: impl FnMut()) -> RailWatch { +fn run_over(root: &Path, tick: impl FnMut() -> crate::probe::liveness::TickOutcome) -> RailWatch { let epoch = Instant::now(); counter_run( || RaplProbe::open_in(root).ok().map(|p| move || p.raw_sample()), @@ -243,7 +243,10 @@ impl RaplPackages { /// other than the host's sysfs: a test's fake tree. Not cached; the run /// takes about 300 ms over live counters and the whole /// [`CPU_RAIL_LIVENESS_BUDGET`] over a held one. - pub fn live_in(root: &Path, tick: impl FnMut()) -> Result { + pub fn live_in( + root: &Path, + tick: impl FnMut() -> crate::probe::liveness::TickOutcome, + ) -> Result { let status = counter_status_of(run_over(root, tick).verdict()); gated("RAPL", status, || RaplProbe::open_in(root)).map(|probe| RaplPackages { probe }) } @@ -561,6 +564,9 @@ mod tests { tree.write(dir, &uj.to_string()); } std::thread::sleep(Duration::from_millis(25)); + // A scripted tick: it stands in for the burn, and says so by + // reporting a turn. + crate::probe::liveness::TickOutcome { cpu: Duration::from_millis(25), spins: 1 } }); let status = counter_status_of(watch.verdict()); eprintln!("rapl run: zones {advancing:?} advancing, the rest holding -> {status:?}"); @@ -580,7 +586,10 @@ mod tests { ); let psys_only = FakePowercap::with_zones(&[("intel-rapl:0", Some("psys"), "90000", Some("262143328850"))]); let ticks = std::cell::Cell::new(0); - let watch = run_over(&psys_only.root, || ticks.set(ticks.get() + 1)); + let watch = run_over(&psys_only.root, || { + ticks.set(ticks.get() + 1); + crate::probe::liveness::TickOutcome { cpu: Duration::ZERO, spins: 1 } + }); assert_eq!((counter_status_of(watch.verdict()), ticks.get()), (CounterStatus::Unavailable, 0)); } @@ -686,6 +695,7 @@ mod tests { tree.write(dir, &uj.to_string()); } std::thread::sleep(Duration::from_millis(25)); + crate::probe::liveness::TickOutcome { cpu: Duration::from_millis(25), spins: 1 } }) } let tree = two_sockets_with_psys_and_dram(); -- 2.54.0 (Apple Git-157) From 6a20eb2675f9d14645d4d02a6f4c0f8c7feb632c Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 09:54:19 -0400 Subject: [PATCH 3/3] energy tests: the Linux-gated call sites a macOS run cannot see MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI's jetson-hub job failed to compile `sandbox-meter`'s `tests/rapl_hardware.rs`, which is `#![cfg(target_os = "linux")]` — invisible to every run I had done. Two sites, found by compiling the Linux paths rather than by waiting for another CI round: - `tests/rapl_hardware.rs` hands `RaplPackages::live_in` a tick built on the test's own `oracle::burn`. It now returns a `TickOutcome` carrying the CPU the oracle measured and a declared spin, with a comment saying that the spin count is this test's assertion that a real spin ran and not a reading taken from the probe — the oracle stays independent of what it checks. - `probe::counter_liveness_tick`, the public tick handed to `counter_liveness` for a real counter, is `cfg(any(macos, linux))` but reached on the Linux side through `MsrRaplMeter::host`. It now returns the outcome `counter_tick` already produces. `cargo check --target aarch64-unknown-linux-gnu --all-targets` compiles the gated code and found the second one; it is a weak oracle (it does not run anything) but it is exactly the right shape for this class of error, which is a type mismatch in code the host platform never compiles. `CARGO_FEATURE_NO_NEON=1` is needed because blake3's build script otherwise wants Linux C headers. `sandbox-meter`, `sandbox-exec-microvm`, `proof-cascade`, `eoc-meter` and `jouleclaw-energy` all check clean for that target. The whole sandbox workspace cannot: `zstd-sys` needs a real cross compiler. Instead I checked directly that nothing outside those crates references the changed entry points (`counter_liveness`, `counter_liveness_tick`, the three `live_in`s, or `TickOutcome`), so the per-crate checks cover every caller. macOS unchanged: sandbox-meter 124 + 19 passed. Co-Authored-By: Claude Opus 5 --- sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs | 4 ++-- .../crates/sandbox-meter/tests/rapl_hardware.rs | 8 ++++++-- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs index b943f7d58..c21c7f2f5 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs @@ -275,8 +275,8 @@ where /// 25 ms of the calling thread's CPU time, capped at 500 ms of wall time — /// the `tick` to hand [`counter_liveness`] for a real counter. #[cfg(any(target_os = "macos", target_os = "linux"))] -pub fn counter_liveness_tick() { - liveness::counter_tick(liveness::PROBE_TICK); +pub fn counter_liveness_tick() -> TickOutcome { + liveness::counter_tick(liveness::PROBE_TICK) } /// This host's NVML status, probed once per process and cached. diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/tests/rapl_hardware.rs b/sandbox/sandbox-rs/crates/sandbox-meter/tests/rapl_hardware.rs index ed81a215a..9adfc5f01 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/tests/rapl_hardware.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/tests/rapl_hardware.rs @@ -20,7 +20,7 @@ use std::path::Path; use std::sync::{Mutex, MutexGuard}; use std::time::{Duration, Instant}; -use sandbox_meter::probe::{rapl_status, CounterStatus, PowerMeter, RaplPackages}; +use sandbox_meter::probe::{rapl_status, CounterStatus, PowerMeter, RaplPackages, TickOutcome}; use sandbox_meter::Provenance; use sandbox_schema::DeviceClass; @@ -484,7 +484,11 @@ fn the_ci_containers_masked_view_is_unavailable() { let view = oracle::MaskedView::of_host("sandbox-meter"); let watch = oracle::watch(&view.0); let opened = RaplPackages::live_in(&view.0, || { - oracle::burn(Duration::from_millis(25), Duration::from_millis(500)); + // The oracle's own burn, independent of the probe's. The spin count is + // this test's declaration that a real spin ran, not a reading taken + // from the probe — the oracle stays independent of what it checks. + let cpu = oracle::burn(Duration::from_millis(25), Duration::from_millis(500)); + TickOutcome { cpu, spins: 1 } }); eprintln!("rapl masked view: oracle {}; probe {:?}", watch.summary(), opened.as_ref().map(|p| p.zones().len()).map_err(|e| e.to_string())); assert!(matches!(watch.verdict, Verdict::Unreadable | Verdict::NoPackage), "{watch:?}"); -- 2.54.0 (Apple Git-157)