From f1b662078b550000b3ffaf514d72df083e08c8f4 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 10:03:30 -0400 Subject: [PATCH] energy tests: the 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 #166 fixed this class of defect in `eoc-meter` and `jouleclaw-energy`: an energy-probe test asserting a floor on thread CPU per tick, which the host's scheduler controls, failing on the dev Mac because the dev Mac is also the macOS runner. The same code exists in two more crates, and the same assertion with it. CI surfaced `proof-cascade` by failing an unrelated PR; sweeping for the pattern found `sandbox-meter` as well, rather than waiting for another round. A tick spins until the thread's CPU clock advances 25 ms **or** a 500 ms wall cap passes. Both copies carried a comment asserting the opposite — "the tick burns thread CPU time, so host load does not shorten it; only its wall-clock cap can" — a sentence containing its own refutation, since the cap is how load shortens a tick. 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 tried a per-turn CPU floor first, reasoning that a turn is fixed work so starvation lowers turns-per-second rather than the cost of a turn. Measuring refuted it: 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 was wrong. So each tick reports what it did. `spin_tick` / `spin_for` return a `TickOutcome` — the CPU it saw itself burn, and how many turns of the spin loop it ran — and each probe collects one per tick, alongside the interval's wall span beside its CPU span. Per tick: the loop ran at all (a tick that never span did not burn CPU, at any load), and the tick 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. - **proof-cascade**: three load-sensitive sites — `assert_sampling`'s per-interval floor, an aggregate floor over a whole scripted call, and a per-interval floor in the live-rail test. `ProbeRun` gains `interval_wall` and the per-tick outcomes; `burn_thread_cpu` reports the CPU it was already computing. - **sandbox-meter**: the per-interval `PROBE_TICK / 2` floor. This crate already had `assert_tick` using the either-condition rule for the tick itself, so the interval check now matches the crate's own convention — and both are stronger for the spin count, since that rule alone admits a tick that slept through its cap. `TickOutcome` becomes public because it already appears in a public signature: `RaplPackages::live_in` and `counter_liveness` take a tick that returns it, so `sandbox-exec-microvm` has to name it and build one. Where a scripted tick stands in for the burn — fake powercap trees, the MSR fakes, the hardware test's own oracle — it reports a turn, with a comment saying that this is the test declaring a real spin ran and not a figure chosen to clear a threshold. The hardware test's tick keeps using `oracle::burn`, so the oracle stays independent of what it checks. Three doc comments asserting "a tick burns a full tick however loaded the machine is" are corrected in place; leaving that beside a fixed assertion would reinvite the mistake. Two call sites are `cfg(target_os = "linux")` and invisible to every run on this host: `sandbox-meter/tests/rapl_hardware.rs`, which CI's jetson-hub job caught, and `probe::counter_liveness_tick`, reached on the Linux side through `MsrRaplMeter::host`, which `cargo check --target aarch64-unknown-linux-gnu --all-targets` caught. That check is a weak oracle — it runs nothing — but it is the right shape for a type mismatch in code the host never compiles. `CARGO_FEATURE_NO_NEON=1` is needed, or blake3's build script wants Linux C headers. The whole sandbox workspace cannot cross-check (`zstd-sys` needs a real cross compiler), so instead I confirmed that nothing outside these crates references the changed entry points, which makes the per-crate checks exhaustive for callers. Falsified in both crates: a tick that sleeps instead of spinning, and a tick skipped entirely. One sleep falsification first 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. Verified: proof-rs 139 passed, sandbox-rs 324 passed, and the five touched crates check clean for aarch64-unknown-linux-gnu. The two clippy warnings in proof-cascade are in untouched code, the same pair that predates the change in eoc-meter — these files are copies of one another, which is why the defect was in four places. 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 | 25 ++- .../crates/sandbox-meter/src/probe/rapl.rs | 16 +- .../sandbox-meter/tests/rapl_hardware.rs | 8 +- 7 files changed, 298 insertions(+), 84 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..c21c7f2f5 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>, { @@ -268,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. @@ -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(); 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)