From bcd00518a76f493ce122716fe0160b3e13366ed4 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 30 Sep 2026 20:56:37 -0400 Subject: [PATCH 1/3] jcp-energy: meter this process's own CPU energy, live where IOReport is not MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit On macOS 27.0.1 an unprivileged reader sees IOReport's CPU rails republished in lumps, so the IOReport rung is declined on both the M5 Max and the M3 Ultra, and every span gets the time×power estimate. The kernel keeps a live count that this crate did not read. `proc_pid_rusage(getpid(), RUSAGE_INFO_V6, ...)` from libproc (public API, no entitlement, no privilege) fills `rusage_info_v6`, and its `ri_energy_nj` is the cumulative CPU energy the kernel attributes to this process's threads. Measured on the M5 Max: 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. This commit adds it as a rung. The rung. `Meter::ProcessEnergy` reads `ri_energy_nj` before and after the closure `measure` runs. It is graded `HwShunt` (the owner's decision is that vendor counters are readings) with `Coverage::Whole` for in-process CPU work. Its domain is documented on the variant, on its module and in SPEC §5.1: the CPU energy of this process's threads during the span, every thread of the process and not only the one running the closure. It excludes other processes, child processes, the GPU, the Neural Engine and DRAM. Order. The rung sits below RAPL and NVML and above IOReport. Both it and IOReport are vendor readings, but they read different domains. The per-process count is the work's own CPU energy. IOReport's counter is SoC-wide: it takes in every other process and the machine-wide GPU rail. Where both are live, the work's own figure wins. RAPL and NVML do not exist on macOS, so its place relative to them changes nothing there. Liveness. The rung uses the sustained-advance rule that 475680ab shared (`liveness::probe`), applied to `ri_energy_nj` while the probing thread burns 25 ms ticks of its own CPU. The result is cached once per process as `process_energy_status()`, and the counter is Live in about 310 ms on both chips. A span over which `ri_energy_nj` did not advance gets the time×power figure at `ModelBased`, as IOReport's held spans do. A rise is rounded up to whole µJ, so a span that spent energy never reads as zero. FFI. The decoding is pure: `rusage_v6::decode` reads the two words at bytes 336 and 344 of the 464-byte struct. Those are the C compiler's `sizeof` and `offsetof` for `struct rusage_info_v6` against the macOS 26, 26.5 and 27 SDKs, which agree. The 27 SDK named three of the nine reserved words the 26 SDKs had, and nothing before them moved. The read goes into a 464-byte buffer with 8-byte alignment. Status. All additions; no existing name changes. `process_energy_status()`, `enum Rung`, `Meter::rung()`, `struct Detection` and `Meter::detect_explained()`, which returns the meter together with the selected rung and the cached status of every rung asked on the way to it. A rung below the selected one is never asked, so its probe never runs and its status is `None`. `Meter::detect()` is now `detect_explained().0`. Consequences. On this M5 Max `detect()` now selects ProcessEnergy and never probes IOReport: in a fresh process the IOReport probe runs 0 times. The first `detect()` therefore burns about 310 ms of CPU, where the IOReport probe burned about one second. Spans shorter than the count's update interval fall to the model's figure. jcp-cli's demo probe, a 20,000-term sum, now prints "meter HwShunt backend → 2171 µJ probe (estimated, and says so)". Three IOReport hardware tests asked `detect()` whether IOReport was selected, and `detect()` no longer reaches IOReport here. They now ask the IOReport gate itself, with the rungs above it declined (`Ladder::ioreport_only()`). Tests, with no skip-as-pass. jcp-energy has 75 lib tests (63 before) and its integration test. All pass on the M5 Max with and without `--features nvml`, and 75/75 pass on the M3 Ultra. - Pure, on every platform. The layout constants equal the C compiler's literals and `offset_of!` on a field-by-field transcription of the SDK struct. On a buffer of distinct bytes, decoding reads exactly bytes 336..344 and 344..352, and a literal little-endian buffer decodes to 2,400,000,000 nJ and 1. A span is a reading only on a rise: 480,000,001 nJ gives 480,001 µJ, and 500 nJ gives 1 µJ. A count that held, fell or failed to read gets the model's figure. The probe on a scripted count is Live at the tenth interval and Frozen when the count holds. - The gate and the order, on macOS. Only Live selects the rung and opens its counter. When it is declined, the ladder goes on to IOReport and `Detection` says so. With the per-process rung Live, IOReport is never asked; with RAPL Live, the per-process status is never asked. Off macOS the rung is never selected. - Against the hardware, on macOS. Each test runs in a fresh process of its own, because the count covers the whole process and tests running beside it would land in its spans. The rung is Live, and `detect_explained()` reports it with IOReport unasked. The reader's count sits between two reads of this pid by the tests' own oracle, which uses its own FFI declaration and the transcribed struct. 200 ms of one thread's CPU is `HwShunt`, whole, and between 0.2 and 20 J. 200 ms asleep meters under 0.1 J. Two threads meter more than one. A span that runs `yes > /dev/null` for 200 ms, then kills and reaps it, meters under 0.1 J, while the oracle reads the child's own count at 0.1 J or more. M5 Max, verbatim from the final run: process energy: status=Live (first call took 316.761333ms); a fresh probe: Live after 12 intervals over a 314.907375ms window, advances [("ri_energy_nj", 12)], in 314.914166ms; detect_explained: Detection { selected: ProcessEnergy, rapl: Some(Unavailable), nvml: Some(Unavailable), process_energy: Some(Live), ioreport: None }; IOReport probe runs = 0 process energy: 200 ms of one thread's CPU -> 402729 µJ (0.403 J), HwShunt, coverage Whole process energy: 200 ms asleep -> 77 µJ (0.000077 J), HwShunt process energy: 200 ms of CPU on 1 thread -> 623347 µJ (0.623 J), on each of 2 threads -> 1221565 µJ (1.222 J), ratio 1.96 process energy: a span running `yes > /dev/null` for 200 ms -> 6993 µJ (0.006993 J), HwShunt; the child's own count 350042940 nJ (0.350 J) Over five more runs of these five tests: one thread 0.41-0.53 J, a 2-to-1 thread ratio of 1.73-2.09, asleep 0.2-1.0 mJ, and the child span 1.2-25 mJ against the child's own 0.32-0.46 J. M3 Ultra, verbatim. The lib test binary was built here with `target-cpu=apple-m1` (the global config builds native to the M5), copied to 10.10.10.2 (sha256 acf9bac254c0f97b... on both ends), run with --nocapture, then deleted: process energy: status=Live (first call took 300.089625ms); a fresh probe: Live after 12 intervals over a 300.076ms window, advances [("ri_energy_nj", 12)], in 300.079042ms; detect_explained: Detection { selected: ProcessEnergy, rapl: Some(Unavailable), nvml: Some(Unavailable), process_energy: Some(Live), ioreport: None }; IOReport probe runs = 0 process energy: 200 ms of one thread's CPU -> 1354645 µJ (1.355 J), HwShunt, coverage Whole process energy: 200 ms asleep -> 744 µJ (0.000744 J), HwShunt process energy: 200 ms of CPU on 1 thread -> 1328119 µJ (1.328 J), on each of 2 threads -> 2172758 µJ (2.173 J), ratio 1.64 process energy: a span running `yes > /dev/null` for 200 ms -> 3351 µJ (0.003351 J), HwShunt; the child's own count 1213689002 nJ (1.214 J) ioreport liveness: status=CpuRailFrozen oracle=CpuRailMoved(false) selected=false jcp-intercept (12), jcp-schema (30) and jcp-conformance (1 unit test and 5 pack tests) pass. The jcp-conformance binary prints "all checks passed", and jcp-cli runs. clippy --no-deps is clean on jcp-energy with and without `nvml`, for aarch64-apple-darwin, x86_64-apple-darwin and x86_64-unknown-linux-gnu. `cargo doc` with `-D warnings` is clean. Falsified, each by a temporary edit restored with git checkout (git diff was empty after each): - Reading another pid (the parent's, via getppid) fails all five hardware tests. The probe sees the idle parent's count hold: "detect() did not select the per-process rung: Detection { selected: TimePower, ..., process_energy: Some(Frozen), ioreport: Some(CpuRailFrozen) }". - A reader that returns a constant fails the same five, the same way. - Ignoring liveness in `detect` (opening the rung whatever its status) fails `only_a_live_status_selects_the_process_energy_rung` ("status Unavailable gave ProcessEnergy(...)") and the order test. A cached status of Live with no probe fails the fresh-process pin ("the per-process liveness probe ran 0 times"). - Grading the rung `ModelBased` fails `the_process_energy_rung_is_live_here`. Grading an advancing span with `Energy::modeled` fails the pure span test and four hardware tests ("provenance: ModelBased"). - Grading a span with no advance as a reading fails the span test ("held: ... measured_uj: Some(0) ... HwShunt"). Truncating nJ to µJ fails it too (480000, not 480001). - Decoding the word before `ri_energy_nj` fails the decoding test and the oracle check ("the reader's ri_energy_nj 977683212 is not this process's (1464983856 .. 1464983856)"). - Ranking IOReport above the per-process rung fails three tests. An uncached status fails the pin ("ran 32 times"). Not done here: - `Whole` assumes the work stays on this process's CPU threads. A closure that hands work to a child process or to the GPU is under-counted, and the figure still says `Whole`, because the meter cannot see that. The domain says so, and the child test pins the boundary. Grading such work `Partial` would need the caller to say what it does. - The figure is process-wide. Concurrent unrelated threads of the same process land in a span and over-debit it, as other processes do under a package counter. - The one-thread lower bound of 0.2 J has the least margin: the lowest seen on the M5 Max under load was 0.351 J. Rebased onto 25bfdcd9 (the RAPL figure sums the package zones by name), which adds four RAPL lib tests and changes no line of this commit; the counts above predate it. After the rebase jcp-energy has 82 lib tests at this commit (70 before it). Three full runs on the M5 Max passed. A fourth, under a host load average near 30, failed `one_thread_burning_200_ms_is_a_whole_hardware_reading` at its 200,000..=20,000,000 µJ range check (the figure was not captured); ten runs of that test alone then metered 218,593 to 298,209 µJ, below the 0.351 J noted above, so the 0.2 J lower bound is thinner than it says. The M3 Ultra run was not repeated. Co-Authored-By: Claude Opus 5.5 --- jcp/README.md | 2 +- jcp/SPEC.md | 21 +- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 948 ++++++++++++++++++++++-- 3 files changed, 919 insertions(+), 52 deletions(-) diff --git a/jcp/README.md b/jcp/README.md index 0f49aa0bb..bdc66cd1b 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()`), 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), a time×calibrated-power model (`ModelBased`, always available), and a constant per-op estimator (`Estimator`). 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 model. +- **`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, and 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×calibrated-power model (`ModelBased`, always available), and a constant per-op estimator (`Estimator`). 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 model. - **`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. 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/SPEC.md b/jcp/SPEC.md index 8800979b4..6dc8bd243 100644 --- a/jcp/SPEC.md +++ b/jcp/SPEC.md @@ -405,7 +405,8 @@ MUST NOT claim coverage of a domain its counter does not read; where the format has a coverage field, such a figure is Partial. The record of why is the implementation's to choose; the reference meter -exposes the IOReport liveness status it was selected or declined on. Coverage +exposes each counter's liveness status, and which rung it selected with the +status of every rung above it that it declined. Coverage is defined in §5.2. ### 5.1 The metering ladder (REQUIRED behavior, RECOMMENDED backends) @@ -432,18 +433,28 @@ Recommended ladder, best first: counter is live by the same rule; the probe cannot load the GPU, so for this counter live means published continuously, advancing on the device's own draw. A span over which it did not advance is metered by a lower rung. -3. **Apple IOReport** (the Energy Model group) — the SoC energy counters +3. **Per-process CPU energy** (macOS `proc_pid_rusage`, `ri_energy_nj`) — + the kernel's count of the CPU energy of the metering process's own + threads → `HwShunt`, `Whole` for work that runs on those threads. + Selected only while the count is live by the rule above. Its domain is + that process's threads alone: not other processes, not its child + processes, not the GPU, the Neural Engine or DRAM. It ranks above the + SoC-wide counter because it attributes the work's own CPU energy rather + than the machine's. A span over which it did not advance is metered by a + lower rung. +4. **Apple IOReport** (the Energy Model group) — the SoC energy counters → `HwShunt`, selected only while every CPU energy rail (one per die on a - multi-die part) is live by the rule above. A span over which that rail did not advance is metered by the next + multi-die part) is live by the rule above. A span over which no CPU rail + advanced is metered by the next rung, never graded `HwShunt`. Where the CPU rail is not live but the GPU rail is, the rung is declined rather than reporting the GPU rail as a `Partial` reading of the work: the GPU rail is machine-wide (display compositing moves it), so booking it to a task misattributes energy the task did not spend, and the partial figure would under-debit the budget, the CPU's share going unmetered. The whole-task estimate below is the honest figure. -4. **Time × calibrated power** — wall-clock duration times a host-calibrated +5. **Time × calibrated power** — wall-clock duration times a host-calibrated active power → `ModelBased`. Always available. -5. **Constant per-operation estimate** → `Estimator`. +6. **Constant per-operation estimate** → `Estimator`. ### 5.2 Coverage (REQUIRED where a figure is partial) diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index a20556a00..4ebd13763 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -13,7 +13,8 @@ //! at least 80% of them, over at least 300 ms. A figure that sums a frozen rail //! with live ones would leave out the frozen rail's share while claiming the //! whole domain. Each probe runs once per process, and each rung's status says -//! why it was declined. +//! why it was declined: [`Meter::detect_explained`] reports the rung selected +//! and the status of every rung asked on the way to it. //! 1. **RAPL** (`/sys/class/powercap`, Linux) — hardware package energy, //! `Provenance::HwShunt`, **only while every package counter is live** //! under the probe's CPU burn ([`rapl_status`]). The figure sums the @@ -27,7 +28,19 @@ //! GPU, so the CPU's share of the work is unmetered and the figure never //! claims the whole task. Only while the counter is live ([`nvml_status`]); //! a span over which it did not advance is the model's whole-task figure. -//! 3. **IOReport** (Apple Silicon) — the on-die SoC Energy Model counters via +//! 3. **Per-process CPU energy** (macOS) — the kernel's count of this +//! process's own CPU energy, `ri_energy_nj` from +//! `proc_pid_rusage(getpid(), RUSAGE_INFO_V6)` (public libproc, no +//! entitlement, no privilege), `Provenance::HwShunt`, `Coverage::Whole` +//! for in-process CPU work, **only while the count is live** under the +//! probe's CPU burn ([`process_energy_status`]). Its domain is the CPU +//! energy of this process's threads, all of them: not other processes, not +//! child processes, not the GPU, the Neural Engine or DRAM. It sits above +//! IOReport because it attributes the work's own CPU energy, where +//! IOReport's SoC-wide counter includes every other process. It is live +//! 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 model's figure. +//! 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 //! reading, not an estimate, and what it lacks is an independent root — how @@ -54,9 +67,9 @@ //! energy the task did not spend, and a partial figure would under-debit the //! budget, the CPU's share of the work going unmetered. The whole-task //! estimate stands. -//! 4. **Time × power model** — wall-clock duration times a calibrated active +//! 5. **Time × power model** — wall-clock duration times a calibrated active //! power, `Provenance::ModelBased`. Always available. -//! 5. **Constant estimator** — a fixed per-operation figure, +//! 6. **Constant estimator** — a fixed per-operation figure, //! `Provenance::Estimator`. For environments without even a usable clock. use std::time::Instant; @@ -597,9 +610,11 @@ mod liveness { } /// The liveness status of a single vendor energy counter rung — RAPL's -/// package counters, NVML's total-energy counter — as its probe found it on -/// this host. Probed once per process and cached; see [`rapl_status`] and -/// [`nvml_status`]. Only [`CounterStatus::Live`] admits the rung (SPEC §5). +/// package counters, NVML's total-energy counter, the kernel's per-process CPU +/// energy count — as its probe found it on this host. Probed once per process +/// and cached; see [`rapl_status`], [`nvml_status`] and +/// [`process_energy_status`]. Only [`CounterStatus::Live`] admits the rung +/// (SPEC §5). #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum CounterStatus { /// The counter could not be opened or read — absent (not this platform, @@ -749,6 +764,174 @@ pub fn nvml_status() -> CounterStatus { } } +/// The byte layout of `struct rusage_info_v6`, which macOS's +/// `proc_pid_rusage(pid, RUSAGE_INFO_V6, &info)` fills, as far as this crate +/// reads it. From ``, measured with `sizeof` and `offsetof` by +/// the C compiler against the macOS 26, 26.5 and 27 SDKs, which agree: the +/// struct is 464 bytes, a 16-byte UUID then 56 `uint64_t`s, and `ri_energy_nj` +/// and `ri_penergy_nj` sit at bytes 336 and 344 (the 43rd and 44th words). +/// New fields go into the struct's reserved tail: the 27 SDK named three of +/// the nine reserved words the 26 SDKs had, and the size and the offsets +/// before them held. +/// +/// 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 rusage_v6 { + /// `RUSAGE_INFO_V6` in ``. + pub(crate) const FLAVOR: i32 = 6; + /// `sizeof(struct rusage_info_v6)`. + pub(crate) const SIZE: usize = 464; + /// `offsetof(struct rusage_info_v6, ri_energy_nj)`. + pub(crate) const ENERGY_NJ: usize = 336; + /// `offsetof(struct rusage_info_v6, ri_penergy_nj)`. + pub(crate) const PENERGY_NJ: usize = 344; + + /// What this crate reads of one `rusage_info_v6`. + #[derive(Debug, Clone, Copy, PartialEq, Eq)] + pub(crate) struct ProcessEnergyReading { + /// `ri_energy_nj`: the CPU energy the kernel has attributed to this + /// process's threads since it started, in nanojoules. + pub(crate) energy_nj: u64, + /// `ri_penergy_nj`: the part of it spent on performance cores. + pub(crate) penergy_nj: u64, + } + + /// The `uint64_t` at `offset`, in the host's byte order: the kernel writes + /// the struct in place, natively. + fn word(info: &[u8; SIZE], offset: usize) -> u64 { + let mut bytes = [0u8; 8]; + bytes.copy_from_slice(&info[offset..offset + 8]); + u64::from_ne_bytes(bytes) + } + + /// Decode the energy counts from the bytes `proc_pid_rusage` wrote. + pub(crate) fn decode(info: &[u8; SIZE]) -> ProcessEnergyReading { + ProcessEnergyReading { energy_nj: word(info, ENERGY_NJ), penergy_nj: word(info, PENERGY_NJ) } + } +} + +/// 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 +/// the kernel attributes to this process's threads, in nanojoules. +/// +/// Its domain, exactly: the CPU energy of **this process's threads** — every +/// thread of the process, not only the one a span runs on, so a span also +/// takes in what the process's other threads spent meanwhile, as a package +/// counter takes in other processes. Not other processes. Not child processes: a child's energy is its own, and it is not +/// added to the parent's count when the child exits (a test pins this by +/// spawning one). Not the GPU, the Neural Engine or DRAM. +/// +/// It is live for an unprivileged reader where IOReport's CPU rails are not. +/// 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. +#[cfg(target_os = "macos")] +#[allow(unsafe_code)] +mod process_energy { + use std::os::raw::{c_int, c_void}; + + use crate::liveness; + use crate::rusage_v6::{self, ProcessEnergyReading}; + + unsafe extern "C" { + fn proc_pid_rusage(pid: c_int, flavor: c_int, buffer: *mut c_void) -> c_int; + fn getpid() -> c_int; + } + + /// A `rusage_info_v6`-sized buffer, aligned as the struct is. + #[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). + 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. + #[derive(Debug)] + pub struct ProcessEnergy { + _opened: (), + } + + impl ProcessEnergy { + /// `Some` when the kernel answers for this process. 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: () }) + } + + /// `ri_energy_nj` now, in nJ. + pub(crate) fn read_nj(&self) -> Option { + read().map(|r| r.energy_nj) + } + + /// One liveness sample: `ri_energy_nj` as the counter's one rail. + pub(crate) fn liveness_sample(&self) -> Option> { + let nj = self.read_nj()?; + Some(liveness::every_rail(&[("ri_energy_nj".to_string(), i64::try_from(nj).unwrap_or(i64::MAX))])) + } + } +} + +/// How many times the per-process energy probe has run in this process. Always +/// 0 off macOS, which has no such counter. +#[cfg_attr(not(test), allow(dead_code))] +fn process_energy_probe_runs() -> usize { + PROCESS_ENERGY_PROBE_RUNS.load(std::sync::atomic::Ordering::SeqCst) +} + +static PROCESS_ENERGY_PROBE_RUNS: std::sync::atomic::AtomicUsize = std::sync::atomic::AtomicUsize::new(0); + +/// This host's per-process CPU energy status, probed once per process and +/// cached. Always [`CounterStatus::Unavailable`] off macOS. +/// +/// [`Meter::detect`] selects the process-energy rung only when this is +/// [`CounterStatus::Live`]: `ri_energy_nj` advanced while the probing thread +/// burned CPU, in at least five sample intervals, at least 80% of them, over at +/// least 300 ms — the rule every vendor counter here is held to. The first call +/// on macOS burns about 300 ms of the calling thread's CPU when the counter is +/// live (one second when it is not). +pub fn process_energy_status() -> CounterStatus { + #[cfg(target_os = "macos")] + { + static STATUS: std::sync::OnceLock = std::sync::OnceLock::new(); + *STATUS.get_or_init(process_energy_host_status) + } + #[cfg(not(target_os = "macos"))] + { + CounterStatus::Unavailable + } +} + +/// The real per-process probe: the real opener and tick. Counts itself, then +/// composes; its only caller is the cache in [`process_energy_status`]. +#[cfg(target_os = "macos")] +fn process_energy_host_status() -> CounterStatus { + PROCESS_ENERGY_PROBE_RUNS.fetch_add(1, std::sync::atomic::Ordering::SeqCst); + liveness::status_of(process_energy_probe().as_ref()) +} + +/// The per-process probe on the real parts: [`liveness::probe`] on this +/// process's counter, sampled after every 25 ms of the probing thread's CPU, +/// by the real clock, for one budget. +#[cfg(target_os = "macos")] +fn process_energy_probe() -> Option { + liveness::probe( + process_energy::ProcessEnergy::open, + process_energy::ProcessEnergy::liveness_sample, + liveness::burn_tick, + Instant::now, + liveness::BUDGET, + ) +} + /// Apple Silicon IOReport energy reader — a real, no-sudo, no-external-binary /// reading of the SoC Energy Model channels through Apple's private IOReport C /// API. Like RAPL and NVML it is a vendor energy counter: how Apple derives the @@ -3512,7 +3695,11 @@ mod ioreport { fn the_ioreport_rung_is_never_selected_on_a_frozen_cpu_rail() { let _hw = crate::ioreport_hw_lock(); let status = crate::ioreport_status(); - let selected = matches!(crate::Meter::detect(), crate::Meter::IoReport(_)); + // The IOReport rung's own gate, on this host's cached status, with + // the rungs above it declined: `detect()` reaches it only then, and + // on a host whose per-process counter is live it never does. + let selected = + matches!(crate::Meter::detect_with(&crate::Ladder::ioreport_only()).0, crate::Meter::IoReport(_)); let window = crate::CPU_RAIL_LIVENESS_BUDGET * 3; let run = oracle_cpu_rail(window); // One line, so a CI log says which branch below was actually asserted. @@ -4139,14 +4326,15 @@ mod ioreport { /// CPU rail holds. /// /// When it is not, the status says why (never `Live`), and the meter - /// `detect()` returned still meters real work honestly: 100 ms of CPU + /// the ladder fell to still meters real work honestly: 100 ms of CPU /// work is the time×power model's figure, at least 100 ms at the /// documented default power, tagged `ModelBased` with no measurement. /// Never a floored or zero figure for work that ran. #[test] fn a_selected_ioreport_meter_meters_cpu_work() { let _hw = crate::ioreport_hw_lock(); - let meter = crate::Meter::detect(); + // The rungs above IOReport declined, as `detect()` reaches it. + let meter = crate::Meter::detect_with(&crate::Ladder::ioreport_only()).0; if let crate::Meter::IoReport(io) = &meter { assert_eq!( crate::ioreport_status(), @@ -4232,7 +4420,8 @@ mod ioreport { // Not a pass by default: the oracle's all-channel subscription // must fail to open too, or the counter's opener is broken. let oracle_opens = oracle_subscribe().map(oracle_unsubscribe).is_some(); - let selected = matches!(crate::Meter::detect(), crate::Meter::IoReport(_)); + let selected = + matches!(crate::Meter::detect_with(&crate::Ladder::ioreport_only()).0, crate::Meter::IoReport(_)); eprintln!("ioreport counter: no counter opens on this host; oracle opens={oracle_opens} selected={selected}"); assert!(!oracle_opens, "the counter does not open, but the oracle's all-channel subscription does"); assert!(!selected, "detect() selected an IOReport counter that does not open"); @@ -4439,6 +4628,18 @@ pub enum Meter { /// time×power model's whole-task figure. #[cfg(feature = "nvml")] Nvml(Box), + /// This process's CPU energy, as the kernel counts it for this process's + /// threads (`ri_energy_nj`, macOS) → `Provenance::HwShunt`, + /// `Coverage::Whole` for in-process CPU work. Its domain is this process's + /// threads' CPU energy, every thread of the process during the span: not + /// other processes, not child processes, not the GPU, the Neural Engine + /// or DRAM. Work that stays on this process's CPU threads is covered + /// whole; work a span hands to a child process or to the GPU is not in + /// the figure. [`Meter::detect`] selects it only while the counter is live + /// ([`process_energy_status`]), and a span over which it did not advance is + /// the time×power model's figure (`process_span`). + #[cfg(target_os = "macos")] + ProcessEnergy(process_energy::ProcessEnergy), /// Apple Silicon IOReport Energy Model energy → `Provenance::HwShunt`, the /// grade of RAPL's and NVML's vendor counters. [`Meter::detect`] selects it /// only while every CPU energy rail is live, and a span over which no CPU @@ -4451,22 +4652,83 @@ pub enum Meter { Const { per_op_uj: u64 }, } -/// Where [`Meter::detect`] gets each rung's liveness status, and the RAPL -/// counter it opens: the cached host probes ([`Ladder::host`]), or in tests -/// any status and a fake counter, so every gate is driven with every status on -/// a host whose own statuses are one value each. +/// A rung of the metering ladder, in ladder order, best first. Every rung is +/// named on every platform, so a caller can match on it anywhere; a rung the +/// platform does not have is never selected. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Rung { + /// RAPL package counters (Linux). + Rapl, + /// NVML's GPU total-energy counter (feature `nvml`). + Nvml, + /// The kernel's count of this process's CPU energy (macOS). + ProcessEnergy, + /// IOReport's SoC Energy Model counters (Apple Silicon). + IoReport, + /// The time×power model. + TimePower, + /// The constant per-operation estimator. + Constant, +} + +/// Why [`Meter::detect_explained`] selected the rung it did: the rung, and the +/// status each counter rung above it was declined on. +/// +/// The ladder is walked best first and stops at the first rung admitted, so a +/// status is `Some` for every rung it asked — those above the selected one and +/// the selected one itself — and `None` for every rung below it, which it never +/// asked: asking would have run that rung's liveness probe. A status that +/// admits its rung beside a lower `selected` rung means the counter was live +/// but did not open when the meter was built. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct Detection { + /// The rung the meter was built on. + pub selected: Rung, + /// [`rapl_status`], if asked. + pub rapl: Option, + /// [`nvml_status`], if asked. + pub nvml: Option, + /// [`process_energy_status`], if asked. + pub process_energy: Option, + /// [`ioreport_status`], if asked. + pub ioreport: Option, +} + +impl Detection { + /// This explanation, with `meter`'s rung as the one selected. + fn selecting(mut self, meter: Meter) -> (Meter, Detection) { + self.selected = meter.rung(); + (meter, self) + } +} + +/// Where [`Meter::detect`] gets each rung's liveness status, and the counters +/// it opens: the cached host probes ([`Ladder::host`]), or in tests any status +/// and a fake counter, so every gate is driven with every status on a host +/// whose own statuses are one value each. struct Ladder<'a> { rapl: &'a dyn Fn() -> CounterStatus, open_rapl: &'a dyn Fn() -> Option, nvml: &'a dyn Fn() -> CounterStatus, + process_energy: &'a dyn Fn() -> CounterStatus, + #[cfg(target_os = "macos")] + open_process_energy: &'a dyn Fn() -> Option, ioreport: &'a dyn Fn() -> IoReportStatus, } impl Ladder<'static> { /// The ladder [`Meter::detect`] runs: the cached host probes and the real - /// RAPL opener. + /// openers. fn host() -> Self { - Ladder { rapl: &rapl_status, open_rapl: &Rapl::open, nvml: &nvml_status, ioreport: &ioreport_status } + Ladder { + rapl: &rapl_status, + open_rapl: &Rapl::open, + nvml: &nvml_status, + process_energy: &process_energy_status, + #[cfg(target_os = "macos")] + open_process_energy: &process_energy::ProcessEnergy::open, + ioreport: &ioreport_status, + } } } @@ -4476,39 +4738,80 @@ impl Meter { /// always an estimate, it just says so in its provenance. /// /// A vendor counter rung is selected only while its counter is live (SPEC - /// §5): RAPL on [`rapl_status`], NVML on [`nvml_status`], IOReport on - /// [`ioreport_status`], each probed once per process. Each status is - /// asked for only once every rung above it is declined, so a process pays - /// for no probe below the rung it gets. + /// §5): RAPL on [`rapl_status`], NVML on [`nvml_status`], the per-process + /// counter on [`process_energy_status`], IOReport on [`ioreport_status`], + /// each probed once per process. Each status is asked for only once every + /// rung above it is declined, so a process pays for no probe below the + /// rung it gets. [`Meter::detect_explained`] says which rung was selected + /// and why the ones above it were declined. + /// + /// The per-process counter sits above IOReport. Both are vendor readings, + /// but they read different domains: the per-process count is the CPU + /// energy of this process's own threads, so it attributes the work's own + /// CPU energy, while IOReport's counter is SoC-wide and takes in every + /// other process's draw and the machine-wide GPU rail. Where both are + /// live the figure that is the work's own wins. pub fn detect() -> Self { + Self::detect_with(&Ladder::host()).0 + } + + /// [`Meter::detect`], and why: the rung selected and the liveness status + /// of every rung asked on the way to it ([`Detection`]). The statuses are + /// the cached ones `detect` reads, so a caller or a receipt can record why + /// a host is metered by the rung it is, and not by a better one. + pub fn detect_explained() -> (Self, Detection) { Self::detect_with(&Ladder::host()) } - /// [`Meter::detect`] on a given ladder. Each counter rung is opened only - /// when its status admits it ([`select`], [`admits`]). - fn detect_with(ladder: &Ladder<'_>) -> Self { + /// [`Meter::detect_explained`] on a given ladder. Each counter rung is + /// opened only when its status admits it ([`select`], [`admits`]). + fn detect_with(ladder: &Ladder<'_>) -> (Self, Detection) { + let mut why = + Detection { selected: Rung::TimePower, rapl: None, nvml: None, process_energy: None, ioreport: None }; // Opening a counter is not enough: it must be live (SPEC §5), or a // count republished in lumps landing in one span is graded a hardware // reading of that span's work. - if let Some(r) = select((ladder.rapl)(), ladder.open_rapl) { - return Meter::Rapl(r); + let rapl = (ladder.rapl)(); + why.rapl = Some(rapl); + if let Some(r) = select(rapl, ladder.open_rapl) { + return why.selecting(Meter::Rapl(r)); } let nvml = (ladder.nvml)(); + why.nvml = Some(nvml); #[cfg(feature = "nvml")] if let Some(n) = select(nvml, Nvml::open) { - return Meter::Nvml(Box::new(n)); + return why.selecting(Meter::Nvml(Box::new(n))); } - #[cfg(not(feature = "nvml"))] - let _ = nvml; + let process = (ladder.process_energy)(); + why.process_energy = Some(process); #[cfg(target_os = "macos")] - if admits((ladder.ioreport)()) { - if let Some(io) = ioreport::IoReport::open() { - return Meter::IoReport(io); + if let Some(p) = select(process, ladder.open_process_energy) { + return why.selecting(Meter::ProcessEnergy(p)); + } + let io = (ladder.ioreport)(); + why.ioreport = Some(io); + #[cfg(target_os = "macos")] + if admits(io) { + if let Some(m) = ioreport::IoReport::open() { + return why.selecting(Meter::IoReport(m)); } } - #[cfg(not(target_os = "macos"))] - let _ = ladder.ioreport; - Meter::TimePower { milliwatts: DEFAULT_ACTIVE_MILLIWATTS } + why.selecting(Meter::TimePower { milliwatts: DEFAULT_ACTIVE_MILLIWATTS }) + } + + /// The rung this meter is. + pub fn rung(&self) -> Rung { + match self { + Meter::Rapl(_) => Rung::Rapl, + #[cfg(feature = "nvml")] + Meter::Nvml(_) => Rung::Nvml, + #[cfg(target_os = "macos")] + Meter::ProcessEnergy(_) => Rung::ProcessEnergy, + #[cfg(target_os = "macos")] + Meter::IoReport(_) => Rung::IoReport, + Meter::TimePower { .. } => Rung::TimePower, + Meter::Const { .. } => Rung::Constant, + } } /// A time×power model with a host-calibrated active power. @@ -4528,6 +4831,8 @@ impl Meter { #[cfg(feature = "nvml")] Meter::Nvml(_) => Provenance::HwShunt, #[cfg(target_os = "macos")] + Meter::ProcessEnergy(_) => Provenance::HwShunt, + #[cfg(target_os = "macos")] Meter::IoReport(_) => Provenance::HwShunt, Meter::TimePower { .. } => Provenance::ModelBased, Meter::Const { .. } => Provenance::Estimator, @@ -4563,6 +4868,14 @@ impl Meter { (out, nvml_span(before, n.read_uj(), elapsed.as_nanos())) } #[cfg(target_os = "macos")] + Meter::ProcessEnergy(p) => { + let before = p.read_nj(); + let started = Instant::now(); + let out = work(); + let elapsed = started.elapsed(); + (out, process_span(before, p.read_nj(), elapsed.as_nanos())) + } + #[cfg(target_os = "macos")] Meter::IoReport(io) => { let before = io.read(); let started = Instant::now(); @@ -4643,6 +4956,26 @@ fn nvml_span(before_uj: Option, after_uj: Option, elapsed_ns: u128) -> counter_span(rose, elapsed_ns, Energy::measured_partial) } +/// The figure the per-process rung gives one span, from `ri_energy_nj` read +/// either side of it. +/// +/// A reading, `HwShunt` and whole, only when the count 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 model's figure, `ModelBased`, as +/// IOReport's held spans are ([`ioreport_span`]). Never `HwShunt` on a model +/// figure. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +fn process_span(before_nj: Option, after_nj: Option, elapsed_ns: u128) -> Energy { + let rose_uj = match (before_nj, after_nj) { + (Some(b), Some(a)) => a.checked_sub(b).map(|nj| nj.div_ceil(1_000)), + _ => None, + }; + counter_span(rose_uj, elapsed_ns, Energy::measured) +} + /// µJ for a span: `mW × ns` is 10⁻³ W · 10⁻⁹ s = 10⁻¹² J = 10⁻⁶ µJ. fn time_power_uj(elapsed_ns: u128, milliwatts: u64) -> u64 { u64::try_from(elapsed_ns.saturating_mul(milliwatts as u128) / 1_000_000).unwrap_or(u64::MAX) @@ -4755,8 +5088,14 @@ mod tests { fn probed_once_from_eight_threads() { const THREADS: usize = 8; assert_eq!( - (ioreport_probe_runs(), ioreport_energy_model_opens(), rapl_probe_runs(), nvml_probe_runs()), - (0, 0, 0, 0), + ( + ioreport_probe_runs(), + ioreport_energy_model_opens(), + rapl_probe_runs(), + nvml_probe_runs(), + process_energy_probe_runs() + ), + (0, 0, 0, 0, 0), "something probed before the pin began, so its calls are not the first use" ); let barrier = std::sync::Barrier::new(THREADS); @@ -4785,18 +5124,26 @@ mod tests { workers.into_iter().map(|w| w.join().expect("a thread panicked")).collect() }); let (runs, opens) = (ioreport_probe_runs(), ioreport_energy_model_opens()); - let (rapl_runs, nvml_runs) = (rapl_probe_runs(), nvml_probe_runs()); + let (rapl_runs, nvml_runs, process_runs) = (rapl_probe_runs(), nvml_probe_runs(), process_energy_probe_runs()); eprintln!( "ioreport cache (fresh process, lib tests): {THREADS} threads, first use concurrent; they saw {statuses:?}; \ probe runs = {runs}, Energy Model subscriptions opened = {opens}; RAPL probe runs = {rapl_runs} \ - (status {:?}), NVML probe runs = {nvml_runs} (status {:?})", + (status {:?}), NVML probe runs = {nvml_runs} (status {:?}), per-process probe runs = {process_runs} \ + (status {:?})", rapl_status(), - nvml_status() + nvml_status(), + process_energy_status() ); - // Every `detect()` asks for the RAPL status first, and NVML's next: - // each probe ran once, on whichever thread asked first. + // Every `detect()` asks for the RAPL status first, then NVML's, then + // the per-process counter's: each probe ran once, on whichever thread + // asked first. Off macOS there is no per-process probe. assert_eq!(rapl_runs, 1, "the RAPL liveness probe did not run exactly once in this process"); assert_eq!(nvml_runs, usize::from(cfg!(feature = "nvml")), "the NVML liveness probe ran {nvml_runs} times"); + assert_eq!( + process_runs, + usize::from(cfg!(target_os = "macos")), + "the per-process liveness probe ran {process_runs} times" + ); assert!(statuses.iter().all(|s| *s == statuses[0]), "threads saw different statuses: {statuses:?}"); assert_eq!(statuses[0], ioreport_status(), "the spawned threads and this one disagree"); if cfg!(target_os = "macos") { @@ -4867,7 +5214,7 @@ mod tests { #[test] fn the_ioreport_rung_stamps_the_hardware_grade() { let _hw = ioreport_hw_lock(); - let meter = Meter::detect_with(&Ladder { ioreport: &|| IoReportStatus::Live, ..Ladder::none() }); + let (meter, _) = Meter::detect_with(&Ladder { ioreport: &|| IoReportStatus::Live, ..Ladder::none() }); if matches!(meter, Meter::IoReport(_)) { let live = ioreport_span( Some(IoReportReading { total_uj: 0, cpu_uj: 0 }), @@ -4891,14 +5238,14 @@ mod tests { let _hw = ioreport_hw_lock(); use IoReportStatus as S; for status in [S::Unavailable, S::CpuRailAbsent, S::CpuRailFrozen] { - let meter = Meter::detect_with(&Ladder { ioreport: &|| status, ..Ladder::none() }); + let (meter, _) = Meter::detect_with(&Ladder { ioreport: &|| status, ..Ladder::none() }); assert!( matches!(meter, Meter::TimePower { milliwatts: DEFAULT_ACTIVE_MILLIWATTS }), "status {status:?} gave {meter:?}" ); } let opens = ioreport::IoReport::open().is_some(); - let meter = Meter::detect_with(&Ladder { ioreport: &|| S::Live, ..Ladder::none() }); + let (meter, _) = Meter::detect_with(&Ladder { ioreport: &|| S::Live, ..Ladder::none() }); assert_eq!( matches!(meter, Meter::IoReport(_)), opens, @@ -4915,9 +5262,20 @@ mod tests { rapl: &|| CounterStatus::Unavailable, open_rapl: &|| None, nvml: &|| CounterStatus::Unavailable, + process_energy: &|| CounterStatus::Unavailable, + #[cfg(target_os = "macos")] + open_process_energy: &|| None, ioreport: &|| IoReportStatus::Unavailable, } } + + /// The ladder as `detect()` walks it on a host where every rung above + /// IOReport is declined: this host's cached IOReport status, and the + /// IOReport rung's own gate. + #[cfg(target_os = "macos")] + pub(crate) fn ioreport_only() -> Self { + Ladder { ioreport: &ioreport_status, ..Ladder::none() } + } } // ── The counter rungs' gate: RAPL and NVML ────────────────────────────── @@ -5243,7 +5601,7 @@ mod tests { opened.set(opened.get() + 1); Rapl::open_in(&fake.root) }; - let meter = Meter::detect_with(&Ladder { rapl: &|| status, open_rapl: &open, ..Ladder::none() }); + let (meter, _) = Meter::detect_with(&Ladder { rapl: &|| status, open_rapl: &open, ..Ladder::none() }); let live = status == CounterStatus::Live; assert_eq!(matches!(meter, Meter::Rapl(_)), live, "status {status:?} gave {meter:?}"); assert_eq!(opened.get(), usize::from(live), "status {status:?} opened the counter {} times", opened.get()); @@ -5309,6 +5667,504 @@ mod tests { } } + // ── The per-process CPU energy rung ───────────────────────────────────── + + /// `struct rusage_info_v6`, transcribed field by field from + /// `` in the macOS 27 SDK: an independent statement of the + /// layout, for the tests to hold the implementation's offsets to and for + /// their own oracle to read through. + #[allow(dead_code)] + #[repr(C)] + struct RusageInfoV6Mirror { + 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], + } + + /// The decoder's layout is the SDK's, two ways: the literals the C + /// compiler printed for `sizeof` and `offsetof` on the header (the same + /// in the macOS 26, 26.5 and 27 SDKs), and `offset_of!` on the + /// field-by-field transcription of the 27 SDK's. + #[test] + fn the_rusage_v6_layout_is_the_sdks() { + assert_eq!( + (rusage_v6::FLAVOR, rusage_v6::SIZE, rusage_v6::ENERGY_NJ, rusage_v6::PENERGY_NJ), + (6, 464, 336, 344), + "not RUSAGE_INFO_V6 and the C compiler's sizeof/offsetof of struct rusage_info_v6" + ); + assert_eq!(std::mem::size_of::(), rusage_v6::SIZE); + assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_energy_nj), rusage_v6::ENERGY_NJ); + assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_penergy_nj), rusage_v6::PENERGY_NJ); + } + + /// The decoding, on fixed byte layouts. Every byte holding its own index + /// (mod 251) makes every word distinct, so a decoder reading any other + /// word, or straddling two, reads other bytes. And a literal buffer: + /// `ri_energy_nj` = 2,400,000,000 nJ and `ri_penergy_nj` = 1, little-endian + /// as on every macOS target, with every other byte 0xFF. + #[test] + fn rusage_v6_decoding_reads_its_two_words_and_nothing_else() { + let mut info = [0u8; rusage_v6::SIZE]; + for (i, b) in info.iter_mut().enumerate() { + *b = (i % 251) as u8; + } + let at = |start: u8| u64::from_ne_bytes(std::array::from_fn(|k| start + k as u8)); + let r = rusage_v6::decode(&info); + assert_eq!((r.energy_nj, r.penergy_nj), (at(85), at(93)), "bytes 336..344 and 344..352 are 85..93 and 93..101"); + + let mut info = [0xFFu8; rusage_v6::SIZE]; + info[336..344].copy_from_slice(&[0x00, 0x18, 0x0D, 0x8F, 0x00, 0x00, 0x00, 0x00]); + info[344..352].copy_from_slice(&[0x01, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00]); + let r = rusage_v6::decode(&info); + if cfg!(target_endian = "little") { + assert_eq!((r.energy_nj, r.penergy_nj), (2_400_000_000, 1)); + } else { + assert_eq!((r.energy_nj, r.penergy_nj), (0x0018_0D8F_0000_0000, 0x0100_0000_0000_0000)); + } + } + + /// A per-process span is a reading only when `ri_energy_nj` advanced: + /// `HwShunt` and whole, the rise in µJ rounded up, so a rise under 1 µJ is + /// 1 µJ and never 0. A count that held or fell, or a failed read, is the + /// time×power model's figure. + #[test] + fn a_process_span_is_a_reading_only_when_the_count_advanced() { + let e = process_span(Some(1_000_000), Some(481_000_001), 200_000_000); + assert_eq!((e.provenance, e.measured_uj, e.is_whole()), (Provenance::HwShunt, Some(480_001), true), "{e:?}"); + e.check_provenance().unwrap(); + let e = process_span(Some(5), Some(505), 1_000); + assert_eq!((e.provenance, e.measured_uj), (Provenance::HwShunt, Some(1)), "a sub-µJ rise read as zero: {e:?}"); + let model = time_power_uj(200_000_000, DEFAULT_ACTIVE_MILLIWATTS); + let b = Some(9_000_000_000); + for (what, before, after) in [("held", b, b), ("fell", b, Some(1)), ("before failed", None, b), ("after failed", b, None)] { + let e = process_span(before, after, 200_000_000); + assert_eq!((e.provenance, e.measured_uj, e.uj()), (Provenance::ModelBased, None, model), "{what}: {e:?}"); + } + } + + /// The per-process probe's rule on a scripted `ri_energy_nj`: rising + /// ~60 mJ every interval, as under the probe's burn, Live at the tenth + /// interval; held, Frozen. + #[test] + fn the_process_energy_gate_on_a_scripted_count() { + let count = |nj: i64| Some(vec![("ri_energy_nj".to_string(), nj)]); + let (status, w, _, _) = scripted_counter(|i| count(2_529_044 + 60_000_000 * i as i64), COUNTER_STEP); + assert_eq!((status, w.unwrap().intervals), (CounterStatus::Live, 10)); + let (status, _, _, _) = scripted_counter(|_| count(2_529_044), COUNTER_STEP); + assert_eq!(status, CounterStatus::Frozen); + } + + /// The per-process rung is selected on a `Live` status and on no other, + /// and its counter is opened only then. Declined, the ladder goes on to + /// IOReport, and the explanation says so. + #[cfg(target_os = "macos")] + #[test] + fn only_a_live_status_selects_the_process_energy_rung() { + use CounterStatus as S; + for status in [S::Unavailable, S::Frozen, S::Live] { + let opened = Cell::new(0); + let open = || { + opened.set(opened.get() + 1); + process_energy::ProcessEnergy::open() + }; + let ladder = Ladder { process_energy: &|| status, open_process_energy: &open, ..Ladder::none() }; + let (meter, why) = Meter::detect_with(&ladder); + let live = status == S::Live; + assert_eq!(matches!(meter, Meter::ProcessEnergy(_)), live, "status {status:?} gave {meter:?}"); + assert_eq!(opened.get(), usize::from(live), "status {status:?} opened the counter {} times", opened.get()); + let expect = Detection { + selected: if live { Rung::ProcessEnergy } else { Rung::TimePower }, + rapl: Some(S::Unavailable), + nvml: Some(S::Unavailable), + process_energy: Some(status), + ioreport: if live { None } else { Some(IoReportStatus::Unavailable) }, + }; + assert_eq!(why, expect, "status {status:?}"); + assert_eq!(meter.rung(), why.selected); + } + } + + /// The order of the rungs: RAPL above the per-process counter, which is + /// above IOReport. A rung below the selected one is never asked, so its + /// probe never runs. + #[cfg(target_os = "macos")] + #[test] + fn the_process_energy_rung_sits_between_rapl_and_ioreport() { + let _hw = ioreport_hw_lock(); + use CounterStatus as S; + let asked = Cell::new(0); + let ioreport = || { + asked.set(asked.get() + 1); + IoReportStatus::Live + }; + let (meter, why) = Meter::detect_with(&Ladder { + process_energy: &|| S::Live, + open_process_energy: &process_energy::ProcessEnergy::open, + ioreport: &ioreport, + ..Ladder::none() + }); + assert!(matches!(meter, Meter::ProcessEnergy(_)), "{meter:?}"); + assert_eq!((why.ioreport, asked.get()), (None, 0), "IOReport was asked below a selected per-process rung"); + let (meter, why) = Meter::detect_with(&Ladder { + process_energy: &|| S::Frozen, + open_process_energy: &process_energy::ProcessEnergy::open, + ioreport: &ioreport, + ..Ladder::none() + }); + assert_eq!((why.process_energy, why.ioreport), (Some(S::Frozen), Some(IoReportStatus::Live))); + assert_eq!(matches!(meter, Meter::IoReport(_)), ioreport::IoReport::open().is_some(), "{meter:?}"); + let fake = FakePowercap::new(&["1000"]); + let process_asked = Cell::new(0); + let process = || { + process_asked.set(process_asked.get() + 1); + S::Live + }; + let (meter, why) = Meter::detect_with(&Ladder { + rapl: &|| S::Live, + open_rapl: &|| Rapl::open_in(&fake.root), + process_energy: &process, + open_process_energy: &process_energy::ProcessEnergy::open, + ..Ladder::none() + }); + assert!(matches!(meter, Meter::Rapl(_)), "{meter:?}"); + assert_eq!( + why, + Detection { selected: Rung::Rapl, rapl: Some(S::Live), nvml: None, process_energy: None, ioreport: None } + ); + assert_eq!(process_asked.get(), 0, "the per-process status was asked below a selected RAPL rung"); + } + + /// Off macOS there is no per-process counter: a `Live` status (which the + /// host never reports there) still selects nothing, and the explanation + /// shows a status that admitted its rung beside a lower selected one. + #[cfg(not(target_os = "macos"))] + #[test] + fn the_process_energy_rung_is_never_selected_off_macos() { + assert_eq!(process_energy_status(), CounterStatus::Unavailable); + let (meter, why) = Meter::detect_with(&Ladder { process_energy: &|| CounterStatus::Live, ..Ladder::none() }); + assert!(matches!(meter, Meter::TimePower { .. }), "{meter:?}"); + assert_eq!((why.selected, why.process_energy), (Rung::TimePower, Some(CounterStatus::Live))); + } + + /// Each meter names its rung. + #[test] + fn each_meter_names_its_rung() { + #[cfg(target_os = "macos")] + let _hw = ioreport_hw_lock(); + assert_eq!(Meter::time_power(1).rung(), Rung::TimePower); + assert_eq!(Meter::constant(1).rung(), Rung::Constant); + let fake = FakePowercap::new(&["1"]); + assert_eq!(Meter::Rapl(Rapl::open_in(&fake.root).unwrap()).rung(), Rung::Rapl); + #[cfg(target_os = "macos")] + { + assert_eq!(Meter::ProcessEnergy(process_energy::ProcessEnergy::open().unwrap()).rung(), Rung::ProcessEnergy); + if let Some(io) = ioreport::IoReport::open() { + assert_eq!(Meter::IoReport(io).rung(), Rung::IoReport); + } + } + } + + // ── The per-process rung against the hardware (macOS) ─────────────────── + + /// Set in the environment of a fresh process that [`in_a_fresh_process`] + /// starts, to the one test it runs. + #[cfg(target_os = "macos")] + const FRESH_TEST: &str = "JCP_ENERGY_FRESH_PROCESS_TEST"; + + /// Runs `body` as the only test of a fresh process: this test binary + /// again, filtered to `test` exactly, on one test thread. The count read + /// is the whole process's, so tests running beside it in this process + /// would land in its spans. Lines the body prints that begin with "process + /// energy" are echoed here. + #[cfg(target_os = "macos")] + fn in_a_fresh_process(test: &str, body: fn()) { + if std::env::var(FRESH_TEST).as_deref() == Ok(test) { + return body(); + } + let _hw = ioreport_hw_lock(); + let out = std::process::Command::new(std::env::current_exe().expect("this test binary's path")) + .args([test, "--exact", "--nocapture", "--test-threads=1"]) + .env(FRESH_TEST, test) + .output() + .expect("could not run this test binary again"); + let text = format!("{}{}", String::from_utf8_lossy(&out.stdout), String::from_utf8_lossy(&out.stderr)); + for line in text.lines().filter(|l| l.starts_with("process energy")) { + eprintln!("{line}"); + } + assert!(out.status.success(), "{test} failed in a fresh process:\n{text}"); + // A filter that matched nothing would also exit 0. + assert!(text.contains("running 1 test") && text.contains("1 passed"), "the fresh process did not run {test}:\n{text}"); + } + + /// `_CLOCK_THREAD_CPUTIME_ID` in macOS ``, the tests' own copy. + #[cfg(target_os = "macos")] + const TESTS_THREAD_CPU_CLOCK: std::os::raw::c_int = 16; + + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + unsafe extern "C" { + fn clock_gettime_nsec_np(clock_id: std::os::raw::c_int) -> u64; + fn proc_pid_rusage(pid: std::os::raw::c_int, flavor: std::os::raw::c_int, buffer: *mut std::ffi::c_void) -> std::os::raw::c_int; + } + + /// This thread's CPU time, by the tests' own clock. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn tests_thread_cpu() -> Duration { + Duration::from_nanos(unsafe { clock_gettime_nsec_np(TESTS_THREAD_CPU_CLOCK) }) + } + + /// Spin until this thread has used `cpu` more CPU time, by the tests' own + /// clock. + #[cfg(target_os = "macos")] + fn burn_thread_cpu(cpu: Duration) { + let start = tests_thread_cpu(); + let mut acc: u64 = 0; + while tests_thread_cpu().saturating_sub(start) < cpu { + for _ in 0..1_000 { + acc = std::hint::black_box(acc.wrapping_add(1)); + } + } + } + + /// The tests' own read of any process's `ri_energy_nj`, through their own + /// FFI declaration and the transcribed struct: the oracle. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn oracle_energy_nj(pid: u32) -> Option<(u64, u64)> { + let mut info = std::mem::MaybeUninit::::zeroed(); + let rc = unsafe { proc_pid_rusage(pid as std::os::raw::c_int, 6, info.as_mut_ptr().cast()) }; + (rc == 0).then(|| { + let info = unsafe { info.assume_init() }; + (info.ri_energy_nj, info.ri_penergy_nj) + }) + } + + /// The meter `detect()` builds here, which must be the per-process rung. + #[cfg(target_os = "macos")] + fn process_meter() -> Meter { + let (meter, why) = Meter::detect_explained(); + assert!(matches!(meter, Meter::ProcessEnergy(_)), "detect() did not select the per-process rung: {why:?}"); + meter + } + + /// J, for the log. + #[cfg(target_os = "macos")] + fn joules(uj: u64) -> f64 { + uj as f64 / 1e6 + } + + /// The per-process counter is live on this host, by the cached probe that + /// `detect()` reads and by a fresh probe on the real parts; `detect()` + /// selects the rung, and never asks IOReport, whose probe below it never + /// runs. The counter it reads is this process's: between two reads of the + /// tests' own oracle for this pid, its count sits between theirs. + #[cfg(target_os = "macos")] + #[test] + fn the_process_energy_rung_is_live_here() { + in_a_fresh_process("tests::the_process_energy_rung_is_live_here", || { + let started = std::time::Instant::now(); + let status = process_energy_status(); + let first_call = started.elapsed(); + let (meter, why) = Meter::detect_explained(); + let started = std::time::Instant::now(); + let fresh = process_energy_probe().expect("the per-process counter does not open"); + let fresh_took = started.elapsed(); + eprintln!( + "process energy: status={status:?} (first call took {first_call:?}); a fresh probe: {:?} after {} \ + intervals over a {:?} window, advances {:?}, in {fresh_took:?}; detect_explained: {why:?}; IOReport \ + probe runs = {}", + liveness::status_of(Some(&fresh)), + fresh.intervals, + fresh.window, + fresh.rails.iter().map(|(k, n)| (k.name.clone(), *n)).collect::>(), + ioreport_probe_runs() + ); + assert_eq!(status, CounterStatus::Live, "the per-process counter is not live here"); + assert_eq!(liveness::status_of(Some(&fresh)), CounterStatus::Live, "a fresh probe says otherwise"); + assert!(matches!(meter, Meter::ProcessEnergy(_)), "{meter:?}"); + assert_eq!(meter.provenance(), Provenance::HwShunt); + assert_eq!( + why, + Detection { + selected: Rung::ProcessEnergy, + rapl: Some(CounterStatus::Unavailable), + nvml: Some(CounterStatus::Unavailable), + process_energy: Some(CounterStatus::Live), + ioreport: None, + } + ); + assert_eq!(ioreport_probe_runs(), 0, "IOReport was probed below a live per-process rung"); + let me = std::process::id(); + let before = oracle_energy_nj(me).expect("the oracle cannot read this process"); + let read = process_energy::read().expect("the reader cannot read this process"); + let after = oracle_energy_nj(me).expect("the oracle cannot read this process"); + eprintln!( + "process energy: oracle {before:?} <= reader ({}, {}) <= oracle {after:?} (ri_energy_nj, ri_penergy_nj)", + read.energy_nj, read.penergy_nj + ); + assert!( + before.0 <= read.energy_nj && read.energy_nj <= after.0, + "the reader's ri_energy_nj {} is not this process's ({} .. {})", + read.energy_nj, + before.0, + after.0 + ); + assert!(before.1 <= read.penergy_nj && read.penergy_nj <= after.1, "ri_penergy_nj is not this process's"); + assert!(before.0 > 0, "this process's count is zero after its own probe burned CPU"); + }); + } + + /// 200 ms of one thread's CPU is a hardware reading of it: `HwShunt`, + /// whole, between 0.2 J and 20 J. + #[cfg(target_os = "macos")] + #[test] + fn one_thread_burning_200_ms_is_a_whole_hardware_reading() { + in_a_fresh_process("tests::one_thread_burning_200_ms_is_a_whole_hardware_reading", || { + let meter = process_meter(); + let ((), e) = meter.measure(|| burn_thread_cpu(Duration::from_millis(200))); + eprintln!( + "process energy: 200 ms of one thread's CPU -> {} µJ ({:.3} J), {:?}, coverage {:?}", + e.uj(), + joules(e.uj()), + e.provenance, + e.coverage + ); + e.check_provenance().unwrap(); + assert_eq!(e.provenance, Provenance::HwShunt, "{e:?}"); + assert!(e.is_whole(), "{e:?}"); + assert!((200_000..=20_000_000).contains(&e.uj()), "200 ms of one thread's CPU metered {} µJ", e.uj()); + }); + } + + /// 200 ms asleep meters under 0.1 J: the counter reads this process's + /// CPU, not wall time at a guessed power. + #[cfg(target_os = "macos")] + #[test] + fn sleeping_200_ms_meters_under_a_tenth_of_a_joule() { + in_a_fresh_process("tests::sleeping_200_ms_meters_under_a_tenth_of_a_joule", || { + let meter = process_meter(); + let ((), e) = meter.measure(|| std::thread::sleep(Duration::from_millis(200))); + eprintln!("process energy: 200 ms asleep -> {} µJ ({:.6} J), {:?}", e.uj(), joules(e.uj()), e.provenance); + assert!(e.uj() < 100_000, "200 ms asleep metered {} µJ: {e:?}", e.uj()); + assert_eq!(e.provenance, Provenance::HwShunt, "{e:?}"); + }); + } + + /// Two threads burning 200 ms of CPU each meter more than one: every + /// thread of the process is in the count. + #[cfg(target_os = "macos")] + #[test] + fn two_threads_burning_meter_more_than_one() { + in_a_fresh_process("tests::two_threads_burning_meter_more_than_one", || { + let meter = process_meter(); + let cpu = Duration::from_millis(200); + let ((), one) = meter.measure(|| burn_thread_cpu(cpu)); + let ((), two) = meter.measure(|| { + std::thread::scope(|s| { + s.spawn(|| burn_thread_cpu(cpu)); + burn_thread_cpu(cpu); + }) + }); + eprintln!( + "process energy: 200 ms of CPU on 1 thread -> {} µJ ({:.3} J), on each of 2 threads -> {} µJ ({:.3} J), \ + ratio {:.2}", + one.uj(), + joules(one.uj()), + two.uj(), + joules(two.uj()), + two.uj() as f64 / one.uj().max(1) as f64 + ); + assert_eq!((one.provenance, two.provenance), (Provenance::HwShunt, Provenance::HwShunt)); + assert!(two.uj() > one.uj(), "two threads metered {} µJ, one thread {} µJ", two.uj(), one.uj()); + }); + } + + /// Work done by a child process is not attributed: a span that runs + /// `yes > /dev/null` for 200 ms, then kills and reaps it, meters under + /// 0.1 J, though the child's own count, by the tests' oracle, shows it + /// spent far more. This pins the documented domain: this process's + /// threads, not its children. + #[cfg(target_os = "macos")] + #[test] + fn a_child_process_work_is_not_attributed() { + in_a_fresh_process("tests::a_child_process_work_is_not_attributed", || { + let meter = process_meter(); + let mut child_nj = None; + let ((), e) = meter.measure(|| { + let mut child = std::process::Command::new("yes") + .stdout(std::process::Stdio::null()) + .spawn() + .expect("could not spawn yes"); + std::thread::sleep(Duration::from_millis(200)); + child_nj = oracle_energy_nj(child.id()); + child.kill().expect("could not kill yes"); + child.wait().expect("could not reap yes"); + }); + let child_nj = child_nj.expect("the oracle could not read the child's count").0; + eprintln!( + "process energy: a span running `yes > /dev/null` for 200 ms -> {} µJ ({:.6} J), {:?}; the child's own \ + count {child_nj} nJ ({:.3} J)", + e.uj(), + joules(e.uj()), + e.provenance, + child_nj as f64 / 1e9 + ); + assert!(child_nj >= 100_000_000, "the child spent only {child_nj} nJ, too little to tell"); + assert!(e.uj() < 100_000, "the span metered {} µJ: the child's work was attributed to it", e.uj()); + assert_eq!(e.provenance, Provenance::HwShunt, "{e:?}"); + }); + } + #[test] fn rapl_wraparound_delta() { let r = Rapl { -- 2.54.0 (Apple Git-157) From 830fc085f25d4dc75f14f4eaef1ca4c82b96ece1 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 30 Sep 2026 21:43:24 -0400 Subject: [PATCH 2/3] jcp-energy: a per-process span a child process worked in is partial MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The per-process rung graded every span that advanced `ri_energy_nj` as `HwShunt`, `Coverage::Whole`. That count covers only this process's threads. A child's energy is its own, and the kernel never adds it to the parent's count, not even when the child is reaped. So a closure that drives a child process was under-counted while its figure claimed the whole span. SPEC §5 forbids that: a figure must not claim coverage of a domain its counter does not read. The previous commit named this under "Not done here" and said grading it `Partial` would need the caller's help. It does not: the same `rusage_info_v6` shows it, and so does the kernel's list of children. The rule, in `process_span`: a span whose count advanced is whole only when no child process can have worked in it unseen. That means two things. The process's reaped children's CPU time (`ri_child_user_time` + `ri_child_system_time`) held across the span, and at the span's end `proc_listchildpids` lists no child, running or exited and not yet reaped. Otherwise the span is `Energy::measured_partial`: `HwShunt`, `Partial`, the same rise. A failed child count is `Partial` too, since nothing then shows the figure whole. A child the process had before the span counts as well, because the meter cannot tell whether the span's work drove it. `measure` lists the children before it reads the count, so a child reaped between the two shows up in one or the other. A span whose count did not advance is still the model's whole-task figure. What the kernel does, measured on an M5 Max, macOS 27.0.1, with the C compiler and small C and Rust programs rather than assumed: - `ri_child_user_time` and `ri_child_system_time` are at bytes 96 and 104 (`offsetof` against the 27 SDK). They are in Mach absolute time units: a `yes` that ran ~190 ms showed 4,565,473 of its own, and reaping it raised the parent's by 4,565,861. `ri_energy_nj` did not move on the reap. - Spawning a child by absolute path, or letting it run, never moved those times; only the reap did (24 of 24 trials, posix_spawn and fork+exec alike). - `proc_listchildpids` returns a count of pids when given a buffer. It lists a killed child until it is reaped. Without a buffer it returns a size estimate (1,098 with no child), so the reader always passes one. - A failed `posix_spawn` can move the reaped children's time too: a spawn of a missing path moved it in 2 of 200 attempts (90-127 units). A program spawned by name is looked up by trying each `PATH` directory. Here, with 12 ahead of `/usr/bin`, `Command::new("yes")` moved the time at spawn in 7 of 24 spawns, and `/usr/bin/yes` by absolute path in none of 12. Such a span is `Partial` on that alone, which errs on the side of claiming less. It is documented on `process_span`. A run of the new left-running test, which then spawned `yes` by name, caught it: "reaped children's CPU 0 -> 115 Mach units" with nothing reaped. The tests now spawn `/usr/bin/yes`. The decoder reads the two child-time words next to the energy words. `process_energy::child_count()` wraps `proc_listchildpids` with a 64-pid buffer. Docs: the crate's ladder entry, the module, `Meter::ProcessEnergy`, `process_span`, SPEC §5.1 item 3 and the README's jcp-energy bullet now say that a span that reaps a child or ends with one is `Partial`. Tests. jcp-energy has 80 lib tests (78 before) and its integration test. All pass with and without `--features nvml`, and three runs in a row were green: - Layout: the child-time offsets equal the C compiler's 96 and 104 and `offset_of!` on the transcribed struct. Decoding reads all four words and nothing else; on a literal buffer, 446,368 + 4,119,493 = 4,565,861. - Pure, on every platform: on a count that rose 0.48 J, a reaped child, a child left at the end, both, and a failed child count are each `HwShunt`/`Partial` with the same 480,001 µJ. Neither is whole. A held count is the model's whole figure whatever the children did. - Hardware, each in a fresh process. A span that runs `/usr/bin/yes > /dev/null` for 200 ms and reaps it is `Partial`. The tests' own reads show that the reaped time rose and no child is left, so the reap alone decided it. A span that leaves `yes` running is `Partial`; the child is listed and the reaped time held, so the left child alone decided it. A pure 200 ms in-process burn, with no child before or after, is whole. The old `a_child_process_work_is_not_attributed` is now the reap test, and keeps its check that the child's energy is not in the figure. - The tests' oracles are their own: `proc_listchildpids` through their own declaration, counting nonzero pids in a zeroed buffer, and the child times through the transcribed struct. A guard kills and reaps every child, so a failing test leaves none running. Falsified, each by a temporary edit restored with git checkout (git diff was empty after each): - Ignoring children (`whole = true`) fails the pure test and both hardware child tests: "a span that reaped a child claimed to cover it: Energy { measured_uj: Some(1368), ..., coverage: Whole }" and "a span that left a child running claimed to cover it: ... coverage: Whole". - Ignoring the reaped children's time fails the pure test and the reap test only. - Ignoring the children left at the end fails the pure test and the left-running test only. - A `child_count` that always says 0 fails the left-running test. jcp-intercept (12) and jcp-conformance (1 unit test and 5 pack tests) pass. The jcp-conformance binary prints "all checks passed", C9 included, and jcp-cli runs and exits 0. clippy --no-deps -D warnings is clean on jcp-energy for aarch64-apple-darwin (with and without `nvml`), x86_64-apple-darwin and x86_64-unknown-linux-gnu, and `cargo doc` with `-D warnings` is clean. M5 Max, verbatim: process energy: a span running `yes > /dev/null` for 200 ms, then reaping it -> 409 µJ (0.000409 J), HwShunt, coverage Partial; the child's own count 229352810 nJ (0.229 J); reaped children's CPU 0 -> 4673857 Mach units; children left [] process energy: a span leaving `yes > /dev/null` running -> 29048 µJ (0.029048 J), HwShunt, coverage Partial; children at its end [41504] (the child 41504); reaped children's CPU 0 -> 0 Mach units M3 Ultra, verbatim. The lib test binary was built here with `target-cpu=apple-m1`, copied to 10.10.10.2 (sha256 060761dd2b0e2efc... on both ends), run with --nocapture, then deleted. 80 of 80 passed: process energy: a span running `yes > /dev/null` for 200 ms, then reaping it -> 1322 µJ (0.001322 J), HwShunt, coverage Partial; the child's own count 1245873027 nJ (1.246 J); reaped children's CPU 0 -> 5041160 Mach units; children left [] process energy: a span leaving `yes > /dev/null` running -> 137541 µJ (0.137541 J), HwShunt, coverage Partial; children at its end [30980] (the child 30980); reaped children's CPU 0 -> 0 Mach units process energy: 200 ms of one thread's CPU -> 1366000 µJ (1.366 J), HwShunt, coverage Whole ioreport liveness: status=CpuRailFrozen oracle=CpuRailMoved(false) selected=false Not done here: - Work handed to the GPU, the Neural Engine, or another process over IPC (a daemon serving this one) is still not in the figure and is not detected. rusage has no per-process GPU energy. - A grandchild that outlives the child that started it is reparented to launchd and is not listed. The reap of its parent still makes that span `Partial`, but a later span cannot see it. - A long-lived child the process keeps makes every span `Partial` while it lives. That is safe, but coarse. Rebased onto 25bfdcd9 (the RAPL figure sums the package zones by name), which adds four RAPL lib tests and changes no line of this commit; the counts above, the M3 Ultra run's included, predate it. After the rebase jcp-energy has 84 lib tests (82 before this commit), all passing on the M5 Max with and without `--features nvml`, as do jcp-intercept, jcp-conformance (its tests and the binary) and jcp-cli. Co-Authored-By: Claude Opus 5.5 --- jcp/README.md | 2 +- jcp/SPEC.md | 5 +- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 407 ++++++++++++++++++++---- 3 files changed, 355 insertions(+), 59 deletions(-) diff --git a/jcp/README.md b/jcp/README.md index bdc66cd1b..46923dc3c 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, and 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×calibrated-power model (`ModelBased`, always available), and a constant per-op estimator (`Estimator`). 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 model. +- **`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×calibrated-power model (`ModelBased`, always available), and a constant per-op estimator (`Estimator`). 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 model. - **`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. 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/SPEC.md b/jcp/SPEC.md index 6dc8bd243..ee40a7a2a 100644 --- a/jcp/SPEC.md +++ b/jcp/SPEC.md @@ -438,7 +438,10 @@ Recommended ladder, best first: threads → `HwShunt`, `Whole` for work that runs on those threads. Selected only while the count is live by the rule above. Its domain is that process's threads alone: not other processes, not its child - processes, not the GPU, the Neural Engine or DRAM. It ranks above the + processes, not the GPU, the Neural Engine or DRAM. A span over which the + process reaped a child (its reaped children's CPU time moved), or at whose + end it has a child, running or not yet reaped, is `Partial` (§5.2): the + child's energy is not in the count. It ranks above the SoC-wide counter because it attributes the work's own CPU energy rather than the machine's. A span over which it did not advance is metered by a lower rung. diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index 4ebd13763..4fa2765a5 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -35,7 +35,10 @@ //! for in-process CPU work, **only while the count is live** under the //! probe's CPU burn ([`process_energy_status`]). Its domain is the CPU //! energy of this process's threads, all of them: not other processes, not -//! child processes, not the GPU, the Neural Engine or DRAM. It sits above +//! child processes, not the GPU, the Neural Engine or DRAM. A span that +//! reaps a child process, or ends with one (running or not yet reaped), is +//! a `Coverage::Partial` reading: the child's energy is not in the count, +//! and the figure does not claim it. It sits above //! IOReport because it attributes the work's own CPU energy, where //! IOReport's SoC-wide counter includes every other process. It is live //! for an unprivileged reader on macOS 27.0.1, where IOReport's CPU rails @@ -769,8 +772,9 @@ pub fn nvml_status() -> CounterStatus { /// reads it. From ``, measured with `sizeof` and `offsetof` by /// the C compiler against the macOS 26, 26.5 and 27 SDKs, which agree: the /// struct is 464 bytes, a 16-byte UUID then 56 `uint64_t`s, and `ri_energy_nj` -/// and `ri_penergy_nj` sit at bytes 336 and 344 (the 43rd and 44th words). -/// New fields go into the struct's reserved tail: the 27 SDK named three of +/// and `ri_penergy_nj` sit at bytes 336 and 344 (the 43rd and 44th words), +/// `ri_child_user_time` and `ri_child_system_time` at bytes 96 and 104 (the +/// 11th and 12th). New fields go into the struct's reserved tail: the 27 SDK named three of /// the nine reserved words the 26 SDKs had, and the size and the offsets /// before them held. /// @@ -786,6 +790,10 @@ mod rusage_v6 { pub(crate) const ENERGY_NJ: usize = 336; /// `offsetof(struct rusage_info_v6, ri_penergy_nj)`. pub(crate) const PENERGY_NJ: usize = 344; + /// `offsetof(struct rusage_info_v6, ri_child_user_time)`. + pub(crate) const CHILD_USER_TIME: usize = 96; + /// `offsetof(struct rusage_info_v6, ri_child_system_time)`. + pub(crate) const CHILD_SYSTEM_TIME: usize = 104; /// What this crate reads of one `rusage_info_v6`. #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -795,6 +803,22 @@ mod rusage_v6 { pub(crate) energy_nj: u64, /// `ri_penergy_nj`: the part of it spent on performance cores. pub(crate) penergy_nj: u64, + /// `ri_child_user_time`: the user CPU time of this process's children + /// that it has reaped, in Mach absolute time units. The kernel adds a + /// child's time here when the child is reaped, and adds nothing to + /// `ri_energy_nj`; a child still running, or exited and not yet + /// reaped, is in neither. + pub(crate) child_user_time: u64, + /// `ri_child_system_time`: the same, for system CPU time. + pub(crate) child_system_time: u64, + } + + impl ProcessEnergyReading { + /// The reaped children's CPU time, user and system, in Mach absolute + /// time units. Only whether it moved across a span is read. + pub(crate) fn reaped_children_cpu(&self) -> u64 { + self.child_user_time.saturating_add(self.child_system_time) + } } /// The `uint64_t` at `offset`, in the host's byte order: the kernel writes @@ -805,9 +829,15 @@ mod rusage_v6 { u64::from_ne_bytes(bytes) } - /// Decode the energy counts from the bytes `proc_pid_rusage` wrote. + /// Decode the energy counts and the reaped children's CPU times from the + /// bytes `proc_pid_rusage` wrote. pub(crate) fn decode(info: &[u8; SIZE]) -> ProcessEnergyReading { - ProcessEnergyReading { energy_nj: word(info, ENERGY_NJ), penergy_nj: word(info, PENERGY_NJ) } + ProcessEnergyReading { + energy_nj: word(info, ENERGY_NJ), + penergy_nj: word(info, PENERGY_NJ), + child_user_time: word(info, CHILD_USER_TIME), + child_system_time: word(info, CHILD_SYSTEM_TIME), + } } } @@ -819,9 +849,22 @@ mod rusage_v6 { /// Its domain, exactly: the CPU energy of **this process's threads** — every /// thread of the process, not only the one a span runs on, so a span also /// takes in what the process's other threads spent meanwhile, as a package -/// counter takes in other processes. Not other processes. Not child processes: a child's energy is its own, and it is not -/// added to the parent's count when the child exits (a test pins this by -/// spawning one). Not the GPU, the Neural Engine or DRAM. +/// counter takes in other processes. Not other processes. Not child +/// processes: a child's energy is its own, and it is not added to the +/// parent's count when the child exits or is reaped. Not the GPU, the Neural +/// Engine or DRAM. +/// +/// So a span whose work drives a child process is under-counted, and the +/// figure must not claim the whole of it (SPEC §5: a figure MUST NOT claim +/// coverage of a domain its counter does not read). The same `rusage_info_v6` +/// shows it: `ri_child_user_time` and `ri_child_system_time` rise when the +/// process reaps a child, and `child_count` lists the children it has — +/// running, or exited and not yet reaped. A span over which the reaped +/// children's CPU time moved, or at whose end the process has a child, is a +/// `Partial` reading (`process_span`). Measured on an M5 Max, macOS 27.0.1: +/// reaping a `yes` that ran ~190 ms raised the parent's child CPU time by +/// 4,565,861 Mach units (the child's own 4,565,473), and left `ri_energy_nj` +/// where it was. /// /// It is live for an unprivileged reader where IOReport's CPU rails are not. /// Measured on an M5 Max, macOS 27.0.1: 0.002 J/s idle, 2.4 J/s with one @@ -837,9 +880,26 @@ mod process_energy { 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 getpid() -> c_int; } + /// How many pids [`child_count`] asks the kernel for at most. + const CHILD_PIDS: usize = 64; + + /// How many child processes this process has now, as + /// `proc_listchildpids` lists them: running, or exited and not yet reaped + /// (a zombie is listed until it is reaped). At most [`CHILD_PIDS`]; only + /// whether there is one is read. `None` if the call fails. Asked with a + /// buffer: asked without one it returns a size estimate, not a count + /// (1,098 for a process with none, on macOS 27.0.1). + pub(crate) fn child_count() -> Option { + let mut pids: [c_int; CHILD_PIDS] = [0; CHILD_PIDS]; + let bytes = c_int::try_from(std::mem::size_of_val(&pids)).ok()?; + let n = unsafe { proc_listchildpids(getpid(), pids.as_mut_ptr().cast(), bytes) }; + usize::try_from(n).ok() + } + /// A `rusage_info_v6`-sized buffer, aligned as the struct is. #[repr(C, align(8))] struct Info([u8; rusage_v6::SIZE]); @@ -872,6 +932,12 @@ mod process_energy { 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. + pub(crate) fn read(&self) -> Option { + read() + } + /// One liveness sample: `ri_energy_nj` as the counter's one rail. pub(crate) fn liveness_sample(&self) -> Option> { let nj = self.read_nj()?; @@ -4635,7 +4701,10 @@ pub enum Meter { /// other processes, not child processes, not the GPU, the Neural Engine /// or DRAM. Work that stays on this process's CPU threads is covered /// whole; work a span hands to a child process or to the GPU is not in - /// the figure. [`Meter::detect`] selects it only while the counter is live + /// the figure. A span that reaped a child, or ends with one, is graded + /// `Coverage::Partial`, so the figure never claims the child's share; work + /// 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 time×power model's figure (`process_span`). #[cfg(target_os = "macos")] @@ -4869,11 +4938,14 @@ impl Meter { } #[cfg(target_os = "macos")] Meter::ProcessEnergy(p) => { - let before = p.read_nj(); + let before = p.read(); let started = Instant::now(); let out = work(); let elapsed = started.elapsed(); - (out, process_span(before, p.read_nj(), elapsed.as_nanos())) + // 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())) } #[cfg(target_os = "macos")] Meter::IoReport(io) => { @@ -4956,24 +5028,49 @@ fn nvml_span(before_uj: Option, after_uj: Option, elapsed_ns: u128) -> counter_span(rose, elapsed_ns, Energy::measured_partial) } -/// The figure the per-process rung gives one span, from `ri_energy_nj` read -/// either side of it. +/// The figure the per-process rung gives one span, from the process's +/// `rusage_info_v6` read either side of it and its child processes counted at +/// its end (`None`: the count failed). /// -/// A reading, `HwShunt` and whole, only when the count 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 model's figure, `ModelBased`, as -/// IOReport's held spans are ([`ioreport_span`]). Never `HwShunt` on a model -/// figure. +/// 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 model's figure, `ModelBased`, as IOReport's held spans +/// are ([`ioreport_span`]). Never `HwShunt` on a model figure. +/// +/// The reading covers the whole span only when no child process can have +/// worked in it unseen: the reaped children's CPU time held across the span, +/// and at its end the process has no child, running or unreaped. A child's +/// energy is its own and never reaches `ri_energy_nj`, so a span that reaped +/// a child, or that leaves one behind, is under-counted by the child's share: +/// [`Energy::measured_partial`], `HwShunt` with `Coverage::Partial`, which MUST +/// NOT be presented as the span's total (SPEC §5.2). So is a span whose child +/// count failed, since nothing then shows the figure whole. A child the +/// process already had before the span counts too: the meter cannot tell +/// whether the span's work drove it. A failed spawn can count as well: the +/// kernel can charge the would-be child's CPU time to the reaped children's +/// time even when `posix_spawn` fails. On an M5 Max (macOS 27.0.1), a +/// `posix_spawn` of a missing path moved it in 2 of 200 attempts (90-127 Mach +/// units). A program spawned by name is looked up by trying each `PATH` +/// directory in turn, so with 12 directories ahead of `/usr/bin`, spawning +/// `yes` by name moved it in 7 of 24 spawns, and by absolute path in none of +/// 12. Such a span is `Partial` on that alone, which errs on the side of +/// claiming less. #[cfg_attr(not(target_os = "macos"), allow(dead_code))] -fn process_span(before_nj: Option, after_nj: Option, elapsed_ns: u128) -> Energy { - let rose_uj = match (before_nj, after_nj) { - (Some(b), Some(a)) => a.checked_sub(b).map(|nj| nj.div_ceil(1_000)), - _ => None, +fn process_span( + before: Option, + after: Option, + children_at_end: Option, + elapsed_ns: u128, +) -> Energy { + let (Some(b), Some(a)) = (before, after) else { + return counter_span(None, elapsed_ns, Energy::measured); }; - counter_span(rose_uj, elapsed_ns, Energy::measured) + let rose_uj = a.energy_nj.checked_sub(b.energy_nj).map(|nj| nj.div_ceil(1_000)); + let whole = children_at_end == Some(0) && a.reaped_children_cpu() == b.reaped_children_cpu(); + counter_span(rose_uj, elapsed_ns, if whole { Energy::measured } else { Energy::measured_partial }) } /// µJ for a span: `mW × ns` is 10⁻³ W · 10⁻⁹ s = 10⁻¹² J = 10⁻⁶ µJ. @@ -5732,8 +5829,9 @@ mod tests { /// The decoder's layout is the SDK's, two ways: the literals the C /// compiler printed for `sizeof` and `offsetof` on the header (the same - /// in the macOS 26, 26.5 and 27 SDKs), and `offset_of!` on the - /// field-by-field transcription of the 27 SDK's. + /// in the macOS 26, 26.5 and 27 SDKs; the child-time offsets printed + /// against the 27 SDK), and `offset_of!` on the field-by-field + /// transcription of the 27 SDK's. #[test] fn the_rusage_v6_layout_is_the_sdks() { assert_eq!( @@ -5741,18 +5839,27 @@ mod tests { (6, 464, 336, 344), "not RUSAGE_INFO_V6 and the C compiler's sizeof/offsetof of struct rusage_info_v6" ); + assert_eq!( + (rusage_v6::CHILD_USER_TIME, rusage_v6::CHILD_SYSTEM_TIME), + (96, 104), + "not the C compiler's offsetof of ri_child_user_time and ri_child_system_time" + ); assert_eq!(std::mem::size_of::(), rusage_v6::SIZE); assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_energy_nj), rusage_v6::ENERGY_NJ); assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_penergy_nj), rusage_v6::PENERGY_NJ); + assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_child_user_time), rusage_v6::CHILD_USER_TIME); + assert_eq!(std::mem::offset_of!(RusageInfoV6Mirror, ri_child_system_time), rusage_v6::CHILD_SYSTEM_TIME); } /// The decoding, on fixed byte layouts. Every byte holding its own index /// (mod 251) makes every word distinct, so a decoder reading any other /// word, or straddling two, reads other bytes. And a literal buffer: - /// `ri_energy_nj` = 2,400,000,000 nJ and `ri_penergy_nj` = 1, little-endian - /// as on every macOS target, with every other byte 0xFF. + /// `ri_energy_nj` = 2,400,000,000 nJ, `ri_penergy_nj` = 1, + /// `ri_child_user_time` = 446,368 and `ri_child_system_time` = 4,119,493 + /// (a reaped `yes`'s, as read on an M5 Max), little-endian as on every + /// macOS target, with every other byte 0xFF. #[test] - fn rusage_v6_decoding_reads_its_two_words_and_nothing_else() { + fn rusage_v6_decoding_reads_its_four_words_and_nothing_else() { let mut info = [0u8; rusage_v6::SIZE]; for (i, b) in info.iter_mut().enumerate() { *b = (i % 251) as u8; @@ -5760,37 +5867,99 @@ mod tests { let at = |start: u8| u64::from_ne_bytes(std::array::from_fn(|k| start + k as u8)); let r = rusage_v6::decode(&info); assert_eq!((r.energy_nj, r.penergy_nj), (at(85), at(93)), "bytes 336..344 and 344..352 are 85..93 and 93..101"); + assert_eq!((r.child_user_time, r.child_system_time), (at(96), at(104)), "bytes 96..104 and 104..112"); let mut info = [0xFFu8; rusage_v6::SIZE]; info[336..344].copy_from_slice(&[0x00, 0x18, 0x0D, 0x8F, 0x00, 0x00, 0x00, 0x00]); info[344..352].copy_from_slice(&[0x01, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00]); + info[96..104].copy_from_slice(&[0xA0, 0xCF, 0x06, 0x00, 0x00, 0x00, 0x00, 0x00]); + info[104..112].copy_from_slice(&[0xC5, 0xDB, 0x3E, 0x00, 0x00, 0x00, 0x00, 0x00]); let r = rusage_v6::decode(&info); if cfg!(target_endian = "little") { assert_eq!((r.energy_nj, r.penergy_nj), (2_400_000_000, 1)); + assert_eq!((r.child_user_time, r.child_system_time), (446_368, 4_119_493)); + assert_eq!(r.reaped_children_cpu(), 4_565_861); } else { assert_eq!((r.energy_nj, r.penergy_nj), (0x0018_0D8F_0000_0000, 0x0100_0000_0000_0000)); } } + /// One `rusage_info_v6` as a span reads it: `ri_energy_nj` = `nj` and the + /// reaped children's CPU time = `children_cpu`, split across user and + /// system time as a reaped `yes`'s was. + fn usage(nj: u64, children_cpu: u64) -> rusage_v6::ProcessEnergyReading { + let user = children_cpu / 10; + rusage_v6::ProcessEnergyReading { + energy_nj: nj, + penergy_nj: nj / 2, + child_user_time: user, + child_system_time: children_cpu - user, + } + } + /// A per-process span is a reading only when `ri_energy_nj` advanced: - /// `HwShunt` and whole, the rise in µJ rounded up, so a rise under 1 µJ is - /// 1 µJ and never 0. A count that held or fell, or a failed read, is the - /// time×power model's figure. + /// `HwShunt` and whole (no child reaped, none at the end), the rise in µJ + /// rounded up, so a rise under 1 µJ is 1 µJ and never 0. A count that held + /// or fell, or a failed read, is the time×power model's figure. #[test] fn a_process_span_is_a_reading_only_when_the_count_advanced() { - let e = process_span(Some(1_000_000), Some(481_000_001), 200_000_000); + let (none, kids) = (Some(0), 4_565_861); + let e = process_span(Some(usage(1_000_000, kids)), Some(usage(481_000_001, kids)), none, 200_000_000); assert_eq!((e.provenance, e.measured_uj, e.is_whole()), (Provenance::HwShunt, Some(480_001), true), "{e:?}"); e.check_provenance().unwrap(); - let e = process_span(Some(5), Some(505), 1_000); + let e = process_span(Some(usage(5, 0)), Some(usage(505, 0)), none, 1_000); assert_eq!((e.provenance, e.measured_uj), (Provenance::HwShunt, Some(1)), "a sub-µJ rise read as zero: {e:?}"); let model = time_power_uj(200_000_000, DEFAULT_ACTIVE_MILLIWATTS); - let b = Some(9_000_000_000); - for (what, before, after) in [("held", b, b), ("fell", b, Some(1)), ("before failed", None, b), ("after failed", b, None)] { - let e = process_span(before, after, 200_000_000); + let b = Some(usage(9_000_000_000, 0)); + for (what, before, after) in + [("held", b, b), ("fell", b, Some(usage(1, 0))), ("before failed", None, b), ("after failed", b, None)] + { + let e = process_span(before, after, none, 200_000_000); assert_eq!((e.provenance, e.measured_uj, e.uj()), (Provenance::ModelBased, None, model), "{what}: {e:?}"); } } + /// A span a child process may have worked in unseen is a `Partial` + /// reading, never whole: the child's energy is its own and is not in + /// `ri_energy_nj`. Each on a count that rose 0.48 J: + /// - the reaped children's CPU time rose across the span (a child was + /// reaped in it): `Partial`, though no child is left at its end; + /// - a child is left at its end (running, or exited and unreaped): + /// `Partial`, though no child was reaped; + /// - both: `Partial`; + /// - the child count failed: `Partial`, since nothing shows it whole; + /// - neither, the reaped time held at a nonzero value: whole. + /// + /// The figure stays the count's rise either way: `Partial` changes what it + /// claims to cover, not what it read. A span whose count held is the + /// model's whole-task figure whatever the children did. + #[test] + fn a_span_a_child_may_have_worked_in_is_a_partial_reading() { + let (b, kids) = (1_000_000, 4_565_861); + let span = |children_after: u64, at_end: Option| { + process_span(Some(usage(b, kids)), Some(usage(481_000_001, kids + children_after)), at_end, 200_000_000) + }; + for (what, e) in [ + ("a child reaped", span(4_565_861, Some(0))), + ("a child left at the end", span(0, Some(1))), + ("a child reaped and one left", span(1, Some(3))), + ("the child count failed", span(0, None)), + ] { + assert_eq!( + (e.provenance, e.measured_uj, e.coverage), + (Provenance::HwShunt, Some(480_001), jcp_schema::Coverage::Partial), + "{what}: the figure claimed a child's share: {e:?}" + ); + assert!(!e.is_whole(), "{what}: {e:?}"); + e.check_provenance().unwrap(); + } + let e = span(0, Some(0)); + assert_eq!((e.provenance, e.measured_uj, e.is_whole()), (Provenance::HwShunt, Some(480_001), true), "{e:?}"); + let held = process_span(Some(usage(b, kids)), Some(usage(b, kids + 9)), Some(2), 200_000_000); + assert_eq!((held.provenance, held.measured_uj), (Provenance::ModelBased, None), "{held:?}"); + assert!(held.is_whole(), "the model's figure is a whole-task estimate: {held:?}"); + } + /// The per-process probe's rule on a scripted `ri_energy_nj`: rising /// ~60 mJ every interval, as under the probe's burn, Live at the tenth /// interval; held, Frozen. @@ -5954,6 +6123,11 @@ mod tests { unsafe extern "C" { fn clock_gettime_nsec_np(clock_id: std::os::raw::c_int) -> u64; fn proc_pid_rusage(pid: std::os::raw::c_int, flavor: std::os::raw::c_int, buffer: *mut std::ffi::c_void) -> std::os::raw::c_int; + fn proc_listchildpids( + ppid: std::os::raw::c_int, + buffer: *mut std::ffi::c_void, + buffersize: std::os::raw::c_int, + ) -> std::os::raw::c_int; } /// This thread's CPU time, by the tests' own clock. @@ -5989,6 +6163,63 @@ mod tests { }) } + /// The tests' own read of a process's reaped children's CPU time + /// (`ri_child_user_time` + `ri_child_system_time`), through their own FFI + /// declaration and the transcribed struct. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn oracle_reaped_children_cpu(pid: u32) -> Option { + let mut info = std::mem::MaybeUninit::::zeroed(); + let rc = unsafe { proc_pid_rusage(pid as std::os::raw::c_int, 6, info.as_mut_ptr().cast()) }; + (rc == 0).then(|| { + let info = unsafe { info.assume_init() }; + info.ri_child_user_time + info.ri_child_system_time + }) + } + + /// The tests' own list of this process's child processes, through their + /// own FFI declaration: the nonzero pids the kernel wrote into a zeroed + /// buffer, whatever the call returns. + #[cfg(target_os = "macos")] + #[allow(unsafe_code)] + fn oracle_child_pids() -> Vec { + let mut pids = [0i32; 256]; + let bytes = std::mem::size_of_val(&pids) as std::os::raw::c_int; + let me = std::process::id() as std::os::raw::c_int; + let rc = unsafe { proc_listchildpids(me, pids.as_mut_ptr().cast(), bytes) }; + assert!(rc >= 0, "the tests' proc_listchildpids failed: {rc}"); + pids.into_iter().filter(|&p| p > 0).collect() + } + + /// A child process that is killed and reaped when dropped, so a test that + /// fails while one runs never leaves it behind. + #[cfg(target_os = "macos")] + struct Reaped(std::process::Child); + + #[cfg(target_os = "macos")] + impl Drop for Reaped { + fn drop(&mut self) { + let _ = self.0.kill(); + let _ = self.0.wait(); + } + } + + /// `yes > /dev/null`, started as a child of this process. By its absolute + /// path: spawned by name, it is looked up by trying each `PATH` directory + /// in turn, and a failed try can move this process's reaped children's CPU + /// time (by 54-289 Mach units in 7 of 24 spawns on an M5 Max, never by + /// absolute path; see `process_span`). That makes a span `Partial` too, + /// and would blur which check a test isolates. + #[cfg(target_os = "macos")] + fn spawn_yes() -> Reaped { + Reaped( + std::process::Command::new("/usr/bin/yes") + .stdout(std::process::Stdio::null()) + .spawn() + .expect("could not spawn yes"), + ) + } + /// The meter `detect()` builds here, which must be the per-process rung. #[cfg(target_os = "macos")] fn process_meter() -> Meter { @@ -6065,13 +6296,17 @@ mod tests { } /// 200 ms of one thread's CPU is a hardware reading of it: `HwShunt`, - /// whole, between 0.2 J and 20 J. + /// whole, between 0.2 J and 20 J. A pure in-process burn in a process with + /// no child, before or after (by the tests' own listing), so nothing is + /// left out of the figure and it claims the whole span. #[cfg(target_os = "macos")] #[test] fn one_thread_burning_200_ms_is_a_whole_hardware_reading() { in_a_fresh_process("tests::one_thread_burning_200_ms_is_a_whole_hardware_reading", || { let meter = process_meter(); + assert_eq!(oracle_child_pids(), Vec::::new(), "the fresh process already has a child"); let ((), e) = meter.measure(|| burn_thread_cpu(Duration::from_millis(200))); + assert_eq!(oracle_child_pids(), Vec::::new(), "a child at the end of a pure in-process burn"); eprintln!( "process energy: 200 ms of one thread's CPU -> {} µJ ({:.3} J), {:?}, coverage {:?}", e.uj(), @@ -6129,39 +6364,97 @@ mod tests { }); } - /// Work done by a child process is not attributed: a span that runs - /// `yes > /dev/null` for 200 ms, then kills and reaps it, meters under - /// 0.1 J, though the child's own count, by the tests' oracle, shows it - /// spent far more. This pins the documented domain: this process's - /// threads, not its children. + /// A span that runs `yes > /dev/null` for 200 ms, then kills and reaps + /// it, is a `Partial` reading. The child's work is not in the figure: the + /// span meters under 0.1 J, though the child's own count, by the tests' + /// oracle, shows it spent far more. So the figure must not claim it. By + /// the tests' own reads, the reaped children's CPU time rose across the + /// span and no child is left at its end: the reap alone is what makes + /// this span `Partial`. #[cfg(target_os = "macos")] #[test] - fn a_child_process_work_is_not_attributed() { - in_a_fresh_process("tests::a_child_process_work_is_not_attributed", || { + fn a_span_that_runs_and_reaps_a_child_is_partial() { + in_a_fresh_process("tests::a_span_that_runs_and_reaps_a_child_is_partial", || { let meter = process_meter(); + let me = std::process::id(); + let reaped_before = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); let mut child_nj = None; let ((), e) = meter.measure(|| { - let mut child = std::process::Command::new("yes") - .stdout(std::process::Stdio::null()) - .spawn() - .expect("could not spawn yes"); + let mut child = spawn_yes(); std::thread::sleep(Duration::from_millis(200)); - child_nj = oracle_energy_nj(child.id()); - child.kill().expect("could not kill yes"); - child.wait().expect("could not reap yes"); + child_nj = oracle_energy_nj(child.0.id()); + child.0.kill().expect("could not kill yes"); + child.0.wait().expect("could not reap yes"); }); + let reaped_after = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); + let left = oracle_child_pids(); let child_nj = child_nj.expect("the oracle could not read the child's count").0; eprintln!( - "process energy: a span running `yes > /dev/null` for 200 ms -> {} µJ ({:.6} J), {:?}; the child's own \ - count {child_nj} nJ ({:.3} J)", + "process energy: a span running `yes > /dev/null` for 200 ms, then reaping it -> {} µJ ({:.6} J), \ + {:?}, coverage {:?}; the child's own count {child_nj} nJ ({:.3} J); reaped children's CPU \ + {reaped_before} -> {reaped_after} Mach units; children left {left:?}", e.uj(), joules(e.uj()), e.provenance, + e.coverage, child_nj as f64 / 1e9 ); assert!(child_nj >= 100_000_000, "the child spent only {child_nj} nJ, too little to tell"); assert!(e.uj() < 100_000, "the span metered {} µJ: the child's work was attributed to it", e.uj()); - assert_eq!(e.provenance, Provenance::HwShunt, "{e:?}"); + assert!(reaped_after > reaped_before, "the reap did not raise the reaped children's CPU time"); + assert!(left.is_empty(), "children left at the span's end: {left:?}"); + assert_eq!( + (e.provenance, e.coverage), + (Provenance::HwShunt, jcp_schema::Coverage::Partial), + "a span that reaped a child claimed to cover it: {e:?}" + ); + e.check_provenance().unwrap(); + }); + } + + /// A span that starts `yes > /dev/null` and leaves it running at its end + /// is a `Partial` reading: the child is still working, and none of its + /// energy is in the count. The closure also burns 20 ms of its own CPU, + /// so the count advances. By the tests' own reads, nothing was reaped in + /// the span (the reaped children's CPU time held) and the child is listed + /// at its end: the child left behind alone is what makes this span + /// `Partial`. The child is killed and reaped after the span, and on any + /// failure. + #[cfg(target_os = "macos")] + #[test] + fn a_span_that_leaves_a_child_running_is_partial() { + in_a_fresh_process("tests::a_span_that_leaves_a_child_running_is_partial", || { + let meter = process_meter(); + let me = std::process::id(); + let reaped_before = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); + let mut running = None; + let ((), e) = meter.measure(|| { + running = Some(spawn_yes()); + burn_thread_cpu(Duration::from_millis(20)); + std::thread::sleep(Duration::from_millis(50)); + }); + let reaped_after = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); + let listed = oracle_child_pids(); + let child = running.expect("the span did not start the child"); + let pid = child.0.id() as i32; + drop(child); + eprintln!( + "process energy: a span leaving `yes > /dev/null` running -> {} µJ ({:.6} J), {:?}, coverage {:?}; \ + children at its end {listed:?} (the child {pid}); reaped children's CPU {reaped_before} -> \ + {reaped_after} Mach units", + e.uj(), + joules(e.uj()), + e.provenance, + e.coverage + ); + assert!(listed.contains(&pid), "the running child {pid} was not listed: {listed:?}"); + assert_eq!(reaped_after, reaped_before, "a child was reaped in the span: the left child is not isolated"); + assert_eq!( + (e.provenance, e.coverage), + (Provenance::HwShunt, jcp_schema::Coverage::Partial), + "a span that left a child running claimed to cover it: {e:?}" + ); + e.check_provenance().unwrap(); }); } -- 2.54.0 (Apple Git-157) From 22e5a6ad9fedf24bee9bdd2d667497cd31b40be4 Mon Sep 17 00:00:00 2001 From: Transaction Science Date: Wed, 30 Sep 2026 22:34:20 -0400 Subject: [PATCH 3/3] jcp-energy: the one-thread burn's floor fits the energy its cores can take MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `one_thread_burning_200_ms_is_a_whole_hardware_reading` asserts that 200 ms of one thread's CPU meters between 0.2 J and 20 J. On a loaded host it read 218,593 µJ in one run and fell under the floor in another. The work was not what varied. Since bcd00518 the burn has spun until the thread's own CPU clock (`CLOCK_THREAD_CPUTIME_ID`) advanced 200 ms, so every run did the same 200 ms of CPU. What varied is the energy of that work: it follows the core tier and the clock the scheduler gives the thread, and 0.2 J was at the bottom of that range. Measured on an M5 Max (6 Super and 12 Performance cores), macOS 27.0.1, reading the process's own `rusage_info_v6` around each burn: - At the default QoS, 200 ms of one thread's CPU read 0.20-0.24 J in one quiet period, 0.50-0.61 J in another, 0.32-0.54 J with 6 to 30 busy-loop spinners, and up to 1.24 J. The effective clock (`ri_cycles` over the CPU time) was 2.5-4.0 GHz in the runs that logged it. - In two runs held on the slower cores by background QoS (`ri_user_ptime` about zero), it read 0.18 J and 0.24 J at about 2 GHz. The 0.18 J run failed the floor. Asking for user-interactive QoS, as eoc-meter's process-energy test does, does not keep the thread off the slower cores. XNU clamps user-interactive and user-initiated QoS to the default in a process with no application role, and a test binary run by `cargo test` is one. After `pthread_set_qos_class_self_np(QOS_CLASS_USER_INTERACTIVE, 0)` returned 0, the burn's CPU time was all in `ri_cpu_time_qos_legacy` (the default QoS) and none in `ri_cpu_time_qos_user_interactive`. A request for user-initiated QoS landed in the default too. Requests for utility and background QoS were not clamped: none of their CPU time was counted at the default. So the tests do not ask, and the burn helper's doc says why. The changes, all in the test module: - `burn_thread_cpu` stops at 5 s of wall time (`TESTS_BURN_WALL_CAP`) and fails the test with a message that says how much CPU the thread got, rather than spinning on unbounded. It returns the wall time the burn took, which the burn tests now log. The cap was seen to fire, with the burn held at background QoS under 18 spinners: "this thread got only 3.752959ms of the 200ms of CPU it was to burn in 5s of wall time: the host is too loaded to meter a fixed amount of CPU work". - The floor is 0.1 J, half the lowest reading above. It still means something. It meets the 0.1 J ceiling of `sleeping_200_ms_meters_under_a_tenth_of_a_joule`, so no counter that reads wall time at a fixed power passes both tests. A counter that holds fails before the floor is reached, and one that advances by a fixed step per read fails the floor (see below). The test's doc records the measured range. - `two_threads_burning_meter_more_than_one` joins its second thread, so a burn that hits the cap there fails with its own message, and logs both spans' wall times. - `a_span_that_runs_and_reaps_a_child_is_partial` had the same shape: `yes` ran for 200 ms of wall time and the test then required the child's own count to read at least 0.1 J. Under load it read 0.216 J once. The child now runs for at least 200 ms and until its own count, polled every 10 ms, reads 0.1 J. The test fails, saying so, if that takes 5 s. Tests. `cargo test -p jcp-energy` (84 lib tests and the integration test) passed 5 times in a row with 18 busy-loop spinners running, at load averages from 24 to 100. The spinners were killed by a trap, and none remained after. Per run, one thread's 200 ms of CPU, then the two-thread test's one and two threads, then the reaped child's own count: - 0.353 J (271 ms wall); 0.366 / 0.718 J; 0.340 J - 0.358 J (297 ms); 0.346 / 0.739 J; 0.334 J - 0.400 J (393 ms); 0.376 / 0.703 J; 0.324 J - 0.367 J (367 ms); 0.411 / 0.762 J; 0.334 J - 0.422 J (670 ms); 0.386 / 0.837 J; 0.316 J Clippy is clean on jcp-energy with `--tests`. The change is inside `#[cfg(test)] mod tests`, so no dependant compiles different code. Falsified, each by a temporary edit restored with git checkout: - `ri_energy_nj` read as a constant: the probe finds it Frozen, `detect()` declines it, and the test fails with "detect() did not select the per-process rung". - The count held across the measured span only, detection untouched: the span is the model's figure (3.05 J, `ModelBased`) and the test fails on its provenance. That figure is inside the bounds, so this case rests on the provenance assertion, not the floor. - The count advancing a fixed 1,000 nJ per read: the probe finds it Live, the span is 1 µJ `HwShunt`, whole, and the test fails with "200 ms of one thread's CPU metered 1 µJ". Not done here: eoc-meter's process-energy test asks for user-interactive QoS and its doc credits it with keeping the burn on the fast cores. The same clamp applies there. Co-Authored-By: Claude Opus 5.5 --- jcp/jcp-rs/crates/jcp-energy/src/lib.rs | 113 +++++++++++++++++++----- 1 file changed, 89 insertions(+), 24 deletions(-) diff --git a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs index 4fa2765a5..af3782ac8 100644 --- a/jcp/jcp-rs/crates/jcp-energy/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-energy/src/lib.rs @@ -6118,6 +6118,12 @@ mod tests { #[cfg(target_os = "macos")] const TESTS_THREAD_CPU_CLOCK: std::os::raw::c_int = 16; + /// The most wall time a test's burn of its own CPU may take. A thread that + /// gets less than 1/25 of a core for a 200 ms burn fails its test with a + /// message that says so, rather than spinning on unbounded. + #[cfg(target_os = "macos")] + const TESTS_BURN_WALL_CAP: Duration = Duration::from_secs(5); + #[cfg(target_os = "macos")] #[allow(unsafe_code)] unsafe extern "C" { @@ -6138,15 +6144,39 @@ mod tests { } /// Spin until this thread has used `cpu` more CPU time, by the tests' own - /// clock. + /// clock, and return the wall time that took. The work is fixed in CPU + /// time, so a loaded host stretches the spin but never shrinks it. + /// Panics, failing the test, if [`TESTS_BURN_WALL_CAP`] of wall time + /// passes first. + /// + /// The energy of that work is not fixed: it follows the core tier and the + /// clock the scheduler gives the thread. The thread does not ask for a + /// higher QoS, because asking changes nothing here: XNU clamps + /// user-interactive and user-initiated QoS to the default in a process + /// with no application role, as a test binary run by `cargo test` is. On + /// an M5 Max, macOS 27.0.1, a burn after + /// `pthread_set_qos_class_self_np(QOS_CLASS_USER_INTERACTIVE, 0)`, which + /// returned 0, was accounted all in the process's + /// `ri_cpu_time_qos_legacy` (the default QoS) and none in + /// `ri_cpu_time_qos_user_interactive`. A request for user-initiated QoS + /// landed in the default too; one for utility or background QoS did not. #[cfg(target_os = "macos")] - fn burn_thread_cpu(cpu: Duration) { - let start = tests_thread_cpu(); + fn burn_thread_cpu(cpu: Duration) -> Duration { + let (start, wall) = (tests_thread_cpu(), std::time::Instant::now()); let mut acc: u64 = 0; - while tests_thread_cpu().saturating_sub(start) < cpu { + loop { for _ in 0..1_000 { acc = std::hint::black_box(acc.wrapping_add(1)); } + let used = tests_thread_cpu().saturating_sub(start); + if used >= cpu { + return wall.elapsed(); + } + assert!( + wall.elapsed() < TESTS_BURN_WALL_CAP, + "this thread got only {used:?} of the {cpu:?} of CPU it was to burn in {TESTS_BURN_WALL_CAP:?} of wall \ + time: the host is too loaded to meter a fixed amount of CPU work" + ); } } @@ -6296,19 +6326,33 @@ mod tests { } /// 200 ms of one thread's CPU is a hardware reading of it: `HwShunt`, - /// whole, between 0.2 J and 20 J. A pure in-process burn in a process with + /// whole, between 0.1 J and 20 J. A pure in-process burn in a process with /// no child, before or after (by the tests' own listing), so nothing is /// left out of the figure and it claims the whole span. + /// + /// The 200 ms are of the thread's own CPU clock (see [`burn_thread_cpu`]), + /// so the work is the same however loaded the host. Its energy is not. On + /// an M5 Max, macOS 27.0.1, at the default QoS, it read from 0.20 J to + /// 1.24 J, idle to 30 busy spinners; held on the slower cores by + /// background QoS, 0.18 J. A floor of 0.2 J sat at the bottom of that + /// range and failed on it. 0.1 J is half the lowest reading. It meets the + /// 0.1 J ceiling of `sleeping_200_ms_meters_under_a_tenth_of_a_joule`, so + /// no counter that reads wall time at a fixed power passes both. A counter + /// that holds fails here before the floor: `detect()` declines it, and a + /// span over which it held is the model's figure, not `HwShunt`. A counter + /// that advances, but by a fixed step per read rather than with the work, + /// fails the floor. #[cfg(target_os = "macos")] #[test] fn one_thread_burning_200_ms_is_a_whole_hardware_reading() { in_a_fresh_process("tests::one_thread_burning_200_ms_is_a_whole_hardware_reading", || { let meter = process_meter(); assert_eq!(oracle_child_pids(), Vec::::new(), "the fresh process already has a child"); - let ((), e) = meter.measure(|| burn_thread_cpu(Duration::from_millis(200))); + let (wall, e) = meter.measure(|| burn_thread_cpu(Duration::from_millis(200))); assert_eq!(oracle_child_pids(), Vec::::new(), "a child at the end of a pure in-process burn"); eprintln!( - "process energy: 200 ms of one thread's CPU -> {} µJ ({:.3} J), {:?}, coverage {:?}", + "process energy: 200 ms of one thread's CPU, in {wall:?} of wall time -> {} µJ ({:.3} J), {:?}, \ + coverage {:?}", e.uj(), joules(e.uj()), e.provenance, @@ -6317,7 +6361,7 @@ mod tests { e.check_provenance().unwrap(); assert_eq!(e.provenance, Provenance::HwShunt, "{e:?}"); assert!(e.is_whole(), "{e:?}"); - assert!((200_000..=20_000_000).contains(&e.uj()), "200 ms of one thread's CPU metered {} µJ", e.uj()); + assert!((100_000..=20_000_000).contains(&e.uj()), "200 ms of one thread's CPU metered {} µJ", e.uj()); }); } @@ -6336,23 +6380,26 @@ mod tests { } /// Two threads burning 200 ms of CPU each meter more than one: every - /// thread of the process is in the count. + /// thread of the process is in the count. Each thread's 200 ms are of its + /// own CPU clock (see [`burn_thread_cpu`]), so neither span's work depends + /// on how loaded the host is. #[cfg(target_os = "macos")] #[test] fn two_threads_burning_meter_more_than_one() { in_a_fresh_process("tests::two_threads_burning_meter_more_than_one", || { let meter = process_meter(); let cpu = Duration::from_millis(200); - let ((), one) = meter.measure(|| burn_thread_cpu(cpu)); - let ((), two) = meter.measure(|| { + let (wall_one, one) = meter.measure(|| burn_thread_cpu(cpu)); + let (wall_two, two) = meter.measure(|| { std::thread::scope(|s| { - s.spawn(|| burn_thread_cpu(cpu)); - burn_thread_cpu(cpu); + let other = s.spawn(|| burn_thread_cpu(cpu)); + let mine = burn_thread_cpu(cpu); + mine.max(other.join().expect("the second burning thread panicked")) }) }); eprintln!( - "process energy: 200 ms of CPU on 1 thread -> {} µJ ({:.3} J), on each of 2 threads -> {} µJ ({:.3} J), \ - ratio {:.2}", + "process energy: 200 ms of CPU on 1 thread, in {wall_one:?} of wall time -> {} µJ ({:.3} J), on each \ + of 2 threads, in {wall_two:?} -> {} µJ ({:.3} J), ratio {:.2}", one.uj(), joules(one.uj()), two.uj(), @@ -6364,33 +6411,47 @@ mod tests { }); } - /// A span that runs `yes > /dev/null` for 200 ms, then kills and reaps - /// it, is a `Partial` reading. The child's work is not in the figure: the - /// span meters under 0.1 J, though the child's own count, by the tests' - /// oracle, shows it spent far more. So the figure must not claim it. By + /// A span that runs `yes > /dev/null`, then kills and reaps it, is a + /// `Partial` reading. The child's work is not in the figure: the span + /// meters under 0.1 J, though the child's own count, by the tests' oracle, + /// shows it spent at least that much. So the figure must not claim it. By /// the tests' own reads, the reaped children's CPU time rose across the /// span and no child is left at its end: the reap alone is what makes /// this span `Partial`. + /// + /// The child runs for at least 200 ms and until its own count reads + /// 0.1 J, not for a fixed wall time, so a loaded host stretches its run + /// but never leaves it too little energy to tell. It fails the test if + /// that takes [`TESTS_BURN_WALL_CAP`]. #[cfg(target_os = "macos")] #[test] fn a_span_that_runs_and_reaps_a_child_is_partial() { in_a_fresh_process("tests::a_span_that_runs_and_reaps_a_child_is_partial", || { + const ENOUGH_NJ: u64 = 100_000_000; let meter = process_meter(); let me = std::process::id(); let reaped_before = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); let mut child_nj = None; let ((), e) = meter.measure(|| { let mut child = spawn_yes(); - std::thread::sleep(Duration::from_millis(200)); - child_nj = oracle_energy_nj(child.0.id()); + let started = std::time::Instant::now(); + loop { + std::thread::sleep(Duration::from_millis(10)); + let ran = started.elapsed(); + child_nj = oracle_energy_nj(child.0.id()).map(|(nj, _)| (nj, ran)); + let enough = child_nj.is_some_and(|(nj, _)| nj >= ENOUGH_NJ); + if (enough && ran >= Duration::from_millis(200)) || ran >= TESTS_BURN_WALL_CAP { + break; + } + } child.0.kill().expect("could not kill yes"); child.0.wait().expect("could not reap yes"); }); let reaped_after = oracle_reaped_children_cpu(me).expect("the oracle cannot read this process"); let left = oracle_child_pids(); - let child_nj = child_nj.expect("the oracle could not read the child's count").0; + let (child_nj, ran) = child_nj.expect("the oracle could not read the child's count"); eprintln!( - "process energy: a span running `yes > /dev/null` for 200 ms, then reaping it -> {} µJ ({:.6} J), \ + "process energy: a span running `yes > /dev/null` for {ran:?}, then reaping it -> {} µJ ({:.6} J), \ {:?}, coverage {:?}; the child's own count {child_nj} nJ ({:.3} J); reaped children's CPU \ {reaped_before} -> {reaped_after} Mach units; children left {left:?}", e.uj(), @@ -6399,7 +6460,11 @@ mod tests { e.coverage, child_nj as f64 / 1e9 ); - assert!(child_nj >= 100_000_000, "the child spent only {child_nj} nJ, too little to tell"); + assert!( + child_nj >= ENOUGH_NJ, + "the child spent only {child_nj} nJ in {ran:?} of wall time, too little to tell: the host is too \ + loaded" + ); assert!(e.uj() < 100_000, "the span metered {} µJ: the child's work was attributed to it", e.uj()); assert!(reaped_after > reaped_before, "the reap did not raise the reaped children's CPU time"); assert!(left.is_empty(), "children left at the span's end: {left:?}"); -- 2.54.0 (Apple Git-157)