diff --git a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs index b5005189e..e1e2a3d9b 100644 --- a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs +++ b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs @@ -48,7 +48,12 @@ //! process's own threads' CPU energy, from `proc_pid_rusage`, live for an //! unprivileged reader. **Never selected by [`detect`]** — it does not see //! a child process's work, or the GPU's — only by [`detect_in_process`], -//! for callers whose metered work runs on the CPU in this process. +//! for callers whose metered work runs on the CPU in this process. The +//! kernel adds a thread's energy to the process's count only when the +//! thread leaves a core, so **each read is taken only once the reading +//! thread is seen to have left its core** (it sleeps at least 50 µs +//! first, and checks); a read whose thread was not seen to leave fails, +//! and its span is no reading: the caller keeps its estimate. //! - macOS `powermetrics`: detected when the binary is on the PATH, but the //! reference wrapper does not parse it, so every read returns //! `Err(NoCounter)`: no figure, and callers keep their own estimate. @@ -70,7 +75,9 @@ // IOReport module (`macos_ioreport`) — the on-die energy counters are // unreachable without the `unsafe extern "C"` IOReport calls — `clocks`, whose // one call is `clock_gettime` for the probing thread's CPU clock, and -// `macos_process_energy`, whose calls are `getpid` and `proc_pid_rusage`. +// `macos_process_energy`, whose calls are `getpid`, `proc_pid_rusage`, and, +// for the reading thread's own energy count, `pthread_self`, +// `pthread_threadid_np` and `proc_pidinfo`. // Everything else stays unsafe-free. #![deny(unsafe_code)] @@ -4480,6 +4487,172 @@ mod macos_powermetrics { #[cfg(target_os = "macos")] pub use macos_powermetrics::MacosPowermetricsCounter; +// When a process may read its own energy count, kept apart from the FFI so +// the rule and the one byte layout it depends on run under test on every +// platform, with scripted counts and scripted sleeps. +// +// The kernel adds a thread's CPU energy to its process's count +// (`ri_energy_nj`) only when the thread leaves a core: a context switch, or +// the end of its quantum, about 10 ms of its CPU. A process's read of its own +// count does not take the reading thread off its core — its CPU time is +// current at the read, its energy is not. So the count read from a thread +// that has been running lacks what that thread spent since it last left a +// core. Bracket a span with two such reads and the first puts up to a +// quantum of energy from BEFORE the span inside it, and the second leaves +// the span's tail out. Measured on an M3 Ultra, macOS 27.0.1 (load average +// about 14, three runs of 40 spans each, against the tests' own reader that +// sleeps before each of its reads): of spans over 1 ms of the reading +// thread's CPU, 39, 40 and 40 read nothing or under two thirds of the work; +// of spans over a 2 ms sleep opened straight after 8 ms of that thread's +// CPU, 40, 40 and 37 read the burn before them as the sleep's energy, about +// 41 mJ for a sleep. +// +// A thread that sleeps leaves its core — unless the sleep's timer fires +// before the thread has blocked, and then it goes on without leaving. So the +// reading thread sleeps and CHECKS: its own energy count +// (`proc_pidinfo`'s `PROC_PIDTHREADCOUNTS`) is moved by the kernel only when +// it adds the thread's energy to the process's, so a rise across a sleep is +// the thread having left its core after everything it did before the sleep. +// The process's context-switch count is no such check, since any other +// thread's switch moves it. The sleeps grow, so one that did not block is +// followed by one that much more surely does. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +mod reading_thread { + use std::time::Duration; + + /// The sleeps the reading thread takes, in turn, until one is seen to + /// take it off its core: 6.25 ms in all on a read that never is. + pub(crate) const SLEEPS: [Duration; 4] = + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)]; + + /// Whether the reading thread was seen to leave its core: its own energy + /// count, read by `count`, rose across one of `sleeps`, taken in turn + /// through `sleep`. A count that held across every sleep, or fell, is no + /// evidence that it left, and a count that cannot be read ends the wait + /// at once: `false`, and the process's count is not read on it. + pub(crate) fn left_its_core( + sleeps: &[Duration], + mut count: impl FnMut() -> Option, + mut sleep: impl FnMut(Duration), + ) -> bool { + for &pause in sleeps { + let Some(before) = count() else { return false }; + sleep(pause); + match count() { + Some(after) if after > before => return true, + Some(_) => {} + None => return false, + } + } + false + } + + /// `PROC_PIDTHREADCOUNTS`: the `proc_pidinfo` flavor that returns one + /// thread's counts, asked by its 64-bit thread id. It is in the kernel's + /// `` (macOS 13 and later), not the SDK's + /// public header, so [`energy_nj`] reads its result in one layout only. + pub(crate) const THREAD_COUNTS_FLAVOR: i32 = 34; + + /// The size of the buffer a read of the thread's counts hands the + /// kernel: room for the header and twelve performance levels. + pub(crate) const THREAD_COUNTS_SIZE: usize = 8 + 12 * 40; + + /// The thread's CPU energy in nanojoules, summed over the CPU performance + /// levels, from the `wrote` bytes the call says it wrote into `counts`. + /// The kernel writes a `uint16_t` count of performance levels and six + /// bytes of padding, then for each level five `uint64_t`: instructions, + /// cycles, user time, system time, energy (nJ). + /// + /// `None` unless the call wrote exactly that: the 8-byte header and one + /// 40-byte record for each level the header names, at least one. A + /// failed call and a result of any other size — a layout this crate does + /// not know — are no count, never a field read from the wrong place. + /// Seen on an M5 Max and an M3 Ultra (macOS 27.0.1): 88 bytes, two + /// levels. + pub(crate) fn energy_nj(counts: &[u8], wrote: i32) -> Option { + let levels = usize::from(u16::from_ne_bytes([*counts.first()?, *counts.get(1)?])); + let size = 8 + levels * 40; + if levels == 0 || size > counts.len() || usize::try_from(wrote).ok() != Some(size) { + return None; + } + let mut nj = 0u64; + for level in 0..levels { + let at = 8 + level * 40 + 32; + let mut energy = [0u8; 8]; + energy.copy_from_slice(&counts[at..at + 8]); + nj = nj.saturating_add(u64::from_ne_bytes(energy)); + } + Some(nj) + } + + #[cfg(test)] + mod tests { + use super::*; + use std::cell::RefCell; + + /// The thread is seen to leave its core only when its own count + /// rose across a sleep: the sleeps are taken in turn until one does. + /// A count that held, fell or could not be read is not a thread + /// seen to leave, and an unreadable count takes no further sleep. + #[test] + fn a_thread_is_seen_to_leave_its_core_only_by_its_own_count_rising() { + let sleeps = [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1)]; + let seen = |counts: &[Option]| { + let mut counts = counts.iter().copied(); + let slept = RefCell::new(Vec::new()); + let left = left_its_core(&sleeps, || counts.next().flatten(), |pause| slept.borrow_mut().push(pause)); + (left, slept.into_inner()) + }; + assert_eq!(seen(&[Some(300), Some(301)]), (true, vec![sleeps[0]]), "rose across the first sleep"); + assert_eq!( + seen(&[Some(300), Some(300), Some(300), Some(300), Some(300), Some(9_000)]), + (true, sleeps.to_vec()), + "held across two sleeps, rose across the third" + ); + assert_eq!(seen(&[Some(300); 6]), (false, sleeps.to_vec()), "held across every sleep"); + assert_eq!(seen(&[Some(300), Some(200), Some(200), Some(100), Some(100), Some(50)]), (false, sleeps.to_vec()), "fell"); + assert_eq!(seen(&[None]), (false, vec![]), "unreadable before any sleep"); + assert_eq!(seen(&[Some(300), None]), (false, vec![sleeps[0]]), "unreadable after a sleep"); + assert!(!left_its_core(&[], || Some(1), |_| panic!("slept")), "no sleep, nothing seen"); + assert_eq!(SLEEPS.iter().sum::(), Duration::from_micros(6_250)); + assert!(SLEEPS.windows(2).all(|w| w[0] < w[1]) && SLEEPS[0] >= Duration::from_micros(50), "{SLEEPS:?}"); + } + + /// A thread's counts as the kernel writes them: `levels` in the + /// first two bytes, six of padding, then five u64 a level, the fifth + /// its energy. + fn counts(levels: u16, energy_nj: &[u64]) -> Vec { + let mut bytes = vec![0u8; THREAD_COUNTS_SIZE]; + bytes[..2].copy_from_slice(&levels.to_ne_bytes()); + for (level, nj) in energy_nj.iter().enumerate() { + for (field, word) in [9_001u64, 9_002, 9_003, 9_004, *nj].into_iter().enumerate() { + let at = 8 + level * 40 + field * 8; + bytes[at..at + 8].copy_from_slice(&word.to_ne_bytes()); + } + } + bytes + } + + /// The energy is each level's fifth u64, summed; and a result of any + /// size but the header and one record per level named is no count. + #[test] + fn the_threads_energy_is_read_only_from_the_layout_known() { + assert_eq!(energy_nj(&counts(2, &[4_000_000, 600]), 88), Some(4_000_600), "two levels, 88 bytes"); + assert_eq!(energy_nj(&counts(1, &[42]), 48), Some(42)); + assert_eq!(energy_nj(&counts(3, &[1, 10, 100]), 128), Some(111)); + assert_eq!(energy_nj(&counts(2, &[u64::MAX, 1]), 88), Some(u64::MAX), "the sum saturates"); + let two = counts(2, &[4_000_000, 600]); + for (wrote, why) in [(-1, "the call failed"), (0, "nothing written"), (48, "one record"), (87, "short"), (128, "long")] { + assert_eq!(energy_nj(&two, wrote), None, "{why}"); + } + assert_eq!(energy_nj(&counts(0, &[]), 8), None, "no performance level"); + assert_eq!(energy_nj(&counts(13, &[]), 8 + 13 * 40), None, "more levels than the buffer holds"); + assert_eq!(energy_nj(&[2], 88), None, "no header"); + assert_eq!(THREAD_COUNTS_FLAVOR, 34); + } + } +} + /// This process's own CPU energy on macOS, as the kernel attributes it to /// this process's threads: `ri_energy_nj` of `proc_pid_rusage(getpid(), /// RUSAGE_INFO_V6)` (libproc; public, no privilege, no entitlement). @@ -4499,11 +4672,48 @@ pub use macos_powermetrics::MacosPowermetricsCounter; /// measured. A caller whose metered work runs on the CPU in this process /// opts in with [`crate::detect_in_process`] or /// [`MacosProcessEnergyCounter::try_new`]. +/// +/// **Each read is taken only once the reading thread is seen to have left +/// its core** (`reading_thread`): the kernel counts a thread's energy into +/// the process's only then, so a read from a thread still on its core lacks +/// what that thread spent since it last left one, and a span bracketed by +/// two such reads holds what the thread spent before the span and lacks its +/// own tail. The read sleeps 50 µs, then 200 µs, 1 ms and 5 ms, until the +/// reading thread's own energy count rose across a sleep, and only then +/// reads the process. A read whose thread was not seen to leave is an +/// error, not a short count: every consumer here takes a failed read as no +/// span, and keeps its estimate. With it, the same spans on the same host, +/// quiet and under 40 busy loops (110 runs of 40 spans of each kind): every +/// 1 ms span read 79% or more of the tests' own window around it (98% on +/// the quiet host), and no sleep read more than 3% of the window that held +/// the burn before it. +/// +/// What that costs, the sleep and the wait for a core after it: 83 µs a +/// read at the median on the quiet host and 113 µs at most; under 40 busy +/// loops (load average up to 105 on 32 cores), 226 µs at the median over +/// the runs, 1.5 ms at the median of the worst run, and up to 38 ms for one +/// read; against under 1 µs for the read alone. A read that fails costs all +/// four sleeps (6.25 ms) and their waits. A span also holds its closing +/// read's own wake-up, a few tens of microjoules (31 µJ for a span over a +/// 500 ms sleep), which is most of the figure for a span over much less +/// than a millisecond of work: such a span is a true reading of what this +/// process spent between its two reads, over that work and not under it. A +/// caller with many short pieces of work brackets the lot with one span, +/// not each with its own. +/// +/// Only the reading thread is seen to leave. Another thread of the process +/// that is on a core at a read is short by what it spent since it last left +/// one, up to a quantum: work on the thread that takes both reads is read +/// whole, and work on other threads (a thread pool, or a task an async +/// runtime moved to another thread between the two reads) to within a +/// quantum for each such thread at each end. The liveness probe samples the +/// count with no sleep: it asks only whether the count keeps advancing under +/// a burn, which it does at every quantum. #[cfg(target_os = "macos")] #[allow(unsafe_code)] mod macos_process_energy { use super::*; - use crate::rail_liveness; + use crate::{rail_liveness, reading_thread}; use std::os::raw::{c_int, c_void}; /// `RUSAGE_INFO_V6` in ``. @@ -4576,6 +4786,9 @@ mod macos_process_energy { unsafe extern "C" { fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + fn proc_pidinfo(pid: c_int, flavor: c_int, arg: u64, buffer: *mut c_void, buffersize: c_int) -> c_int; + fn pthread_self() -> *mut c_void; + fn pthread_threadid_np(thread: *mut c_void, thread_id: *mut u64) -> c_int; fn getpid() -> c_int; } @@ -4584,6 +4797,29 @@ mod macos_process_energy { unsafe { getpid() } } + /// The calling thread's own cumulative CPU energy, in nanojoules: the + /// count a read watches to see the thread leave its core. `None` if the + /// thread's id or its counts cannot be read, or the counts come back in + /// a layout [`reading_thread::energy_nj`] does not know. + pub(crate) fn this_thread_energy_nj() -> Option { + let mut thread = 0u64; + if unsafe { pthread_threadid_np(pthread_self(), &mut thread) } != 0 { + return None; + } + let mut counts = [0u8; reading_thread::THREAD_COUNTS_SIZE]; + let size = c_int::try_from(counts.len()).ok()?; + let wrote = unsafe { + proc_pidinfo(this_pid(), reading_thread::THREAD_COUNTS_FLAVOR, thread, counts.as_mut_ptr() as *mut c_void, size) + }; + reading_thread::energy_nj(&counts, wrote) + } + + /// What a read of this process's own count says when the reading thread + /// was not seen to leave its core before it. + const NOT_SEEN_OFF_CORE: &str = "the reading thread was not seen to leave its core before a read of its own \ + process's energy: the count could lack what the thread spent since it last \ + did, so it was not read"; + /// The cumulative CPU energy, in nanojoules, the kernel attributes to the /// threads of process `pid`; `None` when `proc_pid_rusage` fails (no such /// process, or one this user may not inspect). @@ -4600,6 +4836,10 @@ mod macos_process_energy { #[derive(Debug)] pub struct MacosProcessEnergyCounter { pid: i32, + /// The reading thread's own energy count, which every read is + /// checked against: [`this_thread_energy_nj`], but for a test of a + /// thread that is never seen to leave its core. + thread_count: fn() -> Option, } impl MacosProcessEnergyCounter { @@ -4615,7 +4855,7 @@ mod macos_process_energy { /// every status the gate does not admit declines. pub(crate) fn try_new_given(status: CounterStatus) -> Result { if rail_liveness::admits_vendor_counter(status) { - Ok(Self { pid: this_pid() }) + Ok(Self { pid: this_pid(), thread_count: this_thread_energy_nj }) } else { Err(Error::NoCounter) } @@ -4624,8 +4864,16 @@ mod macos_process_energy { impl JouleCounter for MacosProcessEnergyCounter { /// This process's cumulative CPU energy since it started, in µJ - /// (`ri_energy_nj` / 1000). + /// (`ri_energy_nj` / 1000), read once the calling thread is seen to + /// have left its core, so the count holds all that thread spent + /// before the read. `Err` where it was not seen to leave within + /// [`reading_thread::SLEEPS`]: the process's count is then not read, + /// and a caller that brackets a span with this read has no reading + /// of the span, never a short one. Sleeps at least 50 µs. fn read_microjoules(&self) -> Result { + if !reading_thread::left_its_core(&reading_thread::SLEEPS, self.thread_count, std::thread::sleep) { + return Err(Error::Backend(NOT_SEEN_OFF_CORE.to_string())); + } energy_nj(self.pid) .map(|nj| nj / 1_000) .ok_or_else(|| Error::Backend("proc_pid_rusage(RUSAGE_INFO_V6) failed".to_string())) @@ -4666,10 +4914,28 @@ mod macos_process_energy { /// The real probe: this process's counter, the CPU-burning tick (this /// thread's burn is this process's work, so a live counter advances in /// every interval) and the monotonic clock. Cached by - /// [`crate::process_energy_status`], its only caller. + /// [`crate::process_energy_status`], its only caller. The probe samples + /// the count with no sleep before a sample. + /// + /// `Unavailable`, the probe not run, where the calling thread's own + /// energy count does not read: every read the counter takes is checked + /// against that count, so a counter there could never read. pub(crate) fn host_status() -> CounterStatus { let pid = this_pid(); - status_with(|| energy_nj(pid), crate::clocks::cpu_burn_tick, crate::clocks::wall_now) + status_where(this_thread_energy_nj().is_some(), || { + status_with(|| energy_nj(pid), crate::clocks::cpu_burn_tick, crate::clocks::wall_now) + }) + } + + /// The counter's status on a host where the reading thread's own energy + /// count reads, or does not: what `probe` finds where it does, and + /// `Unavailable`, with no probe run, where it does not. + pub(crate) fn status_where(thread_count_reads: bool, probe: impl FnOnce() -> CounterStatus) -> CounterStatus { + if thread_count_reads { + probe() + } else { + CounterStatus::Unavailable + } } #[cfg(test)] @@ -4721,7 +4987,54 @@ mod macos_process_energy { #[test] fn no_process_no_reading() { assert_eq!(energy_nj(-1), None); - assert!(MacosProcessEnergyCounter { pid: -1 }.read_microjoules().is_err()); + assert!(MacosProcessEnergyCounter { pid: -1, thread_count: this_thread_energy_nj }.read_microjoules().is_err()); + } + + /// A read whose thread is never seen to leave its core is no read: + /// an error after every sleep, never the count as it stands — which + /// could lack what the thread spent — and an error at once when the + /// thread's own count cannot be read. A consumer takes either as no + /// span and keeps its estimate. + #[test] + fn a_read_whose_thread_is_never_seen_off_its_core_fails() { + let held = MacosProcessEnergyCounter { pid: this_pid(), thread_count: || Some(7) }; + let started = std::time::Instant::now(); + let read = held.read_microjoules(); + let took = started.elapsed(); + assert!(matches!(&read, Err(Error::Backend(why)) if why.contains("not seen to leave its core")), "{read:?}"); + let every_sleep: Duration = reading_thread::SLEEPS.iter().sum(); + assert!(took >= every_sleep, "gave up after {took:?}, before all of {:?}", reading_thread::SLEEPS); + + let unreadable = MacosProcessEnergyCounter { pid: this_pid(), thread_count: || None }; + let read = unreadable.read_microjoules(); + assert!(matches!(&read, Err(Error::Backend(why)) if why.contains("not seen to leave its core")), "{read:?}"); + } + + /// On this host the calling thread's own count reads, in the layout + /// known, and a read of the counter sees the thread leave its core: + /// the path every reading takes. Two reads are in order, and the + /// first is this process's count: no more than the count as it + /// stands just after it. + #[test] + fn on_this_host_a_read_sees_the_reading_thread_leave_its_core() { + let thread = this_thread_energy_nj(); + eprintln!("process-energy: this thread's own energy count: {thread:?} nJ"); + assert!(thread.is_some(), "this thread's own energy count does not read here"); + let c = MacosProcessEnergyCounter::try_new_given(CounterStatus::Live).expect("Live constructs"); + let first = c.read_microjoules().expect("the reading thread was not seen to leave its core"); + let now = energy_nj(this_pid()).expect("this process's count") / 1_000; + let second = c.read_microjoules().expect("the reading thread was not seen to leave its core"); + assert!(first <= now && now <= second, "{first} µJ, then {now} µJ as it stands, then {second} µJ"); + } + + /// A host on which the reading thread's own count does not read has + /// no process counter: `Unavailable`, and the probe is not run. + #[test] + fn a_host_without_the_threads_count_has_no_process_counter() { + assert_eq!(status_where(false, || panic!("probed a counter no read could be checked on")), CounterStatus::Unavailable); + for status in [CounterStatus::Live, CounterStatus::Frozen, CounterStatus::Unavailable] { + assert_eq!(status_where(true, || status), status); + } } } } @@ -4757,6 +5070,14 @@ pub fn process_energy_status() -> CounterStatus { /// span over work done anywhere else reads only this process's share of it. /// That is why [`detect`] never selects it, and why only a caller that knows /// its work stays in-process should ask for it. +/// +/// Each read of the process counter sleeps at least 50 µs before it reads — +/// about 80 µs a read on a quiet host, a few hundred on a loaded one — +/// because it is taken only once the reading thread is seen to have left its +/// core ([`MacosProcessEnergyCounter`]). A span bracketed by two reads +/// therefore costs two such sleeps and holds its closing read's own wake-up +/// (tens of microjoules): bracket a batch of short operations with one span, +/// not each operation with its own. pub fn detect_in_process() -> Box { detect_in_process_with(process_energy_status, detect) } diff --git a/eoc/eoc-rs/crates/eoc-meter/tests/process_energy_short_span.rs b/eoc/eoc-rs/crates/eoc-meter/tests/process_energy_short_span.rs new file mode 100644 index 000000000..9439d7691 --- /dev/null +++ b/eoc/eoc-rs/crates/eoc-meter/tests/process_energy_short_span.rs @@ -0,0 +1,199 @@ +//! Short spans on this process's own CPU energy counter, against an oracle +//! that takes the reading thread off its core by a rule of its own. +//! +//! The kernel adds a thread's CPU energy to its process's count only when the +//! thread leaves its core. A process that reads its own count from a thread +//! still on its core reads a count that lacks what that thread spent since it +//! last left one: a span of a millisecond of work then reads nothing, and a +//! span opened straight after other work reads that work as its own. This +//! file brackets exactly such spans with two reads of the counter, as every +//! consumer of a [`JouleCounter`] does, and holds each delta against the +//! tests' own window around it. +//! +//! One test binary with one test: the counter's domain is every thread of the +//! process, and the oracle's check is the process's context-switch count, so +//! nothing else may run here. No joule figure, joules per CPU-second or +//! timing is asserted: what a millisecond of CPU costs follows the core that +//! ran it, and a loaded host stretches everything's wall time. + +#![cfg(target_os = "macos")] + +use std::os::raw::{c_int, c_void}; +use std::time::{Duration, Instant}; + +use eoc_meter::{CounterStatus, JouleCounter, MacosProcessEnergyCounter}; + +unsafe extern "C" { + fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + fn proc_pidinfo(pid: c_int, flavor: c_int, arg: u64, buffer: *mut c_void, buffersize: c_int) -> c_int; + fn clock_gettime_nsec_np(clock_id: u32) -> u64; +} + +/// `CLOCK_THREAD_CPUTIME_ID` in macOS ``. +const CLOCK_THREAD_CPUTIME_ID: u32 = 16; + +/// This thread's CPU time. +fn thread_cpu() -> Duration { + Duration::from_nanos(unsafe { clock_gettime_nsec_np(CLOCK_THREAD_CPUTIME_ID) }) +} + +/// Spin this thread until it has used `d` of its own CPU time (or 20 s of +/// wall time have passed), however loaded the host is. +fn burn(d: Duration) { + let (started, wall) = (thread_cpu(), Instant::now()); + let mut acc: u64 = 0; + while thread_cpu() - started < d && wall.elapsed() < Duration::from_secs(20) { + for _ in 0..1_000 { + acc = std::hint::black_box(acc.wrapping_add(1)); + } + } +} + +fn me() -> c_int { + std::process::id() as c_int +} + +/// The oracle's read of this process's `ri_energy_nj`: `proc_pid_rusage(pid, +/// RUSAGE_INFO_V6)` into 464 raw bytes, the count at byte 336. +fn oracle_energy_nj() -> u64 { + let mut words = [0u64; 464 / 8]; + let rc = unsafe { proc_pid_rusage(me(), 6, words.as_mut_ptr() as *mut c_void) }; + assert_eq!(rc, 0, "the oracle's proc_pid_rusage"); + words[336 / 8] +} + +/// How many times this process's threads have been switched off a core: +/// `pti_csw`, the `int32_t` at byte 80 of the 96-byte `proc_taskinfo` that +/// `proc_pidinfo(pid, PROC_PIDTASKINFO = 4)` fills. +fn oracle_context_switches() -> i32 { + let mut info = [0i32; 96 / 4]; + let wrote = unsafe { proc_pidinfo(me(), 4, 0, info.as_mut_ptr() as *mut c_void, 96) }; + assert_eq!(wrote, 96, "the oracle's proc_pidinfo(PROC_PIDTASKINFO)"); + info[80 / 4] +} + +/// The oracle's read of this process's energy, taken once this thread has +/// left its core by the oracle's own rule: a sleep of 1 ms, then 2, 4 and 8, +/// until the process's context-switch count rose across one. Only this +/// test's thread runs in this process, so a rise is this thread's switch, +/// and the read after it holds all the thread spent before it. The counter +/// under test shares neither call nor number with this. +fn oracle_energy_nj_off_core() -> u64 { + let left = [1, 2, 4, 8].into_iter().any(|ms| { + let before = oracle_context_switches(); + std::thread::sleep(Duration::from_millis(ms)); + oracle_context_switches() > before + }); + assert!(left, "the oracle never saw this thread leave its core across sleeps of 1, 2, 4 and 8 ms"); + oracle_energy_nj() +} + +/// What a span is to a consumer of the counter: the delta of its two reads, +/// only when both succeeded and the counter advanced between them. Anything +/// else measured nothing, and the consumer keeps its own estimate. +fn span_reading(start: eoc_core::Result, end: eoc_core::Result) -> Option { + match (start, end) { + (Ok(s), Ok(e)) if e > s => Some(e - s), + _ => None, + } +} + +#[test] +fn a_short_span_reads_what_an_oracle_that_leaves_its_core_its_own_way_reads() { + const TRIES: usize = 40; + let status = eoc_meter::process_energy_status(); + eprintln!("process-energy short span: status={status:?}"); + assert_eq!(status, CounterStatus::Live, "this process's CPU energy counter is not live here"); + let c = MacosProcessEnergyCounter::try_new().expect("the process counter is live here"); + + // 1. A millisecond of this thread's CPU between two reads of the counter. + // The oracle's window opens before the first read and closes after the + // second, each end read once this thread has left its core, so it + // holds the burn and both readers' own reads and wake-ups. A reading + // is the span's when it is no more than that window (and the µJ the + // two reads round away) and at least two thirds of it: the readers' + // own cost does not shrink with the burn's, and was up to 21% of the + // window on an M3 Ultra under 40 busy loops (2% when quiet). A reading + // above the window is not this process's count at all. + let (mut shares, mut none, mut short, mut over) = (Vec::new(), 0usize, Vec::new(), Vec::new()); + for i in 0..TRIES { + let before = oracle_energy_nj_off_core(); + let start = c.read_microjoules(); + burn(Duration::from_millis(1)); + let end = c.read_microjoules(); + let oracle_nj = oracle_energy_nj_off_core() - before; + match span_reading(start, end).map(|uj| uj * 1_000) { + None => none += 1, + Some(nj) if nj > oracle_nj + 1_000 => over.push((i, nj / 1_000, oracle_nj)), + Some(nj) if nj * 3 < oracle_nj * 2 => short.push((i, nj / 1_000, oracle_nj)), + Some(nj) => shares.push(nj * 1_000 / oracle_nj.max(1)), + } + } + eprintln!( + "process-energy short span: 1 ms burn x {TRIES}: {} read within the oracle's window (at least {}/1000 of it), \ + {none} not read, {} read short {short:?}, {} read over {over:?} (try, µJ, oracle nJ)", + shares.len(), + shares.iter().min().copied().unwrap_or(0), + short.len(), + over.len() + ); + + // 2. A 2 ms sleep between two reads, straight after 8 ms of this thread's + // CPU that the span does not cover. The burn is still on the thread, + // not yet in the process's count, when the span opens; a counter whose + // first read does not take the thread off its core reads the burn as + // the sleep's energy. The oracle's window is the burn and the sleep: a + // reading for the sleep is under a quarter of it (it was under 1% on + // a quiet host and at most 3% under 40 busy loops), or no reading at + // all. + let (mut slept, mut slept_none, mut leaked) = (Vec::new(), 0usize, Vec::new()); + for i in 0..TRIES { + let before = oracle_energy_nj_off_core(); + burn(Duration::from_millis(8)); + let start = c.read_microjoules(); + std::thread::sleep(Duration::from_millis(2)); + let end = c.read_microjoules(); + let oracle_nj = oracle_energy_nj_off_core() - before; + match span_reading(start, end).map(|uj| uj * 1_000) { + None => slept_none += 1, + Some(nj) if nj * 4 >= oracle_nj => leaked.push((i, nj / 1_000, oracle_nj)), + Some(nj) => slept.push(nj * 1_000 / oracle_nj.max(1)), + } + } + eprintln!( + "process-energy short span: 2 ms sleep after an 8 ms burn x {TRIES}: {} read under a quarter of the oracle's \ + window (at most {}/1000 of it), {slept_none} not read, {} read the burn before the span {leaked:?} (try, µJ, \ + oracle nJ)", + slept.len(), + slept.iter().max().copied().unwrap_or(0), + leaked.len() + ); + + // 3. What one read costs, in wall time: reported, never asserted. + let mut micros: Vec = (0..200) + .map(|_| { + let t = Instant::now(); + let _ = c.read_microjoules(); + t.elapsed().as_micros() + }) + .collect(); + micros.sort_unstable(); + eprintln!( + "process-energy short span: one read of the counter costs {} µs at the median, {} µs at the 95th percentile, \ + {} µs at most (200 reads)", + micros[100], micros[190], micros[199] + ); + + assert!(over.is_empty(), "a span read more than this process spent around it: {over:?}"); + // A tenth of the spans may miss the band: on a loaded host the oracle's + // own reads can land on a costlier core than the burn did, and a read + // whose thread was not seen to leave its core is no reading by design. + // A counter that does not take the reading thread off its core misses on + // most spans (all 40, on an idle host). + assert!( + (none + short.len()) * 10 <= TRIES, + "{none} of {TRIES} 1 ms spans were not read and {} were read short: {short:?}", + short.len() + ); + assert!(leaked.len() * 10 <= TRIES, "{} of {TRIES} sleeps read the burn before them: {leaked:?}", leaked.len()); +} diff --git a/eoc/standards/sci-for-ai-energy-provenance-annex.md b/eoc/standards/sci-for-ai-energy-provenance-annex.md index 62470e7e6..2191c07aa 100644 --- a/eoc/standards/sci-for-ai-energy-provenance-annex.md +++ b/eoc/standards/sci-for-ai-energy-provenance-annex.md @@ -74,6 +74,14 @@ at all, the median step was ~20 mJ, two orders above the 1 ms step. It accrues in lumps. A sampler reading it every 500 µs would see nothing most of the time and a 20 mJ jump occasionally, and would report both as measurements. +The lumps are the kernel's bookkeeping, not the hardware's. A thread's energy is +added to its process's count when the thread leaves its core, so a reader on a +running thread sees nothing until that thread's scheduling quantum ends, and then +sees all of it at once. A reader that first leaves its core, and checks that its +own thread's count moved across that pause, reads the same 1 ms spans to within a +few percent of an independent read; unchecked, on an idle host, it read none of +them. The counter is exact; an unchecked read of it is not. + ## c. Proposed requirements An `E` figure claiming to be **measured** MUST carry: diff --git a/jcp/README.md b/jcp/README.md index 97561d76d..0ac850d4d 100644 --- a/jcp/README.md +++ b/jcp/README.md @@ -45,7 +45,7 @@ jcp/ - **`jcp-trace`** — ingests an agent run's **OpenTelemetry GenAI trace** (`gen_ai.*` semantic conventions: `chat` / `tool` / `retriever` spans with token usage) and its **evaluation assessments** (judge / human / code feedback), attaches **per-span joules** (measured where a meter is present, else `Estimator` from token counts — provenance never silently upgrades), and seals one **`eval/1` JCR-1 receipt**: the per-span token + joule breakdown with the headline `uj_per_accepted_token` at the **weakest** provenance present, the assessments, a deterministic **quality-gate** verdict (the sealed, declarative analog of a CI assert), and a **readiness projection** an ARL validation-axis claim consumes. The observability stacks *record* a trace and *log* a judge score in a table; this is the interop projection that **seals** the same trace, puts a joule on it, and hash-chains it via `EvalLog` — no new cryptography. The **gate is content-addressed**, so the sealed receipt commits to exactly which bar it was judged against (a tamper-evident artifact, not a mutable in-code `assert`), and **`align_threshold` / `Judge`** calibrate a judge's decision threshold to human pass/fail labels — judge alignment as a reproducible number, not a UI click. Behind the `server` feature, a std-only **OTLP `/v1/traces` receiver** lets any OpenTelemetry exporter POST a `gen_ai.*` trace (with its assessments) and get the sealed `eval/1` receipt back the instant the run ends. - **`jcp-intercept`** — **attested interceptor chains**: a composable, ordered pipeline of transforms *around* each model and tool call — the `before_model` / `after_model` / `before_tool` seams an agent's middleware stack runs, composed onion-order (forward in, reverse out) and stopping at the first refusal or human-approval hold. An interceptor may inspect or **rewrite** the request (redact a secret before it reaches the model, trim stale context), **refuse** it, or **hold** it for a human. The difference from the incumbent's arbitrary in-process hooks: every step seals an **`intercept/1`** JCR-1 receipt carrying the request digest **before and after** the step (so a redaction or a trim is provable — the content itself never sealed, only its hash), the seam, the outcome, and the **metered joules** at their honest provenance, hash-chained — the exact transform pipeline that produced a model request becomes reconstructable and verifiable by anyone, and a step cannot run un-sealed. Three reference interceptors — `Redact` (a content transform), `CallLimit` (a guardrail), `Approve` (a human-in-the-loop hold) — each reuse a primitive the family already holds rather than reinventing it. - **`jcp-efficiency`** — the **energy-efficiency spec**, surfaced as a sealed receipt. The dark-factory economics turn on four figures — **joules per accepted token, tokens per second, value per token, and the tokens/joules/dollars spent per COMPLETED, VERIFIED unit of work** — and the incumbents publish, at best, a *rate* (cost per token) that can't tell you whether the spend bought a result. An **`efficiency/1`** JCR-1 receipt records all four at honest provenance, hash-chained, with the one thing the rates omit: the **outcome anchor** (`completed` + a verdict). A measurement that didn't complete is spend that bought nothing, and the receipt says so. `aggregate` then splits value-delivered from total spend across a chain — charging *every* attempt (including the failed ones) against the results actually delivered — so `tokens_per_completed_unit` / `uj_per_completed_unit` / `value_per_joule` become the honest efficiency a "cost per token" number is designed to hide. Integers and strings only (JCR-1 forbids bools/floats); the rate figures recompute from the sealed inputs on read. -- **`jcp-energy`** — the metering ladder (SPEC §5.1): RAPL package counters (Linux powercap, wraparound-corrected, `HwShunt`, only while every package counter is live — `rapl_status()`), NVML GPU energy behind the `nvml` feature (`HwShunt` and `Partial`, since it does not read the CPU's share; only while live — `nvml_status()`), the macOS kernel's per-process CPU energy count (`proc_pid_rusage`'s `ri_energy_nj`; `HwShunt`, whole for in-process CPU work, only while live — `process_energy_status()`; it covers this process's threads, not children, the GPU or DRAM, so a span that reaps a child process or ends with one is `Partial`; it is live on macOS 27.0.1 where IOReport's CPU rails are not), Apple Silicon IOReport (`HwShunt`, only while every CPU energy rail, each die's on a multi-die part, is live — on macOS 27.0.1 that rail is republished in lumps, so there the rung is declined and `ioreport_status()` says why; `Meter::detect_explained()` names the rung selected and why each one above it was declined), a time×power model at a power the host calibrated (`ModelBased`, `Meter::time_power`), and estimates no host calibrated (`Estimator`): time × the documented default power — the rung `Meter::detect()` falls to, always available — and a constant per-op figure. A vendor counter's reading is real but vendor-opaque and relayed by the platform, and it counts as a reading only while the counter is live (SPEC §5). Measured when the platform exposes it, estimated when it doesn't — and the provenance always says which; a hardware backend that fails mid-reading degrades honestly to the default-power estimate. +- **`jcp-energy`** — the metering ladder (SPEC §5.1): RAPL package counters (Linux powercap, wraparound-corrected, `HwShunt`, only while every package counter is live — `rapl_status()`), NVML GPU energy behind the `nvml` feature (`HwShunt` and `Partial`, since it does not read the CPU's share; only while live — `nvml_status()`), the macOS kernel's per-process CPU energy count (`proc_pid_rusage`'s `ri_energy_nj`; `HwShunt`, whole for in-process CPU work, only while live — `process_energy_status()`; it covers this process's threads, not children, the GPU or DRAM, so a span that reaps a child process or ends with one is `Partial`; each end of a span is read only once the metering thread is seen to have left its core, because the kernel counts a thread's energy into its process's only then, and a span with an end not so checked is the estimate, never a reading; it is live on macOS 27.0.1 where IOReport's CPU rails are not), Apple Silicon IOReport (`HwShunt`, only while every CPU energy rail, each die's on a multi-die part, is live — on macOS 27.0.1 that rail is republished in lumps, so there the rung is declined and `ioreport_status()` says why; `Meter::detect_explained()` names the rung selected and why each one above it was declined), a time×power model at a power the host calibrated (`ModelBased`, `Meter::time_power`), and estimates no host calibrated (`Estimator`): time × the documented default power — the rung `Meter::detect()` falls to, always available — and a constant per-op figure. A vendor counter's reading is real but vendor-opaque and relayed by the platform, and it counts as a reading only while the counter is live (SPEC §5). Measured when the platform exposes it, estimated when it doesn't — and the provenance always says which; a hardware backend that fails mid-reading degrades honestly to the default-power estimate. - **`jcp-gateway`** — the **energy-native MCP gateway**: a JCP enforcement point that sits in front of an MCP server so an existing client/server pair keeps its transport while every `tools/call` becomes capability-scoped, joule-budgeted, and sealed. The novel mechanic is two-phase metered enforcement: the call is *authorized* before it runs (no debit, because the cost isn't yet known), the upstream call is **metered** by the sibling Sandbox standard's energy probe (Apple Silicon IOReport, RAPL, NVML — vendor energy counters, whose readings are real but vendor-opaque and relayed by the platform, and which count as readings only while the counter is live for the work, SPEC §5; otherwise the figure is an estimate and is graded as one), and the metered joules are debited from the grant — so the budget that stops a runaway agent is denominated in joules, not a token estimate. Where the upstream server is a local process whose CPU energy the host's kernel counts live (macOS `proc_pid_rusage`), each call is read on that server's own process tree, the work's own process rather than the machine (SPEC §5.1, rung 3): sealed `HwShunt`, and `Whole` only when nothing was seen missing from the tree (no descendant reaped or exited in the span, no GPU client held, no in-process Neural Engine memory, every member read and quiet at both ends) and the operator has declared, with `--upstream-self-contained`, that the server hands no work to a process outside its tree; otherwise `Partial`, with the response's `_meta` naming why. Every decision, allow and deny, seals into a **hash-chained receipt log**: excise, reorder, or splice a receipt and the chain breaks at that point. A denied call never reaches the server (the live 2025–26 MCP exploits land on tool *output*, which the gateway frames as untrusted `data` that can never exercise a capability), and the `jcp-gateway` binary runs it over stdio in front of any MCP-server subprocess. This is the chokepoint the AI-gateway field occupies, on the two axes nobody there holds: the unit of account is the joule, and the audit is cryptographic and tamper-evident rather than a dollar figure and a span. - **`jcp-wire`** — the `jcp/1` wire binding (SPEC §11): 4-byte length prefix + canonical det-CBOR over any byte stream, with TCP and Unix-socket endpoints and a client. The decoder rejects non-canonical bodies, so a message has exactly one wire form. Requests carry the full delegation chain and are **caller-signed** — the endpoint authenticates from the request itself and denies an impersonation `bad-signature`, sealed like any other decision. Responses carry the deterministic decision and the sealed receipt. - **`jcp-threshold`** — threshold actors (SPEC §2.2): a `did:key` whose private key is split k-of-n with FROST (RFC 9591); the group key is an ordinary Ed25519 key, so a 2-of-3 team issues, holds, and signs wire requests with nothing else in JCP changing. Shares come from a trusted dealer or **distributed key generation** — with DKG the group's private key never exists anywhere, not even momentarily. The two-agent rule for irreversible actions, refused by arithmetic rather than policy. diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index 374f5c9c2..06a6c1872 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -46,6 +46,19 @@ //! for an unprivileged reader on macOS 27.0.1, where IOReport's CPU rails //! are not. A span over which it did not advance is the default-power //! estimate. +//! +//! The kernel adds a thread's energy to the count only when the thread +//! leaves a core, and a process's read of its own count does not take the +//! reading thread off its core. So each end of a span is read only once +//! the metering thread is SEEN to have left its core: it sleeps (50 µs, +//! then 200 µs, 1 ms, 5 ms) until its own energy count +//! (`proc_pidinfo`, `PROC_PIDTHREADCOUNTS`) rose across a sleep, which it +//! does only when the kernel adds that thread's energy to the process's. +//! An end whose thread was not seen to leave is not read, and the span is +//! the default-power estimate — never a figure that is short of the +//! span's tail, or holds what the thread spent before the span, graded as +//! a reading (SPEC §5.1 rung 3). The rung is selected only where that +//! count reads. //! 4. **IOReport** (Apple Silicon) — the on-die SoC Energy Model counters via //! Apple's IOReport C API (no sudo, no external binary), `Provenance::HwShunt`. //! Like RAPL and NVML it is a vendor energy counter: the count is a real @@ -1105,6 +1118,118 @@ mod rusage_v6 { } } +/// The byte layout of `struct proc_threadcounts`, which macOS's +/// `proc_pidinfo(pid, PROC_PIDTHREADCOUNTS, thread_id, &counts, size)` fills: +/// one thread's counts, by its 64-bit thread id. The flavor and the struct +/// are in the kernel's `` (macOS 13 and later) and +/// not in the SDK's public header, so nothing here trusts the layout further +/// than the call's own return value confirms it: 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 nanojoules. On an M5 Max, macOS 27.0.1: two levels, +/// 88 bytes. +/// +/// The decoding is pure and compiled everywhere, so its tests run on any host, +/// on a fixed byte layout. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +mod thread_counts { + /// `PROC_PIDTHREADCOUNTS`. + pub(crate) const FLAVOR: i32 = 34; + /// The bytes before the first level's record. + pub(crate) const HEADER: usize = 8; + /// The bytes of one level's record: five `uint64_t`. + pub(crate) const LEVEL: usize = 40; + /// Where a level's record keeps its energy: its fifth `uint64_t`. + pub(crate) const ENERGY_NJ: usize = 32; + /// The most performance levels a read leaves room for. + pub(crate) const MAX_LEVELS: usize = 12; + /// The buffer a read hands the kernel. + pub(crate) const SIZE: usize = HEADER + MAX_LEVELS * LEVEL; + + /// The thread's CPU energy in nJ, summed over the performance levels, + /// from the `wrote` bytes the call says it wrote into `counts`. + /// + /// `None` unless that is exactly the header and one record for each + /// level the header names, at least one and no more than the buffer + /// holds. A failed call (`wrote` ≤ 0) and any other size — a layout this + /// crate does not know — are no count, never a field read from the wrong + /// place. + pub(crate) fn energy_nj(counts: &[u8; SIZE], wrote: i32) -> Option { + let levels = usize::from(u16::from_ne_bytes([counts[0], counts[1]])); + if !(1..=MAX_LEVELS).contains(&levels) || usize::try_from(wrote).ok() != Some(HEADER + levels * LEVEL) { + return None; + } + let energy = (0..levels).map(|level| { + let at = HEADER + level * LEVEL + ENERGY_NJ; + let mut word = [0u8; 8]; + word.copy_from_slice(&counts[at..at + 8]); + u64::from_ne_bytes(word) + }); + Some(energy.fold(0, u64::saturating_add)) + } +} + +/// When a process may read its own energy count: once the reading thread has +/// been SEEN to leave its core. +/// +/// The kernel adds a thread's CPU energy to its process's count only when +/// the thread leaves a core (a context switch, or the end of its quantum, +/// about 10 ms of its CPU), and a process's read of its own count does not +/// take the reading thread off its core: its CPU time is current at the +/// read, its energy is not. A span read that way holds, at its start, up to +/// a quantum of what the thread spent BEFORE the span, and lacks, at its +/// end, what the thread spent since it last left a core. Measured on an +/// idle M3 Ultra, macOS 27.0.1, against the tests' own reader that sleeps +/// before each of its reads, 40 spans of each kind a run over six runs: of +/// the spans over 1 ms of the metering thread's CPU, all 40 showed no rise +/// and were the default-power estimate, every run; of the spans over a 2 ms +/// sleep taken straight after 8 ms of that thread's CPU, 39 or 40 were +/// graded `HwShunt` on the burn before them, about 41 mJ for a sleep. (On a +/// loaded host other work takes the thread off its core more often, and the +/// same spans read a part of the work, or of the burn, instead.) With the +/// check below, on that host, idle and under 40 busy loops (110 runs): every +/// span of both kinds was read, the work at 84% or more of the tests' own +/// window around it and the sleep at 6% or less of the window that held the +/// burn. +/// +/// A sleep takes the thread off its core — but not always: when the sleep's +/// timer fires before the thread has blocked, it goes on without leaving. +/// So the thread sleeps and CHECKS: its own energy count +/// (`thread_counts`) is moved by the kernel only when it adds the thread's +/// energy to the process's, so a rise across a sleep is the thread having +/// left its core after all it did before the sleep. The process's +/// context-switch count is no such check: any other thread's switch moves +/// it. The sleeps grow ([`SLEEPS`]), so one that did not block is followed +/// by one that much more surely does. +/// +/// The rule is pure and compiled everywhere, so its tests run on any host. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +mod off_core { + use std::time::Duration; + + /// The sleeps the reading thread takes, in turn, until one is seen to + /// take it off its core: 6.25 ms in all on a read that never is. + pub(crate) const SLEEPS: [Duration; 4] = + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)]; + + /// Whether the reading thread was seen to leave its core: its own energy + /// count (`count`) rose across one of `sleeps`, taken in turn through + /// `sleep`. A count that cannot be read ends the wait at once; one that + /// held across every sleep, or fell, is no evidence. `false` either way, + /// and the caller does not read the process's count. + pub(crate) fn seen(sleeps: &[Duration], mut count: impl FnMut() -> Option, mut sleep: impl FnMut(Duration)) -> bool { + for &pause in sleeps { + let Some(before) = count() else { return false }; + sleep(pause); + let Some(after) = count() else { return false }; + if after > before { + return true; + } + } + false + } +} + /// The kernel's count of this process's own CPU energy, read through /// `proc_pid_rusage(getpid(), RUSAGE_INFO_V6, ...)` from libproc: public API, /// no entitlement, no privilege. `ri_energy_nj` is the cumulative CPU energy @@ -1134,6 +1259,27 @@ mod rusage_v6 { /// Measured on an M5 Max, macOS 27.0.1: 0.002 J/s idle, 2.4 J/s with one /// thread burning, 5.3 J/s with two, changing about every 0.5 ms while /// polled. +/// +/// A span's two reads of the count are each taken only once the metering +/// thread is seen to have left its core (`off_core`), so the count holds +/// all that thread spent before the read; a read not so checked is no read +/// ([`ProcessEnergy::read`]). That covers the thread that reads. Another +/// thread of the process that is on a core at a read is short by what it +/// spent since it last left one, so its share of a span can be off by up to +/// a quantum at each end: work on the thread that opens and closes the span +/// is read whole, and the figure holds what the other threads spent as the +/// kernel had counted it. Each read costs the sleep and the wait for a core +/// after it: on an idle M3 Ultra 79 to 81 µs at the median, 113 µs at most; +/// under 40 busy loops there, 169 µs at the median over 110 runs, 0.6 ms at +/// the median of the worst run, and up to 27 ms for one read (200 reads a +/// run; under 1 µs with no sleep). A read that fails costs all four sleeps +/// (6.25 ms) and their waits. A span also holds its closing read's own +/// wake-up, a few tens of microjoules (59 µJ for a span over a 200 ms sleep, +/// on the M3 Ultra): most of the figure for a span over much less than a +/// millisecond of work, which is then a reading of what the process spent +/// between its two reads, over that work and not under it. The liveness +/// probe samples the count with no sleep: it asks only whether the count +/// keeps advancing under a burn, which it does at every quantum. #[cfg(target_os = "macos")] #[allow(unsafe_code)] mod process_energy { @@ -1141,10 +1287,14 @@ mod process_energy { use crate::liveness; use crate::rusage_v6::{self, ProcessEnergyReading}; + use crate::{off_core, thread_counts}; unsafe extern "C" { fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; fn proc_listchildpids(ppid: c_int, buffer: *mut c_void, buffersize: c_int) -> c_int; + fn proc_pidinfo(pid: c_int, flavor: c_int, arg: u64, buffer: *mut c_void, buffersize: c_int) -> c_int; + fn pthread_self() -> *mut c_void; + fn pthread_threadid_np(thread: *mut c_void, thread_id: *mut u64) -> c_int; fn getpid() -> c_int; } @@ -1168,38 +1318,93 @@ mod process_energy { #[repr(C, align(8))] struct Info([u8; rusage_v6::SIZE]); - /// This process's energy counts, now. `None` if the call fails (a kernel - /// without the V6 flavor). + /// This process's energy counts as the kernel holds them now, read with + /// no sleep before the call: short of what the calling thread spent + /// since it last left a core. `None` if the call fails (a kernel without + /// the V6 flavor). No span is made of this read alone: a span's ends are + /// [`read_off_core`]. pub(crate) fn read() -> Option { let mut info = Info([0; rusage_v6::SIZE]); let rc = unsafe { proc_pid_rusage(getpid(), rusage_v6::FLAVOR, info.0.as_mut_ptr().cast()) }; (rc == 0).then(|| rusage_v6::decode(&info.0)) } - /// The per-process CPU energy counter of this process. Holds nothing: each - /// read asks the kernel about the calling process. + /// A `proc_threadcounts`-sized buffer, aligned as the struct is. + #[repr(C, align(8))] + struct Counts([u8; thread_counts::SIZE]); + + /// The calling thread's own CPU energy count, in nJ: what `off_core` + /// watches. `None` if the thread's id or its counts cannot be read, or + /// the counts come back in a layout `thread_counts` does not know. + pub(crate) fn thread_energy_nj() -> Option { + let mut thread = 0u64; + if unsafe { pthread_threadid_np(pthread_self(), &mut thread) } != 0 { + return None; + } + let mut counts = Counts([0; thread_counts::SIZE]); + let bytes = c_int::try_from(thread_counts::SIZE).ok()?; + let wrote = unsafe { proc_pidinfo(getpid(), thread_counts::FLAVOR, thread, counts.0.as_mut_ptr().cast(), bytes) }; + thread_counts::energy_nj(&counts.0, wrote) + } + + /// One end of a span: this process's energy counts, read once the + /// calling thread is seen to have left its core (`off_core::seen` on + /// `thread_count`, sleeping `off_core::SLEEPS`), so they hold all that + /// thread spent before the read. `None` if the thread was not seen to + /// leave — the process's count is then not read at all — or the read + /// itself fails. + fn read_off_core(thread_count: fn() -> Option) -> Option { + off_core::seen(&off_core::SLEEPS, thread_count, std::thread::sleep).then(read).flatten() + } + + /// The per-process CPU energy counter of this process. Each read asks + /// the kernel about the calling process and the calling thread. #[derive(Debug)] pub struct ProcessEnergy { - _opened: (), + /// The reading thread's own energy count, which each read of a span + /// is checked against: [`thread_energy_nj`], but for a test of a + /// thread that is never seen to leave its core. + thread_count: fn() -> Option, } impl ProcessEnergy { - /// `Some` when the kernel answers for this process. Opening is not - /// selection: [`crate::Meter::detect`] selects the rung only while + /// `Some` when the kernel answers for this process, and for the + /// calling thread's own count: every read of a span is checked + /// against that count, and a counter whose reads could never be + /// checked would only ever estimate. Opening is not selection: + /// [`crate::Meter::detect`] selects the rung only while /// [`crate::process_energy_status`] is Live. pub(crate) fn open() -> Option { - read().map(|_| ProcessEnergy { _opened: () }) + read()?; + thread_energy_nj()?; + Some(ProcessEnergy { thread_count: thread_energy_nj }) } - /// `ri_energy_nj` now, in nJ. + /// A counter whose reading thread is never seen to leave its core: + /// its own count reads, and never moves. + #[cfg(test)] + pub(crate) fn never_off_core() -> Self { + ProcessEnergy { thread_count: || Some(7) } + } + + /// `ri_energy_nj` now, in nJ, with no sleep before the read: the + /// liveness probe's sample. pub(crate) fn read_nj(&self) -> Option { read().map(|r| r.energy_nj) } /// What a span reads at each end: the energy count and the reaped - /// children's CPU time, from one call. + /// children's CPU time, from one call, taken once the calling thread + /// is seen to have left its core. `None` where it was not: that end + /// has no reading, and the span is the default-power estimate + /// (`process_span`). pub(crate) fn read(&self) -> Option { - read() + read_off_core(self.thread_count) + } + + /// [`Self::read`]'s energy count alone, in nJ. + pub(crate) fn read_energy_nj(&self) -> Option { + self.read().map(|r| r.energy_nj) } /// One liveness sample: `ri_energy_nj` as the counter's one rail. @@ -5214,7 +5419,10 @@ pub enum Meter { /// handed to the GPU is not detected. [`Meter::detect`] selects it only /// while the counter is live /// ([`process_energy_status`]), and a span over which it did not advance is - /// the default-power estimate (`process_span`). + /// the default-power estimate (`process_span`). So is a span either of + /// whose two reads the metering thread was not seen to leave its core + /// before: the kernel counts a thread's energy into its process's only + /// when the thread leaves a core, so each read sleeps first and checks. #[cfg(target_os = "macos")] ProcessEnergy(process_energy::ProcessEnergy), /// Apple Silicon IOReport Energy Model energy → `Provenance::HwShunt`, the @@ -5479,6 +5687,10 @@ impl Meter { } #[cfg(target_os = "macos")] Meter::ProcessEnergy(p) => { + // Each read sleeps first, and is taken only once this thread + // is seen to have left its core. The sleeps are outside the + // work's wall time, which the estimate for a span with no + // reading scales by. let before = p.read(); let started = Instant::now(); let out = work(); @@ -5486,7 +5698,9 @@ impl Meter { // The children first, then the count: a child reaped between // the two is then listed, or in the reaped children's time. let children = process_energy::child_count(); - (out, process_span(before, p.read(), children, elapsed.as_nanos())) + // No reading at the start is no span: the end is not read. + let after = before.and_then(|_| p.read()); + (out, process_span(before, after, children, elapsed.as_nanos())) } #[cfg(target_os = "macos")] Meter::IoReport(io) => { @@ -5625,6 +5839,10 @@ pub struct FabricEnergy { pub struct FabricMeter { #[cfg(target_os = "macos")] ioreport: Option, + /// This process's CPU energy count, where the kernel answers for it and + /// for the reading thread's own count its reads are checked against. + #[cfg(target_os = "macos")] + process: Option, } impl FabricMeter { @@ -5632,7 +5850,7 @@ impl FabricMeter { pub fn detect() -> Self { #[cfg(target_os = "macos")] { - FabricMeter { ioreport: ioreport::IoReport::open() } + FabricMeter { ioreport: ioreport::IoReport::open(), process: process_energy::ProcessEnergy::open() } } #[cfg(not(target_os = "macos"))] { @@ -5645,7 +5863,7 @@ impl FabricMeter { let mut out = Vec::new(); #[cfg(target_os = "macos")] { - if process_energy::read().is_some() { + if self.process.is_some() { out.push((Fabric::Cpu, Attribution::Process)); } if self.ioreport.is_some() { @@ -5666,10 +5884,16 @@ impl FabricMeter { /// only for a counter that is live: the Neural Engine is reported only /// once [`npu_rail_liveness`] has proved its rail live, because on macOS /// 27.0.1 an unprivileged reader's `ANE0` holds through real ANE work. + /// + /// The CPU figure is this process's own count, read at each end only + /// once the calling thread is seen to have left its core (the kernel + /// counts a thread's energy into its process's only then). A span with + /// an end not so read has no CPU figure: it is omitted, not reported + /// short or with what the thread spent before the span. pub fn measure(&self, work: impl FnOnce() -> T) -> (T, Vec) { - let started = std::time::Instant::now(); #[cfg(target_os = "macos")] - let cpu_before = process_energy::read().map(|r| r.energy_nj); + let cpu_before = self.process.as_ref().and_then(|p| p.read_energy_nj()); + let started = std::time::Instant::now(); #[cfg(target_os = "macos")] let io_before = self.ioreport.as_ref().and_then(|m| m.read()); @@ -5679,7 +5903,8 @@ impl FabricMeter { let mut readings = Vec::new(); #[cfg(target_os = "macos")] { - if let (Some(b), Some(a)) = (cpu_before, process_energy::read().map(|r| r.energy_nj)) { + let cpu_after = cpu_before.and_then(|_| self.process.as_ref()?.read_energy_nj()); + if let (Some(b), Some(a)) = (cpu_before, cpu_after) { readings.push(FabricEnergy { fabric: Fabric::Cpu, uj: a.saturating_sub(b) / 1_000, @@ -6276,11 +6501,13 @@ fn nvml_span(before_uj: Option, after_uj: Option, elapsed_ns: u128) -> /// /// A reading, `HwShunt`, only when `ri_energy_nj` advanced across the span: /// then it is the rise, in µJ rounded **up**, so a span that spent energy never -/// reads as zero and the work is never under-debited by the rounding. The -/// count changes about every 0.5 ms on a busy thread, so a shorter span can see -/// no rise though the work ran; that span, a count that fell, and a failed read -/// are the time×power figure at the default power, `Estimator`, as IOReport's -/// held spans are ([`ioreport_span`]). Never `HwShunt` on a figure no counter +/// reads as zero and the work is never under-debited by the rounding. Each +/// read is taken once the metering thread is seen to have left its core, so +/// the count holds what that thread spent up to the read; an end where it was +/// not seen to leave has no read (`None`). That span, a span over which the +/// count did not rise, a count that fell, and a failed read are the +/// time×power figure at the default power, `Estimator`, as IOReport's held +/// spans are ([`ioreport_span`]). Never `HwShunt` on a figure no counter /// read. /// /// The reading covers the whole span only when no child process can have @@ -7951,6 +8178,303 @@ mod tests { }); } + /// One `proc_threadcounts` as the kernel writes it into a read's buffer: + /// `levels` in its first two bytes, six bytes of padding, then for each + /// of `energy_nj` a record of five `uint64_t` whose fifth is that level's + /// energy and whose first four are other counts. + fn thread_counts_bytes(levels: u16, energy_nj: &[u64]) -> [u8; thread_counts::SIZE] { + let mut counts = [0u8; thread_counts::SIZE]; + counts[..2].copy_from_slice(&levels.to_ne_bytes()); + for (level, nj) in energy_nj.iter().enumerate() { + let record = thread_counts::HEADER + level * thread_counts::LEVEL; + for (field, word) in [1_111u64, 2_222, 3_333, 4_444, *nj].into_iter().enumerate() { + counts[record + field * 8..record + field * 8 + 8].copy_from_slice(&word.to_ne_bytes()); + } + } + counts + } + + /// The layout constants are the kernel header's: flavor 34, an 8-byte + /// header, 40 bytes a level, the energy 32 bytes into a level. The + /// decoding reads each level's energy and nothing else, and reads no + /// count at all from a result of any size but the header and one record + /// for each level it names: a failed call, a short or long result, no + /// level, more levels than the buffer holds. + #[test] + fn thread_counts_decoding_reads_each_levels_energy_in_the_one_layout_it_knows() { + assert_eq!( + (thread_counts::FLAVOR, thread_counts::HEADER, thread_counts::LEVEL, thread_counts::ENERGY_NJ), + (34, 8, 40, 32) + ); + // Two levels, 88 bytes: what an M5 Max and an M3 Ultra write. + assert_eq!(thread_counts::energy_nj(&thread_counts_bytes(2, &[3_000_000, 250]), 88), Some(3_000_250)); + assert_eq!(thread_counts::energy_nj(&thread_counts_bytes(1, &[77]), 48), Some(77)); + assert_eq!(thread_counts::energy_nj(&thread_counts_bytes(3, &[1, 2, 4]), 128), Some(7)); + assert_eq!(thread_counts::energy_nj(&thread_counts_bytes(2, &[u64::MAX, 5]), 88), Some(u64::MAX), "saturates"); + let two = thread_counts_bytes(2, &[3_000_000, 250]); + for (wrote, why) in [(-1, "the call failed"), (0, "nothing written"), (48, "one record for two levels"), (80, "short"), (96, "long")] + { + assert_eq!(thread_counts::energy_nj(&two, wrote), None, "{why}"); + } + assert_eq!(thread_counts::energy_nj(&thread_counts_bytes(0, &[]), 8), None, "no performance level"); + let too_many = u16::try_from(thread_counts::MAX_LEVELS + 1).unwrap(); + assert_eq!( + thread_counts::energy_nj(&thread_counts_bytes(too_many, &[]), 8 + 40 * i32::from(too_many)), + None, + "more levels than the buffer holds" + ); + } + + /// The rule for reading one's own process: the reading thread is seen + /// off its core only when its own energy count rose across a sleep. The + /// sleeps are taken in turn until one does; a count that held across + /// them all, or fell, is not a thread seen to leave, and a count that + /// cannot be read ends the wait at once. + #[test] + fn a_thread_is_seen_off_its_core_only_by_its_own_count_rising_across_a_sleep() { + use std::cell::RefCell; + let sleeps = [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1)]; + // The thread's count at each read in turn; the sleeps taken. + let seen = |counts: &[Option]| { + let mut counts = counts.iter().copied(); + let slept = RefCell::new(Vec::new()); + let seen = off_core::seen(&sleeps, || counts.next().flatten(), |pause| slept.borrow_mut().push(pause)); + (seen, slept.into_inner()) + }; + assert_eq!(seen(&[Some(10), Some(11)]), (true, vec![sleeps[0]]), "rose across the first sleep"); + assert_eq!( + seen(&[Some(10), Some(10), Some(10), Some(10), Some(10), Some(4_000)]), + (true, sleeps.to_vec()), + "held across two sleeps, rose across the third" + ); + assert_eq!(seen(&[Some(10); 6]), (false, sleeps.to_vec()), "held across every sleep"); + assert_eq!(seen(&[Some(10), Some(9), Some(9), Some(8), Some(8), Some(7)]), (false, sleeps.to_vec()), "fell"); + assert_eq!(seen(&[None]), (false, vec![]), "unreadable before any sleep"); + assert_eq!(seen(&[Some(10), None]), (false, vec![sleeps[0]]), "unreadable after a sleep"); + assert!(!off_core::seen(&[], || Some(1), |_| panic!("slept")), "no sleep, nothing seen"); + assert_eq!( + off_core::SLEEPS, + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)] + ); + } + + /// On this host the metering thread's own count reads, in the layout + /// `thread_counts` knows: between two reads of the tests' own per-thread + /// oracle (their own FFI declaration and decoding), the meter's read of + /// it sits between theirs. And a span's read sees the thread leave its + /// core: the path every figure of the rung takes. + /// + /// A thread that has not left a core since it started has a count of + /// zero (seen on an idle M3 Ultra), which would make the comparison one + /// of zeros. So the thread first burns and sleeps until the oracle's + /// count is above zero. + #[cfg(target_os = "macos")] + #[test] + fn the_metering_threads_own_count_reads_here_and_a_span_read_sees_it_leave_its_core() { + for ms in [1, 2, 4, 8] { + burn_thread_cpu(Duration::from_millis(1)); + std::thread::sleep(Duration::from_millis(ms)); + if oracle_this_thread_energy_nj() > 0 { + break; + } + } + let before = oracle_this_thread_energy_nj(); + let mine = process_energy::thread_energy_nj().expect("the meter cannot read this thread's own count"); + let after = oracle_this_thread_energy_nj(); + eprintln!("process energy: this thread's own count: oracle {before} <= meter {mine} <= oracle {after} nJ"); + assert!(before > 0, "this thread's own count is still zero after four burns and sleeps"); + assert!(before <= mine && mine <= after, "the meter's count {mine} nJ is not this thread's ({before} .. {after})"); + let counter = process_energy::ProcessEnergy::open().expect("the per-process counter does not open"); + assert!(counter.read().is_some(), "this thread was not seen to leave its core within {:?}", off_core::SLEEPS); + } + + /// A span whose metering thread is never seen to leave its core is not a + /// reading: the rung's figure for it is the default-power estimate, + /// `Estimator`, with no measured figure — never a zero, and never a + /// figure graded `HwShunt` on a count that may lack what the thread + /// spent. The work still runs, once, and the read gives up only after + /// every sleep. The per-fabric meter reports no CPU figure for such a + /// span, while it still lists the CPU as a fabric it reads. + #[cfg(target_os = "macos")] + #[test] + fn a_span_whose_thread_is_never_seen_off_its_core_is_an_estimate() { + let meter = Meter::ProcessEnergy(process_energy::ProcessEnergy::never_off_core()); + let mut runs = 0; + let started = std::time::Instant::now(); + let ((), e) = meter.measure(|| runs += 1); + let took = started.elapsed(); + assert_eq!(runs, 1, "the work ran {runs} times"); + assert_eq!((e.provenance, e.measured_uj), (Provenance::Estimator, None), "{e:?}"); + e.check_provenance().unwrap(); + let every_sleep: Duration = off_core::SLEEPS.iter().sum(); + assert!(took >= every_sleep, "the read gave up after {took:?}, before all of {:?}", off_core::SLEEPS); + + let fabrics = FabricMeter { ioreport: None, process: Some(process_energy::ProcessEnergy::never_off_core()) }; + assert_eq!(fabrics.readable(), vec![(Fabric::Cpu, Attribution::Process)]); + let ((), readings) = fabrics.measure(|| ()); + assert!(readings.is_empty(), "a CPU figure for a span no end of which was read: {readings:?}"); + } + + /// `proc_pidinfo` flavor 4, `PROC_PIDTASKINFO` in ``: a + /// process's task counts, 96 bytes — six `uint64_t` (sizes and CPU + /// times), then twelve `int32_t`, the ninth of them `pti_csw`, how many + /// times the process's threads have been switched off a core. + #[cfg(target_os = "macos")] + const TESTS_PIDTASKINFO: std::os::raw::c_int = 4; + + /// The tests' own count of this process's context switches (`pti_csw`, + /// the `int32_t` at byte 80 of `proc_taskinfo`), through their own FFI + /// declaration. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn oracle_context_switches() -> i32 { + let mut info = [0i32; 24]; + let bytes = std::mem::size_of_val(&info) as std::os::raw::c_int; + let me = std::process::id() as std::os::raw::c_int; + let wrote = unsafe { proc_pidinfo(me, TESTS_PIDTASKINFO, 0, info.as_mut_ptr().cast(), bytes) }; + assert_eq!(wrote, bytes, "the tests' proc_pidinfo(PROC_PIDTASKINFO) wrote {wrote} of {bytes} bytes"); + info[80 / 4] + } + + /// The tests' own read of this process's `ri_energy_nj`, taken once the + /// calling thread has left its core by the tests' own rule: a sleep of + /// 1 ms, then 2, 4 and 8, until the process's context-switch count rose + /// across one. In a fresh process running one test on one thread, a rise + /// is this thread's switch. The kernel adds a thread's energy to its + /// process's count when the thread leaves a core, so this read holds all + /// the thread spent before it. The meter's own check shares nothing with + /// it: another call, another count, sleeps a twentieth as long. + #[cfg(target_os = "macos")] + fn oracle_energy_nj_off_core() -> u64 { + let left = [1, 2, 4, 8].into_iter().any(|ms| { + let before = oracle_context_switches(); + std::thread::sleep(Duration::from_millis(ms)); + oracle_context_switches() > before + }); + assert!(left, "the tests' oracle never saw this thread leave its core across sleeps of 1, 2, 4 and 8 ms"); + oracle_energy_nj(std::process::id()).expect("the oracle cannot read this process").0 + } + + /// A span of a millisecond of the metering thread's CPU is that work's + /// reading, and a sleep metered straight after a burn is not given the + /// burn. Each `HwShunt` figure is held against the tests' own window + /// around its span, whose two ends are read once this thread has left + /// its core by the tests' own rule. + /// + /// - 1 ms of this thread's CPU, 40 times: a `HwShunt` figure is no more + /// than the oracle's window (which holds the span and both readers' + /// own reads and wake-ups) and at least two thirds of it. Those reads + /// do not shrink with the burn's cost: under 2% of the window on an + /// idle M3 Ultra, up to 16% under 40 busy loops (the lowest of 4,400 + /// spans). A span the meter could not read is the default-power + /// estimate, which claims no reading. At most a tenth of the spans + /// may be that or fall short of the band; none may be over the + /// oracle's window. + /// - a 2 ms sleep straight after 8 ms of this thread's CPU that the span + /// does not cover, 40 times: the oracle's window is the burn and the + /// sleep, and a `HwShunt` figure for the sleep is under a quarter of + /// it (it was under 1% idle, and at most 6% under the busy loops), in + /// at least nine spans of ten. + /// + /// No joule figure and no timing is asserted: what a millisecond of CPU + /// costs follows the core that ran it. A meter that reads its own + /// process's count from a thread still on its core fails both: the count + /// lacks what that thread spent since it last left one, so the first + /// kind of span reads nothing or part of the burn, and the second reads + /// the burn before it as the sleep's energy. + #[cfg(target_os = "macos")] + #[test] + fn a_short_span_is_its_own_reading_by_an_oracle_that_leaves_its_core_its_own_way() { + in_a_fresh_process("tests::a_short_span_is_its_own_reading_by_an_oracle_that_leaves_its_core_its_own_way", || { + const TRIES: usize = 40; + let meter = process_meter(); + + // (try, the figure in µJ, the oracle's window in nJ) of each + // HwShunt figure that is short of its span's, and of each that is + // over the oracle's window, which no read of this process's + // count can be. + let (mut agreed, mut estimated, mut wrong, mut over) = (Vec::new(), 0usize, Vec::new(), Vec::new()); + for i in 0..TRIES { + let before = oracle_energy_nj_off_core(); + let (_, e) = meter.measure(|| burn_thread_cpu(Duration::from_millis(1))); + let oracle_nj = oracle_energy_nj_off_core() - before; + let nj = e.uj().saturating_mul(1_000); + match e.provenance { + // The meter rounds a rise up to the next whole µJ. + Provenance::HwShunt if nj >= oracle_nj + 1_000 => over.push((i, e.uj(), oracle_nj)), + Provenance::HwShunt if nj * 3 >= oracle_nj * 2 => agreed.push(nj * 1_000 / oracle_nj.max(1)), + Provenance::HwShunt => wrong.push((i, e.uj(), oracle_nj)), + Provenance::ModelBased | Provenance::Estimator => estimated += 1, + } + } + eprintln!( + "process energy: 1 ms of this thread's CPU x {TRIES}: {} HwShunt within the oracle's window (at least \ + {}/1000 of it), {estimated} estimated, {} HwShunt and short of the span's {wrong:?}, {} HwShunt and \ + over the oracle's window {over:?} (try, µJ, oracle nJ)", + agreed.len(), + agreed.iter().min().copied().unwrap_or(0), + wrong.len(), + over.len() + ); + + let (mut small, mut slept_estimated, mut leaked) = (Vec::new(), 0usize, Vec::new()); + for i in 0..TRIES { + let before = oracle_energy_nj_off_core(); + burn_thread_cpu(Duration::from_millis(8)); + let ((), e) = meter.measure(|| std::thread::sleep(Duration::from_millis(2))); + let oracle_nj = oracle_energy_nj_off_core() - before; + let nj = e.uj().saturating_mul(1_000); + match e.provenance { + Provenance::HwShunt if nj * 4 < oracle_nj => small.push(nj * 1_000 / oracle_nj.max(1)), + Provenance::HwShunt => leaked.push((i, e.uj(), oracle_nj)), + Provenance::ModelBased | Provenance::Estimator => slept_estimated += 1, + } + } + eprintln!( + "process energy: a 2 ms sleep after an 8 ms burn x {TRIES}: {} HwShunt under a quarter of the oracle's \ + window (at most {}/1000 of it), {slept_estimated} estimated, {} HwShunt with the burn before the span \ + in them {leaked:?} (try, µJ, oracle nJ)", + small.len(), + small.iter().max().copied().unwrap_or(0), + leaked.len() + ); + + // What a read of the count costs: reported, not asserted. + let counter = process_energy::ProcessEnergy::open().expect("the per-process counter does not open"); + let mut micros: Vec = (0..200) + .map(|_| { + let started = std::time::Instant::now(); + let _ = counter.read(); + started.elapsed().as_micros() + }) + .collect(); + micros.sort_unstable(); + eprintln!( + "process energy: one read of the count for a span costs {} µs at the median, {} µs at the 95th \ + percentile, {} µs at most (200 reads)", + micros[100], micros[190], micros[199] + ); + + assert!(over.is_empty(), "a span was graded HwShunt on more than the process spent around it: {over:?}"); + // A tenth of the spans may miss the band. On a loaded host the + // oracle's own reads can land on a costlier core than the burn + // did, which shrinks a correct figure's share of the oracle's + // window; and a span the meter could not read is an estimate by + // design. A meter that does not take the metering thread off + // its core misses on every span of an idle host. + assert!( + (estimated + wrong.len()) * 10 <= TRIES, + "{estimated} of {TRIES} 1 ms spans were not read and {} were graded HwShunt short of the work: {wrong:?}", + wrong.len() + ); + assert!( + leaked.len() * 10 <= TRIES, + "{} of {TRIES} sleeps were graded HwShunt on the energy of the burn before them: {leaked:?}", + leaked.len() + ); + }); + } + /// 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`]). Both burn in one span, and the diff --git a/jouleclaw/SPEC.md b/jouleclaw/SPEC.md index 4c632c300..dde682244 100644 --- a/jouleclaw/SPEC.md +++ b/jouleclaw/SPEC.md @@ -121,7 +121,20 @@ Realistic floors: sales talk; the spec is honest about this. - Apple Silicon, per process (macOS 27.0.1, unprivileged): the process's own CPU energy (`proc_pid_rusage`, nJ, live) is - `HwShunt`. Its GPU energy is `HwShunt` in two cases only: an exact + `HwShunt`. The kernel adds a thread's energy to that count only + when the thread leaves a core, and a process's read of its own + count does not take the reading thread off its core, so such a read + is short of what that thread spent since it last left one: up to a + scheduling quantum, missing from a span that ends there and, spent + before it, inside a span that starts there (measured: of 40 spans + over 1 ms of the reading thread's CPU, 25 to 31 read nothing or + under three quarters of it). An implementation **MUST** take each + read of its own process only once it has checked that the reading + thread left its core just before it — the reference counter sleeps, + and reads only once that thread's own energy count (`proc_pidinfo`, + `PROC_PIDTHREADCOUNTS`) rose across a sleep — and a span with an + end not so checked **MUST NOT** be graded a hardware reading: it is + estimated. Its GPU energy is `HwShunt` in two cases only: an exact zero when its own GPU time (I/O Registry) did not move, and the IOReport `GPU Energy` rail (nJ, live) when it had at least 99% of every GPU client's GPU time over the span. A shared GPU gives no diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/MEASURED_ENERGY.md b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/MEASURED_ENERGY.md index 81516b19e..7735d227b 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/MEASURED_ENERGY.md +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/MEASURED_ENERGY.md @@ -71,6 +71,30 @@ two live sources replace the frozen rails: | `process-cpu` ([`process`](src/process.rs)) | `proc_pid_rusage` `ri_energy_nj` | this process's CPU | **HwShunt** while live | | `ProcessGpuCounter` ([`process_gpu`](src/process_gpu.rs), `ioreport`) | this process's `accumulatedGPUTime` (I/O Registry `IOAccelerator` user clients); IOReport `GPU Energy` (nJ) | this process's GPU | **HwShunt**: 0 µJ exact with no GPU time; the rail at ≥ 99% of every client's GPU time; else no figure | +The CPU count is read only once the reading thread is seen to have left its +core. The kernel adds a thread's energy to its process's count when the thread +leaves a core, and a process reading itself does not make the reading thread +leave, so a read from a thread that has been running is short of what it spent +since it last left: up to a scheduling quantum, missing from a span that ends +there and, spent before it, inside a span that starts there. `process-cpu` +sleeps before each read of its own process (50 µs, then 200 µs, 1 ms, 5 ms) +until the reading thread's own energy count (`proc_pidinfo`, +`PROC_PIDTHREADCOUNTS`) rose across a sleep; a read whose thread was not seen +to leave is no reading (`NotFolded`), and its span falls back to the host +meter. `tests/process_cpu_short_span.rs` holds 1 ms spans, and sleeps metered +straight after a burn, against a reader that folds by its own rule, 40 spans +of each a run. Without the sleep: on an M5 Max at a load average of 90 to 135, +25 to 31 of the 1 ms spans read nothing or under three quarters of the work, +and 25 to 31 of the sleeps read the burn before them (up to 18 mJ); on an idle +M3 Ultra, all 40 of the 1 ms spans read nothing and all 40 of the sleeps read +the whole burn before them (42 to 53 mJ). With it, every span read at least +95% of the work on the loaded M5 Max and 97% on the quiet M3 Ultra, and no +sleep more than 0.5% of the burn; under 40 busy loops on the M3 Ultra (220 +runs) every span read at least 84% (the rest is the two readers' own reads) +and no sleep more than 2%. A read costs about 80 µs on the quiet M3 Ultra, +about 200 to 330 µs at the median under the busy loops, and 81 to 154 µs at +the median on the loaded M5 Max (1 µs without the sleep). + The GPU rail is machine-wide and is never split by GPU time: energy is not proportional to it. On this host a GGUF decode drew ~1.9 W per GPU-second alone while another session's job drew ~17 W, so a time-share split charged the decode diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs index c306fe7d3..e8e440062 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/lib.rs @@ -35,7 +35,11 @@ //! for an unprivileged reader where IOReport's CPU rails are not. It covers this //! process's threads only, so it is not in [`meter::detect_meter`] (for work //! wherever it runs, a subprocess included); [`meter::detect_in_process_meter`] -//! prefers it, for work that runs on this process's own threads. +//! prefers it, for work that runs on this process's own threads. Each read it +//! takes of its own process waits until the reading thread is seen to have +//! left its core, since the kernel counts a thread's energy into its +//! process's only then; a read not so checked is no reading +//! ([`EnergyError::NotFolded`]). //! //! On Apple Silicon (macOS, the `ioreport` feature) it also reads this //! process's own GPU energy (`process_gpu::ProcessGpuCounter`, domain @@ -349,6 +353,20 @@ pub enum EnergyError { /// not see the work: that is not a reading, and never a zero. #[error("the counter did not advance across the work: not a reading")] NotAdvanced, + /// A process's read of its own CPU-energy count was not taken, because + /// the reading thread was not seen to leave its core before it. The + /// kernel adds a thread's energy to its process's count only when the + /// thread leaves a core, so a read from a thread still on one is short of + /// what that thread spent since it last left: up to a scheduling quantum, + /// which would be missing from a window that ends there and — spent + /// before it — inside a window that starts there. That is not a reading + /// of that end (`process`), and a window with such an end has no figure + /// from the counter. + #[error( + "the reading thread was not seen to leave its core before a read of its own process: the count could be \ + short of what the thread spent since it last did — not a reading" + )] + NotFolded, /// A counter's reading at a window's boundary was not current: the IOReport /// GPU rail held while the GPU was busy (it can hold for hundreds of /// milliseconds and then catch up in one step), so a window bounded by that diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs index 698f82291..a4ff9ce33 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/process.rs @@ -37,6 +37,78 @@ //! and cached ([`process_cpu_liveness`]); about 0.3 s where it is live, about //! 1 s where it is not. A counter that is not live meters nothing. //! +//! **Every read of this process by itself is taken once the reading thread is +//! seen to have left its core.** The kernel adds a thread's CPU energy to its +//! process's count only when the thread leaves a core — a context switch, or +//! the end of its quantum, about 10 ms of its CPU — and a process reading +//! ITSELF does not make the reading thread leave: its CPU time is current at +//! the read, its energy is not. So a read from a thread that has been running +//! is short of what that thread spent since it last left a core: a window's +//! first read then puts up to a quantum of energy from BEFORE the window +//! inside it, and its last read leaves the window's tail out. Measured (M5 +//! Max, macOS 27.0.1, load average about 90, 40 windows a run over three +//! runs, against an independent reader that slept before each of its own +//! reads): of windows over 1 ms of the reading thread's CPU, opened just +//! after that thread had left a core, 25 to 31 read no advance at all or +//! under three quarters of the independent reader's window around them; and +//! of windows over a 2 ms sleep opened straight after 8 ms of that thread's +//! CPU, 25 to 31 read the tail of the CPU before them as the sleep's energy, +//! up to 18 mJ for a sleep. On an idle M3 Ultra (macOS 27.0.1), where nothing +//! but its own quantum takes a running thread off its core, all 40 of the +//! 1 ms windows read no advance, and all 40 of the sleeps read the whole 8 ms +//! before them, 42 to 53 mJ, in each of three runs. +//! +//! So before each such read the reading thread sleeps, and the read is taken +//! only once the thread is SEEN to have left its core over a sleep +//! ([`FOLD_SLEEPS`]: 50 µs, then 200 µs, 1 ms and 5 ms). A sleep alone is no +//! proof: one whose timer fires before the thread has blocked returns with +//! the thread still on its core. The proof is the reading thread's own energy +//! count (`proc_pidinfo`'s `PROC_PIDTHREADCOUNTS`, [`this_thread_energy_nj`]), +//! which the kernel moves only when it adds that thread's energy to the +//! process's: a rise across a sleep is the thread having left its core after +//! the work before the read. Not the process's context-switch count, which +//! any other thread's switch moves. A read whose thread was not seen to leave +//! within those sleeps is [`EnergyError::NotFolded`], no reading: a window +//! with one at either end has no figure from this counter, and its caller +//! estimates (a span, [`crate::span`], falls back to the host meter). Never a +//! short figure graded as a hardware reading. +//! +//! With the sleep, the same windows on the same hosts: all 40 of the 1 ms +//! windows read at least 95% of the independent reader's window on the M5 +//! Max (load average about 135, four runs) and at least 97% on the quiet M3 +//! Ultra, and all 40 of the sleeps under 0.5% of the window that held the +//! CPU before them, on both. Under 40 busy loops on the M3 Ultra (220 runs +//! of 40 windows of each kind), every 1 ms window read at least 84% — the +//! rest is the two readers' own reads and wake-ups, which do not shrink +//! with the work — and no sleep more than 2%. +//! +//! What a read costs: two reads of the thread's count (well under a +//! microsecond each), the sleep, and the wait for a core after it. Measured, +//! 200 reads a run: on the quiet M3 Ultra 79 to 88 µs at the median and +//! 109 µs at most, and under 40 busy loops there 193 to 335 µs at the median +//! over 110 runs and 11 ms at most; on the M5 Max at a load average of about +//! 135, 81 to 154 µs at the median, 0.3 to 2.7 ms at the 95th percentile, +//! and up to 13 ms (a read with no sleep: 1 µs). A read whose thread is +//! never seen to leave takes all four sleeps (6.25 ms) and their waits +//! before it fails. A window also +//! holds the energy of its own closing read's wake-up, a few tens of +//! microjoules (17 µJ for a window over a 200 ms sleep, on the M3 Ultra): +//! most of the figure for a window over much less than a millisecond of +//! work, which is then a reading of what this process spent between its two +//! reads and not of that work alone. So a caller with many short pieces of +//! work meters them in one window around the lot, not one each. The liveness +//! probe reads with no sleep: it asks only whether the count keeps advancing +//! under a burn, which it does at each quantum. +//! +//! Only the reading thread is seen to leave. Another thread of this process +//! that is on a core at a read is short by what it spent since it last left +//! one, so its share of a window can be off by up to a quantum at each end: +//! work that runs on the thread that opens and closes the window is read +//! whole, and work on other threads to within a quantum each, at each end. +//! And only reads of THIS process: a counter that reads another process (a +//! child, a process tree) cannot make that process's threads leave their +//! cores, and nothing here sleeps for one. +//! //! **A read that did not advance is not a reading.** No work runs on zero //! energy, so a window over which the counter held did not see the work. //! [`ProcessCpuCounter::measure`] reports such a window as @@ -95,12 +167,129 @@ fn rusage_energy_nj(pid: libc::pid_t) -> Option { Some(unsafe { info.assume_init() }.ri_energy_nj) } -/// This process's cumulative CPU energy, in nanojoules. -pub(crate) fn energy_nj() -> Option { +/// This process's cumulative CPU energy, in nanojoules, as the kernel's count +/// stands now: read with no sleep before it, so short of what the reading +/// thread spent since it last left a core. The liveness probe's reader, and +/// the last step of [`self_read_nj`]; no figure is made of it alone. +fn raw_energy_nj() -> Option { // SAFETY: `getpid` has no preconditions and cannot fail. rusage_energy_nj(unsafe { libc::getpid() }) } +/// The sleeps the reading thread takes, in turn, before a read of its own +/// process, until one is seen to take it off its core ([`left_its_core`]). +/// Growing: a sleep whose timer fired before the thread blocked is followed +/// by one that much more surely blocks. 6.25 ms in all, on a read whose +/// thread is never seen to leave. +const FOLD_SLEEPS: [Duration; 4] = + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)]; + +/// Whether the reading thread was seen to leave its core: it takes each of +/// `sleeps` in turn, reading its own energy count (`count`: production reads +/// [`this_thread_energy_nj`]) either side, and stops at the first sleep +/// across which the count rose. The kernel moves that count only when it adds +/// the thread's energy to its process's, so a rise across a sleep is the +/// thread having left its core after everything it did before the sleep. A +/// count that cannot be read, that held across every sleep, or that fell, is +/// no such evidence: `false`, and no read is made of the process on it. +fn left_its_core(sleeps: &[Duration], mut count: impl FnMut() -> Option, mut sleep: impl FnMut(Duration)) -> bool { + for &d in sleeps { + let Some(before) = count() else { return false }; + sleep(d); + match count() { + Some(after) if after > before => return true, + Some(_) => {} + None => return false, + } + } + false +} + +/// `PROC_PIDTHREADCOUNTS`: the `proc_pidinfo` flavor that returns one thread's +/// counts, asked by its 64-bit thread id. In the kernel's +/// `` (macOS 13 and later), not in the SDK's public +/// header, so the result is used only in the one layout [`thread_energy_nj`] +/// knows. +const PROC_PIDTHREADCOUNTS: libc::c_int = 34; + +/// The calling thread's own cumulative CPU energy, in nanojoules, from the +/// bytes `proc_pidinfo(PROC_PIDTHREADCOUNTS)` wrote into `buf`, of which the +/// call returned `wrote`. The kernel writes `struct proc_threadcounts`: a +/// `uint16_t` count of CPU performance levels and six bytes of padding, then +/// for each level five `uint64_t`s — instructions, cycles, user time, system +/// time and energy in nJ. The energy is summed over the levels. +/// +/// `None` unless the call wrote exactly that header and one 40-byte record +/// for each level it names, at least one: any other size is a layout this +/// code does not know, and is read as no count rather than as a field +/// misread. Measured (M5 Max, macOS 27.0.1): 88 bytes, two levels. +fn thread_energy_nj(buf: &[u8], wrote: libc::c_int) -> Option { + const HEADER: usize = 8; + const LEVEL: usize = 40; + const ENERGY: usize = 32; + let levels = usize::from(u16::from_ne_bytes([*buf.first()?, *buf.get(1)?])); + let size = HEADER + levels * LEVEL; + if levels == 0 || size > buf.len() || usize::try_from(wrote).ok() != Some(size) { + return None; + } + let mut nj = 0u64; + for level in 0..levels { + let at = HEADER + level * LEVEL + ENERGY; + let energy: [u8; 8] = buf[at..at + 8].try_into().ok()?; + nj = nj.saturating_add(u64::from_ne_bytes(energy)); + } + Some(nj) +} + +/// The calling thread's own cumulative CPU energy, in nanojoules: the count +/// [`left_its_core`] watches. `None` if the thread's id or its counts cannot +/// be read, or the counts come back in a layout [`thread_energy_nj`] does not +/// know. +fn this_thread_energy_nj() -> Option { + let mut tid: u64 = 0; + // SAFETY: `tid` is writable, and `pthread_self` is the calling thread. + if unsafe { libc::pthread_threadid_np(libc::pthread_self(), &mut tid) } != 0 { + return None; + } + let mut buf = [0u8; 512]; + // SAFETY: `buf` is writable for its length, which the call is given; + // `getpid` has no preconditions. + let wrote = unsafe { + libc::proc_pidinfo(libc::getpid(), PROC_PIDTHREADCOUNTS, tid, buf.as_mut_ptr().cast(), buf.len() as libc::c_int) + }; + thread_energy_nj(&buf, wrote) +} + +/// One read of this process by itself, as every figure here takes it: its +/// cumulative CPU energy in nanojoules, read once the reading thread is seen +/// to have left its core ([`left_its_core`] over [`FOLD_SLEEPS`]), so the +/// count holds all that thread spent before the read. A thread not seen to +/// leave is [`EnergyError::NotFolded`], and the process is not read: there is +/// then no reading at this end of a window, and no figure for the window. +pub(crate) fn self_read_nj() -> Result { + self_read_with(this_thread_energy_nj, std::thread::sleep, raw_energy_nj) +} + +/// [`self_read_nj`] on its parts: the reading thread's own energy count, the +/// sleep, and the read of the process. The tests script all three. +fn self_read_with( + count: impl FnMut() -> Option, + sleep: impl FnMut(Duration), + read: impl FnOnce() -> Option, +) -> Result { + if !left_its_core(&FOLD_SLEEPS, count, sleep) { + return Err(EnergyError::NotFolded); + } + read().ok_or_else(|| EnergyError::Platform("proc_pid_rusage failed".to_string())) +} + +/// [`self_read_nj`], for a caller that keeps a window's two readings and +/// hands them to [`window_uj`] ([`crate::span`]): `None` where there is no +/// reading, whichever of its two reasons it has. +pub(crate) fn energy_nj() -> Option { + self_read_nj().ok() +} + /// How many times this process has run the real liveness probe. Read through /// [`crate::process_cpu_probe_runs`] by the test that pins the probe to one run /// per process. @@ -111,38 +300,82 @@ pub(crate) static REAL_RUNS: AtomicUsize = AtomicUsize::new(0); /// (it burns that thread's CPU for about 0.3 s where the counter is live, about /// 1 s where it is not); every later call, every [`ProcessCpuCounter::new`] and /// every [`crate::meter::detect_in_process_meter`] reuse the answer. +/// +/// [`CounterLiveness::Unavailable`], with no probe run, where the calling +/// thread's own energy count does not read ([`this_thread_energy_nj`]): every +/// read this counter takes of its own process is checked against that count +/// ([`self_read_nj`]), so a counter without it could never give a figure. pub fn process_cpu_liveness() -> CounterLiveness { static LIVENESS: OnceLock = OnceLock::new(); *LIVENESS.get_or_init(|| { REAL_RUNS.fetch_add(1, Ordering::SeqCst); - probe_reader(energy_nj) + liveness_given(this_thread_energy_nj().is_some(), || probe_reader(raw_energy_nj)) }) } +/// The counter's liveness on a host where the reading thread's own energy +/// count `reads` or does not: what `probe` finds where it does, and +/// `Unavailable`, the probe not run, where it does not. +fn liveness_given(thread_count_reads: bool, probe: impl FnOnce() -> CounterLiveness) -> CounterLiveness { + if thread_count_reads { + probe() + } else { + CounterLiveness::Unavailable + } +} + /// One run of the liveness probe over `read`, a reader of a cumulative counter: /// the shared probe ([`crate::liveness::probe`]) over one channel, burning /// [`PROBE_TICK`] of this thread's CPU time between samples. Production passes -/// [`energy_nj`]; the tests pass readers that hold or fail. +/// [`raw_energy_nj`] (the count as it stands, no sleep before a sample: the +/// rule asks whether it keeps advancing under the burn, which it does at each +/// quantum); the tests pass readers that hold or fail. fn probe_reader(read: impl Fn() -> Option) -> CounterLiveness { crate::liveness::probe(|| read().map(|_| (1, || read().map(|nj| vec![nj]))), PROBE_TICK) } -/// The energy of a window of work from the counter's raw readings, in nJ, -/// before and after it, as whole µJ: or why it is not a reading. A failed read -/// is not a zero; a counter that went backwards wrapped or was reset; and one -/// that did not advance by a whole µJ — the resolution of the figure — did not -/// see the work, which runs on more than zero energy. +/// The energy of a window of work from this process's readings of itself, in +/// nJ, before and after it ([`energy_nj`]), as whole µJ: or why it is not a +/// reading. An end with no reading (`None`) is not a zero, and leaves the +/// window with no figure; a counter that went backwards wrapped or was reset; +/// and one that did not advance by a whole µJ — the resolution of the figure — +/// did not see the work, which runs on more than zero energy. pub(crate) fn window_uj(before_nj: Option, after_nj: Option) -> Result { let (Some(before), Some(after)) = (before_nj, after_nj) else { - return Err(EnergyError::Platform("proc_pid_rusage failed".to_string())); + return Err(EnergyError::Platform( + "no reading of this process at an end of the window: the reading thread was not seen to leave its core, \ + or proc_pid_rusage failed" + .to_string(), + )); }; - match after.checked_sub(before).map(|nj| nj / 1_000) { + advance_uj(before, after) +} + +/// How far the counter advanced between two readings in nJ, as whole µJ, or +/// why that is no reading: it went backwards ([`EnergyError::CounterWrap`]), +/// or advanced by less than a whole µJ ([`EnergyError::NotAdvanced`]). +fn advance_uj(before_nj: u64, after_nj: u64) -> Result { + match after_nj.checked_sub(before_nj).map(|nj| nj / 1_000) { None => Err(EnergyError::CounterWrap), Some(0) => Err(EnergyError::NotAdvanced), Some(uj) => Ok(uj), } } +/// A window of `work` between two reads of the counter by `read`: the work's +/// result, and how far the counter advanced across it, or why there is no +/// figure — the first of the two reads that gave none, else what +/// [`advance_uj`] says. `work` runs whatever the first read gave; the second +/// is taken only when the first gave a reading. +fn window_over( + mut read: impl FnMut() -> Result, + work: impl FnOnce() -> T, +) -> (T, Result) { + let before = read(); + let out = work(); + (out, before.and_then(|before| read().and_then(|after| advance_uj(before, after)))) +} + /// This process's own CPU energy counter (macOS): see the module docs for its /// domain, which is exactly this process's threads' CPU energy. pub struct ProcessCpuCounter { @@ -182,22 +415,26 @@ impl ProcessCpuCounter { /// Run `work` and meter it: its result, and the CPU energy this process's /// threads spent while it ran, in µJ — a hardware reading over /// [`EnergyDomain::ProcessCpu`] — or why there is no figure: the counter is - /// not live ([`EnergyError::NoCounter`]), a read failed, the counter went + /// not live ([`EnergyError::NoCounter`]), the calling thread was not seen + /// to leave its core before one of the two reads + /// ([`EnergyError::NotFolded`]: that read could be short of what the + /// thread had spent, so there is none), a read failed, the counter went /// backwards ([`EnergyError::CounterWrap`]), or it did not advance by a /// whole µJ while the work ran ([`EnergyError::NotAdvanced`]: not a /// reading, never a zero). /// /// Every thread of this process is in the figure, the work's and any other /// running at the same time; no other process's, and none of the GPU's. - /// `work` runs whether or not the counter is live. + /// Work on the calling thread is read whole; another thread's, to within + /// what it spent since it last left a core at each read (the module + /// docs). Each of the two reads sleeps at least 50 µs first + /// ([`self_read_nj`]), outside the figure at the start and inside it at + /// the end. `work` runs whether or not the counter is live. pub fn measure(&self, work: impl FnOnce() -> T) -> (T, Result) { if !self.is_available() { return (work(), Err(EnergyError::NoCounter(EnergyDomain::ProcessCpu))); } - let before = energy_nj(); - let out = work(); - let after = energy_nj(); - (out, window_uj(before, after)) + window_over(self_read_nj, work) } } @@ -227,8 +464,10 @@ impl EnergyCounter for ProcessCpuCounter { } fn min_window_ns(&self) -> u64 { - // It moves about every 0.5 ms under load; below ~1 ms a window may - // straddle no update at all. + // A read holds all the reading thread spent before it, so a window + // of any length reads that thread's work whole. It also holds its + // closing read's own wake-up, a few tens of µJ: below ~1 ms of work + // that is a large part of the figure. 1_000_000 } @@ -236,7 +475,10 @@ impl EnergyCounter for ProcessCpuCounter { if !self.is_available() { return Err(EnergyError::NoCounter(EnergyDomain::ProcessCpu)); } - let nj = energy_nj().ok_or_else(|| EnergyError::Platform("proc_pid_rusage failed".to_string()))?; + // Taken once this thread is seen to have left its core, or not at all + // (`NotFolded`): a caller that subtracts two of these gets a window + // that holds this thread's work whole. + let nj = self_read_nj()?; let timestamp_ns = SystemTime::now() .duration_since(UNIX_EPOCH) .map(|d| d.as_nanos() as u64) @@ -319,6 +561,174 @@ mod tests { assert!(matches!(window_uj(Some(1), None), Err(EnergyError::Platform(_)))); } + /// The rule for seeing the reading thread leave its core: each sleep in + /// turn until the thread's own count rose across one. A count that held + /// across every sleep, fell, or could not be read is not a thread seen to + /// leave — and an unreadable count ends the wait at once. + #[test] + fn a_thread_is_seen_to_leave_only_by_its_own_count_rising_across_a_sleep() { + use std::cell::RefCell; + let sleeps = [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1)]; + // The thread's count at each read in turn, and the sleeps taken. + let seen = |counts: &[Option]| { + let mut counts = counts.iter().copied(); + let slept = RefCell::new(Vec::new()); + let left = left_its_core(&sleeps, || counts.next().flatten(), |d| slept.borrow_mut().push(d)); + (left, slept.into_inner()) + }; + assert_eq!(seen(&[Some(40), Some(41)]), (true, vec![sleeps[0]]), "rose across the first sleep"); + assert_eq!( + seen(&[Some(40), Some(40), Some(40), Some(40), Some(40), Some(90)]), + (true, sleeps.to_vec()), + "held across two sleeps that did not take it off its core, rose across the third" + ); + assert_eq!(seen(&[Some(40); 6]), (false, sleeps.to_vec()), "held across every sleep"); + assert_eq!(seen(&[Some(40), Some(39), Some(39), Some(39), Some(39), Some(39)]), (false, sleeps.to_vec()), "fell"); + assert_eq!(seen(&[None]), (false, vec![]), "unreadable before the first sleep: no sleep taken"); + assert_eq!(seen(&[Some(40), None]), (false, vec![sleeps[0]]), "unreadable after a sleep: no further sleep"); + assert!(!left_its_core(&[], || Some(1), |_| panic!("slept")), "no sleep, nothing seen"); + } + + /// A read of this process by itself is taken only once the reading thread + /// is seen to leave its core: where it is, the read is the process's + /// count; where its count never rises, the read is `NotFolded` after + /// every sleep, and the process is not read at all; where its count + /// cannot be read, `NotFolded` at once. A failed read of the process + /// after a thread seen to leave is the platform's failure, not a fold's. + #[test] + fn a_self_read_whose_thread_is_not_seen_to_leave_is_no_reading() { + use std::cell::{Cell, RefCell}; + let run = |counts: &[Option], process: Option| { + let mut counts = counts.iter().copied().cycle(); + let slept = RefCell::new(Vec::new()); + let read = Cell::new(false); + let r = self_read_with( + || counts.next().flatten(), + |d| slept.borrow_mut().push(d), + || { + read.set(true); + process + }, + ); + (r, slept.into_inner(), read.get()) + }; + let (r, slept, read) = run(&[Some(7), Some(9)], Some(123_456)); + assert!(matches!(r, Ok(123_456)) && slept == [FOLD_SLEEPS[0]] && read, "{r:?} {slept:?} {read}"); + let (r, slept, read) = run(&[Some(7)], Some(123_456)); + assert!(matches!(r, Err(EnergyError::NotFolded)), "a count that never rose gave {r:?}"); + assert_eq!((slept, read), (FOLD_SLEEPS.to_vec(), false), "every sleep, then no read of the process"); + let (r, slept, read) = run(&[None], Some(123_456)); + assert!(matches!(r, Err(EnergyError::NotFolded)) && slept.is_empty() && !read, "{r:?} {slept:?} {read}"); + let (r, _, read) = run(&[Some(7), Some(9)], None); + assert!(matches!(r, Err(EnergyError::Platform(_))) && read, "{r:?}"); + } + + /// A window is the counter's advance between two reads, and one with no + /// reading at either end has no figure: the reason of the first end + /// without one. The work runs either way, and after a start with no + /// reading the end is not read. + #[test] + fn a_window_with_an_end_not_read_has_no_figure() { + use std::cell::Cell; + let window = |reads: [Result; 2]| { + let (taken, ran) = (Cell::new(0), Cell::new(false)); + let mut reads = reads.into_iter(); + let (out, figure) = window_over( + || { + taken.set(taken.get() + 1); + reads.next().expect("a third read") + }, + || ran.set(true), + ); + assert!(ran.get(), "the work did not run"); + (out, figure, taken.get()) + }; + let ((), figure, taken) = window([Ok(5_000_000), Ok(7_500_999)]); + assert!(matches!(figure, Ok(2_500)) && taken == 2, "{figure:?} after {taken} reads"); + let ((), figure, taken) = window([Err(EnergyError::NotFolded), Ok(7_500_999)]); + assert!(matches!(figure, Err(EnergyError::NotFolded)) && taken == 1, "{figure:?} after {taken} reads"); + let ((), figure, taken) = window([Ok(5_000_000), Err(EnergyError::NotFolded)]); + assert!(matches!(figure, Err(EnergyError::NotFolded)) && taken == 2, "{figure:?} after {taken} reads"); + let ((), figure, _) = window([Ok(5_000_000), Ok(5_000_400)]); + assert!(matches!(figure, Err(EnergyError::NotAdvanced)), "{figure:?}"); + let ((), figure, _) = window([Ok(5_000_000), Ok(4_000_000)]); + assert!(matches!(figure, Err(EnergyError::CounterWrap)), "{figure:?}"); + } + + /// One `proc_threadcounts` as the kernel writes it: a count of `levels` + /// performance levels in its first two bytes, six bytes of padding, and + /// for each level five u64s, the fifth its energy. + fn threadcounts(levels: u16, energy_nj: &[u64]) -> Vec { + let mut buf = vec![0u8; 512]; + buf[..2].copy_from_slice(&levels.to_ne_bytes()); + for (l, nj) in energy_nj.iter().enumerate() { + let record = 8 + l * 40; + for (field, word) in [11u64, 22, 33, 44, *nj].iter().enumerate() { + buf[record + field * 8..record + field * 8 + 8].copy_from_slice(&word.to_ne_bytes()); + } + } + buf + } + + /// The thread's count is read only in the one layout known: a header and + /// one 40-byte record per level it names. Its energy is the fifth u64 of + /// each record, summed. A call that failed, wrote any other size, or + /// names no level or more levels than the buffer holds, is no count. + #[test] + fn the_threads_count_is_read_only_in_the_layout_known() { + // The dev host's shape: two levels, 88 bytes. + assert_eq!(thread_energy_nj(&threadcounts(2, &[1_000, 250]), 88), Some(1_250)); + assert_eq!(thread_energy_nj(&threadcounts(1, &[77]), 48), Some(77)); + assert_eq!(thread_energy_nj(&threadcounts(3, &[1, 2, 4]), 128), Some(7)); + assert_eq!(thread_energy_nj(&threadcounts(2, &[u64::MAX, 9]), 88), Some(u64::MAX), "the sum saturates"); + for (wrote, why) in [(-1, "the call failed"), (0, "nothing written"), (80, "a shorter record"), (96, "a longer one")] { + assert_eq!(thread_energy_nj(&threadcounts(2, &[1_000, 250]), wrote), None, "{why}"); + } + assert_eq!(thread_energy_nj(&threadcounts(0, &[]), 8), None, "no performance level"); + assert_eq!(thread_energy_nj(&threadcounts(13, &[]), 528), None, "more levels than the buffer holds"); + assert_eq!(thread_energy_nj(&[2], 88), None, "a buffer with no header"); + } + + /// A host on which the reading thread's own count does not read has no + /// process counter: `Unavailable`, and the liveness probe is not run. + #[test] + fn a_host_without_the_threads_count_has_no_process_counter() { + assert_eq!(liveness_given(false, || panic!("probed a counter no read could be checked on")), CounterLiveness::Unavailable); + for verdict in [CounterLiveness::Live, CounterLiveness::Frozen, CounterLiveness::Unavailable] { + assert_eq!(liveness_given(true, || verdict), verdict); + } + } + + /// On this host the calling thread's own count reads, in the layout + /// known and with one record per performance level the host reports + /// (`hw.nperflevels`); and a read of this process by itself sees the + /// thread leave its core — the path every figure takes. + #[test] + fn on_this_host_the_reading_thread_is_seen_to_leave_its_core() { + let nj = this_thread_energy_nj().expect("this thread's own energy count"); + let mut tid = 0u64; + let mut buf = [0u8; 512]; + // SAFETY: as in `this_thread_energy_nj`. + let wrote = unsafe { + libc::pthread_threadid_np(libc::pthread_self(), &mut tid); + libc::proc_pidinfo(libc::getpid(), PROC_PIDTHREADCOUNTS, tid, buf.as_mut_ptr().cast(), buf.len() as libc::c_int) + }; + let levels = u16::from_ne_bytes([buf[0], buf[1]]); + let mut host_levels: libc::c_int = 0; + let mut size = std::mem::size_of::(); + // SAFETY: `host_levels` is writable for `size` bytes. + let rc = unsafe { + libc::sysctlbyname(c"hw.nperflevels".as_ptr(), (&mut host_levels as *mut libc::c_int).cast(), &mut size, std::ptr::null_mut(), 0) + }; + eprintln!("process-cpu: this thread's counts: {wrote} bytes, {levels} levels (hw.nperflevels {host_levels}, rc {rc}), {nj} nJ"); + assert_eq!(wrote, 8 + 40 * libc::c_int::from(levels)); + if rc == 0 { + assert_eq!(libc::c_int::from(levels), host_levels); + } + let read = self_read_nj(); + assert!(read.is_ok(), "this thread was not seen to leave its core within {FOLD_SLEEPS:?}: {read:?}"); + } + /// On this host: the counter is live, and 100 ms of this thread's CPU time /// meters as at least 0.05 J (a core at 0.5 W). The process-wide figure /// includes any concurrent test's threads, so the bound here is one-sided; diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/span.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/span.rs index 968b3c634..5b709853f 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/span.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/src/span.rs @@ -33,6 +33,10 @@ //! fallback's window is the work's own (and the CPU reads), never the //! snapshots' waits — a time-based estimate over those would bill a span of a //! few microseconds of work for up to two seconds of the meter's waiting. +//! Each CPU read sleeps before it reads (`process`: at least 50 µs, until the +//! reading thread is seen to have left its core), so the fallback's window +//! holds those two sleeps as well as the work: about a sixth of a +//! millisecond on an idle host, more on a loaded one. use std::time::Instant; diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu_short_span.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu_short_span.rs new file mode 100644 index 000000000..588622fc8 --- /dev/null +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-energy/tests/process_cpu_short_span.rs @@ -0,0 +1,228 @@ +//! Short spans on this process's own CPU-energy counter, against an oracle +//! that takes the reading thread off its core by a rule of its own. +//! +//! The kernel adds a thread's CPU energy to its process's count only when the +//! thread leaves its core, so a process that reads ITSELF from a thread that +//! has been running does not see that thread's latest energy. A span of a +//! millisecond of work then reads nothing at all, or what the thread spent +//! before the span. This file asks the counter for exactly such spans and +//! holds each figure against the test's own window around it. +//! +//! The counter reads every thread of this process, so the file is one test +//! binary with one test, which runs its checks in sequence on one thread. No +//! joule figure, joules per CPU-second or timing floor is asserted: what a +//! millisecond of CPU costs depends on the core class that ran it, and on a +//! loaded host the wall time of everything here stretches. + +#![cfg(target_os = "macos")] + +use std::time::{Duration, Instant}; + +use jouleclaw_energy::process::ProcessCpuCounter; +use jouleclaw_energy::{CounterLiveness, EnergyCounter}; + +/// This thread's CPU time. +fn thread_cpu() -> Duration { + let mut ts = libc::timespec { tv_sec: 0, tv_nsec: 0 }; + // SAFETY: `ts` is a valid, writable timespec for the duration of the call. + let rc = unsafe { libc::clock_gettime(libc::CLOCK_THREAD_CPUTIME_ID, &mut ts) }; + assert_eq!(rc, 0, "the thread CPU clock"); + Duration::new(ts.tv_sec as u64, ts.tv_nsec as u32) +} + +/// Burn `cpu` of this thread's own CPU time (not wall time, so a loaded host +/// that deschedules the thread still gets the whole burn). +fn burn(cpu: Duration) { + let start = thread_cpu(); + let mut x = 1u64; + while thread_cpu() - start < cpu { + for _ in 0..1_000 { + x = std::hint::black_box(x.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(1)); + } + } +} + +/// The oracle's read of this process's cumulative CPU energy, in nJ, +/// independent of the crate: `proc_pid_rusage(getpid(), RUSAGE_INFO_V6)` into +/// a 464-byte buffer, whose `ri_energy_nj` is the u64 at byte offset 336. +fn oracle_energy_nj() -> u64 { + let mut buf = [0u64; 58]; + // SAFETY: `buf` is 464 writable bytes, the size of `rusage_info_v6`; + // `getpid` has no preconditions. + let rc = unsafe { libc::proc_pid_rusage(libc::getpid(), 6, buf.as_mut_ptr() as *mut libc::rusage_info_t) }; + assert_eq!(rc, 0, "the oracle's proc_pid_rusage"); + buf[336 / 8] +} + +/// How many times this process's threads have been switched off a core +/// (`proc_pidinfo(PROC_PIDTASKINFO)`'s `pti_csw`). Only this test's thread +/// runs here, so a rise across a sleep is this thread leaving its core. +fn oracle_switches() -> i64 { + // SAFETY: an all-zero `proc_taskinfo` is a valid value of a struct of + // plain integers. + let mut info: libc::proc_taskinfo = unsafe { std::mem::zeroed() }; + let size = std::mem::size_of::() as libc::c_int; + // SAFETY: `info` is writable for `size` bytes, which the call is given. + let n = unsafe { + libc::proc_pidinfo(libc::getpid(), libc::PROC_PIDTASKINFO, 0, (&mut info as *mut libc::proc_taskinfo).cast(), size) + }; + assert_eq!(n, size, "the oracle's proc_pidinfo(PROC_PIDTASKINFO)"); + i64::from(info.pti_csw) +} + +/// The oracle's own way of taking this thread off its core, so that its +/// energy so far is in the process's count: sleep 1 ms, then 2, 4 and 8, +/// until the process's context-switch count rose across one. Not the +/// counter's rule (which watches this thread's own energy count across far +/// shorter sleeps): the two share no call and no number. +fn oracle_fold() { + for ms in [1, 2, 4, 8] { + let before = oracle_switches(); + std::thread::sleep(Duration::from_millis(ms)); + if oracle_switches() > before { + return; + } + } + panic!("the oracle never saw this thread leave its core across sleeps of 1, 2, 4 and 8 ms"); +} + +/// What one short span came to. +#[derive(Default)] +struct Tally { + /// A figure the check accepts as the span's. + agreed: usize, + /// Each accepted figure as a share of the oracle's window, in parts per + /// thousand: reported, so the margin the check leaves can be seen. + shares: Vec, + /// No figure: the counter said the span was not a reading. + no_figure: usize, + /// A figure that is not the span's — too little of the work, or, for a + /// sleep, the burn before it: the tries, with the figure (µJ) and the + /// oracle's window (nJ). + wrong: Vec<(usize, u64, u64)>, + /// A figure above the oracle's window: more than this process spent + /// around the span, which no read of this process's count can be. + over: Vec<(usize, u64, u64)>, +} + +impl Tally { + fn accept(&mut self, uj: u64, oracle_nj: u64) { + self.agreed += 1; + self.shares.push(uj * 1_000 * 1_000 / oracle_nj.max(1)); + } +} + +#[test] +fn a_short_span_reads_what_an_oracle_that_folds_on_its_own_reads() { + const TRIES: usize = 40; + let counter = ProcessCpuCounter::new(); + assert_eq!(counter.liveness(), CounterLiveness::Live, "this process's CPU-energy counter is not live here"); + + // 1. A millisecond of this thread's CPU, metered. The oracle's window + // opens before the counter's and closes after it, each end read once + // this thread has left its core, so it holds the whole burn and the + // counter's own reads. A figure is the span's when it is no more than + // that window and at least two thirds of it. The rest is the oracle's + // and the counter's own reads and wake-ups, which do not shrink with + // the burn's cost: at most 5% of the window on an M5 Max at a load + // average of 135, under 3% on a quiet M3 Ultra, and up to 16% on that + // M3 Ultra under 40 busy loops (the lowest of 8,800 spans). A counter + // that reads itself without first taking the reading thread off its + // core reads no advance across such a span, or part of the burn. + let mut burned = Tally::default(); + for i in 0..TRIES { + oracle_fold(); + let before = oracle_energy_nj(); + let ((), figure) = counter.measure(|| burn(Duration::from_millis(1))); + oracle_fold(); + let oracle_nj = oracle_energy_nj() - before; + match figure { + Ok(uj) if uj * 1_000 > oracle_nj => burned.over.push((i, uj, oracle_nj)), + Ok(uj) if uj * 1_000 * 3 >= oracle_nj * 2 => burned.accept(uj, oracle_nj), + Ok(uj) => burned.wrong.push((i, uj, oracle_nj)), + Err(_) => burned.no_figure += 1, + } + } + println!( + "short span: 1 ms burn x {TRIES}: {} agreed with the oracle (at least {}/1000 of its window), {} gave no \ + figure, {} gave a figure short of the span's {:?}, {} one over the oracle's window {:?} (try, µJ, oracle nJ)", + burned.agreed, + burned.shares.iter().min().copied().unwrap_or(0), + burned.no_figure, + burned.wrong.len(), + burned.wrong, + burned.over.len(), + burned.over + ); + + // 2. A 2 ms sleep, metered straight after 8 ms of this thread's CPU that + // the span does not cover. The sleep itself costs this process next to + // nothing; the burn before it is still on the thread, not yet in the + // process's count, when the span opens. A counter whose opening read + // does not take the thread off its core first reads that burn's tail + // as the sleep's energy. The oracle's window is the burn and the + // sleep; a figure for the sleep is under a quarter of it (it was at + // most 2% of it over 8,800 spans under 40 busy loops), or (a sleep + // over which nothing of this process ran) not a figure at all. + let mut slept = Tally::default(); + for i in 0..TRIES { + oracle_fold(); + let before = oracle_energy_nj(); + burn(Duration::from_millis(8)); + let ((), figure) = counter.measure(|| std::thread::sleep(Duration::from_millis(2))); + oracle_fold(); + let oracle_nj = oracle_energy_nj() - before; + match figure { + Ok(uj) if uj * 1_000 * 4 < oracle_nj => slept.accept(uj, oracle_nj), + Ok(uj) => slept.wrong.push((i, uj, oracle_nj)), + Err(_) => slept.no_figure += 1, + } + } + println!( + "short span: 2 ms sleep after an 8 ms burn x {TRIES}: {} under a quarter of the oracle's window (at most \ + {}/1000 of it), {} gave no figure, {} read the burn before the span {:?} (try, µJ, oracle nJ)", + slept.agreed, + slept.shares.iter().max().copied().unwrap_or(0), + slept.no_figure, + slept.wrong.len(), + slept.wrong + ); + + // 3. What a read costs: the wall time of each of 200 reads of the + // counter, back to back. Reported, never asserted — on a loaded host + // the wait for a core after the read's sleep is most of it. + let mut micros: Vec = (0..200) + .map(|_| { + let t = Instant::now(); + let _ = counter.read(); + t.elapsed().as_micros() + }) + .collect(); + micros.sort_unstable(); + println!( + "short span: one read of the counter costs {} µs at the median, {} µs at the 95th percentile, {} µs at most \ + (200 reads)", + micros[100], micros[190], micros[199] + ); + + assert!(burned.over.is_empty(), "a span read more than this process spent around it: {:?}", burned.over); + // A tenth of the spans may miss the band. On a loaded host the oracle's + // own reads can land on a costlier core than the burn did, which shrinks + // a correct figure's share of the oracle's window; and a read whose + // thread was not seen to leave its core is no reading by design. A + // counter that does not take the reading thread off its core misses on + // most spans: 25 to 31 of 40 on a loaded host, all 40 on an idle one. + assert!( + (burned.no_figure + burned.wrong.len()) * 10 <= TRIES, + "{} of {TRIES} 1 ms spans were given no figure and {} a figure short of the span's: {:?}", + burned.no_figure, + burned.wrong.len(), + burned.wrong + ); + assert!( + slept.wrong.len() * 10 <= TRIES, + "{} of {TRIES} sleeps were given the energy of the burn before them: {:?}", + slept.wrong.len(), + slept.wrong + ); +} diff --git a/proof/proof-rs/crates/proof-cascade/src/meter.rs b/proof/proof-rs/crates/proof-cascade/src/meter.rs index f8f377885..25f61049c 100644 --- a/proof/proof-rs/crates/proof-cascade/src/meter.rs +++ b/proof/proof-rs/crates/proof-cascade/src/meter.rs @@ -11,7 +11,8 @@ //! this process's threads burn meanwhile, which in a quiet caller is the //! workers' start-up and the sleeping caller, a few microjoules — while //! other processes are excluded by construction: no idle baseline to -//! subtract. +//! subtract. Each of the two reads is taken only once the calling thread +//! is seen to have left its core (below). //! 2. **IOReport's Energy Model** (Apple Silicon, read directly via its C API — //! no `macmon`, no sudo): SoC power bracketed busy against idle. //! 3. **RAPL** `energy_uj` (Linux): package power bracketed busy against idle. @@ -53,6 +54,52 @@ //! about every 0.5–0.7 ms under load, holds near 1–2 mJ/s idle, and keeps the //! energy of threads that have exited. //! +//! **A read of this process's own counter is taken only once the reading +//! thread is seen to have left its core.** The kernel adds a thread's energy +//! to its process's count only when the thread leaves a core — a context +//! switch, or the end of its quantum, about 10 ms of its CPU — and a +//! process's read of its own count does not take the reading thread off its +//! core: its CPU time is current at the read, its energy is not. So a window +//! bracketed by two plain reads holds, at its start, up to a quantum of what +//! the reading thread spent BEFORE the window (the liveness probe's burn, +//! say, or the caller's own work), and lacks, at its end, what that thread +//! spent since it last left a core. Measured on an M3 Ultra (macOS 27.0.1, +//! three runs of 40 windows of each kind, against the tests' own reader that +//! sleeps before each of its reads): a window over 1 ms of the reading +//! thread's CPU read no advance in all 40, every run; a window over a 2 ms +//! sleep opened straight after 8 ms of that thread's CPU read the burn +//! before it in all 40, every run, 40 to 48 mJ for a sleep. +//! +//! So before each read of its window the measuring thread sleeps (50 µs, +//! then 200 µs, 1 ms, 5 ms) until its own energy count +//! (`proc_pidinfo`'s `PROC_PIDTHREADCOUNTS`, by its thread id) rose across a +//! sleep — which it does only when the kernel adds that thread's energy to +//! the process's — and only then reads the process. A sleep alone is no +//! proof: one whose timer fires before the thread has blocked returns with +//! the thread still on its core; and the process's context-switch count is +//! none either, since any other thread's switch moves it. A read whose +//! thread was not seen to leave is no read: the measurement returns `None`, +//! and the caller keeps its estimate — never a figure short of the window's +//! tail, or holding what was spent before it, graded `HwShunt`. With it, the +//! same windows on the same host: quiet, all 40 of the 1 ms windows read 98% +//! or more of the tests' own window around them, and all 40 of the sleeps +//! under 1% of the window that held the burn before them; under 40 busy +//! loops (110 runs), every window read 82% or more, and no sleep more than +//! 4%. A read costs about 80 µs on the quiet host (the sleep and the wait +//! for a core after it) and 190 µs at the median under the busy loops (0.9 ms +//! at the median of the worst run, 50 ms the worst single read), against +//! under 1 µs for the read alone, and all four sleeps (6.25 ms) and their +//! waits when it fails. The measurement takes two, around a window of a +//! second over every spare core: one window around the whole batch of +//! calls, not one around each call. The workers have exited and been joined +//! before the closing read, and a thread's exit puts its last time on a core +//! into the count before the join returns (measured: a 5 ms burn read the +//! same at the join whether or not the thread slept before it exited), so +//! the window holds every call it counts. The counter is used only where the +//! measuring thread's own count reads, in the one layout known, and the +//! liveness probe samples with no sleep: it asks only whether the count +//! keeps advancing under a burn, which it does at every quantum. +//! //! **IOReport counts as reachable only while every CPU energy rail is live** //! ([`ioreport_status`](crate::meter::ioreport_status)). A subscription can //! open while no CPU rail tracks the work: measured on macOS 27.0.1 for an @@ -485,7 +532,9 @@ pub enum CounterStatus { /// permission to read it (RAPL's `energy_uj` is root-only on current /// kernels), or never two consecutive reads within the probe's five /// budgets. Never used. (The process counter is never `Absent`: it is one - /// counter, read or not.) + /// counter, read or not. It is `Unavailable` too where the measuring + /// thread's own energy count does not read: each read of a window is + /// checked against that count, so without it no window could be read.) Unavailable, /// The interface was read, but holds no counter for the domain a figure /// would claim (RAPL: zones, but no `package-` zone). Never used. @@ -742,13 +791,29 @@ static REAL_PROCESS_PROBE_RUNS: std::sync::atomic::AtomicUsize = std::sync::atom #[cfg(target_os = "macos")] fn process_host_status() -> CounterStatus { REAL_PROCESS_PROBE_RUNS.fetch_add(1, Ordering::SeqCst); - counter_status_of(&process_probe_with( - macos_process::energy_nj, - probe_clock::spin_tick, - probe_clock::wall_clock, - probe_clock::thread_cpu_time, - PROCESS_LIVENESS_BUDGET, - )) + process_status_where(macos_process::thread_energy_nj().is_some(), || { + counter_status_of(&process_probe_with( + macos_process::energy_nj, + probe_clock::spin_tick, + probe_clock::wall_clock, + probe_clock::thread_cpu_time, + PROCESS_LIVENESS_BUDGET, + )) + }) +} + +/// The process counter's status on a host where the measuring thread's own +/// energy count reads, or does not: what `probe` finds where it does, and +/// `Unavailable`, with no probe run, where it does not — every read of a +/// window is checked against that count ([`own_read`]), so a counter there +/// could never meter. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +fn process_status_where(thread_count_reads: bool, probe: impl FnOnce() -> CounterStatus) -> CounterStatus { + if thread_count_reads { + probe() + } else { + CounterStatus::Unavailable + } } /// This host's process-counter status, probed once per process and cached: @@ -785,6 +850,27 @@ pub fn simulate_frozen_process_energy() { macos_process::FROZEN.store(true, Ordering::SeqCst); } +/// The read [`measure_marginal`] takes of this process's CPU energy counter at +/// each end of its window, in nanojoules, where that counter is live: `None` +/// off macOS, where it is not live, and where the calling thread was not seen +/// to leave its core before the read ([`own_read`]). Exposed for the +/// short-span test, which brackets work of its own with two of these reads in +/// a process of its own; not part of the meter's interface. +#[doc(hidden)] +pub fn process_window_read_nj() -> Option { + #[cfg(target_os = "macos")] + { + if !admits_counter(process_energy_status()) { + return None; + } + macos_process::window_read_nj() + } + #[cfg(not(target_os = "macos"))] + { + None + } +} + /// The process-counter rung: `work` on every spare core, metered by this /// process's CPU energy counter — only while it is live (its own gate, on the /// cached status). `None` off macOS. @@ -797,7 +883,7 @@ where if !admits_counter(process_energy_status()) { return None; } - process_marginal_with(work, macos_process::energy_nj, PROCESS_WINDOW) + process_marginal_with(work, macos_process::window_read_nj, PROCESS_WINDOW) } #[cfg(not(target_os = "macos"))] { @@ -818,10 +904,11 @@ fn spare_cores() -> usize { /// rounded to the nearest: the counter's advance ÷ every call that completed. /// Reading after the join puts the energy of every counted call, and only /// those calls' window, in the figure; a call still running when `window` -/// ends finishes and is counted. `None` if either read fails (the work never -/// runs when the first one does), if the counter went down, or if no call -/// completed. Generic over the counter, so the tests drive it on a scripted -/// counter. +/// ends finishes and is counted. `None` if either read gives nothing (the +/// work never runs when the first one does) — the call failed, or, in +/// production, the calling thread was not seen to leave its core before the +/// read ([`own_read`]) — if the counter went down, or if no call completed. +/// Generic over the counter, so the tests drive it on a scripted counter. #[cfg_attr(not(target_os = "macos"), allow(dead_code))] fn process_marginal_with(work: F, counter: impl Fn() -> Option, window: std::time::Duration) -> Option where @@ -2422,6 +2509,194 @@ mod probe_clock { } } +// --------------------------------------------------------------------------- +// A process's read of its own energy counter: when it may be taken, and the +// one byte layout that check depends on. Kept apart from the FFI so both are +// pure, tested code on every platform; the macOS module only supplies the +// thread's own count, the sleep and the read. Why the check exists is in the +// module doc ("A read of this process's own counter…"). +// --------------------------------------------------------------------------- +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +mod own_read { + use std::time::Duration; + + /// The sleeps the measuring thread takes, in turn, before a read of its + /// own process, until one is seen to take it off its core. They grow, so + /// a sleep that returned without blocking is followed by one that much + /// more surely blocks; 6.25 ms in all on a read that is never seen to. + pub(super) const SLEEPS: [Duration; 4] = + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)]; + + /// Whether the measuring thread was seen to leave its core: its own + /// energy count (`count`) rose across one of `sleeps`, each taken in turn + /// through `sleep`. The kernel moves that count only when it adds the + /// thread's energy to its process's, so a rise across a sleep is the + /// thread having left its core after all it did before the sleep. A + /// count that held across every sleep, or went down, shows no such + /// thing, and one that cannot be read ends the wait at once. + pub(super) fn thread_left_its_core( + sleeps: &[Duration], + mut count: impl FnMut() -> Option, + mut sleep: impl FnMut(Duration), + ) -> bool { + for &pause in sleeps { + let Some(before) = count() else { return false }; + sleep(pause); + let Some(after) = count() else { return false }; + if after > before { + return true; + } + } + false + } + + /// One read at an end of the measurement's window: `counter`, this + /// process's cumulative CPU energy, read only once the measuring thread + /// was seen to leave its core ([`thread_left_its_core`] over [`SLEEPS`]). + /// `None` where it was not — the counter is then not read at all — or + /// the counter's own read gives nothing. + pub(super) fn window_read( + count: impl FnMut() -> Option, + sleep: impl FnMut(Duration), + counter: impl FnOnce() -> Option, + ) -> Option { + if thread_left_its_core(&SLEEPS, count, sleep) { + counter() + } else { + None + } + } + + /// `PROC_PIDTHREADCOUNTS`, the `proc_pidinfo` flavor that returns one + /// thread's counts, asked by its 64-bit thread id: in the kernel's + /// `` (macOS 13 and later), not the SDK's + /// public header, so its result is read in one layout only + /// ([`thread_energy_nj`]). + pub(super) const THREAD_COUNTS_FLAVOR: i32 = 34; + + /// The bytes a read of a thread's counts gives the kernel room for: the + /// header and twelve performance levels. + pub(super) const THREAD_COUNTS_BYTES: usize = 8 + 12 * 40; + + /// A thread's cumulative CPU energy in nanojoules, summed over the CPU + /// performance levels, from the `wrote` bytes the call says it wrote + /// into `counts`: a `uint16_t` count of levels and six bytes of padding, + /// then for each level five `uint64_t` — instructions, cycles, user + /// time, system time, energy (nJ). + /// + /// `None` unless the call wrote exactly the 8-byte header and one 40-byte + /// record for each level the header names, at least one. A failed call + /// and a result of any other size are a layout this code does not know: + /// no count, never a number read from the wrong place. An M5 Max and an + /// M3 Ultra (macOS 27.0.1) write 88 bytes, two levels. + pub(super) fn thread_energy_nj(counts: &[u8], wrote: i32) -> Option { + let levels = usize::from(u16::from_ne_bytes([*counts.first()?, *counts.get(1)?])); + let bytes = 8 + levels * 40; + if levels == 0 || bytes > counts.len() || usize::try_from(wrote).ok() != Some(bytes) { + return None; + } + let energy = (0..levels).map(|level| { + let at = 8 + level * 40 + 32; + let mut word = [0u8; 8]; + word.copy_from_slice(&counts[at..at + 8]); + u64::from_ne_bytes(word) + }); + Some(energy.fold(0, u64::saturating_add)) + } + + #[cfg(test)] + mod tests { + use super::*; + use std::cell::{Cell, RefCell}; + + /// The measuring thread is seen to leave its core only when its own + /// count rose across a sleep; the sleeps are taken in turn until one + /// does. A count that held, went down or could not be read is no + /// such sight, and an unreadable count takes no further sleep. + #[test] + fn the_thread_is_seen_to_leave_its_core_only_by_its_own_count_rising() { + let sleeps = [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1)]; + let seen = |counts: &[Option]| { + let mut counts = counts.iter().copied(); + let slept = RefCell::new(Vec::new()); + let left = thread_left_its_core(&sleeps, || counts.next().flatten(), |pause| slept.borrow_mut().push(pause)); + (left, slept.into_inner()) + }; + assert_eq!(seen(&[Some(70), Some(71)]), (true, vec![sleeps[0]]), "rose across the first sleep"); + assert_eq!( + seen(&[Some(70), Some(70), Some(70), Some(70), Some(70), Some(5_000)]), + (true, sleeps.to_vec()), + "held across two sleeps, rose across the third" + ); + assert_eq!(seen(&[Some(70); 6]), (false, sleeps.to_vec()), "held across every sleep"); + assert_eq!(seen(&[Some(70), Some(60), Some(60), Some(50), Some(50), Some(40)]), (false, sleeps.to_vec()), "went down"); + assert_eq!(seen(&[None]), (false, vec![]), "unreadable before any sleep"); + assert_eq!(seen(&[Some(70), None]), (false, vec![sleeps[0]]), "unreadable after a sleep"); + assert!(!thread_left_its_core(&[], || Some(1), |_| panic!("slept")), "no sleep, nothing seen"); + assert_eq!(SLEEPS.iter().sum::(), Duration::from_micros(6_250)); + } + + /// A window's read is the counter's only once the thread was seen to + /// leave its core. Where its count never rises the read is `None` + /// after every sleep, and the counter is not read at all; where its + /// count cannot be read, `None` at once. A counter that gives + /// nothing after a thread seen to leave is `None` too. + #[test] + fn a_window_read_whose_thread_is_not_seen_to_leave_its_core_is_no_read() { + let run = |counts: &[Option], counter: Option| { + let mut counts = counts.iter().copied().cycle(); + let slept = RefCell::new(Vec::new()); + let read = Cell::new(false); + let r = window_read( + || counts.next().flatten(), + |pause| slept.borrow_mut().push(pause), + || { + read.set(true); + counter + }, + ); + (r, slept.into_inner(), read.get()) + }; + assert_eq!(run(&[Some(3), Some(8)], Some(123_456)), (Some(123_456), vec![SLEEPS[0]], true)); + assert_eq!(run(&[Some(3)], Some(123_456)), (None, SLEEPS.to_vec(), false), "a count that never rose"); + assert_eq!(run(&[None], Some(123_456)), (None, vec![], false), "a count that cannot be read"); + assert_eq!(run(&[Some(3), Some(8)], None), (None, vec![SLEEPS[0]], true), "the counter gave nothing"); + } + + /// A thread's counts as the kernel writes them: `levels` in the first + /// two bytes, six of padding, five u64 a level, the fifth its energy. + fn counts(levels: u16, energy_nj: &[u64]) -> Vec { + let mut bytes = vec![0u8; THREAD_COUNTS_BYTES]; + bytes[..2].copy_from_slice(&levels.to_ne_bytes()); + for (level, nj) in energy_nj.iter().enumerate() { + for (field, word) in [71u64, 72, 73, 74, *nj].into_iter().enumerate() { + let at = 8 + level * 40 + field * 8; + bytes[at..at + 8].copy_from_slice(&word.to_ne_bytes()); + } + } + bytes + } + + /// The energy is each level's fifth u64, summed, and a result of any + /// size but the header and one record a level is no count. + #[test] + fn a_threads_energy_is_read_only_from_the_layout_known() { + assert_eq!(THREAD_COUNTS_FLAVOR, 34); + assert_eq!(thread_energy_nj(&counts(2, &[2_500_000, 40]), 88), Some(2_500_040), "two levels, 88 bytes"); + assert_eq!(thread_energy_nj(&counts(1, &[9]), 48), Some(9)); + assert_eq!(thread_energy_nj(&counts(3, &[1, 20, 300]), 128), Some(321)); + assert_eq!(thread_energy_nj(&counts(2, &[u64::MAX, 2]), 88), Some(u64::MAX), "the sum saturates"); + let two = counts(2, &[2_500_000, 40]); + for (wrote, why) in [(-1, "the call failed"), (0, "nothing written"), (48, "one record"), (80, "short"), (96, "long")] { + assert_eq!(thread_energy_nj(&two, wrote), None, "{why}"); + } + assert_eq!(thread_energy_nj(&counts(0, &[]), 8), None, "no performance level"); + assert_eq!(thread_energy_nj(&counts(13, &[]), 8 + 13 * 40), None, "more levels than the buffer holds"); + assert_eq!(thread_energy_nj(&[2], 88), None, "no header"); + } + } +} + // --------------------------------------------------------------------------- // macOS — this process's CPU energy counter: `proc_pid_rusage(getpid(), // RUSAGE_INFO_V6)`, public libproc API, readable by an unprivileged process. @@ -2429,6 +2704,7 @@ mod probe_clock { #[cfg(target_os = "macos")] #[allow(unsafe_code)] mod macos_process { + use super::own_read; use std::os::raw::{c_int, c_void}; use std::sync::atomic::{AtomicBool, Ordering}; @@ -2503,6 +2779,14 @@ mod macos_process { /// ``: `int proc_pid_rusage(int pid, int flavor, /// rusage_info_t *buffer)`; 0 on success. fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + /// ``: `int proc_pidinfo(int pid, int flavor, uint64_t arg, + /// void *buffer, int buffersize)`; the bytes written, or 0 or less. + fn proc_pidinfo(pid: c_int, flavor: c_int, arg: u64, buffer: *mut c_void, buffersize: c_int) -> c_int; + /// ``: the calling thread. + fn pthread_self() -> *mut c_void; + /// ``: `int pthread_threadid_np(pthread_t thread, + /// uint64_t *thread_id)`; 0 on success. + fn pthread_threadid_np(thread: *mut c_void, thread_id: *mut u64) -> c_int; } /// Set by [`super::simulate_frozen_process_energy`]. @@ -2530,6 +2814,34 @@ mod macos_process { (rc == 0).then(|| unsafe { info.assume_init() }.ri_energy_nj) } + /// The calling thread's own cumulative CPU energy in nanojoules: the + /// count a window's read watches to see the thread leave its core. + /// `None` if the thread's id or its counts cannot be read, or the counts + /// come back in a layout [`own_read::thread_energy_nj`] does not know. + pub(super) fn thread_energy_nj() -> Option { + let pid = c_int::try_from(std::process::id()).ok()?; + let mut thread = 0u64; + // SAFETY: `thread` is a writable u64, and `pthread_self` is the + // calling thread, alive for the call. + if unsafe { pthread_threadid_np(pthread_self(), &mut thread) } != 0 { + return None; + } + let mut counts = [0u8; own_read::THREAD_COUNTS_BYTES]; + let size = c_int::try_from(counts.len()).ok()?; + // SAFETY: `counts` is writable for `size` bytes, which the call is + // given; the kernel writes plain integers and no more than that. + let wrote = unsafe { proc_pidinfo(pid, own_read::THREAD_COUNTS_FLAVOR, thread, counts.as_mut_ptr().cast(), size) }; + own_read::thread_energy_nj(&counts, wrote) + } + + /// The read the measurement takes at each end of its window: this + /// process's counter ([`energy_nj`]), read only once the calling thread + /// was seen to leave its core ([`own_read::window_read`]). `None` where + /// it was not, or the counter's read fails. + pub(super) fn window_read_nj() -> Option { + own_read::window_read(thread_energy_nj, std::thread::sleep, energy_nj) + } + #[cfg(test)] mod tests { use super::*; @@ -2595,6 +2907,21 @@ mod macos_process { } assert!(prod.windows(2).all(|w| w[1] > w[0]), "the production reads did not advance across 50 ms burns: {prod:?}"); } + + /// On this host the calling thread's own count reads, in the layout + /// known, and a window's read sees the thread leave its core: the + /// path both of the measurement's reads take. The read is this + /// process's counter, between two of the tests' own reads of it. + #[test] + fn a_window_read_sees_the_measuring_thread_leave_its_core_here() { + let thread = thread_energy_nj(); + eprintln!("process window read: this thread's own energy count: {thread:?} nJ"); + assert!(thread.is_some(), "this thread's own energy count does not read here"); + let lo = oracle_energy_nj(); + let v = window_read_nj().expect("the measuring thread was not seen to leave its core"); + let hi = oracle_energy_nj(); + assert!(lo <= v && v <= hi, "the window's read {v} is outside the oracle's [{lo}, {hi}]"); + } } } @@ -5148,6 +5475,46 @@ mod tests { assert_eq!(process_marginal_with(half_up, || Some(NJ3.load(Ordering::SeqCst)), Duration::from_millis(50)), Some(8)); } + /// A host on which the measuring thread's own energy count does not read + /// has no process counter: `Unavailable`, which never meters, and the + /// liveness probe is not run. Where the count reads, the status is the + /// probe's. + #[test] + fn process_no_counter_where_the_threads_own_count_does_not_read() { + let status = process_status_where(false, || panic!("probed a counter no window could be read on")); + assert_eq!(status, CounterStatus::Unavailable); + assert!(!admits_counter(status)); + for probed in [CounterStatus::Live, CounterStatus::Frozen, CounterStatus::Unavailable] { + assert_eq!(process_status_where(true, || probed), probed); + } + } + + /// The production window read on a thread never seen to leave its core + /// gives the measurement no figure, and the work never runs: the same + /// `None` an unreadable counter gives, never a window read from a count + /// that may lack what the thread spent. + #[test] + fn process_a_window_whose_thread_is_not_seen_to_leave_its_core_gives_no_figure() { + static CALLS: AtomicU64 = AtomicU64::new(0); + fn counted() { + CALLS.fetch_add(1, Ordering::SeqCst); + } + let read = Cell::new(0u32); + // The thread's count reads, and never moves; the counter would read. + let never_seen = || { + own_read::window_read( + || Some(7), + |_| {}, + || { + read.set(read.get() + 1); + Some(1_000_000) + }, + ) + }; + assert_eq!(process_marginal_with(counted, never_seen, Duration::from_millis(50)), None); + assert_eq!((CALLS.load(Ordering::SeqCst), read.get()), (0, 0), "the work ran, or the counter was read"); + } + /// No figure — never an invented one — from a counter that cannot be read /// (and then the work never runs) or that went down. #[test] diff --git a/proof/proof-rs/crates/proof-cascade/tests/process_energy_short_span.rs b/proof/proof-rs/crates/proof-cascade/tests/process_energy_short_span.rs new file mode 100644 index 000000000..f9cbf3087 --- /dev/null +++ b/proof/proof-rs/crates/proof-cascade/tests/process_energy_short_span.rs @@ -0,0 +1,188 @@ +//! Short spans on this process's CPU energy counter, bracketed by the read +//! the meter takes at each end of its window, against an oracle that takes +//! the reading thread off its core by a rule of its own. +//! +//! The kernel adds a thread's CPU energy to its process's count only when the +//! thread leaves its core. A process that reads its own count from a thread +//! still on its core reads a count that lacks what that thread spent since it +//! last left one: a window of a millisecond of the reading thread's work then +//! reads nothing, and a window opened straight after other work reads that +//! work as its own. +//! +//! One test binary with one test: the counter counts every thread of the +//! process, and the oracle's check is the process's context-switch count, so +//! nothing else may run here. No joule figure, joules per CPU-second or +//! timing is asserted: what a millisecond of CPU costs follows the core that +//! ran it, and a loaded host stretches everything's wall time. + +#![cfg(target_os = "macos")] + +use proof_cascade::meter::{meter_source, process_energy_status, process_window_read_nj, CounterStatus, MeterSource}; +use std::os::raw::{c_int, c_void}; +use std::time::{Duration, Instant}; + +unsafe extern "C" { + fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut [u64; 58]) -> c_int; + fn proc_pidinfo(pid: c_int, flavor: c_int, arg: u64, buffer: *mut c_void, buffersize: c_int) -> c_int; + fn getpid() -> c_int; + fn clock_gettime_nsec_np(clock_id: u32) -> u64; +} + +/// This thread's CPU time (`CLOCK_THREAD_CPUTIME_ID` is 16 in ``). +fn thread_cpu() -> Duration { + // SAFETY: the call takes a clock id and returns a number. + Duration::from_nanos(unsafe { clock_gettime_nsec_np(16) }) +} + +/// Spin until this thread has used `d` of its own CPU time (or 20 s of wall +/// time have passed), however loaded the host is. +fn burn(d: Duration) { + let (started, wall) = (thread_cpu(), Instant::now()); + let mut acc = 0u64; + while thread_cpu() - started < d && wall.elapsed() < Duration::from_secs(20) { + for _ in 0..1_000 { + acc = std::hint::black_box(acc.wrapping_add(1)); + } + } +} + +/// The oracle's read of `ri_energy_nj`: `proc_pid_rusage(getpid(), 6)` into a +/// raw 464-byte buffer, the count at byte 336 (its 43rd `uint64_t`). +fn oracle_energy_nj() -> u64 { + let mut buf = [0u64; 58]; + // SAFETY: buf is 464 writable bytes, the size of rusage_info_v6. + let rc = unsafe { proc_pid_rusage(getpid(), 6, &mut buf) }; + assert_eq!(rc, 0, "the oracle's proc_pid_rusage(getpid(), 6) failed"); + buf[42] +} + +/// How many times this process's threads have been switched off a core: +/// `pti_csw`, the `int32_t` at byte 80 of the 96-byte `proc_taskinfo` that +/// `proc_pidinfo(getpid(), PROC_PIDTASKINFO = 4)` fills. +fn oracle_context_switches() -> i32 { + let mut info = [0i32; 24]; + // SAFETY: info is 96 writable bytes, the size the call is given. + let wrote = unsafe { proc_pidinfo(getpid(), 4, 0, info.as_mut_ptr().cast(), 96) }; + assert_eq!(wrote, 96, "the oracle's proc_pidinfo(PROC_PIDTASKINFO) wrote {wrote} bytes"); + info[20] +} + +/// The oracle's read of this process's energy once this thread has left its +/// core, by the oracle's own rule: a sleep of 1 ms, then 2, 4 and 8, until +/// the process's context-switch count rose across one. This test's thread is +/// the only one that runs here, so a rise is its own switch, and the read +/// after it holds all the thread spent before. The meter's read shares +/// neither call nor number with this. +fn oracle_energy_nj_off_core() -> u64 { + let left = [1, 2, 4, 8].into_iter().any(|ms| { + let before = oracle_context_switches(); + std::thread::sleep(Duration::from_millis(ms)); + oracle_context_switches() > before + }); + assert!(left, "the oracle never saw this thread leave its core across sleeps of 1, 2, 4 and 8 ms"); + oracle_energy_nj() +} + +/// The meter's window over what ran between its two reads: the counter's +/// advance in nJ, or `None` where a read gave nothing or the counter did not +/// advance — no reading, as the meter itself takes it. +fn window_nj(before: Option, after: Option) -> Option { + after?.checked_sub(before?).filter(|nj| *nj > 0) +} + +#[test] +fn a_short_window_reads_what_an_oracle_that_leaves_its_core_its_own_way_reads() { + const TRIES: usize = 40; + let (status, source) = (process_energy_status(), meter_source()); + eprintln!("process short window: status={status:?} source={source:?}"); + assert_eq!(status, CounterStatus::Live, "this process's CPU energy counter is not live here"); + assert_eq!(source, Some(MeterSource::ProcessEnergy), "a live process counter was not selected"); + + // 1. A millisecond of this thread's CPU between the meter's two reads. + // The oracle's window opens before the first and closes after the + // second, each end read once this thread has left its core, so it + // holds the burn and both readers' own reads and wake-ups. A window + // is the burn's when it is no more than the oracle's and at least two + // thirds of it: the readers' own cost does not shrink with the + // burn's. A reading above the oracle's is not this process's count. + let (mut shares, mut none, mut short, mut over) = (Vec::new(), 0usize, Vec::new(), Vec::new()); + for i in 0..TRIES { + let oracle_before = oracle_energy_nj_off_core(); + let before = process_window_read_nj(); + burn(Duration::from_millis(1)); + let after = process_window_read_nj(); + let oracle_nj = oracle_energy_nj_off_core() - oracle_before; + match window_nj(before, after) { + None => none += 1, + Some(nj) if nj > oracle_nj => over.push((i, nj, oracle_nj)), + Some(nj) if nj * 3 < oracle_nj * 2 => short.push((i, nj, oracle_nj)), + Some(nj) => shares.push(nj * 1_000 / oracle_nj.max(1)), + } + } + eprintln!( + "process short window: 1 ms burn x {TRIES}: {} read within the oracle's window (at least {}/1000 of it), \ + {none} not read, {} read short {short:?}, {} read over {over:?} (try, nJ, oracle nJ)", + shares.len(), + shares.iter().min().copied().unwrap_or(0), + short.len(), + over.len() + ); + + // 2. A 2 ms sleep between the two reads, straight after 8 ms of this + // thread's CPU that the window does not cover. The burn is still on + // the thread, not yet in the process's count, when the window opens; + // a first read that does not take the thread off its core leaves the + // burn to land inside the window. The oracle's window is the burn and + // the sleep: a reading for the sleep is under a quarter of it, or no + // reading at all. + let (mut slept, mut slept_none, mut leaked) = (Vec::new(), 0usize, Vec::new()); + for i in 0..TRIES { + let oracle_before = oracle_energy_nj_off_core(); + burn(Duration::from_millis(8)); + let before = process_window_read_nj(); + std::thread::sleep(Duration::from_millis(2)); + let after = process_window_read_nj(); + let oracle_nj = oracle_energy_nj_off_core() - oracle_before; + match window_nj(before, after) { + None => slept_none += 1, + Some(nj) if nj * 4 >= oracle_nj => leaked.push((i, nj, oracle_nj)), + Some(nj) => slept.push(nj * 1_000 / oracle_nj.max(1)), + } + } + eprintln!( + "process short window: 2 ms sleep after an 8 ms burn x {TRIES}: {} read under a quarter of the oracle's \ + window (at most {}/1000 of it), {slept_none} not read, {} read the burn before the window {leaked:?} (try, \ + nJ, oracle nJ)", + slept.len(), + slept.iter().max().copied().unwrap_or(0), + leaked.len() + ); + + // 3. What one read costs, in wall time: reported, never asserted. + let mut micros: Vec = (0..200) + .map(|_| { + let t = Instant::now(); + let _ = process_window_read_nj(); + t.elapsed().as_micros() + }) + .collect(); + micros.sort_unstable(); + eprintln!( + "process short window: one read costs {} us at the median, {} us at the 95th percentile, {} us at most (200 \ + reads)", + micros[100], micros[190], micros[199] + ); + + assert!(over.is_empty(), "a window read more than this process spent around it: {over:?}"); + // A tenth of the windows may miss the band: on a loaded host the + // oracle's own reads can land on a costlier core than the burn did, and + // a read whose thread was not seen to leave its core is no reading by + // design. A read that does not take the reading thread off its core + // misses on most windows (all 40, on a quiet host). + assert!( + (none + short.len()) * 10 <= TRIES, + "{none} of {TRIES} 1 ms windows were not read and {} were read short: {short:?}", + short.len() + ); + assert!(leaked.len() * 10 <= TRIES, "{} of {TRIES} sleeps read the burn before them: {leaked:?}", leaked.len()); +} diff --git a/proof/proof-rs/crates/proof-cli/src/main.rs b/proof/proof-rs/crates/proof-cli/src/main.rs index 1e7fe0347..fcf469202 100644 --- a/proof/proof-rs/crates/proof-cli/src/main.rs +++ b/proof/proof-rs/crates/proof-cli/src/main.rs @@ -287,7 +287,8 @@ fn process_reason() -> &'static str { use proof_cascade::meter::{process_energy_status, CounterStatus}; match process_energy_status() { CounterStatus::Unavailable => { - "this process's CPU energy counter (proc_pid_rusage, ri_energy_nj) could not be read" + "this process's CPU energy counter (proc_pid_rusage, ri_energy_nj) could not be read, or the measuring \ + thread's own energy count, which each of its reads is checked against, could not" } CounterStatus::Absent => "this process's CPU energy counter is absent", CounterStatus::Frozen => {