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 {