jcp-energy: meter a closure's CPU work with the per-process energy counter, which macOS 27 keeps live #122

Merged

dcharlot merged 3 commits from jcp-energy/process-energy into main 2026-10-01 06:02:25 -04:00

Conversation 0 Commits 3 Files changed 3 +1280 -52

2026-09-30

Transaction Science

jcp-energy: the one-thread burn's floor fits the energy its cores can take ...

`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 <[email protected]>

22e5a6ad9f

• View at this point in history

2026-09-30 22:48:07 -04:00

Transaction Science

jcp-energy: a per-process span a child process worked in is partial ...

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 <[email protected]>

830fc085f2

• View at this point in history

2026-09-30 22:05:52 -04:00

Transaction Science

jcp-energy: meter this process's own CPU energy, live where IOReport is not ...

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 <[email protected]>

bcd00518a7

• View at this point in history

2026-09-30 22:05:52 -04:00