From eeaea3234ce8b287ea5bc7e3c08a53eebb62449f Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Tue, 6 Oct 2026 17:40:42 -0400 Subject: [PATCH 1/9] jcp-energy: compare two threads' energy within one span, not across two two_threads_burning_meter_more_than_one metered one thread's 200 ms of CPU in one span and two threads' in a second span, then required the second figure to be larger. The CPU work in each span is fixed by the threads' own CPU clocks, but its energy is not: it follows the core type and clock the scheduler gives each span. On the loaded macOS runner one thread read 0.92 J and two threads 0.59 J, and the check failed though the meter counted every thread. Both threads now burn in one span, and a per-thread oracle (the tests' own proc_pidinfo PROC_PIDTHREADCOUNTS read of each thread's energy count) reads each one's rise across its burn. The span's figure must be at least the two rises added up, and more than either one's alone. The figures compared cover the same work at the same time, so host load cannot move one against the other. The check is stronger than before: it bounds the figure by both threads' whole counts, not only by another span's figure. A meter that reads only the calling thread fails it. Test-only change; no production code changed. Co-Authored-By: Claude Opus 5.5 --- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 108 +++++++++++++++++++++--- 1 file changed, 94 insertions(+), 14 deletions(-) diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index 930183d30..167903ada 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -7250,6 +7250,14 @@ mod tests { buffer: *mut std::ffi::c_void, buffersize: std::os::raw::c_int, ) -> std::os::raw::c_int; + fn proc_pidinfo( + pid: std::os::raw::c_int, + flavor: std::os::raw::c_int, + arg: u64, + buffer: *mut std::ffi::c_void, + buffersize: std::os::raw::c_int, + ) -> std::os::raw::c_int; + fn pthread_threadid_np(thread: *mut std::ffi::c_void, thread_id: *mut u64) -> std::os::raw::c_int; } /// This thread's CPU time, by the tests' own clock. @@ -7309,6 +7317,56 @@ mod tests { }) } + /// `proc_pidinfo` flavor 34, `PROC_PIDTHREADCOUNTS` in the kernel's + /// `` (the SDK's copy of that header leaves it out): one + /// thread's counts, asked by its 64-bit thread id. The kernel writes a + /// `uint16_t` count of CPU performance levels and six bytes of padding, + /// then for each level five `uint64_t`: instructions, cycles, user time, + /// system time, and the thread's CPU energy in nJ. On the dev host: two + /// levels, 88 bytes. + #[cfg(target_os = "macos")] + const TESTS_PIDTHREADCOUNTS: std::os::raw::c_int = 34; + + /// The tests' own read of the calling thread's own CPU energy count, in + /// nJ, summed over the performance levels it ran on: the per-thread + /// oracle, through their own FFI declarations. The meter reads the whole + /// process's count by another call, and the kernel keeps that count as + /// its threads' counts added up, an exited thread's included. On the dev + /// host, under a load average near 100, a span in which one thread burned + /// rose by exactly that thread's own rise, and one in which two did, by + /// their sum and a little more (spawning and joining the second): never + /// less, in every span measured. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn oracle_this_thread_energy_nj() -> u64 { + const LEVELS: usize = 8; + let mut tid = 0u64; + let rc = unsafe { pthread_threadid_np(std::ptr::null_mut(), &mut tid) }; + assert_eq!(rc, 0, "the tests' pthread_threadid_np failed"); + let mut counts = [0u64; 1 + 5 * LEVELS]; + let bytes = std::mem::size_of_val(&counts) as std::os::raw::c_int; + let me = std::process::id() as std::os::raw::c_int; + let wrote = unsafe { proc_pidinfo(me, TESTS_PIDTHREADCOUNTS, tid, counts.as_mut_ptr().cast(), bytes) }; + let head = counts[0].to_ne_bytes(); + let levels = usize::from(u16::from_ne_bytes([head[0], head[1]])); + assert!( + (1..=LEVELS).contains(&levels) && usize::try_from(wrote) == Ok(8 + 40 * levels), + "the tests' per-thread counts: {wrote} bytes written for {levels} performance level(s)" + ); + (0..levels).map(|level| counts[1 + 5 * level + 4]).sum() + } + + /// [`burn_thread_cpu`], with the rise of this thread's own energy count + /// across the burn by the per-thread oracle, in nJ: the wall time the burn + /// took, and that rise. + #[cfg(target_os = "macos")] + fn burn_thread_cpu_counted(cpu: Duration) -> (Duration, u64) { + let before = oracle_this_thread_energy_nj(); + let wall = burn_thread_cpu(cpu); + let after = oracle_this_thread_energy_nj(); + (wall, after.checked_sub(before).expect("this thread's own energy count fell")) + } + /// The tests' own read of a process's reaped children's CPU time /// (`ri_child_user_time` + `ri_child_system_time`), through their own FFI /// declaration and the transcribed struct. @@ -7497,33 +7555,55 @@ mod tests { /// Two threads burning 200 ms of CPU each meter more than one: every /// thread of the process is in the count. Each thread's 200 ms are of its - /// own CPU clock (see [`burn_thread_cpu`]), so neither span's work depends - /// on how loaded the host is. + /// own CPU clock (see [`burn_thread_cpu`]). Both burn in one span, and the + /// tests' per-thread oracle reads each one's own count across its burn. + /// The span's figure must be at least the two counts added up, and so + /// more than either one's: what one thread burning that CPU would meter. + /// + /// The figures compared come from the same span, so whichever cores and + /// clocks a loaded host gives the threads, they count the same work. Two + /// spans one after the other do not: the CPU is the same in both, but its + /// energy follows the core type and clock each span ran on, and on a + /// loaded host one thread's 200 ms read 0.92 J and two threads' 0.59 J. + /// A meter that counts only the thread that calls it reads one thread + /// here, and fails. #[cfg(target_os = "macos")] #[test] fn two_threads_burning_meter_more_than_one() { in_a_fresh_process("tests::two_threads_burning_meter_more_than_one", || { let meter = process_meter(); let cpu = Duration::from_millis(200); - let (wall_one, one) = meter.measure(|| burn_thread_cpu(cpu)); - let (wall_two, two) = meter.measure(|| { + let (((wall_mine, mine_nj), (wall_other, other_nj)), two) = meter.measure(|| { std::thread::scope(|s| { - let other = s.spawn(|| burn_thread_cpu(cpu)); - let mine = burn_thread_cpu(cpu); - mine.max(other.join().expect("the second burning thread panicked")) + let other = s.spawn(|| burn_thread_cpu_counted(cpu)); + let mine = burn_thread_cpu_counted(cpu); + (mine, other.join().expect("the second burning thread panicked")) }) }); + let threads_nj = mine_nj + other_nj; eprintln!( - "process energy: 200 ms of CPU on 1 thread, in {wall_one:?} of wall time -> {} µJ ({:.3} J), on each \ - of 2 threads, in {wall_two:?} -> {} µJ ({:.3} J), ratio {:.2}", - one.uj(), - joules(one.uj()), + "process energy: 200 ms of CPU on each of 2 threads, in {wall_mine:?} and {wall_other:?} of wall \ + time -> {} µJ ({:.3} J); the threads' own counts rose {mine_nj} + {other_nj} nJ ({:.3} J), ratio \ + {:.3}", two.uj(), joules(two.uj()), - two.uj() as f64 / one.uj().max(1) as f64 + threads_nj as f64 / 1e9, + two.uj() as f64 * 1e3 / threads_nj.max(1) as f64 + ); + assert_eq!(two.provenance, Provenance::HwShunt, "{two:?}"); + assert!(mine_nj > 0 && other_nj > 0, "a burning thread's own count did not rise: {mine_nj} and {other_nj} nJ"); + let metered_nj = two.uj().saturating_mul(1_000); + assert!( + metered_nj > mine_nj.max(other_nj), + "two threads metered {} µJ, no more than one of them alone ({mine_nj} and {other_nj} nJ)", + two.uj() + ); + assert!( + metered_nj >= threads_nj, + "two threads metered {} µJ, under their own counts added up, {mine_nj} + {other_nj} = {threads_nj} nJ: \ + a thread of the process is not in the count", + two.uj() ); - assert_eq!((one.provenance, two.provenance), (Provenance::HwShunt, Provenance::HwShunt)); - assert!(two.uj() > one.uj(), "two threads metered {} µJ, one thread {} µJ", two.uj(), one.uj()); }); } -- 2.54.0 (Apple Git-157) From 85aab0239c45c2ad6500d78671208eed721cba1e Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Tue, 6 Oct 2026 17:40:42 -0400 Subject: [PATCH 2/9] jouleclaw-energy: end the child window on the child's energy, not 300 ms the_process_counter_meters_this_process_and_nothing_else let a busy child run for a fixed 300 ms of wall time and required its own counter to rise 0.2 J. How much CPU a child gets in 300 ms depends on host load: on the loaded macOS runner it spent 0.12 J and the test failed, though nothing about the counter under test was wrong. The window now lasts until the child's own count, read independently, has risen 0.2 J, and at least 300 ms. A loaded host stretches the window but always leaves 0.2 J of the child's work in it, twice the 0.1 J ceiling on what this process may meter meanwhile, so the child-exclusion check still has the same margin. A child that has not spent 0.2 J in 20 s fails the test: it did not work, or the host is too loaded to tell. Test-only change; no production code changed. Co-Authored-By: Claude Opus 5.5 --- .../jouleclaw-energy/tests/process_cpu.rs | 33 +++++++++++++++---- 1 file changed, 26 insertions(+), 7 deletions(-) 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..22f554147 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,16 @@ 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 window + // lasts until it has risen 0.2 J, twice the window's ceiling, and at + // least 300 ms. It ends on the child's work, not on wall time, so a + // loaded host that gives the child less of a core stretches the window + // but never leaves too little energy in it to tell (a fixed 300 ms read + // 0.12 J of the child's on a loaded host). A child that has not spent + // 0.2 J in 20 s fails the test: it did not work, or the host is too + // loaded to tell. + const CHILD_NJ: u64 = 200_000_000; + const CHILD_WALL_CAP: Duration = Duration::from_secs(20); let mut child = Command::new("/bin/sh") .args(["-c", "while :; do :; done"]) .stdout(Stdio::null()) @@ -111,18 +120,28 @@ 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 (child_burned_nj, parent) = counter.measure(|| { - std::thread::sleep(Duration::from_millis(300)); - let burned = energy_nj_of(pid) - child_before; + let ((child_burned_nj, ran), parent) = counter.measure(|| { + let started = Instant::now(); + let burned = loop { + std::thread::sleep(Duration::from_millis(10)); + let (burned, ran) = (energy_nj_of(pid) - child_before, started.elapsed()); + if (burned >= CHILD_NJ && ran >= Duration::from_millis(300)) || ran >= CHILD_WALL_CAP { + break (burned, ran); + } + }; 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 {:.0} ms; this process's window = {parent:?} µJ", + child_burned_nj as f64 / 1e9, + ran.as_secs_f64() * 1e3 + ); + assert!( + child_burned_nj >= CHILD_NJ, + "the child burned only {child_burned_nj} nJ in {ran:?}: it did not work, or the host is too loaded to tell" ); - assert!(child_burned_nj >= 200_000_000, "the child did not burn: {child_burned_nj} nJ"); match parent { Ok(uj) => assert!(uj < 100_000, "{uj} µJ in this process while only the child worked"), Err(EnergyError::NotAdvanced) => {} -- 2.54.0 (Apple Git-157) From 2641dead720a96764f1b3e532aefb98e8d1ad24f Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Tue, 6 Oct 2026 17:40:42 -0400 Subject: [PATCH 3/9] proof-cascade: the probe tick burns its whole 25 ms of thread CPU The liveness probe's tick burned 25 ms of the probing thread's CPU time but gave up after 500 ms of wall time. On a loaded host that runs the thread for under 5% of a core, the cap cut the tick short: on the macOS runner an interval held 12.4 ms of thread CPU, under the tests' 12.5 ms floor, and the host_status_calls_*_frozen tests failed. In production the same cap made the probe's work per interval, and so its verdict, depend on host load. Production change: the tick is bounded by thread CPU time only. It ends once the thread has burned the whole 25 ms, however much wall time that takes. Against a thread CPU clock that stops moving it ends after 10,000 spin rounds in a row without the clock moving, a count of the thread's own work rather than of wall time. An unreadable clock still falls back to 25 ms of wall time. Tests: R1 (each_tick_burns_the_probe_tick_of_thread_cpu_time) now requires 25 ms of thread CPU from every tick. Its escape clause for a tick that hit the wall cap is gone; that clause let a tick that only slept for 500 ms pass. The R2 floor is unchanged, and its message no longer cites the cap. Co-Authored-By: Claude Opus 5.5 --- .../crates/proof-cascade/src/meter.rs | 69 +++++++++++-------- 1 file changed, 40 insertions(+), 29 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..b3e547e04 100644 --- a/proof/proof-rs/crates/proof-cascade/src/meter.rs +++ b/proof/proof-rs/crates/proof-cascade/src/meter.rs @@ -325,8 +325,8 @@ pub enum IoReportStatus { } /// How long (wall time) the liveness probe watches the CPU energy rail before -/// concluding it is frozen. Before each re-sample the probe burns ~25 ms of -/// the calling thread's own CPU time (at most 500 ms of wall time per tick). +/// concluding it is frozen. Before each re-sample the probe burns 25 ms of +/// the calling thread's own CPU time (however much wall time that takes). /// It samples its own subscription to the Energy Model group alone — 364 /// channels on an M5 Max, 645 on an M3 Ultra, ~6–9 ms of thread CPU a sample, /// where a sample of every channel (~11,900 / ~14,300) costs ~85–125 ms — so on @@ -2314,9 +2314,13 @@ mod probe_clock { /// Thread CPU time a probe burns before each liveness re-sample. pub(super) const PROBE_TICK: Duration = Duration::from_millis(25); - /// The most wall time one tick may take to burn [`PROBE_TICK`] of CPU - /// time. Only a thread starved of the CPU for that long is cut short. - const TICK_WALL_CAP: Duration = Duration::from_millis(500); + /// Spin rounds in a row after which a thread CPU clock that has not moved + /// is taken to be stuck, and the tick ends. Each round is 4,096 dependent + /// additions: on the dev host 10,000 rounds are about 40 ms of this + /// thread's CPU optimised and 150 ms unoptimised, more than a tick, and + /// the clock moved in every round of 100,000 on a loaded host. A count of + /// the thread's own work, not of wall time, so host load cannot reach it. + const STUCK_CLOCK_ROUNDS: u32 = 10_000; /// Wall time since this process first asked: the probes' wall clock. One /// process-wide epoch, so a test can place its own reads on the same @@ -2337,31 +2341,41 @@ mod probe_clock { } /// One probe tick: burn [`PROBE_TICK`] of this thread's CPU time — CPU - /// time, not wall time, so a loaded host that runs this thread only part - /// of the time still gets the full burn — giving up after - /// [`TICK_WALL_CAP`] of wall time. Without a readable thread CPU clock it - /// 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. + /// time, not wall time, and with no wall-clock cap, so every tick is the + /// same work however loaded the host: one that runs this thread only part + /// of the time stretches the tick in wall time, never shortens its burn. + /// (A 500 ms wall cap here cut ticks short on a loaded host, to 12.4 ms of + /// thread CPU.) Without a readable thread CPU clock it spins + /// [`PROBE_TICK`] of wall time; with one that stops moving, or stops + /// reading, it ends early (see [`STUCK_CLOCK_ROUNDS`]). 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); + burn_thread_cpu(PROBE_TICK); } - fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { - let wall = Instant::now(); + fn burn_thread_cpu(cpu: Duration) { let mut acc: u64 = 0; let Some(start) = thread_cpu_time() else { + let wall = Instant::now(); while wall.elapsed() < cpu { acc = std::hint::black_box(acc.wrapping_add(1)); } return; }; - while wall.elapsed() < wall_cap { + let (mut last, mut unmoved) = (start, 0u32); + loop { 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 => {} + Some(now) if now.saturating_sub(start) >= cpu => break, + Some(now) if now != last => { + last = now; + unmoved = 0; + } + Some(_) if unmoved + 1 < STUCK_CLOCK_ROUNDS => unmoved += 1, _ => break, } } @@ -3189,12 +3203,11 @@ mod macos_ioreport { /// read wait, not burn. The test's own literal. const MAX_MEDIAN_READ_CPU: Duration = Duration::from_millis(50); - /// The probe's burn, as the tests see it: at least this much of the - /// probing thread's CPU in every interval, and per tick at least - /// [`TICK_CPU`] unless the tick ran into [`TICK_WALL`]. The tests' own - /// literals, not the implementation's constants. + /// The probe's burn, as the tests see it: at least [`TICK_CPU`] of the + /// probing thread's CPU per tick, however loaded the host, and at + /// least half of it in every interval. The tests' own literal, not the + /// implementation's constant. const TICK_CPU: Duration = Duration::from_millis(25); - const TICK_WALL: Duration = Duration::from_millis(500); /// Real, cheap, pure CPU work for the metering tests. fn cpu_work() { @@ -3308,8 +3321,8 @@ mod macos_ioreport { } /// R1, the tick, on the tests' own clock: each production tick - /// consumes at least 25 ms of this thread's CPU time, unless it ran - /// into its 500 ms wall-clock cap — and never more CPU than wall time. + /// consumes at least 25 ms of this thread's CPU time, however long + /// that takes in wall time — and never more CPU than wall time. #[test] fn each_tick_burns_the_probe_tick_of_thread_cpu_time() { for i in 0..5 { @@ -3319,9 +3332,8 @@ mod macos_ioreport { let (cpu, wall) = (c1 - c0, w1 - w0); eprintln!("ioreport tick: tick {i} burned {cpu:?} of thread CPU time in {wall:?}"); assert!( - cpu >= TICK_CPU || wall >= TICK_WALL, - "tick {i} burned {cpu:?} of thread CPU (tests' clock) in {wall:?}: under {TICK_CPU:?}, and it \ - did not run into the {TICK_WALL:?} wall cap" + cpu >= TICK_CPU, + "tick {i} burned {cpu:?} of thread CPU (tests' clock) in {wall:?}: under {TICK_CPU:?}" ); assert!(cpu <= wall, "tick {i}: {cpu:?} of thread CPU in {wall:?} of wall time"); } @@ -3727,9 +3739,8 @@ mod macos_ioreport { 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", + {:?}: the probe is not burning CPU before each re-read. The tick burns thread CPU time with no \ + wall-clock cap, so host load does not shorten it", run.intervals, TICK_CPU / 2 ); -- 2.54.0 (Apple Git-157) From 7fc2315ab041ffc92e693de103046f9e73c3baf7 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Tue, 6 Oct 2026 17:58:24 -0400 Subject: [PATCH 4/9] jcp-energy: the probe tick burns its whole 25 ms of thread CPU The liveness probes' tick (liveness::burn_tick, which the per-process, IOReport and RAPL probes all use) burned 25 ms of the probing thread's CPU time but gave up after 500 ms of wall time. On a host that runs the thread for under 5% of a core, the cap cut the tick short. A probe that burns less between samples can see a live counter hold, and call it frozen. The meter's verdict then depends on host load. This is the defect fixed in proof-cascade's tick, in this crate's own copy. Production change: liveness::burn is bounded by thread CPU time only. The tick ends once the thread has burned the whole 25 ms, however much wall time that takes. Against a thread CPU clock that stops moving it ends after 40,000 spin rounds in a row without the clock moving, a count of the thread's own work rather than of wall time. With no readable thread clock it still spins 500 ms of wall time, as before; the constant is renamed PROBE_TICK_NO_CLOCK_WALL for that remaining role. Tests: assert_ticks_burned drops its escape clause (`|| wall >= TICK_WALL_CAP`) and requires 25 ms of thread CPU from every tick. The real-probe test requires a whole tick of CPU per interval unconditionally, where it allowed half a tick whenever a tick was slow. Co-Authored-By: Claude Opus 5.5 --- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 93 ++++++++++++++----------- 1 file changed, 52 insertions(+), 41 deletions(-) diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index 167903ada..b54feb745 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -321,10 +321,18 @@ mod liveness { /// loaded. pub(crate) const PROBE_TICK: Duration = Duration::from_millis(25); - /// The most wall time one tick may take. A thread that cannot get - /// [`PROBE_TICK`] of CPU in this long (under 5% of a core) stops its tick - /// here, so a starved probe still ends. - pub(crate) const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); + /// How long one tick spins, by wall time, when this thread's CPU clock + /// cannot be read: wall time is then all there is to go by. With a + /// readable clock no wall time bounds a tick (see [`burn`]). + pub(crate) const PROBE_TICK_NO_CLOCK_WALL: Duration = Duration::from_millis(500); + + /// Spin rounds in a row after which a thread CPU clock that has not moved + /// is taken to be stuck, and the spin ends. Each round is 1,000 dependent + /// additions: on the dev host 40,000 rounds are about 50 ms of this + /// thread's CPU optimised and 170 ms unoptimised, more than a tick, and the + /// clock moved in every round of 400,000 on a loaded host. A count of the + /// thread's own work, not of wall time, so host load cannot reach it. + pub(crate) const STUCK_CLOCK_ROUNDS: u32 = 40_000; /// In how many separate sample intervals each rail must advance before /// it counts as live. Two is not enough: see `ioreport::RailWatch`. @@ -595,33 +603,45 @@ mod liveness { } /// Spin this thread until it has used `cpu` of CPU time by its own CPU - /// clock, or until `wall_cap` of wall time has passed, whichever comes - /// first. However loaded the host, the thread has then burned `cpu`, unless - /// it got under `cpu / wall_cap` of a core. With no readable thread clock - /// only the wall cap ends the spin: slower, never shorter. - pub(crate) fn burn(cpu: Duration, wall_cap: Duration) { + /// clock, however much wall time that takes: a loaded host that runs the + /// thread only part of the time stretches the spin, never shortens it, so + /// every tick is the same work. (A 500 ms wall cap here could cut a tick + /// short on a starved thread, and a probe that burned less could call a + /// live counter frozen.) A clock that stops moving ends the spin after + /// [`STUCK_CLOCK_ROUNDS`] rounds. With no readable thread clock only wall + /// time can end it, after `no_clock_wall`: slower, never shorter. + pub(crate) fn burn(cpu: Duration, no_clock_wall: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); + let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1_000 { acc = std::hint::black_box(acc.wrapping_add(1)); } - let used = match (start, thread_cpu_time()) { - (Some(a), Some(b)) => b.saturating_sub(a), - _ => Duration::ZERO, - }; - if used >= cpu || wall.elapsed() >= wall_cap { - return; + match (start, thread_cpu_time()) { + (Some(a), Some(b)) if b.saturating_sub(a) >= cpu => return, + (Some(_), Some(b)) if Some(b) != last => { + last = Some(b); + unmoved = 0; + } + (Some(_), Some(_)) => { + unmoved += 1; + if unmoved >= STUCK_CLOCK_ROUNDS { + return; + } + } + _ if wall.elapsed() >= no_clock_wall => return, + _ => {} } } } /// The real probes' tick for a CPU-energy counter: spin until this thread - /// has burned [`PROBE_TICK`] of its own CPU time, or - /// [`PROBE_TICK_WALL_CAP`] of wall time has passed. + /// has burned [`PROBE_TICK`] of its own CPU time, however long that takes + /// (or, with no readable thread clock, for [`PROBE_TICK_NO_CLOCK_WALL`]). pub(crate) fn burn_tick() { - burn(PROBE_TICK, PROBE_TICK_WALL_CAP); + burn(PROBE_TICK, PROBE_TICK_NO_CLOCK_WALL); } } @@ -3266,10 +3286,9 @@ mod ioreport { } } - /// The CPU floor and wall cap the tests hold each tick to: their own - /// literals, not the implementation's constants. + /// The CPU floor the tests hold each tick to, however loaded the host: + /// their own literal, not the implementation's constant. const TICK_CPU_FLOOR: Duration = Duration::from_millis(25); - const TICK_WALL_CAP: Duration = Duration::from_millis(500); /// How far a CPU reading may pass the wall time around it: the /// granularity of reading two clocks, nothing more. @@ -3310,8 +3329,8 @@ mod ioreport { /// Each tick between two FFI reads, by the tests' own clocks: the probe /// burned [`TICK_CPU_FLOOR`] of this thread's CPU between every two - /// reads, unless the tick ran into [`TICK_WALL_CAP`] of wall time, and - /// no tick shows more CPU than wall time. `reads` are the (entered, + /// reads, however much wall time that took, and no tick shows more CPU + /// than wall time. `reads` are the (entered, /// left) stamps of each read, in order. Returns each tick's (CPU, wall). fn assert_ticks_burned(reads: &[(Stamp, Stamp)], what: &str) -> Vec<(Duration, Duration)> { let ticks: Vec<(Duration, Duration)> = reads.windows(2).map(|w| w[0].1.until(w[1].0)).collect(); @@ -3321,9 +3340,9 @@ mod ioreport { "{what}: tick {k} shows {cpu:?} of this thread's CPU in {wall:?} of wall time, by the tests' clocks" ); assert!( - cpu >= TICK_CPU_FLOOR || wall >= TICK_WALL_CAP, + cpu >= TICK_CPU_FLOOR, "{what}: tick {k} used {cpu:?} of this thread's CPU in {wall:?}, by the tests' own clock: a tick \ - must burn {TICK_CPU_FLOOR:?} of thread CPU, and only a {TICK_WALL_CAP:?} wall cap may cut that short" + must burn {TICK_CPU_FLOOR:?} of thread CPU, however long that takes" ); } ticks @@ -4155,11 +4174,10 @@ mod ioreport { /// calls, by the tests' own clock, is under 50 ms. A group sample costs /// ~8-9 ms of CPU however contended; an all-channel one ~100-125 ms. /// - Burning, by the tests' own clocks: between every two FFI reads the - /// thread burned 25 ms of its CPU, unless that tick ran into a 500 ms - /// wall cap, and no tick shows more CPU than wall time. The probe's - /// own record agrees, tick by tick. Over the whole probe, at least - /// half a tick of CPU per interval, and a whole tick when no tick was - /// capped. + /// thread burned 25 ms of its CPU, however much wall time that took, + /// and no tick shows more CPU than wall time. The probe's own record + /// agrees, tick by tick. Over the whole probe, at least a whole tick + /// of CPU per interval. #[test] fn the_liveness_probe_never_reports_a_frozen_rail_as_live() { let _hw = crate::ioreport_hw_lock(); @@ -4309,17 +4327,10 @@ mod ioreport { if intervals > 0 { let per_interval = cpu / intervals; assert!( - per_interval >= TICK_CPU_FLOOR / 2, + per_interval >= TICK_CPU_FLOOR, "the probing thread used {cpu:?} of CPU over {intervals} intervals, {per_interval:?} each, under \ - half of each {TICK_CPU_FLOOR:?} tick: the probe must burn CPU between samples, not wait" + a whole {TICK_CPU_FLOOR:?} tick: the probe must burn CPU between samples, not wait" ); - if tick_wall.iter().all(|&wall| wall < TICK_WALL_CAP) { - assert!( - per_interval >= TICK_CPU_FLOOR, - "the probing thread used {per_interval:?} of CPU per interval, under a whole \ - {TICK_CPU_FLOOR:?} tick, though no tick ran into the {TICK_WALL_CAP:?} wall cap" - ); - } } } @@ -4922,8 +4933,8 @@ pub enum IoReportStatus { /// How long the liveness probe burns CPU, on the calling thread, before /// concluding the CPU rail is not live. The probe samples its own subscription /// to the Energy Model group, ~5–12 ms a sample, after every 25 ms of the -/// calling thread's own CPU time (a tick that cannot get that in 500 ms of wall -/// time stops there) — about 30 intervals in the budget on an idle host, fewer +/// calling thread's own CPU time (however much wall time that takes) — about +/// 30 intervals in the budget on an idle host, fewer /// under load, each a sample and the one before it. Every CPU rail must keep /// advancing (each die's, on a multi-die part): each in at least five /// intervals, making up at least 80% of those observed, over at least 300 ms -- 2.54.0 (Apple Git-157) From 0a17079912adb67a49cf5790fabb242aada9fa53 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Tue, 6 Oct 2026 17:58:24 -0400 Subject: [PATCH 5/9] jouleclaw-energy: the probe ticks burn their whole 25 ms of thread CPU Both liveness ticks in this crate had a 500 ms wall-time cap. One is liveness::burn_thread_cpu, used by the shared probe (the per-process, RAPL and NVML counters). The other is apple_ioreport's own burn_thread_cpu, used by the IOReport rail probe. Each burned its tick of the probing thread's CPU time, but gave up after 500 ms of wall time. On a host that runs the thread for under 5% of a core, the cap cut the tick short. A probe that burns less between samples can see a live counter hold, and call it frozen. The meter's verdict then depends on host load. This is the defect fixed in proof-cascade's tick. Production change: both are bounded by thread CPU time only. A tick ends once the thread has burned the whole amount, however much wall time that takes. Against a thread CPU clock that stops moving, it ends after liveness::STUCK_CLOCK_ROUNDS (40,000) spin rounds in a row without the clock moving, a count of the thread's own work rather than of wall time. With no readable thread clock each still spins its amount of wall time, as before. The wall_cap parameter and PROBE_TICK_WALL_CAP are gone; the tests that passed a cap to the burn as a hang guard pass only the CPU amount now. Tests: apple_ioreport's assert_tick drops its escape clause (`|| wall >= TEST_TICK_WALL_CAP`) and requires 25 ms of thread CPU from every tick, however long it took. Co-Authored-By: Claude Opus 5.5 --- .../jouleclaw-energy/src/apple_ioreport.rs | 79 ++++++++++--------- .../crates/jouleclaw-energy/src/lib.rs | 4 +- .../crates/jouleclaw-energy/src/liveness.rs | 47 +++++++---- .../crates/jouleclaw-energy/src/process.rs | 2 +- 4 files changed, 76 insertions(+), 56 deletions(-) diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs index a80744e7c..6eb24ea7d 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs @@ -403,11 +403,6 @@ pub const CPU_RAIL_LIVENESS_BUDGET: Duration = Duration::from_millis(1000); /// interval. const PROBE_TICK: Duration = Duration::from_millis(25); -/// The most wall-clock time one [`PROBE_TICK`] may take. Only a host so loaded -/// that this thread gets less than a tick of CPU in this long cuts a tick -/// short; the probe's wall-clock budget and cap bound the probe either way. -const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); - /// In at least how many separate sample intervals each CPU rail must advance to /// count as live. One is not enough, nor two: a batch refresh can be published /// in two steps. See [`RailWatch`]. @@ -714,10 +709,10 @@ fn open_probe_sampler() -> Option Option>> { AppleIoReportCounter::open_energy_model().map(|state| move || sample_energy_model(&state)) } -/// The real tick: burn [`PROBE_TICK`] of this thread's CPU time, or stop at -/// [`PROBE_TICK_WALL_CAP`] of wall time on a host too loaded to grant it. +/// The real tick: burn [`PROBE_TICK`] of this thread's CPU time, however much +/// wall time a loaded host makes that take. fn probe_tick() { - burn_thread_cpu(PROBE_TICK, PROBE_TICK_WALL_CAP); + burn_thread_cpu(PROBE_TICK); } /// This thread's CPU time so far (`CLOCK_THREAD_CPUTIME_ID`: user and system @@ -732,26 +727,37 @@ fn thread_cpu_time() -> Option { } /// Burn `cpu` of this thread's own CPU time — until its thread CPU clock has -/// advanced by `cpu`, not until the wall clock has — or stop after `wall_cap` -/// of wall-clock time, whichever comes first. A wall-clock spin on a loaded -/// host burns only the share of its time the scheduler grants it; this burns -/// the whole amount unless the thread gets less than `cpu` of CPU in -/// `wall_cap`. If the thread CPU clock cannot be read, it spins for `cpu` of -/// wall-clock time instead. -fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { +/// advanced by `cpu`, not until the wall clock has — however much wall-clock +/// time that takes. A wall-clock spin on a loaded host burns only the share of +/// its time the scheduler grants it; this burns the whole amount, so every +/// tick is the same work. (A 500 ms wall cap here could cut a tick short on a +/// starved thread, and a probe that burned less could call a live rail +/// frozen.) A clock that stops moving ends the burn after +/// [`crate::liveness::STUCK_CLOCK_ROUNDS`] rounds. If the thread CPU clock +/// cannot be read, it spins for `cpu` of wall-clock time instead. +fn burn_thread_cpu(cpu: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); + let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1024 { acc = std::hint::black_box(acc.wrapping_add(1)); } - let burned = match (start, thread_cpu_time()) { - (Some(start), Some(now)) => now.saturating_sub(start), - _ => wall.elapsed(), - }; - if burned >= cpu || wall.elapsed() >= wall_cap { - break; + match (start, thread_cpu_time()) { + (Some(start), Some(now)) if now.saturating_sub(start) >= cpu => break, + (Some(_), Some(now)) if Some(now) != last => { + last = Some(now); + unmoved = 0; + } + (Some(_), Some(_)) => { + unmoved += 1; + if unmoved >= crate::liveness::STUCK_CLOCK_ROUNDS { + break; + } + } + _ if wall.elapsed() >= cpu => break, + _ => {} } } std::hint::black_box(acc); @@ -2334,30 +2340,27 @@ mod tests { .collect() } - /// A tick, in the tests' own literals rather than the production - /// constants: 25 ms of the thread's CPU time, cut short only by a 500 ms - /// wall-clock cap. + /// A tick, in the tests' own literal rather than the production + /// constant: 25 ms of the thread's CPU time, however loaded the host. const TEST_TICK: Duration = Duration::from_millis(25); - const TEST_TICK_WALL_CAP: Duration = Duration::from_millis(500); /// The probe's budget, in the tests' own literal. const TEST_BUDGET: Duration = Duration::from_millis(1000); /// One production tick as the tests measured it — this thread's CPU time /// on the tests' own clock, and wall time. It burned a whole tick of the - /// thread's CPU time unless its wall-clock cap cut it short, and it - /// stopped once it had: a tick that has the CPU does not burn on toward - /// its wall cap, so it never burns two ticks' worth. + /// thread's CPU time, however much wall time that took, and it stopped + /// once it had, so it never burns two ticks' worth. fn assert_tick(what: &str, cpu: Duration, wall: Duration) { assert!( - cpu >= TEST_TICK || wall >= TEST_TICK_WALL_CAP, + cpu >= TEST_TICK, "{what} burned {cpu:?} of this thread's CPU time in {wall:?} of wall time: a tick burns {TEST_TICK:?} of \ - thread CPU time, and only its {TEST_TICK_WALL_CAP:?} wall-clock cap may cut that short" + thread CPU time, however long that takes" ); assert!( cpu < 2 * TEST_TICK, "{what} burned {cpu:?} of this thread's CPU time (in {wall:?} of wall time): a tick stops once it has \ - burned {TEST_TICK:?}, and does not run on toward its {TEST_TICK_WALL_CAP:?} wall-clock cap" + burned {TEST_TICK:?}" ); } @@ -2650,9 +2653,9 @@ mod tests { } /// Each production tick ([`probe_tick`]), measured around it on the tests' - /// own clocks: it burned 25 ms of this thread's CPU time (or hit its - /// 500 ms wall cap), it stopped once it had rather than running on to the - /// cap, and it used no more CPU time than the wall time that passed. + /// own clocks: it burned 25 ms of this thread's CPU time, however much wall + /// time that took, it stopped once it had rather than burning on, and it + /// used no more CPU time than the wall time that passed. #[test] fn each_production_tick_burns_a_tick_of_this_threads_cpu_time() { let mut seen = Vec::new(); @@ -3065,8 +3068,8 @@ mod tests { /// And, from the tests' own clocks, none of it wall-clock bounded: the /// production probe opened one subscription, handed the rule every sample /// that came back, and between every two sample calls burned a tick — 25 ms - /// of this thread's CPU time, unless its 500 ms wall cap cut it short, and - /// never twice that. + /// of this thread's CPU time, however loaded the host, and never twice + /// that. #[test] fn the_liveness_probe_never_reports_a_frozen_rail_as_live() { let (probed, rec) = seam::recording(probe_host_status); @@ -3573,7 +3576,7 @@ mod tests { assert_eq!(rail, Some(CpuRail::Live), "an available counter whose own CPU rail does not move"); let _ = counter.read(); // prime let before = counter.read().expect("baseline read"); - burn_thread_cpu(Duration::from_millis(200), Duration::from_secs(5)); + burn_thread_cpu(Duration::from_millis(200)); let after = counter.read().expect("work read"); assert!( after.uj > before.uj, @@ -3623,7 +3626,7 @@ mod tests { let work = Duration::from_millis(150).max(Duration::from_nanos(active.min_window_ns())); let before = composite.read().expect("the fallback reads"); let t = Instant::now(); - burn_thread_cpu(work, Duration::from_secs(5)); + burn_thread_cpu(work); let after = composite.read().expect("the fallback reads"); let took = t.elapsed(); let uj = after.uj.checked_sub(before.uj).expect("the fallback's reading never runs backwards"); diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs index c306fe7d3..3e1a451be 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs @@ -174,8 +174,8 @@ pub enum IoReportStatus { /// On macOS with the `ioreport` feature, the first call opens an IOReport /// subscription to the `Energy Model` group and burns CPU on the calling thread /// while it watches the CPU energy rails, re-sampling after every 25 ms of the -/// thread's own CPU time (a tick gives up after 500 ms of wall time on a host -/// too loaded to grant it that): about +/// thread's own CPU time (however much wall time a loaded host makes that +/// take): about /// `apple_ioreport::CPU_RAIL_LIVENESS_BUDGET` where the rail is frozen, less /// where it is live (it stops as soon as every CPU rail has advanced in five /// intervals, four in every five of those observed, over at least 300 ms), and diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs index d1e82f633..0fc784b66 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs @@ -92,9 +92,13 @@ pub(crate) const PROBE_CAP_BUDGETS: u32 = 5; /// up to [`PROBE_CAP_BUDGETS`] budgets. pub(crate) const LIVENESS_BUDGET: Duration = Duration::from_millis(1000); -/// The most wall-clock time one tick of the probe's burn may take, on a host too -/// loaded to grant the probing thread its CPU. -pub(crate) const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); +/// Spin rounds in a row after which a thread CPU clock that has not moved is +/// taken to be stuck, and [`burn_thread_cpu`] ends. Each round is 1,024 +/// dependent additions: on the dev host 40,000 rounds are about 50 ms of this +/// thread's CPU optimised and 170 ms unoptimised, more than a tick, and the +/// clock moved in every round of 400,000 on a loaded host. A count of the +/// thread's own work, not of wall time, so host load cannot reach it. +pub(crate) const STUCK_CLOCK_ROUNDS: u32 = 40_000; /// The rule, fed whole samples — one cumulative value per channel, in a fixed /// channel order — each with the wall-clock time it was taken. Each interval is @@ -240,7 +244,7 @@ where F: FnMut() -> Option>, { let epoch = Instant::now(); - probe_with(open, || burn_thread_cpu(tick_cpu, PROBE_TICK_WALL_CAP), move || epoch.elapsed(), LIVENESS_BUDGET) + probe_with(open, || burn_thread_cpu(tick_cpu), move || epoch.elapsed(), LIVENESS_BUDGET) } /// This thread's CPU time so far (`CLOCK_THREAD_CPUTIME_ID`), or `None` where @@ -259,23 +263,36 @@ fn thread_cpu_time() -> Option { None } -/// Burn `cpu` of this thread's own CPU time, or stop after `wall_cap` of -/// wall-clock time, whichever comes first. Where the thread CPU clock cannot be -/// read, spin for `cpu` of wall-clock time instead. -pub(crate) fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { +/// Burn `cpu` of this thread's own CPU time, however much wall-clock time that +/// takes: a loaded host that runs the thread only part of the time stretches +/// the burn, never shortens it, so every tick is the same work. (A 500 ms wall +/// cap here could cut a tick short on a starved thread, and a probe that burned +/// less could call a live counter frozen.) A clock that stops moving ends the +/// burn after [`STUCK_CLOCK_ROUNDS`] rounds. Where the thread CPU clock cannot +/// be read, spin for `cpu` of wall-clock time instead. +pub(crate) fn burn_thread_cpu(cpu: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); + let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1024 { acc = std::hint::black_box(acc.wrapping_add(1)); } - let burned = match (start, thread_cpu_time()) { - (Some(start), Some(now)) => now.saturating_sub(start), - _ => wall.elapsed(), - }; - if burned >= cpu || wall.elapsed() >= wall_cap { - break; + match (start, thread_cpu_time()) { + (Some(start), Some(now)) if now.saturating_sub(start) >= cpu => break, + (Some(_), Some(now)) if Some(now) != last => { + last = Some(now); + unmoved = 0; + } + (Some(_), Some(_)) => { + unmoved += 1; + if unmoved >= STUCK_CLOCK_ROUNDS { + break; + } + } + _ if wall.elapsed() >= cpu => break, + _ => {} } } std::hint::black_box(acc); @@ -599,7 +616,7 @@ pub(crate) mod tests { #[test] fn the_burn_burns_this_threads_cpu() { let before = thread_cpu_time(); - burn_thread_cpu(Duration::from_millis(20), Duration::from_millis(500)); + burn_thread_cpu(Duration::from_millis(20)); match (before, thread_cpu_time()) { (Some(b), Some(a)) => assert!(a - b >= Duration::from_millis(20), "{:?}", a - b), _ if cfg!(unix) => panic!("a Unix host has a thread CPU clock"), diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs index 8502f1f63..fff33ffe4 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs @@ -319,7 +319,7 @@ mod tests { #[test] fn on_this_host_the_counter_is_live_and_meters_this_threads_burn() { let c = ProcessCpuCounter::new(); - let (_, figure) = c.measure(|| crate::liveness::burn_thread_cpu(Duration::from_millis(100), Duration::from_secs(2))); + let (_, figure) = c.measure(|| crate::liveness::burn_thread_cpu(Duration::from_millis(100))); eprintln!("process-cpu on this host: liveness={:?} 100 ms thread-CPU burn={figure:?} µJ", c.liveness()); assert_eq!(c.liveness(), CounterLiveness::Live); let uj = figure.expect("a live counter meters a burn"); -- 2.54.0 (Apple Git-157) From 3201f5f92e782e177763478a3bbf361b42619ee3 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 09:15:12 -0400 Subject: [PATCH 6/9] Revert "jouleclaw-energy: end the child window on the child's energy, not 300 ms" This reverts commit 85aab023. PR #166 (energy/load-robust-tests) fixes the same test, jouleclaw-energy/tests/process_cpu.rs, the same way: it reads the child's own counter until it reaches 0.2 J, for at least 300 ms and at most 5 s. Dropping this branch's copy of that fix keeps the two PRs from conflicting on the file; #166 carries it. Co-Authored-By: Claude Opus 5.5 --- .../jouleclaw-energy/tests/process_cpu.rs | 33 ++++--------------- 1 file changed, 7 insertions(+), 26 deletions(-) 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 22f554147..cfaf9cbb8 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu.rs @@ -102,16 +102,7 @@ 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: the window - // lasts until it has risen 0.2 J, twice the window's ceiling, and at - // least 300 ms. It ends on the child's work, not on wall time, so a - // loaded host that gives the child less of a core stretches the window - // but never leaves too little energy in it to tell (a fixed 300 ms read - // 0.12 J of the child's on a loaded host). A child that has not spent - // 0.2 J in 20 s fails the test: it did not work, or the host is too - // loaded to tell. - const CHILD_NJ: u64 = 200_000_000; - const CHILD_WALL_CAP: Duration = Duration::from_secs(20); + // own counter, read independently, shows the work happened. let mut child = Command::new("/bin/sh") .args(["-c", "while :; do :; done"]) .stdout(Stdio::null()) @@ -120,28 +111,18 @@ 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 ((child_burned_nj, ran), parent) = counter.measure(|| { - let started = Instant::now(); - let burned = loop { - std::thread::sleep(Duration::from_millis(10)); - let (burned, ran) = (energy_nj_of(pid) - child_before, started.elapsed()); - if (burned >= CHILD_NJ && ran >= Duration::from_millis(300)) || ran >= CHILD_WALL_CAP { - break (burned, ran); - } - }; + let (child_burned_nj, parent) = counter.measure(|| { + std::thread::sleep(Duration::from_millis(300)); + let burned = energy_nj_of(pid) - child_before; child.kill().expect("kill the child"); child.wait().expect("reap the child"); burned }); println!( - "process-cpu: child burned {:.3} J in {:.0} ms; this process's window = {parent:?} µJ", - child_burned_nj as f64 / 1e9, - ran.as_secs_f64() * 1e3 - ); - assert!( - child_burned_nj >= CHILD_NJ, - "the child burned only {child_burned_nj} nJ in {ran:?}: it did not work, or the host is too loaded to tell" + "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"); match parent { Ok(uj) => assert!(uj < 100_000, "{uj} µJ in this process while only the child worked"), Err(EnergyError::NotAdvanced) => {} -- 2.54.0 (Apple Git-157) From a45a070ef2906d51e199f264d510311555e4590d Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 14:29:23 -0400 Subject: [PATCH 7/9] Revert "jouleclaw-energy: the probe ticks burn their whole 25 ms of thread CPU" This reverts commit 0a17079912adb67a49cf5790fabb242aada9fa53. --- .../jouleclaw-energy/src/apple_ioreport.rs | 79 +++++++++---------- .../crates/jouleclaw-energy/src/lib.rs | 4 +- .../crates/jouleclaw-energy/src/liveness.rs | 47 ++++------- .../crates/jouleclaw-energy/src/process.rs | 2 +- 4 files changed, 56 insertions(+), 76 deletions(-) diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs index 6eb24ea7d..a80744e7c 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/apple_ioreport.rs @@ -403,6 +403,11 @@ pub const CPU_RAIL_LIVENESS_BUDGET: Duration = Duration::from_millis(1000); /// interval. const PROBE_TICK: Duration = Duration::from_millis(25); +/// The most wall-clock time one [`PROBE_TICK`] may take. Only a host so loaded +/// that this thread gets less than a tick of CPU in this long cuts a tick +/// short; the probe's wall-clock budget and cap bound the probe either way. +const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); + /// In at least how many separate sample intervals each CPU rail must advance to /// count as live. One is not enough, nor two: a batch refresh can be published /// in two steps. See [`RailWatch`]. @@ -709,10 +714,10 @@ fn open_probe_sampler() -> Option Option>> { AppleIoReportCounter::open_energy_model().map(|state| move || sample_energy_model(&state)) } -/// The real tick: burn [`PROBE_TICK`] of this thread's CPU time, however much -/// wall time a loaded host makes that take. +/// The real tick: burn [`PROBE_TICK`] of this thread's CPU time, or stop at +/// [`PROBE_TICK_WALL_CAP`] of wall time on a host too loaded to grant it. fn probe_tick() { - burn_thread_cpu(PROBE_TICK); + burn_thread_cpu(PROBE_TICK, PROBE_TICK_WALL_CAP); } /// This thread's CPU time so far (`CLOCK_THREAD_CPUTIME_ID`: user and system @@ -727,37 +732,26 @@ fn thread_cpu_time() -> Option { } /// Burn `cpu` of this thread's own CPU time — until its thread CPU clock has -/// advanced by `cpu`, not until the wall clock has — however much wall-clock -/// time that takes. A wall-clock spin on a loaded host burns only the share of -/// its time the scheduler grants it; this burns the whole amount, so every -/// tick is the same work. (A 500 ms wall cap here could cut a tick short on a -/// starved thread, and a probe that burned less could call a live rail -/// frozen.) A clock that stops moving ends the burn after -/// [`crate::liveness::STUCK_CLOCK_ROUNDS`] rounds. If the thread CPU clock -/// cannot be read, it spins for `cpu` of wall-clock time instead. -fn burn_thread_cpu(cpu: Duration) { +/// advanced by `cpu`, not until the wall clock has — or stop after `wall_cap` +/// of wall-clock time, whichever comes first. A wall-clock spin on a loaded +/// host burns only the share of its time the scheduler grants it; this burns +/// the whole amount unless the thread gets less than `cpu` of CPU in +/// `wall_cap`. If the thread CPU clock cannot be read, it spins for `cpu` of +/// wall-clock time instead. +fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); - let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1024 { acc = std::hint::black_box(acc.wrapping_add(1)); } - match (start, thread_cpu_time()) { - (Some(start), Some(now)) if now.saturating_sub(start) >= cpu => break, - (Some(_), Some(now)) if Some(now) != last => { - last = Some(now); - unmoved = 0; - } - (Some(_), Some(_)) => { - unmoved += 1; - if unmoved >= crate::liveness::STUCK_CLOCK_ROUNDS { - break; - } - } - _ if wall.elapsed() >= cpu => break, - _ => {} + let burned = match (start, thread_cpu_time()) { + (Some(start), Some(now)) => now.saturating_sub(start), + _ => wall.elapsed(), + }; + if burned >= cpu || wall.elapsed() >= wall_cap { + break; } } std::hint::black_box(acc); @@ -2340,27 +2334,30 @@ mod tests { .collect() } - /// A tick, in the tests' own literal rather than the production - /// constant: 25 ms of the thread's CPU time, however loaded the host. + /// A tick, in the tests' own literals rather than the production + /// constants: 25 ms of the thread's CPU time, cut short only by a 500 ms + /// wall-clock cap. const TEST_TICK: Duration = Duration::from_millis(25); + const TEST_TICK_WALL_CAP: Duration = Duration::from_millis(500); /// The probe's budget, in the tests' own literal. const TEST_BUDGET: Duration = Duration::from_millis(1000); /// One production tick as the tests measured it — this thread's CPU time /// on the tests' own clock, and wall time. It burned a whole tick of the - /// thread's CPU time, however much wall time that took, and it stopped - /// once it had, so it never burns two ticks' worth. + /// thread's CPU time unless its wall-clock cap cut it short, and it + /// stopped once it had: a tick that has the CPU does not burn on toward + /// its wall cap, so it never burns two ticks' worth. fn assert_tick(what: &str, cpu: Duration, wall: Duration) { assert!( - cpu >= TEST_TICK, + cpu >= TEST_TICK || wall >= TEST_TICK_WALL_CAP, "{what} burned {cpu:?} of this thread's CPU time in {wall:?} of wall time: a tick burns {TEST_TICK:?} of \ - thread CPU time, however long that takes" + thread CPU time, and only its {TEST_TICK_WALL_CAP:?} wall-clock cap may cut that short" ); assert!( cpu < 2 * TEST_TICK, "{what} burned {cpu:?} of this thread's CPU time (in {wall:?} of wall time): a tick stops once it has \ - burned {TEST_TICK:?}" + burned {TEST_TICK:?}, and does not run on toward its {TEST_TICK_WALL_CAP:?} wall-clock cap" ); } @@ -2653,9 +2650,9 @@ mod tests { } /// Each production tick ([`probe_tick`]), measured around it on the tests' - /// own clocks: it burned 25 ms of this thread's CPU time, however much wall - /// time that took, it stopped once it had rather than burning on, and it - /// used no more CPU time than the wall time that passed. + /// own clocks: it burned 25 ms of this thread's CPU time (or hit its + /// 500 ms wall cap), it stopped once it had rather than running on to the + /// cap, and it used no more CPU time than the wall time that passed. #[test] fn each_production_tick_burns_a_tick_of_this_threads_cpu_time() { let mut seen = Vec::new(); @@ -3068,8 +3065,8 @@ mod tests { /// And, from the tests' own clocks, none of it wall-clock bounded: the /// production probe opened one subscription, handed the rule every sample /// that came back, and between every two sample calls burned a tick — 25 ms - /// of this thread's CPU time, however loaded the host, and never twice - /// that. + /// of this thread's CPU time, unless its 500 ms wall cap cut it short, and + /// never twice that. #[test] fn the_liveness_probe_never_reports_a_frozen_rail_as_live() { let (probed, rec) = seam::recording(probe_host_status); @@ -3576,7 +3573,7 @@ mod tests { assert_eq!(rail, Some(CpuRail::Live), "an available counter whose own CPU rail does not move"); let _ = counter.read(); // prime let before = counter.read().expect("baseline read"); - burn_thread_cpu(Duration::from_millis(200)); + burn_thread_cpu(Duration::from_millis(200), Duration::from_secs(5)); let after = counter.read().expect("work read"); assert!( after.uj > before.uj, @@ -3626,7 +3623,7 @@ mod tests { let work = Duration::from_millis(150).max(Duration::from_nanos(active.min_window_ns())); let before = composite.read().expect("the fallback reads"); let t = Instant::now(); - burn_thread_cpu(work); + burn_thread_cpu(work, Duration::from_secs(5)); let after = composite.read().expect("the fallback reads"); let took = t.elapsed(); let uj = after.uj.checked_sub(before.uj).expect("the fallback's reading never runs backwards"); diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs index 3e1a451be..c306fe7d3 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs @@ -174,8 +174,8 @@ pub enum IoReportStatus { /// On macOS with the `ioreport` feature, the first call opens an IOReport /// subscription to the `Energy Model` group and burns CPU on the calling thread /// while it watches the CPU energy rails, re-sampling after every 25 ms of the -/// thread's own CPU time (however much wall time a loaded host makes that -/// take): about +/// thread's own CPU time (a tick gives up after 500 ms of wall time on a host +/// too loaded to grant it that): about /// `apple_ioreport::CPU_RAIL_LIVENESS_BUDGET` where the rail is frozen, less /// where it is live (it stops as soon as every CPU rail has advanced in five /// intervals, four in every five of those observed, over at least 300 ms), and diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs index 0fc784b66..d1e82f633 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/liveness.rs @@ -92,13 +92,9 @@ pub(crate) const PROBE_CAP_BUDGETS: u32 = 5; /// up to [`PROBE_CAP_BUDGETS`] budgets. pub(crate) const LIVENESS_BUDGET: Duration = Duration::from_millis(1000); -/// Spin rounds in a row after which a thread CPU clock that has not moved is -/// taken to be stuck, and [`burn_thread_cpu`] ends. Each round is 1,024 -/// dependent additions: on the dev host 40,000 rounds are about 50 ms of this -/// thread's CPU optimised and 170 ms unoptimised, more than a tick, and the -/// clock moved in every round of 400,000 on a loaded host. A count of the -/// thread's own work, not of wall time, so host load cannot reach it. -pub(crate) const STUCK_CLOCK_ROUNDS: u32 = 40_000; +/// The most wall-clock time one tick of the probe's burn may take, on a host too +/// loaded to grant the probing thread its CPU. +pub(crate) const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); /// The rule, fed whole samples — one cumulative value per channel, in a fixed /// channel order — each with the wall-clock time it was taken. Each interval is @@ -244,7 +240,7 @@ where F: FnMut() -> Option>, { let epoch = Instant::now(); - probe_with(open, || burn_thread_cpu(tick_cpu), move || epoch.elapsed(), LIVENESS_BUDGET) + probe_with(open, || burn_thread_cpu(tick_cpu, PROBE_TICK_WALL_CAP), move || epoch.elapsed(), LIVENESS_BUDGET) } /// This thread's CPU time so far (`CLOCK_THREAD_CPUTIME_ID`), or `None` where @@ -263,36 +259,23 @@ fn thread_cpu_time() -> Option { None } -/// Burn `cpu` of this thread's own CPU time, however much wall-clock time that -/// takes: a loaded host that runs the thread only part of the time stretches -/// the burn, never shortens it, so every tick is the same work. (A 500 ms wall -/// cap here could cut a tick short on a starved thread, and a probe that burned -/// less could call a live counter frozen.) A clock that stops moving ends the -/// burn after [`STUCK_CLOCK_ROUNDS`] rounds. Where the thread CPU clock cannot -/// be read, spin for `cpu` of wall-clock time instead. -pub(crate) fn burn_thread_cpu(cpu: Duration) { +/// Burn `cpu` of this thread's own CPU time, or stop after `wall_cap` of +/// wall-clock time, whichever comes first. Where the thread CPU clock cannot be +/// read, spin for `cpu` of wall-clock time instead. +pub(crate) fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); - let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1024 { acc = std::hint::black_box(acc.wrapping_add(1)); } - match (start, thread_cpu_time()) { - (Some(start), Some(now)) if now.saturating_sub(start) >= cpu => break, - (Some(_), Some(now)) if Some(now) != last => { - last = Some(now); - unmoved = 0; - } - (Some(_), Some(_)) => { - unmoved += 1; - if unmoved >= STUCK_CLOCK_ROUNDS { - break; - } - } - _ if wall.elapsed() >= cpu => break, - _ => {} + let burned = match (start, thread_cpu_time()) { + (Some(start), Some(now)) => now.saturating_sub(start), + _ => wall.elapsed(), + }; + if burned >= cpu || wall.elapsed() >= wall_cap { + break; } } std::hint::black_box(acc); @@ -616,7 +599,7 @@ pub(crate) mod tests { #[test] fn the_burn_burns_this_threads_cpu() { let before = thread_cpu_time(); - burn_thread_cpu(Duration::from_millis(20)); + burn_thread_cpu(Duration::from_millis(20), Duration::from_millis(500)); match (before, thread_cpu_time()) { (Some(b), Some(a)) => assert!(a - b >= Duration::from_millis(20), "{:?}", a - b), _ if cfg!(unix) => panic!("a Unix host has a thread CPU clock"), diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs index fff33ffe4..8502f1f63 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs @@ -319,7 +319,7 @@ mod tests { #[test] fn on_this_host_the_counter_is_live_and_meters_this_threads_burn() { let c = ProcessCpuCounter::new(); - let (_, figure) = c.measure(|| crate::liveness::burn_thread_cpu(Duration::from_millis(100))); + let (_, figure) = c.measure(|| crate::liveness::burn_thread_cpu(Duration::from_millis(100), Duration::from_secs(2))); eprintln!("process-cpu on this host: liveness={:?} 100 ms thread-CPU burn={figure:?} µJ", c.liveness()); assert_eq!(c.liveness(), CounterLiveness::Live); let uj = figure.expect("a live counter meters a burn"); -- 2.54.0 (Apple Git-157) From d960a72b388c4c3eb8faff7580a7fff8aebebe9d Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 14:29:23 -0400 Subject: [PATCH 8/9] Revert "jcp-energy: the probe tick burns its whole 25 ms of thread CPU" This reverts commit 7fc2315ab041ffc92e693de103046f9e73c3baf7. --- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 93 +++++++++++-------------- 1 file changed, 41 insertions(+), 52 deletions(-) diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index b54feb745..167903ada 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -321,18 +321,10 @@ mod liveness { /// loaded. pub(crate) const PROBE_TICK: Duration = Duration::from_millis(25); - /// How long one tick spins, by wall time, when this thread's CPU clock - /// cannot be read: wall time is then all there is to go by. With a - /// readable clock no wall time bounds a tick (see [`burn`]). - pub(crate) const PROBE_TICK_NO_CLOCK_WALL: Duration = Duration::from_millis(500); - - /// Spin rounds in a row after which a thread CPU clock that has not moved - /// is taken to be stuck, and the spin ends. Each round is 1,000 dependent - /// additions: on the dev host 40,000 rounds are about 50 ms of this - /// thread's CPU optimised and 170 ms unoptimised, more than a tick, and the - /// clock moved in every round of 400,000 on a loaded host. A count of the - /// thread's own work, not of wall time, so host load cannot reach it. - pub(crate) const STUCK_CLOCK_ROUNDS: u32 = 40_000; + /// The most wall time one tick may take. A thread that cannot get + /// [`PROBE_TICK`] of CPU in this long (under 5% of a core) stops its tick + /// here, so a starved probe still ends. + pub(crate) const PROBE_TICK_WALL_CAP: Duration = Duration::from_millis(500); /// In how many separate sample intervals each rail must advance before /// it counts as live. Two is not enough: see `ioreport::RailWatch`. @@ -603,45 +595,33 @@ mod liveness { } /// Spin this thread until it has used `cpu` of CPU time by its own CPU - /// clock, however much wall time that takes: a loaded host that runs the - /// thread only part of the time stretches the spin, never shortens it, so - /// every tick is the same work. (A 500 ms wall cap here could cut a tick - /// short on a starved thread, and a probe that burned less could call a - /// live counter frozen.) A clock that stops moving ends the spin after - /// [`STUCK_CLOCK_ROUNDS`] rounds. With no readable thread clock only wall - /// time can end it, after `no_clock_wall`: slower, never shorter. - pub(crate) fn burn(cpu: Duration, no_clock_wall: Duration) { + /// clock, or until `wall_cap` of wall time has passed, whichever comes + /// first. However loaded the host, the thread has then burned `cpu`, unless + /// it got under `cpu / wall_cap` of a core. With no readable thread clock + /// only the wall cap ends the spin: slower, never shorter. + pub(crate) fn burn(cpu: Duration, wall_cap: Duration) { let wall = Instant::now(); let start = thread_cpu_time(); - let (mut last, mut unmoved) = (start, 0u32); let mut acc: u64 = 0; loop { for _ in 0..1_000 { acc = std::hint::black_box(acc.wrapping_add(1)); } - match (start, thread_cpu_time()) { - (Some(a), Some(b)) if b.saturating_sub(a) >= cpu => return, - (Some(_), Some(b)) if Some(b) != last => { - last = Some(b); - unmoved = 0; - } - (Some(_), Some(_)) => { - unmoved += 1; - if unmoved >= STUCK_CLOCK_ROUNDS { - return; - } - } - _ if wall.elapsed() >= no_clock_wall => return, - _ => {} + let used = match (start, thread_cpu_time()) { + (Some(a), Some(b)) => b.saturating_sub(a), + _ => Duration::ZERO, + }; + if used >= cpu || wall.elapsed() >= wall_cap { + return; } } } /// The real probes' tick for a CPU-energy counter: spin until this thread - /// has burned [`PROBE_TICK`] of its own CPU time, however long that takes - /// (or, with no readable thread clock, for [`PROBE_TICK_NO_CLOCK_WALL`]). + /// has burned [`PROBE_TICK`] of its own CPU time, or + /// [`PROBE_TICK_WALL_CAP`] of wall time has passed. pub(crate) fn burn_tick() { - burn(PROBE_TICK, PROBE_TICK_NO_CLOCK_WALL); + burn(PROBE_TICK, PROBE_TICK_WALL_CAP); } } @@ -3286,9 +3266,10 @@ mod ioreport { } } - /// The CPU floor the tests hold each tick to, however loaded the host: - /// their own literal, not the implementation's constant. + /// The CPU floor and wall cap the tests hold each tick to: their own + /// literals, not the implementation's constants. const TICK_CPU_FLOOR: Duration = Duration::from_millis(25); + const TICK_WALL_CAP: Duration = Duration::from_millis(500); /// How far a CPU reading may pass the wall time around it: the /// granularity of reading two clocks, nothing more. @@ -3329,8 +3310,8 @@ mod ioreport { /// Each tick between two FFI reads, by the tests' own clocks: the probe /// burned [`TICK_CPU_FLOOR`] of this thread's CPU between every two - /// reads, however much wall time that took, and no tick shows more CPU - /// than wall time. `reads` are the (entered, + /// reads, unless the tick ran into [`TICK_WALL_CAP`] of wall time, and + /// no tick shows more CPU than wall time. `reads` are the (entered, /// left) stamps of each read, in order. Returns each tick's (CPU, wall). fn assert_ticks_burned(reads: &[(Stamp, Stamp)], what: &str) -> Vec<(Duration, Duration)> { let ticks: Vec<(Duration, Duration)> = reads.windows(2).map(|w| w[0].1.until(w[1].0)).collect(); @@ -3340,9 +3321,9 @@ mod ioreport { "{what}: tick {k} shows {cpu:?} of this thread's CPU in {wall:?} of wall time, by the tests' clocks" ); assert!( - cpu >= TICK_CPU_FLOOR, + cpu >= TICK_CPU_FLOOR || wall >= TICK_WALL_CAP, "{what}: tick {k} used {cpu:?} of this thread's CPU in {wall:?}, by the tests' own clock: a tick \ - must burn {TICK_CPU_FLOOR:?} of thread CPU, however long that takes" + must burn {TICK_CPU_FLOOR:?} of thread CPU, and only a {TICK_WALL_CAP:?} wall cap may cut that short" ); } ticks @@ -4174,10 +4155,11 @@ mod ioreport { /// calls, by the tests' own clock, is under 50 ms. A group sample costs /// ~8-9 ms of CPU however contended; an all-channel one ~100-125 ms. /// - Burning, by the tests' own clocks: between every two FFI reads the - /// thread burned 25 ms of its CPU, however much wall time that took, - /// and no tick shows more CPU than wall time. The probe's own record - /// agrees, tick by tick. Over the whole probe, at least a whole tick - /// of CPU per interval. + /// thread burned 25 ms of its CPU, unless that tick ran into a 500 ms + /// wall cap, and no tick shows more CPU than wall time. The probe's + /// own record agrees, tick by tick. Over the whole probe, at least + /// half a tick of CPU per interval, and a whole tick when no tick was + /// capped. #[test] fn the_liveness_probe_never_reports_a_frozen_rail_as_live() { let _hw = crate::ioreport_hw_lock(); @@ -4327,10 +4309,17 @@ mod ioreport { if intervals > 0 { let per_interval = cpu / intervals; assert!( - per_interval >= TICK_CPU_FLOOR, + per_interval >= TICK_CPU_FLOOR / 2, "the probing thread used {cpu:?} of CPU over {intervals} intervals, {per_interval:?} each, under \ - a whole {TICK_CPU_FLOOR:?} tick: the probe must burn CPU between samples, not wait" + half of each {TICK_CPU_FLOOR:?} tick: the probe must burn CPU between samples, not wait" ); + if tick_wall.iter().all(|&wall| wall < TICK_WALL_CAP) { + assert!( + per_interval >= TICK_CPU_FLOOR, + "the probing thread used {per_interval:?} of CPU per interval, under a whole \ + {TICK_CPU_FLOOR:?} tick, though no tick ran into the {TICK_WALL_CAP:?} wall cap" + ); + } } } @@ -4933,8 +4922,8 @@ pub enum IoReportStatus { /// How long the liveness probe burns CPU, on the calling thread, before /// concluding the CPU rail is not live. The probe samples its own subscription /// to the Energy Model group, ~5–12 ms a sample, after every 25 ms of the -/// calling thread's own CPU time (however much wall time that takes) — about -/// 30 intervals in the budget on an idle host, fewer +/// calling thread's own CPU time (a tick that cannot get that in 500 ms of wall +/// time stops there) — about 30 intervals in the budget on an idle host, fewer /// under load, each a sample and the one before it. Every CPU rail must keep /// advancing (each die's, on a multi-die part): each in at least five /// intervals, making up at least 80% of those observed, over at least 300 ms -- 2.54.0 (Apple Git-157) From 2db8eff6083b37a86ece8351b9ffa79d7608c524 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 7 Oct 2026 14:29:24 -0400 Subject: [PATCH 9/9] Revert "proof-cascade: the probe tick burns its whole 25 ms of thread CPU" This reverts commit 2641dead720a96764f1b3e532aefb98e8d1ad24f. --- .../crates/proof-cascade/src/meter.rs | 69 ++++++++----------- 1 file changed, 29 insertions(+), 40 deletions(-) diff --git a/proof/proof-rs/crates/proof-cascade/src/meter.rs b/proof/proof-rs/crates/proof-cascade/src/meter.rs index b3e547e04..0419aa834 100644 --- a/proof/proof-rs/crates/proof-cascade/src/meter.rs +++ b/proof/proof-rs/crates/proof-cascade/src/meter.rs @@ -325,8 +325,8 @@ pub enum IoReportStatus { } /// How long (wall time) the liveness probe watches the CPU energy rail before -/// concluding it is frozen. Before each re-sample the probe burns 25 ms of -/// the calling thread's own CPU time (however much wall time that takes). +/// concluding it is frozen. Before each re-sample the probe burns ~25 ms of +/// the calling thread's own CPU time (at most 500 ms of wall time per tick). /// It samples its own subscription to the Energy Model group alone — 364 /// channels on an M5 Max, 645 on an M3 Ultra, ~6–9 ms of thread CPU a sample, /// where a sample of every channel (~11,900 / ~14,300) costs ~85–125 ms — so on @@ -2314,13 +2314,9 @@ mod probe_clock { /// Thread CPU time a probe burns before each liveness re-sample. pub(super) const PROBE_TICK: Duration = Duration::from_millis(25); - /// Spin rounds in a row after which a thread CPU clock that has not moved - /// is taken to be stuck, and the tick ends. Each round is 4,096 dependent - /// additions: on the dev host 10,000 rounds are about 40 ms of this - /// thread's CPU optimised and 150 ms unoptimised, more than a tick, and - /// the clock moved in every round of 100,000 on a loaded host. A count of - /// the thread's own work, not of wall time, so host load cannot reach it. - const STUCK_CLOCK_ROUNDS: u32 = 10_000; + /// The most wall time one tick may take to burn [`PROBE_TICK`] of CPU + /// time. Only a thread starved of the CPU for that long is cut short. + const TICK_WALL_CAP: Duration = Duration::from_millis(500); /// Wall time since this process first asked: the probes' wall clock. One /// process-wide epoch, so a test can place its own reads on the same @@ -2341,41 +2337,31 @@ mod probe_clock { } /// One probe tick: burn [`PROBE_TICK`] of this thread's CPU time — CPU - /// time, not wall time, and with no wall-clock cap, so every tick is the - /// same work however loaded the host: one that runs this thread only part - /// of the time stretches the tick in wall time, never shortens its burn. - /// (A 500 ms wall cap here cut ticks short on a loaded host, to 12.4 ms of - /// thread CPU.) Without a readable thread CPU clock it spins - /// [`PROBE_TICK`] of wall time; with one that stops moving, or stops - /// reading, it ends early (see [`STUCK_CLOCK_ROUNDS`]). 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. + /// time, not wall time, so a loaded host that runs this thread only part + /// of the time still gets the full burn — giving up after + /// [`TICK_WALL_CAP`] of wall time. Without a readable thread CPU clock it + /// 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); + burn_thread_cpu(PROBE_TICK, TICK_WALL_CAP); } - fn burn_thread_cpu(cpu: Duration) { + fn burn_thread_cpu(cpu: Duration, wall_cap: Duration) { + let wall = Instant::now(); let mut acc: u64 = 0; let Some(start) = thread_cpu_time() else { - let wall = Instant::now(); while wall.elapsed() < cpu { acc = std::hint::black_box(acc.wrapping_add(1)); } return; }; - let (mut last, mut unmoved) = (start, 0u32); - loop { + while wall.elapsed() < wall_cap { 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) if now != last => { - last = now; - unmoved = 0; - } - Some(_) if unmoved + 1 < STUCK_CLOCK_ROUNDS => unmoved += 1, + Some(now) if now.saturating_sub(start) < cpu => {} _ => break, } } @@ -3203,11 +3189,12 @@ mod macos_ioreport { /// read wait, not burn. The test's own literal. const MAX_MEDIAN_READ_CPU: Duration = Duration::from_millis(50); - /// The probe's burn, as the tests see it: at least [`TICK_CPU`] of the - /// probing thread's CPU per tick, however loaded the host, and at - /// least half of it in every interval. The tests' own literal, not the - /// implementation's constant. + /// The probe's burn, as the tests see it: at least this much of the + /// probing thread's CPU in every interval, and per tick at least + /// [`TICK_CPU`] unless the tick ran into [`TICK_WALL`]. The tests' own + /// literals, not the implementation's constants. const TICK_CPU: Duration = Duration::from_millis(25); + const TICK_WALL: Duration = Duration::from_millis(500); /// Real, cheap, pure CPU work for the metering tests. fn cpu_work() { @@ -3321,8 +3308,8 @@ mod macos_ioreport { } /// R1, the tick, on the tests' own clock: each production tick - /// consumes at least 25 ms of this thread's CPU time, however long - /// that takes in wall time — and never more CPU than wall time. + /// consumes at least 25 ms of this thread's CPU time, unless it ran + /// into its 500 ms wall-clock cap — and never more CPU than wall time. #[test] fn each_tick_burns_the_probe_tick_of_thread_cpu_time() { for i in 0..5 { @@ -3332,8 +3319,9 @@ mod macos_ioreport { let (cpu, wall) = (c1 - c0, w1 - w0); eprintln!("ioreport tick: tick {i} burned {cpu:?} of thread CPU time in {wall:?}"); assert!( - cpu >= TICK_CPU, - "tick {i} burned {cpu:?} of thread CPU (tests' clock) in {wall:?}: under {TICK_CPU:?}" + cpu >= TICK_CPU || wall >= TICK_WALL, + "tick {i} burned {cpu:?} of thread CPU (tests' clock) in {wall:?}: under {TICK_CPU:?}, and it \ + did not run into the {TICK_WALL:?} wall cap" ); assert!(cpu <= wall, "tick {i}: {cpu:?} of thread CPU in {wall:?} of wall time"); } @@ -3739,8 +3727,9 @@ mod macos_ioreport { 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 with no \ - wall-clock cap, so host load does not shorten it", + {:?}: 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 ); -- 2.54.0 (Apple Git-157)