diff --git a/eoc/eoc-rs/crates/eoc-local/src/lib.rs b/eoc/eoc-rs/crates/eoc-local/src/lib.rs index 0fedc4fc6..e0b4d80ff 100644 --- a/eoc/eoc-rs/crates/eoc-local/src/lib.rs +++ b/eoc/eoc-rs/crates/eoc-local/src/lib.rs @@ -47,6 +47,18 @@ //! the final read's. A generation that ends in an error is estimated over //! the tokens streamed before it, at least one. //! +//! Which counter to hand a backend is the caller's choice, and the counter's +//! domain must cover where the backend's work runs. Every backend here runs +//! in this process (each binds its runtime as a library, none spawns a +//! subprocess), but most offload to an accelerator: `mlx` to the GPU and +//! Neural Engine, `mlc` to the GPU, `llamacpp` to the GPU by default +//! (`n_gpu_layers` 999), and `onnx` too with a CoreML, CUDA, DirectML or +//! TensorRT provider. This process's own CPU energy counter +//! ([`eoc_meter::detect_in_process`]) sees none of that. It covers a backend +//! only while all of its work stays on the CPU here: `onnx` with the CPU +//! provider, `llamacpp` with `n_gpu_layers` 0. Otherwise hand it what +//! [`eoc_meter::detect`] selects. +//! //! ## WASM //! //! [`gguf`] and [`tokenizer`] compile to `wasm32-unknown-unknown`. The diff --git a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs index 504476135..984a7aef5 100644 --- a/eoc/eoc-rs/crates/eoc-meter/src/lib.rs +++ b/eoc/eoc-rs/crates/eoc-meter/src/lib.rs @@ -44,6 +44,11 @@ //! RAPL and NVML are, so a delta it reads is `Measured` — but only while the //! rails are live: the counter exists only on a host whose rails the probe //! found live, and on any other there is no IOReport reading to tag. +//! - macOS per-process energy ([`MacosProcessEnergyCounter`]): this +//! 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. //! - 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. @@ -52,12 +57,13 @@ //! ([`nvml_status`]). //! - WASM and unknown targets fall through to `StubCounter`. -// `deny` not `forbid`: the whole crate is safe except two audited FFI modules, -// each with a scoped `#[allow(unsafe_code)]`: the Apple-Silicon IOReport module -// (`macos_ioreport`) — the on-die energy counters are unreachable without the -// `unsafe extern "C"` IOReport calls — and `clocks`, whose one call is -// `clock_gettime` for the probing thread's CPU clock. Everything else stays -// unsafe-free. +// `deny` not `forbid`: the whole crate is safe except three audited FFI +// modules, each with a scoped `#[allow(unsafe_code)]`: the Apple-Silicon +// 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`. +// Everything else stays unsafe-free. #![deny(unsafe_code)] // `Error` is used by platform-conditional modules below. @@ -276,7 +282,7 @@ mod rail_liveness { /// A watch of every channel of a sample: for a vendor counter (RAPL's /// package counters, one channel a package; NVML's total-energy /// counter), whose every channel counts the domain it claims. - #[cfg_attr(not(any(target_os = "linux", feature = "cuda")), allow(dead_code))] // used by the RAPL and NVML rungs + #[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter pub(crate) fn every_channel() -> Self { Self::of(|_| true) } @@ -536,7 +542,7 @@ mod rail_liveness { /// it does not open: then nothing is sampled and nothing ticks. Generic /// over each part so the tests drive this very function with a scripted /// counter, tick and clock; each rung's cached probe passes the real ones. - #[cfg_attr(not(any(target_os = "linux", feature = "cuda")), allow(dead_code))] // used by the RAPL and NVML rungs + #[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter pub(crate) fn probe_counter( open: impl FnOnce() -> Option, mut sample: impl FnMut(&C) -> Option>, @@ -552,7 +558,7 @@ mod rail_liveness { /// not open) and not one interval observed (no two usable samples in five /// budgets) are both `Unavailable`; only a rail that kept advancing is /// `Live`. - #[cfg_attr(not(any(target_os = "linux", feature = "cuda")), allow(dead_code))] // used by the RAPL and NVML rungs + #[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter pub(crate) fn counter_status(probed: Option<&RailWatch>) -> crate::CounterStatus { match probed { None => crate::CounterStatus::Unavailable, @@ -564,7 +570,7 @@ mod rail_liveness { /// Whether a counter rung with this status may be selected: only when it /// is live. The one gate the RAPL and NVML constructors pass through. - #[cfg_attr(not(any(target_os = "linux", feature = "cuda")), allow(dead_code))] // used by the RAPL and NVML rungs + #[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter pub(crate) fn admits_vendor_counter(status: crate::CounterStatus) -> bool { status == crate::CounterStatus::Live } @@ -3658,7 +3664,7 @@ pub enum CounterStatus { /// that is not live before declining it: one second, as /// `CPU_RAIL_LIVENESS_BUDGET`. A live counter is called live about 300 ms in. /// Paid once per process, and only where the counter opens. -#[cfg_attr(not(any(target_os = "linux", feature = "cuda")), allow(dead_code))] // used by the RAPL and NVML rungs +#[cfg_attr(not(any(target_os = "linux", target_os = "macos", feature = "cuda")), allow(dead_code))] // used by RAPL, NVML and the process counter const VENDOR_COUNTER_LIVENESS_BUDGET: std::time::Duration = std::time::Duration::from_millis(1000); /// This host's RAPL status, probed once per process and cached. @@ -4418,6 +4424,301 @@ mod macos_powermetrics { #[cfg(target_os = "macos")] pub use macos_powermetrics::MacosPowermetricsCounter; +/// 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). +/// +/// The domain, exactly: the CPU energy of **this process's threads**, all of +/// them, cumulative since the process started. Not a child process's (a +/// child's energy is its own, and is not added to the parent's when it is +/// reaped), and not the GPU, the Neural Engine, DRAM, or anything else on the +/// SoC. So it measures work this process runs on the CPU, in-process, and +/// nothing else; and it measures all of that, including another thread's +/// unrelated work during the same span. +/// +/// That is why [`crate::detect`] never selects it: eoc's counter brackets +/// stages that may run their work in a subprocess (a CLI-backed tool, a +/// scoring interpreter) or on the GPU, and a span over such work would read +/// only this process's share — a figure for work it did not see, tagged +/// measured. A caller whose metered work runs on the CPU in this process +/// opts in with [`crate::detect_in_process`] or +/// [`MacosProcessEnergyCounter::try_new`]. +#[cfg(target_os = "macos")] +#[allow(unsafe_code)] +mod macos_process_energy { + use super::*; + use crate::rail_liveness; + use std::os::raw::{c_int, c_void}; + + /// `RUSAGE_INFO_V6` in ``. + const RUSAGE_INFO_V6: c_int = 6; + + /// `struct rusage_info_v6` from the macOS 27 SDK's ``, + /// field for field. Only `ri_energy_nj` is read; the layout up to it must + /// match exactly, and the size must cover what the kernel writes. + #[repr(C)] + #[derive(Default)] + struct RusageInfoV6 { + ri_uuid: [u8; 16], + ri_user_time: u64, + ri_system_time: u64, + ri_pkg_idle_wkups: u64, + ri_interrupt_wkups: u64, + ri_pageins: u64, + ri_wired_size: u64, + ri_resident_size: u64, + ri_phys_footprint: u64, + ri_proc_start_abstime: u64, + ri_proc_exit_abstime: u64, + ri_child_user_time: u64, + ri_child_system_time: u64, + ri_child_pkg_idle_wkups: u64, + ri_child_interrupt_wkups: u64, + ri_child_pageins: u64, + ri_child_elapsed_abstime: u64, + ri_diskio_bytesread: u64, + ri_diskio_byteswritten: u64, + ri_cpu_time_qos_default: u64, + ri_cpu_time_qos_maintenance: u64, + ri_cpu_time_qos_background: u64, + ri_cpu_time_qos_utility: u64, + ri_cpu_time_qos_legacy: u64, + ri_cpu_time_qos_user_initiated: u64, + ri_cpu_time_qos_user_interactive: u64, + ri_billed_system_time: u64, + ri_serviced_system_time: u64, + ri_logical_writes: u64, + ri_lifetime_max_phys_footprint: u64, + ri_instructions: u64, + ri_cycles: u64, + ri_billed_energy: u64, + ri_serviced_energy: u64, + ri_interval_max_phys_footprint: u64, + ri_runnable_time: u64, + ri_flags: u64, + ri_user_ptime: u64, + ri_system_ptime: u64, + ri_pinstructions: u64, + ri_pcycles: u64, + ri_energy_nj: u64, + ri_penergy_nj: u64, + ri_secure_time_in_system: u64, + ri_secure_ptime_in_system: u64, + ri_neural_footprint: u64, + ri_lifetime_max_neural_footprint: u64, + ri_interval_max_neural_footprint: u64, + ri_conclave_footprint: u64, + ri_page_wait_time_mach: u64, + ri_page_cache_hits: u64, + ri_reserved: [u64; 6], + } + + // `sizeof(struct rusage_info_v6)` and `offsetof(.., ri_energy_nj)`, as a C + // program compiled against the macOS 27 SDK prints them. + const _: () = assert!(std::mem::size_of::() == 464); + const _: () = assert!(std::mem::offset_of!(RusageInfoV6, ri_energy_nj) == 336); + + unsafe extern "C" { + fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + fn getpid() -> c_int; + } + + /// This process's id. + pub(crate) fn this_pid() -> i32 { + unsafe { getpid() } + } + + /// 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). + pub(crate) fn energy_nj(pid: i32) -> Option { + let mut info = RusageInfoV6::default(); + let rc = unsafe { proc_pid_rusage(pid, RUSAGE_INFO_V6, &mut info as *mut RusageInfoV6 as *mut c_void) }; + (rc == 0).then_some(info.ri_energy_nj) + } + + /// This process's own CPU energy counter; see the module documentation + /// for its domain. Constructed only where the counter is live + /// ([`crate::process_energy_status`]), and then a delta it reads is a + /// measurement of this process's CPU work over the span. + #[derive(Debug)] + pub struct MacosProcessEnergyCounter { + pid: i32, + } + + impl MacosProcessEnergyCounter { + /// This process's energy counter, on a host where it is live. + /// `Err(NoCounter)` otherwise; [`crate::process_energy_status`] says + /// why. For callers whose metered work runs on the CPU in this + /// process only: not a subprocess's work, not the GPU's. + pub fn try_new() -> Result { + Self::try_new_given(crate::process_energy_status()) + } + + /// The constructor behind [`Self::try_new`], given this host's status: + /// 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() }) + } else { + Err(Error::NoCounter) + } + } + } + + impl JouleCounter for MacosProcessEnergyCounter { + /// This process's cumulative CPU energy since it started, in µJ + /// (`ri_energy_nj` / 1000). + fn read_microjoules(&self) -> Result { + energy_nj(self.pid) + .map(|nj| nj / 1_000) + .ok_or_else(|| Error::Backend("proc_pid_rusage(RUSAGE_INFO_V6) failed".to_string())) + } + fn name(&self) -> &'static str { + "process-energy" + } + } + + /// One liveness sample of the counter `read` reads: its raw nanojoules + /// as the one rail. `None` for a failed read, which the probe skips. + fn sample(read: impl Fn() -> Option) -> Option> { + let nj = read()?; + Some(vec![("ri_energy_nj".to_string(), i64::try_from(nj).unwrap_or(i64::MAX))]) + } + + /// The process counter's probe on a given reader: it opens when the + /// counter reads at all, and is then sampled by + /// [`rail_liveness::probe_counter`], with `tick` between samples, by the + /// clock `now`. + pub(crate) fn status_with( + read: impl Fn() -> Option, + tick: impl FnMut(), + now: impl Fn() -> std::time::Duration, + ) -> CounterStatus { + rail_liveness::counter_status( + rail_liveness::probe_counter( + || read().map(|_| ()), + |_| sample(&read), + tick, + now, + crate::VENDOR_COUNTER_LIVENESS_BUDGET, + ) + .as_ref(), + ) + } + + /// 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. + pub(crate) fn host_status() -> CounterStatus { + let pid = this_pid(); + status_with(|| energy_nj(pid), crate::clocks::cpu_burn_tick, crate::clocks::wall_now) + } + + #[cfg(test)] + mod tests { + use super::*; + use std::cell::Cell; + use std::time::Duration; + + /// The probe on scripted reads, with a clock that only the tick + /// moves, by 25 ms. + fn scripted(read: impl Fn(usize) -> Option) -> CounterStatus { + let (clock, reads) = (Cell::new(Duration::ZERO), Cell::new(0usize)); + status_with( + || { + reads.set(reads.get() + 1); + read(reads.get() - 1) + }, + || clock.set(clock.get() + Duration::from_millis(25)), + || clock.get(), + ) + } + + /// A counter that advances at every read is live; one that holds (a + /// constant), steps once, or cannot be read is declined. + #[test] + fn the_process_probe_admits_only_a_counter_that_keeps_advancing() { + assert_eq!(scripted(|i| Some(1_000_000 + 60_000_000 * i as u64)), CounterStatus::Live); + assert_eq!(scripted(|_| Some(1_000_000)), CounterStatus::Frozen, "a constant"); + assert_eq!(scripted(|i| Some(if i < 9 { 1 } else { 2 })), CounterStatus::Frozen, "one step"); + assert_eq!(scripted(|_| None), CounterStatus::Unavailable, "proc_pid_rusage failing"); + } + + /// Only a live status constructs the counter, and it reads this + /// process. + #[test] + fn only_a_live_status_constructs_the_process_counter() { + for status in [CounterStatus::Unavailable, CounterStatus::Frozen] { + assert!( + matches!(MacosProcessEnergyCounter::try_new_given(status), Err(Error::NoCounter)), + "{status:?} constructed the process counter" + ); + } + let c = MacosProcessEnergyCounter::try_new_given(CounterStatus::Live).expect("Live constructs"); + assert_eq!(c.pid, this_pid()); + assert_eq!(c.name(), "process-energy"); + } + + /// A process that does not exist has no energy to read. + #[test] + fn no_process_no_reading() { + assert_eq!(energy_nj(-1), None); + assert!(MacosProcessEnergyCounter { pid: -1 }.read_microjoules().is_err()); + } + } +} + +#[cfg(target_os = "macos")] +pub use macos_process_energy::MacosProcessEnergyCounter; + +/// This host's process-energy status: whether this process's own CPU energy +/// counter ([`MacosProcessEnergyCounter`]) is live, probed once per process +/// and cached, by the rule every counter here is held to — it kept advancing +/// while the probing thread burned CPU, in at least five sample intervals, at +/// least 80% of them, over at least 300 ms. Always +/// [`CounterStatus::Unavailable`] off macOS. The first call burns about 300 ms +/// of the calling thread's CPU where the counter is live (a second if not). +pub fn process_energy_status() -> CounterStatus { + #[cfg(target_os = "macos")] + { + static STATUS: std::sync::OnceLock = std::sync::OnceLock::new(); + *STATUS.get_or_init(macos_process_energy::host_status) + } + #[cfg(not(target_os = "macos"))] + { + CounterStatus::Unavailable + } +} + +/// The counter for a caller whose metered work runs **on the CPU, in this +/// process** — no subprocess, no GPU or Neural Engine offload: this process's +/// own CPU energy counter where it is live ([`process_energy_status`]), and +/// otherwise whatever [`detect`] selects. +/// +/// Its domain is this process's threads' CPU energy and nothing else, so a +/// 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. +pub fn detect_in_process() -> Box { + detect_in_process_with(process_energy_status, detect) +} + +/// The selection behind [`detect_in_process`], given the process counter's +/// status and the fallback. +#[cfg_attr(not(target_os = "macos"), allow(unused_variables))] +pub(crate) fn detect_in_process_with( + status: impl FnOnce() -> CounterStatus, + fallback: impl FnOnce() -> Box, +) -> Box { + #[cfg(target_os = "macos")] + if let Ok(c) = MacosProcessEnergyCounter::try_new_given(status()) { + return Box::new(c); + } + fallback() +} + #[cfg(feature = "cuda")] mod nvml { use super::*; @@ -4566,6 +4867,11 @@ pub use nvml::NvmlCounter; /// → powermetrics on macOS → `StubCounter`. Every hardware rung is held to /// the same sustained-advance rule; a rung whose counter is not live is /// skipped, so callers estimate rather than seal what it read. +/// +/// It never selects this process's own energy counter +/// ([`MacosProcessEnergyCounter`]), whose domain stops at this process's +/// CPU threads: what eoc meters may run in a subprocess or on the GPU. A +/// caller whose work is in-process asks [`detect_in_process`]. pub fn detect() -> Box { detect_with(nvml_status, rapl_status, ioreport_status) } @@ -4650,6 +4956,45 @@ mod tests { } } + /// `detect()` never selects this process's own energy counter, under any + /// status of any rung, nor on this host, whatever that counter's status: + /// eoc's counter brackets stages that may run in a subprocess or on the + /// GPU, which it does not see. + #[test] + fn detect_never_selects_the_process_counter() { + use CounterStatus as S; + let ioreport = [ + IoReportStatus::Unavailable, + IoReportStatus::CpuRailAbsent, + IoReportStatus::CpuRailFrozen, + IoReportStatus::Live, + ]; + for nvml in [S::Unavailable, S::Frozen, S::Live] { + for rapl in [S::Unavailable, S::Frozen, S::Live] { + for io in ioreport { + let picked = detect_with(|| nvml, || rapl, || io).name(); + assert_ne!(picked, "process-energy", "detect_with({nvml:?}, {rapl:?}, {io:?})"); + } + } + } + let picked = detect().name(); + eprintln!("detect()={picked} process_energy_status()={:?}", process_energy_status()); + assert_ne!(picked, "process-energy"); + } + + /// `detect_in_process()` picks the process counter exactly where it is + /// live (only on macOS), and otherwise falls back to what it is given. + #[test] + fn detect_in_process_picks_the_process_counter_only_when_live() { + use CounterStatus as S; + let fallback = || -> Box { Box::new(StubCounter) }; + let picked = detect_in_process_with(|| S::Live, fallback).name(); + assert_eq!(picked == "process-energy", cfg!(target_os = "macos"), "Live picked {picked}"); + for status in [S::Unavailable, S::Frozen] { + assert_eq!(detect_in_process_with(|| status, fallback).name(), "stub", "{status:?}"); + } + } + /// Off Linux there is no RAPL rung to probe; without `cuda`, no NVML one. #[test] fn a_vendor_counter_with_no_rung_is_unavailable() { @@ -4657,6 +5002,8 @@ mod tests { assert_eq!(rapl_status(), CounterStatus::Unavailable); #[cfg(not(feature = "cuda"))] assert_eq!(nvml_status(), CounterStatus::Unavailable); + #[cfg(not(target_os = "macos"))] + assert_eq!(process_energy_status(), CounterStatus::Unavailable); } /// Against this host's RAPL package counters, where there are any: the diff --git a/eoc/eoc-rs/crates/eoc-meter/tests/process_energy.rs b/eoc/eoc-rs/crates/eoc-meter/tests/process_energy.rs new file mode 100644 index 000000000..963f86694 --- /dev/null +++ b/eoc/eoc-rs/crates/eoc-meter/tests/process_energy.rs @@ -0,0 +1,235 @@ +//! This process's own CPU energy counter, against the hardware. +//! +//! In a test binary of their own because the counter's domain is the whole +//! process: every thread of it. In the library's test binary, other tests +//! burn CPU on other threads at the same time (the IOReport liveness probes), +//! and that energy is this process's too, so "a sleeping span reads almost +//! nothing" could not hold there. Here the tests take one lock, so only the +//! test holding it does any work. +//! +//! Every figure is checked against an oracle the tests read for themselves: +//! `proc_pid_rusage` declared here, into a raw buffer, with the SDK's offsets +//! (`ri_energy_nj` at byte 336), not through the implementation's struct. +//! None of these tests passes without asserting: off Apple Silicon the +//! counter's status must agree with the oracle, and on Apple Silicon both +//! must say live. + +#![cfg(target_os = "macos")] + +use std::os::raw::{c_int, c_void}; +use std::process::{Command, Stdio}; +use std::sync::{Mutex, MutexGuard}; +use std::time::{Duration, Instant}; + +use eoc_meter::{CounterStatus, JouleCounter, MacosProcessEnergyCounter}; + +/// One test at a time: each reads the energy of the whole process. +static SERIAL: Mutex<()> = Mutex::new(()); + +fn serial() -> MutexGuard<'static, ()> { + SERIAL.lock().unwrap_or_else(|poisoned| poisoned.into_inner()) +} + +unsafe extern "C" { + fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + fn mach_timebase_info(info: *mut [u32; 2]) -> 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) }) +} + +/// `struct rusage_info_v6` is 464 bytes; read it as words. Offsets from the +/// macOS 27 SDK's `` (`offsetof`, as a C program prints them): +/// `ri_user_time` 16, `ri_system_time` 24, `ri_child_user_time` 96, +/// `ri_child_system_time` 104, `ri_energy_nj` 336. +const WORDS: usize = 464 / 8; +const USER_TIME: usize = 16 / 8; +const SYSTEM_TIME: usize = 24 / 8; +const CHILD_USER_TIME: usize = 96 / 8; +const CHILD_SYSTEM_TIME: usize = 104 / 8; +const ENERGY_NJ: usize = 336 / 8; +const PENERGY_NJ: usize = 344 / 8; + +/// `proc_pid_rusage(pid, RUSAGE_INFO_V6)`, the tests' own read. +fn rusage(pid: u32) -> Option<[u64; WORDS]> { + let mut words = [0u64; WORDS]; + let rc = unsafe { proc_pid_rusage(pid as c_int, 6, words.as_mut_ptr() as *mut c_void) }; + (rc == 0).then_some(words) +} + +fn energy_nj(pid: u32) -> Option { + rusage(pid).map(|w| w[ENERGY_NJ]) +} + +/// Mach absolute time units to a duration (rusage's CPU times are in them). +fn mach(units: u64) -> Duration { + let mut tb = [0u32; 2]; + assert_eq!(unsafe { mach_timebase_info(&mut tb) }, 0, "mach_timebase_info"); + Duration::from_nanos((u128::from(units) * u128::from(tb[0]) / u128::from(tb[1])) as u64) +} + +/// The CPU time of the children this process has reaped, user and system. +fn reaped_children_cpu() -> Duration { + let w = rusage(std::process::id()).expect("this process's rusage"); + mach(w[CHILD_USER_TIME] + w[CHILD_SYSTEM_TIME]) +} + +fn own_cpu() -> Duration { + let w = rusage(std::process::id()).expect("this process's rusage"); + mach(w[USER_TIME] + w[SYSTEM_TIME]) +} + +/// 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)); + } + } +} + +/// The oracle's verdict on this process's counter: read 21 times, 25 ms of +/// this thread's CPU burned between reads; live if it changed in at least 80% +/// of the 20 intervals. Logs what it saw. +fn oracle_live() -> bool { + let pid = std::process::id(); + let mut reads = vec![energy_nj(pid)]; + for _ in 0..20 { + burn(Duration::from_millis(25)); + reads.push(energy_nj(pid)); + } + let changed = reads.windows(2).filter(|w| matches!((w[0], w[1]), (Some(a), Some(b)) if b > a)).count(); + eprintln!( + "process-energy oracle: {changed} of 20 intervals advanced; first {:?} last {:?} nJ", + reads.first().copied().flatten(), + reads.last().copied().flatten() + ); + changed * 5 >= 20 * 4 +} + +/// The counter's status agrees with the oracle, and on Apple Silicon both say +/// live: this is the hardware fact the counter rests on. Where it is live, +/// `detect_in_process()` picks it; `detect()` never does. +#[test] +fn the_process_counter_is_live_and_only_detect_in_process_picks_it() { + let _one = serial(); + let status = eoc_meter::process_energy_status(); + let oracle = oracle_live(); + let (in_process, default) = (eoc_meter::detect_in_process().name(), eoc_meter::detect().name()); + eprintln!("process-energy: status={status:?} oracle_live={oracle} detect_in_process()={in_process} detect()={default}"); + assert_eq!(status == CounterStatus::Live, oracle, "the status disagrees with the oracle"); + if cfg!(target_arch = "aarch64") { + assert_eq!(status, CounterStatus::Live, "this process's CPU energy counter is not live on Apple Silicon"); + } + assert_eq!(in_process == "process-energy", status == CounterStatus::Live, "detect_in_process() picked {in_process}"); + assert_ne!(default, "process-energy", "detect() selected the process counter"); +} + +/// 200 ms of one thread's CPU work reads between 0.1 and 20 J, and the +/// counter reads what the oracle reads around it. +/// +/// The burn counts 200 ms of the thread's own CPU, by its CPU clock, not of +/// wall time: on a loaded host a 200 ms wall-time spin got 90 ms of CPU and +/// read 0.175 J. Even a fixed 200 ms of CPU costs a different amount of +/// energy depending on which core class it ran on and at what clock. On an +/// M5 Max at default QoS it read 0.18-1.24 J. Asking for user-interactive QoS +/// does not help: the call returns 0, but the kernel caps a process with no +/// app role (a test binary) at default QoS, and rusage books the burn as +/// default. So the floor is 0.1 J, half the lowest reading seen. That is also +/// the sleeping test's ceiling, so no counter that reads wall time at a fixed +/// power can pass both tests. +#[test] +fn a_200_ms_one_thread_burn_reads_between_0_1_and_20_j() { + let _one = serial(); + let c = MacosProcessEnergyCounter::try_new().expect("the process counter is live here"); + let pid = std::process::id(); + let (w0, cpu0, wall0) = (rusage(pid).expect("oracle"), own_cpu(), Instant::now()); + let before = c.read_microjoules().expect("read"); + let started = thread_cpu(); + burn(Duration::from_millis(200)); + let burned = thread_cpu() - started; + let after = c.read_microjoules().expect("read"); + let (w1, cpu1) = (rusage(pid).expect("oracle"), own_cpu()); + let (o0, o1) = (w0[ENERGY_NJ], w1[ENERGY_NJ]); + let uj = after - before; + eprintln!( + "process-energy: one-thread burn of {burned:?} thread CPU in {:?} wall read {uj} µJ = {:.3} J \ + ({:.2} J per CPU-second); process CPU {:?}; oracle {o0} -> {o1} nJ, P-core share {} nJ", + wall0.elapsed(), + uj as f64 / 1e6, + uj as f64 / 1e6 / burned.as_secs_f64(), + cpu1 - cpu0, + w1[PENERGY_NJ] - w0[PENERGY_NJ] + ); + assert!(burned >= Duration::from_millis(200), "the thread got only {burned:?} of CPU in 20 s"); + assert!(o0 / 1_000 <= before && before <= after && after <= o1 / 1_000, "the counter read outside the oracle's bracket"); + assert!((100_000..=20_000_000).contains(&uj), "{uj} µJ for 200 ms of one thread's CPU work"); +} + +/// A sleeping span reads under 0.1 J: the counter is this process's energy, +/// not the machine's. +#[test] +fn a_sleeping_span_reads_under_0_1_j() { + let _one = serial(); + let c = MacosProcessEnergyCounter::try_new().expect("the process counter is live here"); + let before = c.read_microjoules().expect("read"); + std::thread::sleep(Duration::from_millis(500)); + let after = c.read_microjoules().expect("read"); + let uj = after - before; + eprintln!("process-energy: 500 ms asleep read {uj} µJ = {:.4} J", uj as f64 / 1e6); + assert!(uj < 100_000, "{uj} µJ while this process slept"); +} + +/// A child process's work is not this process's energy, neither while it +/// runs nor once it is reaped. The child (`yes`, to /dev/null) runs for at +/// least 300 ms and until its own counter has read at least 0.5 J (or 5 s); +/// the parent's counter, read before the spawn and after the reap, moves by +/// under 0.1 J and by under a fifth of the child's own. +#[test] +fn a_child_processs_work_is_not_attributed() { + let _one = serial(); + let c = MacosProcessEnergyCounter::try_new().expect("the process counter is live here"); + let reaped0 = reaped_children_cpu(); + let before = c.read_microjoules().expect("read"); + let mut child = Command::new("yes").stdout(Stdio::null()).spawn().expect("spawn yes"); + let started = Instant::now(); + let mut child_nj = None; + while started.elapsed() < Duration::from_secs(5) { + std::thread::sleep(Duration::from_millis(50)); + child_nj = energy_nj(child.id()); + if child_nj.is_some_and(|nj| nj >= 500_000_000) && started.elapsed() >= Duration::from_millis(300) { + break; + } + } + if child_nj.is_none() { + // The child's own counter cannot be read here: let it run 600 ms. + std::thread::sleep(Duration::from_millis(600).saturating_sub(started.elapsed())); + } + child.kill().expect("kill yes"); + child.wait().expect("reap yes"); + let after = c.read_microjoules().expect("read"); + let child_cpu = reaped_children_cpu() - reaped0; + let uj = after - before; + eprintln!( + "process-energy: child ran {:?}, its own counter read {:?} nJ, its CPU (reaped) {child_cpu:?}; \ + the parent's counter moved {uj} µJ = {:.4} J", + started.elapsed(), + child_nj, + uj as f64 / 1e6 + ); + assert!(child_cpu >= Duration::from_millis(150), "the child did not work: {child_cpu:?} of CPU"); + if let Some(nj) = child_nj { + assert!(nj >= 200_000_000, "the child's own counter read only {nj} nJ"); + assert!(uj * 1_000 * 5 < nj, "the parent read {uj} µJ of a child that read {nj} nJ"); + } + assert!(uj < 100_000, "the parent's counter moved {uj} µJ while its child worked"); +} diff --git a/eoc/eoc-rs/crates/eoc/src/main.rs b/eoc/eoc-rs/crates/eoc/src/main.rs index 3e4ff6914..5c011344c 100644 --- a/eoc/eoc-rs/crates/eoc/src/main.rs +++ b/eoc/eoc-rs/crates/eoc/src/main.rs @@ -20,7 +20,7 @@ use eoc_cascade::Cascade; use eoc_core::Query; use eoc_graph::{GraphStage, Triple}; use eoc_kv::{KvBackend, KvStage, MemoryKvBackend}; -use eoc_meter::detect; +use eoc_meter::{detect, detect_in_process}; use eoc_neural::{EchoBackend, NeuralBackend, NeuralStage}; #[derive(Parser, Debug)] @@ -59,7 +59,16 @@ fn build_cascade() -> Cascade { build_cascade_with(Box::new(EchoBackend::new().with_prefix("[neural fallback] "))) } -/// The CLI's cascade around a given neural backend, metered by [`detect`]. +/// The CLI's cascade around a given neural backend. +/// +/// Metered by [`detect_in_process`], because every stage the CLI builds runs +/// on the CPU in this process: the LRU cache, the in-memory KV store, the +/// in-memory graph, and the echo backend (string formatting). None spawns a +/// subprocess or offloads to the GPU, so this process's own CPU energy +/// counter, where it is live, sees all of their work, and less of everything +/// else than a whole-machine counter would. A backend passed here must keep +/// to that too: work it ran in a child process, or on the GPU, would be +/// outside the counter's domain. fn build_cascade_with(neural: Box) -> Cascade { let cache = Arc::new(LruCache::new(1024)); @@ -78,7 +87,7 @@ fn build_cascade_with(neural: Box) -> Cascade { let neural = Arc::new(NeuralStage::new(neural)); - Cascade::new(cache, kv, graph, neural).with_meter(Arc::from(detect())) + Cascade::new(cache, kv, graph, neural).with_meter(Arc::from(detect_in_process())) } async fn run_query(prompt: String) -> Result<()> { @@ -97,6 +106,10 @@ async fn run_meter() -> Result<()> { println!("counter: {}", counter.name()); #[cfg(target_os = "macos")] println!("ioreport: {}", ioreport_line(eoc_meter::ioreport_status())); + println!( + "query : metered by {} (its stages all run on the CPU in this process)", + detect_in_process().name() + ); let start = counter.read_microjoules(); tokio::time::sleep(Duration::from_secs(1)).await; let end = counter.read_microjoules(); @@ -144,6 +157,11 @@ mod tests { use eoc_neural::NeuralBackend; use std::time::{Duration, Instant}; + /// The tests that burn CPU take this, one at a time: on a Mac the CLI's + /// meter is this process's own counter, whose domain is every thread of + /// the process, so one test's burn would land in the other's span. + static BURNING: tokio::sync::Mutex<()> = tokio::sync::Mutex::const_new(()); + /// A neural backend that does ~100 ms of real CPU work and reports its own /// estimate for it, as a real backend without a meter would. struct BurningBackend; @@ -164,24 +182,31 @@ mod tests { } /// The whole CLI path on this host, around ~100 ms of real CPU work. Where - /// the meter [`super::detect`] picks is no hardware reading — the stub, or - /// the powermetrics stand-in, which is what a Mac whose IOReport CPU rail is - /// not live falls back to — the cost is the backend's own estimate: the - /// same non-zero figure, tagged estimated. Where it is a live hardware - /// counter, the cost is that estimate plus what the counter read, still - /// tagged estimated, because part of it is. Never a zero for the work, and - /// never tagged measured. + /// the meter [`super::detect_in_process`] picks is no hardware reading — + /// the stub, or the powermetrics stand-in — the cost is the backend's own + /// estimate: the same non-zero figure, tagged estimated. Where it is a live + /// counter (this process's own, on a Mac where it is live), the cost is + /// that estimate plus what the counter read, still tagged estimated, + /// because part of it is. Never a zero for the work, and never tagged + /// measured. #[tokio::test] async fn work_on_an_unmetered_host_keeps_its_estimate() { + let _one = BURNING.lock().await; let cascade = build_cascade_with(Box::new(BurningBackend)); let meter = cascade.meter().name(); #[cfg(target_os = "macos")] - assert_eq!( - meter == "ioreport", - eoc_meter::ioreport_status() == eoc_meter::IoReportStatus::Live, - "the CLI's meter is {meter} while IOReport is {:?}", - eoc_meter::ioreport_status() - ); + { + let process = eoc_meter::process_energy_status() == eoc_meter::CounterStatus::Live; + assert_eq!(meter == "process-energy", process, "the CLI's meter is {meter}"); + if !process { + assert_eq!( + meter == "ioreport", + eoc_meter::ioreport_status() == eoc_meter::IoReportStatus::Live, + "the CLI's meter is {meter} while IOReport is {:?}", + eoc_meter::ioreport_status() + ); + } + } let r = cascade.resolve(Query::new("a question nothing has cached")).await; eprintln!("eoc cost on this host: meter={meter} cost={}", r.joule_cost); assert_eq!(r.stage, Stage::Neural); @@ -195,6 +220,47 @@ mod tests { } } + /// A neural backend that does ~100 ms of real CPU work, in this process, + /// and claims no figure for it: the estimated zero a stage reports when + /// it has nothing to estimate with. Built only where its one test runs: + /// off macOS there is no process counter for it to be measured by. + #[cfg(target_os = "macos")] + struct BurningUnestimatedBackend; + + #[cfg(target_os = "macos")] + #[async_trait] + impl NeuralBackend for BurningUnestimatedBackend { + async fn infer(&self, q: &Query) -> Response { + let started = Instant::now(); + let mut acc: u64 = 0; + while started.elapsed() < Duration::from_millis(100) { + acc = acc.wrapping_add(1); + } + std::hint::black_box(acc); + Response::new(q.id, "burned".to_string(), Stage::Neural, JouleCost::zero()) + } + } + + /// On a Mac whose process counter is live, the CLI's cascade measures + /// in-process CPU work: ~100 ms of one thread's work reads as a measured + /// figure — the counter read all of it, and nothing was estimated — + /// between 1 mJ and 10 J. The floor is low on purpose: a wall-time burn + /// on a loaded host, or on efficiency cores, can draw little (an M3 + /// Ultra's efficiency cores read 0.013 J per 200 ms of CPU); the size of + /// a reading is pinned in eoc-meter's own hardware test. + #[cfg(target_os = "macos")] + #[tokio::test] + async fn in_process_work_is_measured_by_the_process_counter() { + let _one = BURNING.lock().await; + assert_eq!(eoc_meter::process_energy_status(), eoc_meter::CounterStatus::Live, "not live on this Mac"); + let cascade = build_cascade_with(Box::new(BurningUnestimatedBackend)); + assert_eq!(cascade.meter().name(), "process-energy"); + let r = cascade.resolve(Query::new("a question nothing has cached")).await; + eprintln!("eoc in-process cost: {}", r.joule_cost); + assert_eq!(r.joule_cost.source, JouleSource::Measured, "{}", r.joule_cost); + assert!((1_000..=10_000_000).contains(&r.joule_cost.microjoules), "{}", r.joule_cost); + } + #[test] fn a_counter_that_did_not_read_is_never_printed_as_a_figure() { let failed = idle_line("powermetrics", Err(Error::NoCounter), Err(Error::NoCounter));