open-standards/proof/proof-rs/crates/proof-cascade/tests/process_energy.rs
Transaction Science 0e9e3c8f6d
All checks were successful
standards workspaces build + test / jouleclaw-rs (pull_request) Successful in 2m8s
standards workspaces build + test / aac-rs (pull_request) Successful in 45s
standards workspaces build + test / joule-code-rs (pull_request) Successful in 1m7s
standards workspaces build + test / joulecontract-rs (pull_request) Successful in 51s
standards workspaces build + test / map-rs (pull_request) Successful in 43s
standards workspaces build + test / mesh-rs (pull_request) Successful in 37s
standards workspaces build + test / openpay (pull_request) Successful in 1m48s
no-vanity-metrics / Scan committed Markdown for vanity metrics (pull_request) Successful in 3s
standards workspaces build + test / eoc-rs (pull_request) Successful in 1m52s
standards workspaces build + test / jcp-rs (pull_request) Successful in 1m18s
standards workspaces build + test / proof-rs (pull_request) Successful in 1m15s
standards workspaces build + test / sandbox-rs (pull_request) Successful in 2m10s
standards workspaces build + test / smart-byte-rs (pull_request) Successful in 2m37s
standards workspaces build + test / arl-rs (pull_request) Successful in 2m45s
standards workspaces build + test / joule-ui-rs (pull_request) Successful in 3m16s
standards workspaces build + test / jouledesk-rs (pull_request) Successful in 2m48s
standards workspaces build + test / joulehook-rs (pull_request) Successful in 3m11s
standards workspaces build + test / sense-rs (pull_request) Successful in 3m10s
standards workspaces build + test / macOS energy backend (jcp-energy) (pull_request) Successful in 2m43s
proof-cascade: meter CPU work with this process's own energy counter while it is live
On both Macs that run this suite (macOS 27.0.1, an M5 Max and an M3 Ultra)
IOReport's CPU energy rail is frozen for an unprivileged reader, so the meter
has correctly declined and `proof --measure` has never printed a figure there.
The kernel keeps a live counter of its own: `proc_pid_rusage(getpid(),
RUSAGE_INFO_V6)`'s `ri_energy_nj`, the cumulative CPU energy it attributes to
this process's threads, in nanojoules. It is public libproc API and needs no
privilege. On the M5 Max it changes every ~0.5-0.7 ms under load, holds near
1-2 mJ/s idle, and keeps the energy of threads that have exited; on both Macs
the probe below calls it Live.

Design. `measure_marginal` (new; `measure_marginal_uj` is now its figure)
runs `work` on every spare core and meters it with the first live source, in
order: on macOS this process's counter, then IOReport; on Linux RAPL. For the
process counter there is no bracket and no idle subtraction: the counter is
read before the workers start and after every one has been joined, and the
figure is its advance ÷ every call that completed, so it covers exactly the
calls counted, and other processes are excluded by construction. What the
figure claims, `MeterSource::domain`, says so: this process's CPU energy as
the kernel attributes it to its threads — not other processes, not child
processes, not GPU, ANE or DRAM — and everything this process burns in the
window, so a caller must not run other work in the process while it meters.
It is graded HwShunt (`MeterSource::provenance`; the owner's decision: a
kernel reading of the CPU's own energy counters), and `Measurement::energy()`
builds the schema reading from it.

The counter is used only while it is live, by the same sustained-advance rule
as IOReport and RAPL: through the same probe loop, it must advance in at least
five sample intervals, in at least 80% of them, over at least 300 ms, while
the probe burns 25 ms of thread CPU before each re-read. `process_energy_status`
probes once per process and caches it; `meter_source` admits only `Live`, and
the process rung has its own gate on the cached status besides. The bracket
paths keep their own gates whatever ranks above them: `power_over` now gates
on IOReport's own status and `rapl_power_over` on RAPL's, not on the overall
selection, so a live process counter can never unlock a frozen IOReport rail.
IOReport is not probed by the selection when the process counter is live.

`proof --measure` prints the decision it acted on (`source=`,
`process_energy_status=`, `ioreport_status=`, `rapl_status=`), why each source
not used was not used, the figure with its source and provenance, and its
domain. On this M5 Max, verbatim:

  --measure: hardware meter available=true · source=ProcessEnergy · process_energy_status=Live · ioreport_status=CpuRailFrozen · rapl_status=Unavailable
  measured: 20819 uj / proof  ·  provenance HwShunt (measured_uj present, the schema's strongest tier)  ·  source ProcessEnergy
  receipt: closed at T0:automation · 215 uj · provenance ModelBased · spec Ungrounded · verified true

The receipt is unchanged: still sealed from `first`, the cascade's own
ModelBased figure for the first goal. The CLI's old line "the standard's
headline is now a real hardware reading" is gone: the per-goal figures stay
ModelBased, and it now says so.

Tests. Hardware tests check the meter against an independent oracle — the
tests' own binding of `proc_pid_rusage`, their own `getpid`, a raw 464-byte
buffer read at byte 336, their own loop and literals — and every branch
asserts:
- the FFI pin: three production reads each lie between two oracle reads, and
  advance across 50 ms burns; the struct is 464 bytes with `ri_energy_nj` at
  336, the macOS 27.0 SDK header's numbers;
- `tests/process_energy.rs` (serialized): the probe is Live exactly when the
  oracle sees the counter keep moving, and then it is selected first; a fixed
  cheap closure meters as a non-zero HwShunt figure three times within 3x; a
  closure that sleeps 2 ms meters at under a tenth of one that computes for
  2 ms, also while four busy child processes burn CPU beside it;
- `tests/process_energy_frozen.rs` drives the whole chain with the counter held
  (`simulate_frozen_process_energy`, a hook that can only turn the meter off):
  Frozen, never selected, no figure, the work never runs, one probe run;
- `proof --measure` (proof-cli test): the source is the first live one in
  order, every printed reason is its printed status's own, the receipt equals
  the first goal's row and stays ModelBased, and where the test process's own
  counter keeps moving the CLI must have printed a non-zero HwShunt
  ProcessEnergy figure with its domain;
- pure, on every platform: the probe composition on scripted counters (live at
  the twelfth 25 ms interval; constant, one-, two- and four-step counters
  Frozen; unreadable Unavailable), the measurement's arithmetic and read order
  on a scripted counter each call raises by exactly 7,000 nJ (exactly 7 uJ; it
  holds only if the counter is read before the first call and after the join),
  rounding, a falling or unreadable counter giving no figure and an unreadable
  one never running the work, the macOS order (IOReport not even asked when the
  process counter is live), and the grading and domain of every source.
The IOReport tests now assert on IOReport's own gate (`bracket_admitted`,
`bracket_marginal_uj`), and `ioreport_once.rs` / `ioreport_unopenable.rs` cover
both probes (each runs once per process; with no Energy Model group and the
counter held, every meter declines).

Measured, verbatim from the test logs (debug builds, macOS 27.0.1):
- M5 Max: `process liveness: status=Live source=Some(ProcessEnergy) oracle=Oracle
  { moved: true, reads: 35, changes: 35, advanced_nj: 1061927078 }`; cheap
  closure, three calls: 355, 355, 360 uJ; compute 2 ms = 2732 uJ, sleep 2 ms =
  7 uJ, sleep 2 ms beside 4 busy children = 6 uJ.
- M3 Ultra (the lib and process_energy test binaries and `proof`, built from
  this commit's code before its last doc-comment and README edits, copied to
  /tmp on 10.10.10.2, run once with --nocapture, deleted): `process liveness: status=Live
  source=Some(ProcessEnergy) oracle=Oracle { moved: true, reads: 29, changes:
  29, advanced_nj: 5293659397 }`; cheap closure 671, 676, 685 uJ; compute 2 ms
  = 6520 uJ, sleep 2 ms = 2 uJ, beside 4 busy children = 9 uJ; `measured: 44537
  uj / proof · provenance HwShunt · source ProcessEnergy`; 88/88 lib tests and
  3/3 process_energy tests passed; IOReport there `CpuRailFrozen` as before.

Falsified, each restored through git before the next (proof-cascade and
proof-cli test suites):
- reading the parent's pid: the FFI pin fails ("round 1: the production read
  177161340 is outside the oracle's [897071438, 897071438]"), and so do the
  liveness test ("the probe says Frozen; the oracle saw the counter change at 35
  of 35 reads"), both metering tests and the CLI test ("this test's own process
  counter changed at 24 of 24 reads, yet the CLI metered with none");
- a constant counter: the same five tests ("the production read 123456789 is
  outside the oracle's [...]");
- liveness ignored at the selection (the counter chosen whenever it reads): the
  frozen-chain test ("a held process counter was selected"), the unopenable test
  and the pure ordering test fail;
- the probe run but its verdict discarded (always Live): the frozen-chain and
  unopenable tests fail ("a held counter was called Live").

`cargo test --workspace` and the proof-conformance binary pass; `cargo check
--workspace --tests` and `cargo clippy --workspace --all-targets` for
x86_64-unknown-linux-gnu are clean; clippy on macOS reports only the two
IOReport FFI lints the README already lists.

Not done: the counter's accuracy is the kernel's; nothing here checks it
against an external meter. Its domain is CPU only, so GPU-bound work would
meter low, and a caller that runs other threads in the process while it
meters is charged for them. The process figure resolves 1 uJ per call;
`Some(0)` from it means under half a microjoule, and the CLI says so.

Co-Authored-By: Claude Opus 5.5 <[email protected]>
2026-09-30 21:40:35 -04:00

210 lines
8.5 KiB
Rust

//! This process's CPU energy counter as a meter, on the real hardware.
//!
//! Every test here checks the meter against an independent oracle: the tests'
//! own binding of `proc_pid_rusage(getpid(), 6)`, read into a raw buffer at
//! byte 336, with their own loop and their own literals. The oracle watches
//! the counter for one second while a helper thread burns CPU and calls it
//! moving only if it changed at no fewer than 5 of its reads and at 80% of
//! them. Where the oracle sees the counter move, the meter must have selected
//! it and must meter with it; where it does not, the meter must not. No branch
//! passes without asserting.
//!
//! The process counter counts everything this process's threads burn, so the
//! tests in this file run one at a time (`SERIAL`), and nothing else here runs
//! while one of them meters.
use proof_cascade::meter::{measure_marginal, meter_source, process_energy_status, CounterStatus, MeterSource};
use proof_schema::Provenance;
use std::sync::{Mutex, MutexGuard, OnceLock};
use std::time::{Duration, Instant};
static SERIAL: Mutex<()> = Mutex::new(());
fn serial() -> MutexGuard<'static, ()> {
SERIAL.lock().unwrap_or_else(|e| e.into_inner())
}
/// What the oracle saw of the counter over its window.
#[derive(Debug, Clone, Copy)]
struct Oracle {
moved: bool,
reads: u32,
changes: u32,
advanced_nj: u64,
}
#[cfg(target_os = "macos")]
mod ffi {
use std::os::raw::c_int;
unsafe extern "C" {
fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut [u64; 58]) -> c_int;
fn getpid() -> c_int;
}
/// `ri_energy_nj` of `proc_pid_rusage(getpid(), RUSAGE_INFO_V6 = 6)`: a
/// 464-byte buffer, read at byte 336 (its 43rd `uint64_t`).
pub fn energy_nj() -> Option<u64> {
let mut buf = [0u64; 58];
// SAFETY: buf is 464 writable bytes, the size of rusage_info_v6.
(unsafe { proc_pid_rusage(getpid(), 6, &mut buf) } == 0).then_some(buf[42])
}
}
/// The oracle's verdict, taken once for this test binary (under `SERIAL`).
fn oracle() -> Oracle {
static ORACLE: OnceLock<Oracle> = OnceLock::new();
*ORACLE.get_or_init(watch_counter)
}
#[cfg(target_os = "macos")]
fn watch_counter() -> Oracle {
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::Arc;
let Some(first) = ffi::energy_nj() else {
return Oracle { moved: false, reads: 0, changes: 0, advanced_nj: 0 };
};
let stop = Arc::new(AtomicBool::new(false));
let burner = {
let stop = stop.clone();
std::thread::spawn(move || {
let mut acc = 0u64;
while !stop.load(Ordering::Relaxed) {
acc = std::hint::black_box(acc.wrapping_add(1));
}
})
};
let started = Instant::now();
let (mut prev, mut reads, mut changes) = (first, 0u32, 0u32);
while started.elapsed() < Duration::from_secs(1) {
std::thread::sleep(Duration::from_millis(25));
let now = ffi::energy_nj().expect("the oracle's read failed after its first succeeded");
reads += 1;
changes += u32::from(now != prev);
prev = now;
}
stop.store(true, Ordering::Relaxed);
let _ = burner.join();
let moved = changes >= 5 && changes * 5 >= reads * 4;
Oracle { moved, reads, changes, advanced_nj: prev - first }
}
#[cfg(not(target_os = "macos"))]
fn watch_counter() -> Oracle {
Oracle { moved: false, reads: 0, changes: 0, advanced_nj: 0 }
}
/// Real, cheap, pure CPU work: a fixed fold.
fn cheap() {
std::hint::black_box((0..20_000u64).fold(0u64, |a, b| a.wrapping_mul(31).wrapping_add(b)));
}
/// 2 ms of computing, by the wall clock.
fn compute_2ms() {
let t = Instant::now();
let mut acc = 0u64;
while t.elapsed() < Duration::from_millis(2) {
acc = std::hint::black_box(acc.wrapping_add(1));
}
}
/// 2 ms of sleeping.
fn sleep_2ms() {
std::thread::sleep(Duration::from_millis(2));
}
/// The counter is selected exactly when the oracle sees it keep moving: live
/// and first in line where it moves, never selected where it does not.
#[test]
fn the_process_counter_is_live_exactly_when_the_oracle_sees_it_move() {
let _serial = serial();
let status = process_energy_status();
let o = oracle();
let source = meter_source();
eprintln!("process liveness: status={status:?} source={source:?} oracle={o:?}");
if cfg!(target_os = "macos") {
assert_eq!(
status == CounterStatus::Live,
o.moved,
"the probe says {status:?}; the oracle saw the counter change at {} of {} reads (+{} nJ)",
o.changes,
o.reads,
o.advanced_nj
);
if o.moved {
assert_eq!(source, Some(MeterSource::ProcessEnergy), "a live process counter was not selected first");
} else {
assert_ne!(source, Some(MeterSource::ProcessEnergy), "a process counter the oracle saw hold was selected");
}
} else {
assert_eq!(status, CounterStatus::Unavailable, "a process counter off macOS");
assert_ne!(source, Some(MeterSource::ProcessEnergy));
}
}
/// A fixed cheap closure meters as a non-zero `HwShunt` figure from the
/// process counter, roughly stable: three calls within a factor of 3.
#[test]
fn a_fixed_cheap_closure_meters_as_a_stable_hwshunt_figure() {
let _serial = serial();
if meter_source() == Some(MeterSource::ProcessEnergy) {
let figures: Vec<_> = (0..3).map(|_| measure_marginal(cheap).expect("a live process counter gave no figure")).collect();
eprintln!("process stability: cheap closure, three calls: {figures:?}");
for m in &figures {
assert_eq!(m.source, MeterSource::ProcessEnergy, "{m:?}");
assert!(m.uj > 0, "a live process counter metered real work as zero: {m:?}");
let e = m.energy();
assert_eq!((e.measured_uj, e.provenance), (Some(m.uj), Provenance::HwShunt), "{m:?}");
assert!(e.check_provenance().is_ok(), "{e:?}");
}
let (lo, hi) = (figures.iter().map(|m| m.uj).min().unwrap(), figures.iter().map(|m| m.uj).max().unwrap());
assert!(hi <= 3 * lo, "three calls on the same closure spread from {lo} to {hi} uJ, more than 3x");
} else {
let o = oracle();
assert!(!o.moved, "the oracle saw the process counter move ({o:?}), yet it was not selected");
let m = measure_marginal(cheap);
assert_ne!(m.map(|m| m.source), Some(MeterSource::ProcessEnergy), "a process-counter figure from a counter not selected");
}
}
/// Sleeping is not computing: a closure that sleeps 2 ms meters at under a
/// tenth of one that computes for 2 ms — and stays there while four busy
/// child processes burn CPU beside it, which the counter excludes.
#[test]
fn a_closure_that_sleeps_meters_far_less_than_one_that_computes() {
let _serial = serial();
if meter_source() == Some(MeterSource::ProcessEnergy) {
let compute = measure_marginal(compute_2ms).expect("computing gave no figure");
let sleep = measure_marginal(sleep_2ms).expect("sleeping gave no figure");
let busy: Vec<_> = (0..4)
.map(|_| {
std::process::Command::new("/bin/sh")
.args(["-c", "while :; do :; done"])
.spawn()
.expect("a busy child process starts")
})
.collect();
std::thread::sleep(Duration::from_millis(100));
let beside_children = measure_marginal(sleep_2ms);
for mut child in busy {
let _ = child.kill();
let _ = child.wait();
}
let beside_children = beside_children.expect("sleeping beside busy children gave no figure");
eprintln!(
"process sleep vs compute: compute 2 ms = {compute:?}; sleep 2 ms = {sleep:?}; sleep 2 ms beside 4 busy \
children = {beside_children:?}"
);
assert!(compute.uj > 0, "computing metered as zero: {compute:?}");
assert!(sleep.uj * 10 < compute.uj, "sleeping metered {} uJ a call, computing {} uJ", sleep.uj, compute.uj);
assert!(
beside_children.uj * 10 < compute.uj,
"sleeping beside busy child processes metered {} uJ a call, computing {} uJ: other processes were counted",
beside_children.uj,
compute.uj
);
} else {
let o = oracle();
assert!(!o.moved, "the oracle saw the process counter move ({o:?}), yet it was not selected");
assert_ne!(measure_marginal(sleep_2ms).map(|m| m.source), Some(MeterSource::ProcessEnergy));
}
}