From 35e4ea0cb7c0971c491cc5309700e085916d3588 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Mon, 5 Oct 2026 21:29:37 -0400 Subject: [PATCH] energy tests: hold under a host loaded past a hundred runnable threads MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two tests failed on the dev Mac, which is also the macOS CI runner, at load averages of 101-179. Neither failure was in the meters: - eoc-meter `the_probe_burns_its_tick_of_thread_cpu_between_samples`. A tick burned only 9.6 ms of the thread's CPU, under the 12.5 ms floor, because its 500 ms wall cap cut it short. The test's own message names that cap as the one thing allowed to shorten a tick, but the test could not tell it apart: ProbeRun recorded no tick's wall time. It now records each tick's wall time (`tick_walls`; recorded, never decided on). A tick that ran its whole wall cap is accepted as cut short, but only if it still spun, burning at least 1 ms of CPU. Any other tick must burn at least half its 25 ms, as before. - jouleclaw-energy `process_cpu`. The `/bin/sh` child, run for a fixed 300 ms, got 0.076 J of CPU against a 0.2 J sanity floor (load average 170). It failed 3 of 3 runs. The child now runs until its own counter reads 0.2 J (at least 300 ms, at most 5 s), as eoc-meter's equivalent test already does. The parent's window still spans the child's whole run. Both pass at a load average of 333. Both tick mutations are caught: a tick that sleeps through its wall cap ("ran its whole 504.6ms wall cap and burned only 87.375µs ... it waited, not spun"), and one that sleeps 25 ms. Co-Authored-By: Claude Opus 5.5 --- eoc/eoc-rs/crates/eoc-meter/src/lib.rs | 31 +++++++++++++++++-- .../jouleclaw-energy/tests/process_cpu.rs | 22 ++++++++++--- 2 files changed, 45 insertions(+), 8 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..513ac80d3 100644 --- a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs +++ b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs @@ -463,6 +463,10 @@ mod rail_liveness { pub(crate) opened: bool, /// Ticks run between samples. pub(crate) ticks: u32, + /// Each tick's wall time, in order. Recorded, never decided on: a test + /// reads it to tell a tick that its wall cap cut short, on a host that + /// gave the thread almost no CPU, from one that did not burn at all. + pub(crate) tick_walls: Vec, /// Every sample call, in order. pub(crate) calls: Vec, /// The rule, folded over every sample that was taken. @@ -493,9 +497,9 @@ 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_walls: Vec::new(), calls: Vec::new(), watch: RailWatch::default() }; }; - let (mut calls, mut ticks) = (Vec::new(), 0u32); + let (mut calls, mut ticks, mut tick_walls) = (Vec::new(), 0u32, Vec::new()); let watch = watch( || { let (cpu_before, started) = (thread_cpu(), wall()); @@ -512,12 +516,14 @@ mod rail_liveness { }, || { ticks += 1; + let at = wall(); tick(); + tick_walls.push(wall().saturating_sub(at)); }, &wall, budget, ); - ProbeRun { opened: true, ticks, calls, watch } + ProbeRun { opened: true, ticks, tick_walls, calls, watch } } /// The status a probe verdict gives this host. No verdict — no @@ -3142,7 +3148,26 @@ mod macos_ioreport { ); 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"); + assert_eq!(run.tick_walls.len(), ticks.len(), "every tick's wall time is recorded"); for (i, t) in ticks.iter().enumerate() { + // A tick may burn less only where its wall cap cut it short: a + // host loaded past a hundred runnable threads gave this thread + // under 2% of a core for 500 ms (9.6 ms of CPU, load average + // 101). A tick that stopped short of both its CPU and its wall + // time waited or skipped, and fails. + // A tick cut short still spun whenever it ran, so it burned + // some CPU. A tick that slept through its 500 ms burned next to + // none, and fails either way. + if run.tick_walls[i] >= crate::clocks::PROBE_TICK_WALL_CAP { + eprintln!("ioreport probe tick {i}: {t:?} of CPU, cut short by its {:?} wall cap", run.tick_walls[i]); + assert!( + *t >= TICK / 25, + "tick {i} ran its whole {:?} wall cap and burned only {t:?} of this thread's CPU: it waited, \ + not spun", + run.tick_walls[i] + ); + continue; + } assert!( *t >= TICK / 2, "tick {i} burned only {t:?} of this thread's CPU (every tick: {ticks:?}): the probe must burn \ 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..75f0d5ce0 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs @@ -102,7 +102,11 @@ fn the_process_counter_meters_this_process_and_nothing_else() { // 5. A child process's work is not attributed: a child burns CPU while this // process sleeps, and is killed and reaped inside the window. The child's - // own counter, read independently, shows the work happened. + // own counter, read independently, shows the work happened. The child + // runs until its own counter has read 0.2 J (at least 300 ms, at most + // 5 s), not for a fixed 300 ms: on a heavily loaded host a fixed 300 ms + // got the child too little CPU (0.076 J at a load average of 170), and + // the test failed on the host's load, not on the meter. let mut child = Command::new("/bin/sh") .args(["-c", "while :; do :; done"]) .stdout(Stdio::null()) @@ -111,16 +115,24 @@ fn the_process_counter_meters_this_process_and_nothing_else() { .expect("spawn a busy child"); let pid = child.id() as libc::pid_t; let child_before = energy_nj_of(pid); + let started = Instant::now(); let (child_burned_nj, parent) = counter.measure(|| { - std::thread::sleep(Duration::from_millis(300)); - let burned = energy_nj_of(pid) - child_before; + let mut burned = 0; + while started.elapsed() < Duration::from_secs(5) { + std::thread::sleep(Duration::from_millis(50)); + burned = energy_nj_of(pid) - child_before; + if burned >= 200_000_000 && started.elapsed() >= Duration::from_millis(300) { + break; + } + } child.kill().expect("kill the child"); child.wait().expect("reap the child"); burned }); println!( - "process-cpu: child burned {:.3} J in 300 ms; this process's window = {parent:?} µJ", - child_burned_nj as f64 / 1e9 + "process-cpu: child burned {:.3} J in {:?}; this process's window = {parent:?} µJ", + child_burned_nj as f64 / 1e9, + started.elapsed() ); assert!(child_burned_nj >= 200_000_000, "the child did not burn: {child_burned_nj} nJ"); match parent { -- 2.54.0 (Apple Git-157)