diff --git a/jcp/SPEC.md b/jcp/SPEC.md index f8684758a..85d1022f8 100644 --- a/jcp/SPEC.md +++ b/jcp/SPEC.md @@ -615,13 +615,49 @@ Recommended ladder, best first: own draw. A span over which it did not advance is metered by a lower rung. 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 + threads → `HwShunt`, `Whole` for work that runs on those threads and + hands nothing to another process (below). 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. 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 + child's energy is not in the count. Nor is work those threads hand to + another process: a system service that handles a message of theirs + (on macOS the kernel bills that service's CPU work to the process + beside the count, `ri_billed_energy`, never in it), a server reached + over a socket or a pipe. So a span over work that calls a system + service, or any other process, is not `Whole` for that work, and the + reference meter, which does not read the billed count on this rung, + does not detect it: an implementation SHOULD meter such work on another + rung, or grade its figure `Partial`. A span over a computation the + implementation knows runs on the metering thread alone and exchanges + nothing with any other process (the reference gateway's flow scan, a + pure computation over the process's own memory) is unaffected, and is + not made `Partial` by a child the process happens to have either: no + part of that work can be in the child or in a service. The count is + folded only when a thread leaves a core, and a process's read of its + own count does not fold the thread reading (its CPU time is current at + the read, its energy is not: a thread that burned 1 ms between two + reads of its own process read no advance in most tries, and up to a + quantum's worth from before the first read in others), so at each end + of a span the reading thread SHOULD leave its core just before it + reads, and an implementation that relies on that MUST check that it + did. A sleep does not always take a thread + off its core: when the sleep's timer fires before the thread has + blocked, the thread goes on without leaving (after 1 µs sleeps at load + averages of 85 to 118, 4 of about 44,000 showed no context switch, and + the read after missed the whole burn before it). The reference meter + sleeps 50 µs, then longer up to 5 ms, until the thread's own energy + count (`proc_pidinfo`'s `PROC_PIDTHREADCOUNTS`) moved across a sleep, + which it does only when the thread is folded; a process-wide + context-switch count is no such check, since another thread's switch + moves it. A read whose thread was not seen to leave its core is no + reading of that end, and the span is metered by a lower rung. Work on + the thread that opens and closes the span is then read whole, and the + figure also holds what every other thread of the process spent inside + it: over that work's CPU energy on those threads, not under it. + 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. @@ -651,7 +687,7 @@ Recommended ladder, best first: the span, not that all of it was spent on the span's own work. The figure is `Partial` (§5.2) when the meter sees any of these over the span; each is energy of the tree's over the span that the figure does - not hold, but for the one noted: + not hold, but for the ones noted: - a descendant reaped inside the span (the reaper's reaped-descendant CPU time moved; a reaped process's energy is in no counter), unless it had already exited at the start, its energy then all spent before @@ -685,16 +721,79 @@ Recommended ladder, best first: client's recorded time is per live command queue and a queue created and released inside the span takes its time with it; or GPU time that could not be read; - - a member that has held Neural Engine model memory in-process. + - a member that has held Neural Engine model memory in-process; + - work another process did on a member's behalf and the platform billed + to it (below): the figure holds the bill, which is short of the + span's delegated work by what no bill carries, and can hold a bill + for work done before the span that was credited inside it — so, like + a member still running at the start, it can make the figure exceed + the tree's energy over the span (the reference gateway: `delegated`); + - a member credited inside the span with service to other processes + (below): the credit is subtracted, and need not be the span's own + service — a credit for service done before the span makes the figure + short, service done in the span and credited after its stop leaves + the figure over — so it too can make the figure exceed the tree's + energy over the span (the reference gateway: `serviced`); + - a member credited inside the span with more service to other + processes than it spent and was billed (below): the figure may + subtract energy spent before the span. + + **Delegated work.** Where the platform bills the CPU work one process + does on another's behalf to the other, the figure SHOULD count it. On + macOS the kernel's bank ledgers do: a service's thread that adopts a + client's voucher while it handles the client's message (an XPC or other + mach message carries one) is charged, at its next voucher change, with + the CPU time and energy it spent, which raise the client's + `ri_billed_energy` and `ri_billed_system_time` (not part of its + `ri_energy_nj`) and the servicer's `ri_serviced_energy` and + `ri_serviced_system_time` (part of its own), readable for any process of + the same user without privilege. Each member's count is then its own + energy, less its serviced energy, plus its billed energy, and the figure + the members' advances of it, summed signed: work a member did for other + processes is theirs, work others did for it is the tree's, and work one + member did for another is counted once, through the payer. A servicing + thread is credited at its next voucher change, not as it works, so a + credit inside a span need not be that span's service: a span over which + any member's serviced energy or serviced CPU time moved is `Partial`, + whether or not its net stayed above zero. A member whose net advance is + below zero — a credit for service done before the span landing inside + it — is counted as it is, never wrapped, and is a gap too. The bill over + a span is not the span's delegated work, and errs both ways. Over: a + bill is credited at the servicing thread's next voucher change, so a + bill for work done before the span — an earlier call's late credit — + lands in whichever span is open, and is added to its figure. Short: it + carries none of the GPU or Neural Engine energy spent in the service + (one on-device inference request on the reference hardware drew 6.73 J + on the Neural Engine and billed 1.79 J); none of the service's work on + threads that never adopt the voucher, or before they do (starting a + per-client service process); no credit that lands after the span (a + servicing thread is credited at its next voucher change, which can be + a second and more after the reply); nothing billed to another + originator (a scheduling daemon's background work, a policy daemon's + scan of the client's binary); and nothing sent over a socket or a + pipe, which carries no voucher, or off the host. So a span over which + any member's billed energy or billed CPU time moved is `Partial`, its + figure holding the bill, and an implementation that names the gaps + beside the figure SHOULD name it (the reference gateway: `delegated`). + Such a span's stop SHOULD wait, briefly and within a bound, for the + billed counts to hold, so that a credit landing just after the reply + falls in its own span rather than the next (the reference meter reads + them every 5 ms until two reads agree, at most 20 times). The billed + counts take no part in deciding that a member is settled: another + process's thread credits them, and the member's run state says nothing + of when. An implementation MUST NOT grade a tree's figure `Whole` on an empty list alone. `Whole` further requires the operator's declaration that the process hands no work to a process outside its tree — a system service, on-device model inference run by a system daemon, a database server, a - remote API — because a reader of the tree cannot see such delegation: + remote API — because a reader of the tree cannot see all such + delegation: billing shows only work done on a voucher, and the rest of that work's energy is charged to the process that does it, which may be another user's and unreadable. Without the declaration the figure is - `Partial`. A span whose root is gone or unreadable at either end, or + `Partial`. The declaration does not outweigh evidence: a span with a + bill (above) is `Partial` under it, the bill showing work done outside + the tree. A span whose root is gone or unreadable at either end, or whose figure did not advance, is metered by a lower rung. The reference gateway (`jcp-gateway`) meters each gated call this way where the upstream server is a local process it can read. diff --git a/jcp/jcp-rs/crates/jcp-gateway/src/bin/jcp_gateway.rs b/jcp/jcp-rs/crates/jcp-gateway/src/bin/jcp_gateway.rs index 31b0aed53..71d9aee2c 100644 --- a/jcp/jcp-rs/crates/jcp-gateway/src/bin/jcp_gateway.rs +++ b/jcp/jcp-rs/crates/jcp-gateway/src/bin/jcp_gateway.rs @@ -24,9 +24,13 @@ //! otherwise; the startup line says which. `--upstream-self-contained` is //! the operator's declaration that the server hands no work to a process //! outside its tree (no system service, no model inference in a system -//! daemon, no database server, no remote API): the meter cannot see that, -//! and without the declaration every reading of the tree is sealed -//! `Partial`. +//! daemon, no database server, no remote API): the meter sees only part of +//! that — the CPU work a system service was billed to the server for, which +//! it counts — and without the declaration every reading of the tree is +//! sealed `Partial`. With it, a call over which such a bill arrived is +//! sealed `Partial` all the same (`delegated`): the bill is evidence the +//! declaration did not hold, for that call or for an earlier one whose bill +//! landed late, in this call's span. use ed25519_dalek::SigningKey; use jcp_gateway::{is_response, message_id, Gateway, Relayed, Upstream}; diff --git a/jcp/jcp-rs/crates/jcp-gateway/src/lib.rs b/jcp/jcp-rs/crates/jcp-gateway/src/lib.rs index 36308c1dd..216ea77f2 100644 --- a/jcp/jcp-rs/crates/jcp-gateway/src/lib.rs +++ b/jcp/jcp-rs/crates/jcp-gateway/src/lib.rs @@ -17,16 +17,28 @@ //! ([`Upstream::pid`]) and the host's kernel counts each process's CPU //! energy live ([`sandbox_meter::TreeMeter`]: macOS), the figure is the //! CPU energy of that server and its descendants over the call, the -//! work's own process rather than the machine — `HwShunt`. It is -//! `Whole` only when the meter saw nothing missing (no descendant -//! reaped or exited in the span, no GPU client held, no in-process -//! Neural Engine memory, every member read and gone quiet at both -//! ends) AND the operator has declared that the server hands no work to -//! a process outside its tree ([`Gateway::declare_upstream_self_contained`]), -//! which no reader of the tree can see. Otherwise it is `Partial`: its -//! remainder is unmeasured, not zero — and where a member was still +//! work's own process rather than the machine, plus the CPU energy the +//! kernel billed them for work system services did on their behalf — +//! `HwShunt`. It is `Whole` only when the meter saw nothing missing (no +//! descendant reaped or exited in the span, no GPU client held, no +//! in-process Neural Engine memory, no work billed to the tree by a +//! service, every member read and gone quiet at both ends) AND the +//! operator has declared that the server hands no work to a process +//! outside its tree ([`Gateway::declare_upstream_self_contained`]), +//! which no reader of the tree can fully see. Work billed to the tree +//! is evidence against that declaration, and outweighs it: such a call +//! is `Partial` (`delegated`) however the server is declared, its +//! figure holding the billed CPU energy — short of the delegated work +//! by what no bill carries, and over it by any bill for work before +//! the call that landed late, in this call. Otherwise it is `Partial`: +//! its remainder is unmeasured, not zero — and where a member was still //! running at the start (`unsettled-at-start`), it may also hold up to a -//! scheduler quantum per running thread from just before the call. +//! scheduler quantum per running thread from just before the call; +//! where a bill landed (`delegated`), a late bill for an earlier call's +//! work; and where a member was credited with service to other processes +//! (`serviced`), subtracted from the figure, the credit may be for work +//! before the call (the figure short) or leave work in the call that is +//! credited after it (the figure over). //! Whole or not, it is the tree's energy over the call, whatever the //! tree spent it on: work the server deferred past an earlier reply is //! read in the call open when it runs. @@ -173,8 +185,8 @@ pub enum Relayed { /// same two labels beside the figure, and where it was read /// (`energy_domain`). A `Partial` figure is debited all the same, as what /// was read over the call (short of the call's energy, or, with - /// `unsettled-at-start` among its reasons, possibly a little over it), - /// and is never presented as its total. + /// `unsettled-at-start`, `delegated` or `serviced` among its reasons, + /// possibly over it), and is never presented as its total. Allowed { response: String, cost_uj: u64, budget_remaining_uj: u64 }, /// A `tools/call` the gateway refused; the upstream was never contacted. /// `response` is a JSON-RPC error to hand back to the client, or empty @@ -257,12 +269,32 @@ pub struct Gateway { /// separate process, and this process's own energy counter does not cover /// a child process — over a tool call it would read the gateway waiting. /// - /// It meters the flow scan, and every gated call the upstream tree meter - /// gives no reading of: an upstream with no process to read, a host - /// whose per-process count is not live (every host but macOS), a root - /// this process may not read, or a span whose tree reading failed. On - /// Linux it is the only meter. + /// It meters every gated call the upstream tree meter gives no reading + /// of: an upstream with no process to read, a host whose per-process + /// count is not live (every host but macOS), a root this process may not + /// read, or a span whose tree reading failed. On Linux it is the only + /// meter of a call. meter: PowerMeter, + /// `PowerMeter::detect_in_process()`: the flow scan's meter (Phase 0 of + /// [`Gateway::relay`]). The scan is a computation over this process's + /// own memory, run on the thread that opens and closes its span: it + /// starts no process, exchanges nothing with any and calls no system + /// service (whose work the kernel would bill to this process beside the + /// count, not in it, and the in-process meter would not see), so where + /// this process's CPU energy count is live (macOS) the span reads the scan's + /// own energy, `HwShunt`, rather than an estimate of the machine's. The + /// meter takes the reading thread off its core before each read and + /// reads only once it has seen the thread folded, so the scan's thread + /// is read whole; in a multithreaded host process (the stdio binary + /// relays on threads of its own) the span also counts what every other + /// thread of the process spent in it — an over-count of the scan's + /// energy, not an under-count, as SPEC §5.1's per-process rung says of a + /// span over this process's threads. A span whose reading thread was not + /// seen to fold, or over which the count did not advance, is the meter's + /// estimate, sealed `Estimator`, never a short or zero figure sealed as + /// measured. Where the count is not live, and off macOS, this is the + /// machine-wide meter, as `meter` is. + scan_meter: PowerMeter, /// The upstream server's process-tree meter: the pid it was built for, /// and the meter, `None` where [`TreeMeter::for_process`] gives none. /// Built on the first gated call (or [`Gateway::call_meter`]) for the pid @@ -339,6 +371,7 @@ impl Gateway { tool_schemas: BTreeMap::new(), caller: did, meter: PowerMeter::detect(), + scan_meter: PowerMeter::detect_in_process(), upstream: None, upstream_self_contained: false, upstream_settle: sandbox_meter::probe::SETTLE_BOUND, @@ -394,10 +427,11 @@ impl Gateway { } /// Whether the MACHINE-WIDE meter has a hardware energy source (vs. the - /// estimator alone). It meters the flow scan, and a gated call only where - /// the upstream server's process tree gives no reading, so this says - /// nothing about a call metered on that tree: [`call_meter`](Self::call_meter) - /// says which meter reads a call. And it says what the meter can read, + /// estimator alone). It meters a gated call only where the upstream + /// server's process tree gives no reading, so this says nothing about a + /// call metered on that tree ([`call_meter`](Self::call_meter) says which + /// meter reads a call), nor about the flow scan, which is metered on this + /// process's own threads. And it says what the meter can read, /// not what a call did: a span whose CPU counter held is estimated even /// on a hardware meter, and each call's receipt carries its own span's /// provenance. @@ -410,19 +444,37 @@ impl Gateway { /// over XPC, no model inference in a system daemon, no database server, /// no remote API. Off by default. /// - /// The tree meter cannot see delegation. Work a server hands to another - /// process is charged to that process, and a process of another user is - /// not even readable here: on-device model inference run by a system - /// daemon drew about 1 W of Neural Engine power (M5 Max, macOS 27.0.1, - /// `sudo powermetrics`) while its client showed no Neural Engine - /// footprint and its own CPU count advanced only by its own share, tens - /// of millijoules per request — a plausible, nonzero figure with nothing - /// in it to show the rest. A reading with nothing seen missing therefore - /// says only that nothing was missing inside the tree, and only the + /// The tree meter sees delegation only in part. Where a system service + /// does work for the server on a message that carries the server's + /// voucher (XPC, and other mach messages), the kernel bills that work's + /// CPU time and energy to the server, and the tree meter reads the bill: + /// it adds it to the figure and lists it as a gap + /// ([`TreeGap::Delegated`]). But the bill over a call is not the call's + /// delegated work: no ledger carries a service's GPU or Neural Engine + /// energy (on-device model inference: 6.73 J on the Neural Engine, + /// 1.79 J billed, for one long request on an M5 Max, macOS 27.0.1), nor + /// a service's work on threads that never adopt the voucher, nor credits + /// that land after the call — and a credit lands when the servicing + /// thread next changes voucher, so a bill for an earlier call's work can + /// land in this one. And work handed over a socket or a pipe (a database + /// server), work billed to another originator, and a remote API leave + /// no bill at all. + /// A reading with nothing seen missing therefore says only that nothing + /// was missing inside the tree and that no bill arrived, and only the /// operator, who knows what the server is, can say there is nothing - /// outside it. With this declaration such a reading is sealed - /// `Whole`; without it every tree reading is sealed `Partial`, and the - /// response's `_meta` says `not-declared-self-contained`. + /// outside it. + /// + /// With this declaration such a reading is sealed `Whole`; without it + /// every tree reading is sealed `Partial`, and the response's `_meta` + /// says `not-declared-self-contained`. Evidence outweighs the + /// declaration: a call over which the server was billed for delegated + /// work is sealed `Partial` (`delegated`) even when declared — the + /// declaration was wrong for that call (or an earlier one, whose bill + /// landed late), or covered work the bill shows was done elsewhere, and + /// the figure, which holds the bill, is short of what the bill does not + /// carry, or over by a late bill for work before the call. The + /// declaration still gates `Whole` + /// where no bill arrived, because the bill misses the delegation above. pub fn declare_upstream_self_contained(&mut self) { self.upstream_self_contained = true; } @@ -544,22 +596,26 @@ impl Gateway { // Phase 0: fold the argument's provenance. The scan finds any verbatim // carry from a tool result admitted earlier this session; the monitor's own // energy for this is metered and sealed separately, never as tool cost. + // It is metered on this process's own threads (`scan_meter`): the + // scan runs here, on this thread, and touches no other process. let declared = declared_witness_ids(¶ms); let anchor = self.log.head(); let mode = self.mode; let (witness, eval) = { let flow = &mut self.flow; let ((_id, _label, witness), m) = - self.meter.measure(|| flow.label_payload(&args_bytes, &declared, mode, anchor)); + self.scan_meter.measure(|| flow.label_payload(&args_bytes, &declared, mode, anchor)); (witness, m) }; let facts = FlowFacts { label: witness.label.clone(), witness_id: witness.id(), eval_uj: eval.total_uj(), - // The span's own provenance: over a scan this short the CPU - // counter can hold, and the span is then an estimate even on a - // hardware meter. + // The span's own provenance: a count that did not advance over + // the scan is the meter's estimate, never a measured zero. The + // flow block has no coverage field, and needs none here: the + // scan's work is all on this process's threads, which the + // in-process count reads whole (over by other threads' work). eval_prov: span_provenance(&eval), }; let seal = FlowSeal { facts: Some(facts.clone()), ceiling: ceiling_digest(&grant) }; @@ -1183,16 +1239,22 @@ impl Metered { } } -/// A [`TreeGap`]'s kind, as `energy_partial_because` names it. The match has -/// no wildcard, so a kind of gap the meter adds cannot reach the wire -/// unnamed: this stops compiling instead. +/// A [`TreeGap`]'s kind, as `energy_partial_because` names it. Every kind +/// has a name of its own, and the match has no catch-all arm: a kind the +/// meter gains later does not compile here until it is given a name, so no +/// gap reaches the wire under a name that does not say what it is. /// /// A member still running at an end is named by its end, because the two /// err in opposite directions: at the stop its reading lacks what it spent /// since its last fold, so the figure is short; at the START its reading is /// short by as much, so the figure may hold up to a quantum per running -/// thread of energy spent BEFORE the call — the one kind by which a -/// `Partial` figure can exceed the call's energy rather than fall short. +/// thread of energy spent BEFORE the call. That, `delegated` — work a +/// service did for the tree, billed to it and added, where a bill for work +/// before the call can land in it — and `serviced` — service to other +/// processes credited in the call, subtracted, which need not be the +/// call's own service (a credit for work before it: short; work in it +/// credited after: over) — are the kinds by which a `Partial` figure can +/// exceed the call's energy rather than fall short. fn gap_kind(gap: &TreeGap) -> &'static str { match gap { TreeGap::Unreadable { .. } => "unreadable", @@ -1208,6 +1270,15 @@ fn gap_kind(gap: &TreeGap) -> &'static str { TreeGap::Gpu { .. } => "gpu", TreeGap::GpuUnknown { .. } => "gpu-unknown", TreeGap::NeuralEngine { .. } => "neural-engine", + // Work a system service did for the tree, billed to it: in the + // figure, which is short of what no bill carries and may hold a + // late bill for work before the call. + TreeGap::Delegated { .. } => "delegated", + // Work the tree did for other processes, credited to it and + // subtracted: the credit lands late, so the figure may be off + // either way by it. + TreeGap::Serviced { .. } => "serviced", + TreeGap::ServicedBeyondSpent { .. } => "serviced-beyond-spent", } } @@ -1220,8 +1291,14 @@ fn gap_kind(gap: &TreeGap) -> &'static str { /// - any other reading — a gap seen, or no declaration: `HwShunt`, /// `Partial`. Its remainder is unmeasured, not zero (and with a member /// still running at the start, `unsettled-at-start`, it may hold a little -/// from before the call: it is then no lower bound), and it is debited -/// all the same, as every allowed call's figure is (SPEC §5); +/// from before the call, and with `delegated` or `serviced` it may be +/// over or short by a bill or a service credit that is not the call's +/// own: it is then no lower bound), and it is debited all the same, as +/// every allowed call's figure is (SPEC §5). A reading with work billed +/// to the tree (`delegated`) is one of these, however the server is +/// declared: the figure holds the bill, and is short of the delegated +/// work the bill does not carry, or over by a late bill for work before +/// the call; /// - no reading — no tree meter, or the span's [`TreeError`] (the root gone /// or unreadable, or the tree's count not advanced): the machine-wide /// span, exactly as [`energy_of`] grades it; @@ -1981,6 +2058,7 @@ mod tests { fn tree_shapes() -> Vec<(Option>, bool, Option<(&'static str, Option<&'static str>)>, &'static str, Vec<&'static str>)> { let reaped = |pid| TreeGap::ReapedDescendant { pid, cpu: Duration::from_micros(800) }; let gaps = vec![reaped(4242), TreeGap::Gpu { ns: 12_000 }, reaped(4243), TreeGap::Unsettled { pid: 4243, end: SpanEnd::Stop }]; + let delegated = TreeGap::Delegated { billed_nj: 1_392_936, billed_cpu: Duration::from_micros(2_857) }; let tree = "upstream-process-tree"; vec![ // Nothing seen missing, and the operator declared the server @@ -1999,6 +2077,34 @@ mod tests { tree, vec!["reaped-descendant", "gpu", "unsettled-at-stop", NOT_DECLARED_SELF_CONTAINED], ), + // Work a service did for the server, billed to it: the evidence + // outweighs the declaration, and the figure (which holds the + // bill) is partial however the server is declared. + (Some(Ok(reading(2_701_397, vec![delegated.clone()]))), true, Some(("HwShunt", Some("Partial"))), tree, vec!["delegated"]), + ( + Some(Ok(reading(2_701_397, vec![delegated]))), + false, + Some(("HwShunt", Some("Partial"))), + tree, + vec!["delegated", NOT_DECLARED_SELF_CONTAINED], + ), + // Service to other processes credited in the call: subtracted, + // and partial however the server is declared, the credit not + // known to be the call's own. + ( + Some(Ok(reading(6_000, vec![TreeGap::Serviced { serviced_nj: 4_000, serviced_cpu: Duration::from_micros(3) }]))), + true, + Some(("HwShunt", Some("Partial"))), + tree, + vec!["serviced"], + ), + ( + Some(Ok(reading(4_000, vec![TreeGap::ServicedBeyondSpent { pid: 4243, excess_nj: 800 }]))), + true, + Some(("HwShunt", Some("Partial"))), + tree, + vec!["serviced-beyond-spent"], + ), // No reading: the machine-wide span, as it would be with no tree. (Some(Err(TreeError::NotAdvanced { gaps: vec![TreeGap::Gone { pid: 9 }] })), true, None, "machine", vec![]), (Some(Err(TreeError::RootGone { pid: 4242 })), true, None, "machine", vec![]), @@ -2252,7 +2358,9 @@ mod tests { } /// Each kind of gap has its own name on the wire, and none is the - /// operator's missing declaration. + /// operator's missing declaration. That every kind HAS a name is the + /// compiler's to check (`gap_kind` has no catch-all arm); that the names + /// are distinct is this list's, kept by hand. #[test] fn every_gap_kind_has_a_distinct_wire_name() { let end = SpanEnd::Start; @@ -2270,10 +2378,14 @@ mod tests { TreeGap::Gpu { ns: 1 }, TreeGap::GpuUnknown { pid: None }, TreeGap::NeuralEngine { pid: 1, bytes: 1 }, + TreeGap::Delegated { billed_nj: 1, billed_cpu: Duration::from_millis(1) }, + TreeGap::Serviced { serviced_nj: 1, serviced_cpu: Duration::from_millis(1) }, + TreeGap::ServicedBeyondSpent { pid: 1, excess_nj: 1 }, ]; let kinds: BTreeSet<&str> = all.iter().map(gap_kind).collect(); assert_eq!(kinds.len(), all.len(), "{kinds:?}"); assert!(!kinds.contains(NOT_DECLARED_SELF_CONTAINED)); + assert_eq!(gap_kind(&TreeGap::Delegated { billed_nj: 0, billed_cpu: Duration::from_nanos(24) }), "delegated"); assert_eq!(gap_kind(&TreeGap::GpuUnknown { pid: Some(3) }), "gpu-unknown"); for k in kinds { assert!(!k.is_empty() && k.chars().all(|c| c.is_ascii_lowercase() || c == '-'), "{k}"); @@ -2358,9 +2470,10 @@ mod tests { assert_eq!(payload.get("jcp_receipt").and_then(Value::as_str), Some("jcp/3")); let flow = payload.get("flow").expect("a flow block"); assert_eq!(flow.get("verdict").and_then(Value::as_str), Some("above")); - // The monitor's own energy is sealed with its own span's provenance. + // The monitor's own energy is sealed with its own span's provenance, + // read on this process's own threads where that count is live. let flow_prov = flow.get("flow_energy_provenance").and_then(Value::as_str); - if g.metering_is_hardware() { + if g.scan_meter.is_hardware() { assert!(matches!(flow_prov, Some("HwShunt" | "Estimator")), "{flow}"); } else { assert_eq!(flow_prov, Some("Estimator"), "an estimated scan sealed as a reading: {flow}"); @@ -2374,6 +2487,65 @@ mod tests { assert!(witness.edges.iter().any(|e| e.kind == jcp_flow::EdgeKind::Witnessed), "the carry is proven"); } + /// The flow scan is metered on this process's own threads: the meter is + /// `detect_in_process`'s — this process's CPU energy count where it is + /// live (macOS; asserted live on this Apple Silicon fleet), the + /// machine-wide meter where it is not — and the meter calls fall back to + /// never reads that count. Each tainted call's sealed flow block grades + /// its scan by the scan's own span: `HwShunt` with a figure above zero + /// where the count advanced over the scan, `Estimator` where it did not, + /// and never a measured zero. Where the count is live the scan's thread + /// is folded before each read, so a scan of microseconds reads as + /// itself, not as nothing: every scan here is a reading. (The figure + /// also holds whatever the test harness's other threads spent in the + /// span: the in-process count's over-count, which this does not bound.) + #[test] + fn the_flow_scan_is_metered_on_this_processs_own_threads() { + use sandbox_meter::{process_energy_status, CounterStatus}; + let steward_pub = SigningKey::from_bytes(&[7u8; 32]).verifying_key().to_bytes(); + let mut g = Gateway::new("mail", &[("read_email", 50_000_000), ("note", 50_000_000)], SigningKey::from_bytes(&[7u8; 32])); + let live = process_energy_status() == CounterStatus::Live; + let sources = g.scan_meter.sources(); + eprintln!("flow scan meter: {sources:?} (process energy {:?}); call fallback meter: {:?}", process_energy_status(), g.meter.sources()); + assert_eq!(sources == ["process-energy"], live, "{sources:?}"); + assert!(!g.meter.sources().contains(&"process-energy"), "the call fallback read this process's own count"); + #[cfg(all(target_os = "macos", target_arch = "aarch64"))] + assert!(live, "measured live on this Apple Silicon fleet (macOS 27.0.1)"); + + let mut server = ExfilServer; + let read = json!({"jsonrpc":"2.0","id":1,"method":"tools/call", + "params":{"name":"read_email","arguments":{"folder":"inbox"}}}).to_string(); + assert!(matches!(g.relay(&read, &mut server).unwrap(), Relayed::Allowed { .. })); + let mut readings = 0; + for id in 2..14 { + // Carries the untrusted read's bytes, so it is tainted and its + // receipt carries the flow block; `note` has no ceiling, so it + // is allowed. + let line = json!({"jsonrpc":"2.0","id":id,"method":"tools/call", + "params":{"name":"note","arguments":{"body":"re: EXFILTRATE-THIS-SECRET-TOKEN-abcdefghij"}}}) + .to_string(); + assert!(matches!(g.relay(&line, &mut server).unwrap(), Relayed::Allowed { .. })); + let payload = jcr1_payload(g.receipts().last().unwrap(), "did:jcp:gateway:mail", &steward_pub); + let flow = payload.get("flow").expect("a tainted call seals a flow block"); + let uj = flow.get("flow_uj").and_then(Value::as_u64).expect("flow_uj"); + let prov = flow.get("flow_energy_provenance").and_then(Value::as_str).expect("flow_energy_provenance"); + eprintln!("flow scan {id}: {uj} µJ [{prov}]"); + match prov { + "HwShunt" => { + assert!(uj > 0, "a measured zero sealed as a reading: {flow}"); + readings += 1; + } + "Estimator" => {} + other => panic!("the scan sealed as {other}: {flow}"), + } + } + if live { + assert_eq!(readings, 12, "a scan on a live count read as an estimate"); + } else if !g.scan_meter.is_hardware() { + assert_eq!(readings, 0, "no hardware source, yet a reading"); + } + } + /// Decode a verified receipt envelope to its JSON payload (test helper). fn jcr1_payload(envelope: &[u8], steward: &str, pubkey: &[u8; 32]) -> Value { let core = jcp_receipt::jcr1::verify_cose_sign1(envelope, steward, pubkey).unwrap(); diff --git a/jcp/jcp-rs/crates/jcp-gateway/tests/upstream_tree.rs b/jcp/jcp-rs/crates/jcp-gateway/tests/upstream_tree.rs index cc950cac0..fb9e577b8 100644 --- a/jcp/jcp-rs/crates/jcp-gateway/tests/upstream_tree.rs +++ b/jcp/jcp-rs/crates/jcp-gateway/tests/upstream_tree.rs @@ -7,7 +7,8 @@ //! The oracle shares no code with the meter or the gateway: the server's //! `proc_pid_rusage(pid, RUSAGE_INFO_V6)` read into a raw buffer and taken //! at the SDK's byte offsets (energy at 336, reaped-descendant CPU time at -//! 96 and 104), read before and after each relay once the server is quiet +//! 96 and 104, billed CPU time at 216, billed and serviced energy at 264 +//! and 272), read before and after each relay once the server is quiet //! on the oracle's own terms: no thread on a core or queued //! (`proc_pidinfo(PROC_PIDTASKINFO)` into a raw buffer, `pti_numrunning` at //! byte 88) at two reads 20 ms apart whose energy agrees. A server blocked @@ -79,6 +80,22 @@ fn reaped_cpu_ticks(ru: &[u64; 64]) -> u64 { ru[96 / 8] + ru[104 / 8] } +/// `ri_billed_system_time`, mach ticks: the CPU time of work other +/// processes did on the server's behalf, billed to it. +fn billed_ticks(ru: &[u64; 64]) -> u64 { + ru[216 / 8] +} + +/// `ri_billed_energy`, nJ: that work's energy. +fn billed_nj(ru: &[u64; 64]) -> u64 { + ru[264 / 8] +} + +/// `ri_serviced_energy`, nJ: the energy of work the server did for others. +fn serviced_nj(ru: &[u64; 64]) -> u64 { + ru[272 / 8] +} + /// `pti_numrunning` of `pid`: `proc_pidinfo(pid, PROC_PIDTASKINFO = 4)` into /// a raw 96-byte buffer, the int32 at byte 88. fn oracle_running(pid: i32) -> Option { @@ -194,6 +211,12 @@ fn burn(id: i64, n: u64) -> String { json!({"jsonrpc":"2.0","id":id,"method":"tools/call","params":{"name":"burn","arguments":{"n":n}}}).to_string() } +/// A `burn` call that also asks the server to hand `k` lookups to a system +/// service (the delegating server below; others ignore `k`). +fn burn_delegating(id: i64, n: u64, k: u64) -> String { + json!({"jsonrpc":"2.0","id":id,"method":"tools/call","params":{"name":"burn","arguments":{"n":n,"k":k}}}).to_string() +} + /// What one allowed call came back as. struct Call { cost_uj: u64, @@ -204,7 +227,13 @@ struct Call { } fn relay(g: &mut Gateway, up: &mut Server, id: i64, n: u64) -> Call { - let Relayed::Allowed { response, cost_uj, .. } = g.relay(&burn(id, n), up).expect("relay") else { + relay_line(g, up, id, n, &burn(id, n)) +} + +/// [`relay`] for a request line of the caller's: its id is `id`, and the +/// server answers it `burned `. +fn relay_line(g: &mut Gateway, up: &mut Server, id: i64, n: u64, line: &str) -> Call { + let Relayed::Allowed { response, cost_uj, .. } = g.relay(line, up).expect("relay") else { panic!("the call was not allowed") }; let pubkey = steward_sk().verifying_key().to_bytes(); @@ -496,3 +525,147 @@ fn an_upstream_naming_a_process_this_one_cannot_read_is_metered_machine_wide() { } the_log_verifies(&g); } + +/// A server for the delegated-work test, speaking the tests' JSON-RPC, built +/// from this source when the test first runs: each request burns its +/// `arguments.n` loop, then looks up `arguments.k` account names no account +/// has (`getpwnam`). A system directory service does each lookup, on a +/// message that carries this process's voucher, so the kernel bills the +/// service's CPU work for it to this process. When it looked any up, it +/// then waits — up to 5 s, in 1 ms sleeps — for its own billed counts to +/// move before it replies `burned `: a servicing thread is credited when +/// it next changes voucher, which can be after the reply, and the test is +/// of how a bill that landed in the call is sealed, not of when the kernel +/// lands it. One process, no children, no GPU client. +const DELEGATING_SERVER: &str = r##"#include +#include +#include +#include +#include +#include +#include +static long field(const char *line, const char *key) { + const char *p = strstr(line, key); + return p ? strtol(p + strlen(key), NULL, 10) : 0; +} +static void billed(unsigned long long *nj, unsigned long long *ticks) { + struct rusage_info_v6 r; + memset(&r, 0, sizeof r); + proc_pid_rusage(getpid(), RUSAGE_INFO_V6, (rusage_info_t *)&r); + *nj = r.ri_billed_energy; + *ticks = r.ri_billed_system_time; +} +int main(void) { + char line[4096]; + unsigned long seq = 0; + while (fgets(line, sizeof line, stdin)) { + long rid = field(line, "\"id\":"), n = field(line, "\"n\":"), k = field(line, "\"k\":"); + volatile unsigned long long x = 1; + for (long i = 0; i < n; i++) x = x * 6364136223846793005ULL + 1; + if (k > 0) { + unsigned long long nj0, t0, nj1, t1; + billed(&nj0, &t0); + for (long i = 0; i < k; i++) { + char name[96]; + snprintf(name, sizeof name, "no-such-account-%d-%lu", (int)getpid(), seq++); + (void)getpwnam(name); + } + for (int waited = 0; waited < 5000; waited++) { + billed(&nj1, &t1); + if (nj1 > nj0 || t1 > t0) break; + usleep(1000); + } + } + printf("{\"jsonrpc\":\"2.0\",\"id\":%ld,\"result\":{\"content\":[{\"type\":\"text\",\"text\":\"burned %ld\"}]}}\n", rid, n); + fflush(stdout); + } + return 0; +} +"##; + +/// The server's rusage once its billed counts have held for 300 ms: +/// whatever was billed for its start, which can land late, has landed. +/// Panics after 20 s. +fn billed_quiet(pid: i32) { + let deadline = Instant::now() + Duration::from_secs(20); + loop { + let a = oracle_rusage(pid).expect("oracle read"); + std::thread::sleep(Duration::from_millis(300)); + let b = oracle_rusage(pid).expect("oracle read"); + if (billed_nj(&a), billed_ticks(&a)) == (billed_nj(&b), billed_ticks(&b)) { + return; + } + assert!(Instant::now() < deadline, "the oracle never saw {pid}'s billed counts hold"); + } +} + +/// A server whose operator declared it self-contained, and whose calls hand +/// work to a system service, is sealed `Partial` with `delegated` among the +/// reasons: the kernel billed the service's CPU work to it, which is +/// evidence the declaration does not hold for that call, and the evidence +/// wins. Its figure holds the bill: at least the oracle's own advance less +/// what it serviced plus what it saw billed (the oracle reads inside the +/// call's span, so a bill landing late is in the gateway's figure and maybe +/// not the oracle's), rounded up to the µJ, and more than the server's own +/// advance alone. The same server's calls that delegate nothing come first +/// (once anything billed for its start has landed), as the control: whole, +/// and exact to the µJ against the oracle. +#[test] +fn a_declared_server_whose_calls_delegate_is_sealed_partial_for_the_delegation() { + let _one = alone(); + let dir = std::path::Path::new(env!("CARGO_TARGET_TMPDIR")); + let source = dir.join("upstream_tree_delegating_server.c"); + let binary = dir.join(format!("upstream_tree_delegating_server-{}", std::process::id())); + std::fs::write(&source, DELEGATING_SERVER).expect("write the delegating server's source"); + let out = Command::new("/usr/bin/cc").args(["-O2", "-o"]).arg(&binary).arg(&source).output().expect("run the C compiler"); + assert!(out.status.success(), "the delegating server did not build:\n{}", String::from_utf8_lossy(&out.stderr)); + let mut s = Server::spawn(binary.to_str().unwrap(), &[]); + let pid = s.pid(); + let mut g = gateway(true); + assert_eq!(g.call_meter(&s), CallMeter::UpstreamTree { pid: pid as u32 }); + // The first call starts the server's work; its start's bills land after. + let _ = relay(&mut g, &mut s, 0, 0); + billed_quiet(pid); + for rep in 1..4 { + let before = quiet(pid); + let c = relay(&mut g, &mut s, rep, 150_000); + let after = quiet(pid); + let own = energy_nj(&after) - energy_nj(&before); + eprintln!( + "upstream tree: declared delegating server, control rep {rep}: {} µJ [{}], oracle own {own} nJ, billed {} nJ, _meta {}", + c.cost_uj, + grade(&c), + billed_nj(&after) - billed_nj(&before), + c.meta + ); + assert_eq!((billed_nj(&after), billed_ticks(&after)), (billed_nj(&before), billed_ticks(&before)), "setup: the control billed nothing"); + assert_eq!(c.sealed["energy_provenance"].as_str(), Some("HwShunt"), "{}", c.sealed); + assert!(c.sealed.get("energy_coverage").is_none(), "the control is whole: {}", c.sealed); + assert!(c.meta.get("energy_partial_because").is_none(), "{}", c.meta); + assert_eq!(c.cost_uj, own.div_ceil(1_000), "the control against the oracle's advance, to the µJ"); + } + for rep in 4..8 { + let before = quiet(pid); + let c = relay_line(&mut g, &mut s, rep, 20_000, &burn_delegating(rep, 20_000, 3)); + let after = quiet(pid); + let own = i128::from(energy_nj(&after) - energy_nj(&before)); + let serviced = i128::from(serviced_nj(&after) - serviced_nj(&before)); + let billed = billed_nj(&after) - billed_nj(&before); + let billed_cpu = billed_ticks(&after) - billed_ticks(&before); + eprintln!( + "upstream tree: declared delegating server, delegating rep {rep}: {} µJ [{}], oracle own {own} nJ, serviced {serviced} nJ, billed {billed} nJ / {billed_cpu} ticks, _meta {}", + c.cost_uj, + grade(&c), + c.meta + ); + assert!(billed > 0 || billed_cpu > 0, "setup: the oracle saw no work billed to the server"); + assert_eq!(c.sealed["energy_provenance"].as_str(), Some("HwShunt"), "{}", c.sealed); + assert_eq!(c.sealed["energy_coverage"].as_str(), Some("Partial"), "a delegating call sealed whole under the declaration: {}", c.sealed); + assert_eq!(c.meta["energy_domain"].as_str(), Some("upstream-process-tree"), "{}", c.meta); + assert_eq!(c.meta["energy_partial_because"], json!(["delegated"]), "{}", c.meta); + let floor = u64::try_from(own - serviced + i128::from(billed)).expect("a positive oracle figure"); + assert!(c.cost_uj >= floor.div_ceil(1_000), "the figure ({} µJ) is under the oracle's own − serviced + billed ({floor} nJ)", c.cost_uj); + assert!(billed == 0 || i128::from(c.cost_uj) * 1_000 > own - serviced, "the bill was not added to the server's own figure"); + } + the_log_verifies(&g); +} diff --git a/sandbox/README.md b/sandbox/README.md index 7edcd240a..68c640209 100644 --- a/sandbox/README.md +++ b/sandbox/README.md @@ -6,7 +6,7 @@ Sandbox is the **isolated-execution substrate** of the Transaction Science open Every other sandbox in the field isolates a **CPU process** — a container, a microVM, a Linux process pinned to a core. The accelerator, where present, is an opaque passthrough that nobody meters and nobody attests. But agentic and AI work does not run on a CPU. It runs across a **fabric** — CPU, GPU, NPU, TPU, photonic, quantum. So in this standard the unit of isolation is not a process; it is a **heterogeneous unit of work**, and the accelerator is a first-class citizen of the isolation boundary: a capability you grant, a resource you meter in joules, and a line item you attest. -A Sandbox run carries exactly four guarantees: **isolation** (the unit runs at the lowest tier of an eight-rung ladder, S0–S7, that satisfies its needs, and cannot reach past it), **capability** (every resource the unit touches — each device class included — was explicitly granted; ungranted access is denied), **metering** (the run emits a signed energy receipt with per-device-class joule attribution and an honest provenance tag on every reading — and the reference meter reads vendor energy counters: Apple Silicon's energy model via IOReport, Intel/AMD RAPL via powercap, NVIDIA's total-energy counter via NVML. A reading is tagged `HwShunt` only while its counter is demonstrably live: each vendor counter is used only if every rail of it that the meter sums into one figure keeps advancing while the meter's probe burns CPU — in at least 5 sample intervals, at least 4 of every 5, over at least 300 ms — every IOReport CPU energy rail (the rail itself, one per die on a multi-die part), every RAPL package and every NVML GPU; and a span across which the CPU counter held is never a reading. A counter that is absent, or present but not live — frozen, or republished in lumps, as the IOReport CPU rails are on macOS 27 — yields no hardware-graded figure: the span degrades to the labeled `Estimator` (wall-clock × TDP), never a fabricated measurement, and `ioreport_status()`, `rapl_status()` and `nvml_status()` say why a host is estimated. For work on the meter's own process there is one more source, kept out of the default meter: on macOS, the CPU energy the kernel attributes to the process's own threads (`proc_pid_rusage`), read through `PowerMeter::detect_in_process()` under the same liveness rule — never for a subprocess, which it does not cover; a single-process child's own figure is read from the exited child instead. For work in another live process of this user — a server, and its descendants — `TreeMeter` reads that same count for every process of its tree over a span, each end read once no thread of the tree is on a core and confirmed by a second walk that finds the tree's processes unchanged, and lists beside the figure every way it was seen to differ from the tree's energy over the span — short of it (a descendant reaped or exited in the span, a GPU client held, in-process Neural Engine memory, a member unreadable or still running at the stop), or, for a member still running at the start, holding some from just before the span; whether the tree hands work to a process outside it is not visible to any reader, so that is for the caller's operator to declare, never the reading's to claim. Because a live counter reports the whole SoC, the meter can **attribute** it to a single process tree by CPU-time apportionment — tagged `ModelBased`, since the reading is a measurement but the split is a model), and **attestation** (a signed statement of *what image ran, at what tier, under what grants, on what hardware, for what cost*, with a deterministic-replay journal hash where one was produced). +A Sandbox run carries exactly four guarantees: **isolation** (the unit runs at the lowest tier of an eight-rung ladder, S0–S7, that satisfies its needs, and cannot reach past it), **capability** (every resource the unit touches — each device class included — was explicitly granted; ungranted access is denied), **metering** (the run emits a signed energy receipt with per-device-class joule attribution and an honest provenance tag on every reading — and the reference meter reads vendor energy counters: Apple Silicon's energy model via IOReport, Intel/AMD RAPL via powercap, NVIDIA's total-energy counter via NVML. A reading is tagged `HwShunt` only while its counter is demonstrably live: each vendor counter is used only if every rail of it that the meter sums into one figure keeps advancing while the meter's probe burns CPU — in at least 5 sample intervals, at least 4 of every 5, over at least 300 ms — every IOReport CPU energy rail (the rail itself, one per die on a multi-die part), every RAPL package and every NVML GPU; and a span across which the CPU counter held is never a reading. A counter that is absent, or present but not live — frozen, or republished in lumps, as the IOReport CPU rails are on macOS 27 — yields no hardware-graded figure: the span degrades to the labeled `Estimator` (wall-clock × TDP), never a fabricated measurement, and `ioreport_status()`, `rapl_status()` and `nvml_status()` say why a host is estimated. For work on the meter's own process there is one more source, kept out of the default meter: on macOS, the CPU energy the kernel attributes to the process's own threads (`proc_pid_rusage`), read through `PowerMeter::detect_in_process()` under the same liveness rule, the reading thread taken off its core before each read and the read taken only once the thread's own energy count shows it was folded (a process's read of itself does not fold the thread reading, so a short span would otherwise read nothing, or energy spent before it; and a sleep does not always take a thread off its core, so the fold is checked, and a read whose thread was not seen to fold leaves the span estimated) — never for a subprocess, which it does not cover, nor whole for work that calls a system service, whose share the kernel bills to the process beside that count and this meter does not read; a single-process child's own figure is read from the exited child instead, a partial figure, since a process's exit does not fold its last time on a core into its count. For work in another live process of this user — a server, and its descendants — `TreeMeter` reads that same count for every process of its tree over a span, each end read once no thread of the tree is on a core and confirmed by a second walk that finds the tree's processes unchanged, and lists beside the figure every way it was seen to differ from the tree's energy over the span — short of it (a descendant reaped or exited in the span, a GPU client held, in-process Neural Engine memory, a member unreadable or still running at the stop, work a system service did for a member), or holding energy from outside the span (a member still running at the start; a bill for a service's work done before the span that was credited inside it; a member credited with service to other processes, which is subtracted, and need not be the span's own service, so the figure may be short of the span's energy or over it). Work a service does on a member's behalf, on a message that carries the member's voucher, is billed to the member by the kernel: the figure counts that billed CPU energy, less what members did for processes outside the tree, and lists it as delegated, because the bill over a span is not the span's delegated work: it carries none of the service's GPU or Neural Engine energy, none of its work on threads that never took the voucher, no credit landing after the span (the stop waits briefly for the billed counts to hold, which catches only a credit that lands within it), and it can hold a late credit for work done before the span — so the figure can be short of the delegated work or over it. Work the tree hands outside itself with no bill — over a socket, to a remote API — is not visible to any reader, so whether there is any is for the caller's operator to declare, never the reading's to claim; and a bill seen outweighs that declaration: such a span is partial whatever the operator said. Because a live counter reports the whole SoC, the meter can **attribute** it to a single process tree by CPU-time apportionment — tagged `ModelBased`, since the reading is a measurement but the split is a model), and **attestation** (a signed statement of *what image ran, at what tier, under what grants, on what hardware, for what cost*, with a deterministic-replay journal hash where one was produced). The substrate is intentionally **ownerless**: no protocol-level token, permissive licensing on spec text and reference code, and conformance vectors so any implementer can verify canonicity without a trust relationship with the authors. A conforming host runs a unit, enforces its grants, meters its energy, and seals its attestation **without contacting any single steward's servers as a condition of operation**. Transaction Science is one steward: it publishes the spec, ships a reference implementation, and operates commercial services around the substrate — not its proprietor. diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/bin/joule_meter.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/bin/joule_meter.rs index 5d795c965..407a9d2ac 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/bin/joule_meter.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/bin/joule_meter.rs @@ -2,6 +2,12 @@ //! reading as a signed sandbox receipt. The end-to-end demo of P0: hardware //! counters → honest per-device records → JCR-1 envelope, verified. //! +//! The workload runs on this process's own threads (one per core), so it is +//! metered with [`PowerMeter::detect_in_process`]: on macOS, where this +//! process's CPU energy count is live, the figure is this process's threads' +//! CPU energy over the span — the workload's own, with no other process in +//! it — and elsewhere the machine-wide meter, as `detect` would give. +//! //! Usage: `joule-meter [seconds]` (default 2). use ed25519_dalek::SigningKey; @@ -36,7 +42,10 @@ fn main() { .and_then(|s| s.parse().ok()) .unwrap_or(2.0); - let mut meter = PowerMeter::detect(); + // The workload's threads are this process's: its own count reads them + // where it is live, and nothing else's. Where it is not (off macOS, or + // a counter that did not advance under the probe), this is `detect`. + let mut meter = PowerMeter::detect_in_process(); let ioreport = sandbox_meter::ioreport_status(); println!( "probes: {}", @@ -51,9 +60,11 @@ fn main() { } ); - // Baseline: idle span of the same length, so the workload's figure has - // context (counters are machine-wide, not process-scoped — that honesty - // matters and is printed, not hidden). + // Baseline: an idle span of the same length, so the workload's figure + // has context. On this process's own count it is this process asleep; + // on a machine-wide counter it is everything else the machine did, and + // the workload's own draw is the difference — which is printed, not + // hidden. let ((), idle) = meter.measure(|| std::thread::sleep(Duration::from_secs_f64(secs))); let ((), work) = meter.measure(|| busy_all_cores(secs)); @@ -81,7 +92,9 @@ fn main() { println!( " source: {} ({})", work.source, - if work.fully_measured() { + if work.source == "process-energy" { + "this process's own threads: the workload's CPU energy, no other process's; not the GPU, DRAM or the rest of the SoC" + } else if work.fully_measured() { "machine-wide counters; subtract idle for the workload's marginal draw" } else { "wall-clock × TDP estimate, not a reading: idle and busy differ only by duration" diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/attribute.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/attribute.rs index 39f27efd3..9c2ac90c0 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/attribute.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/attribute.rs @@ -40,6 +40,13 @@ //! into nothing, so a child that ran its work in descendants (`cargo` running //! `rustc`, `sh -c 'a; b'`) has no figure here, and descendants a child did //! not reap are never covered. It is given only for a single-process child. +//! And it is a PARTIAL reading even of that child: a process's exit does not +//! fold its threads' last time on a core into its energy count (its CPU time +//! it does), so the figure is short by up to a scheduler quantum's energy +//! per thread on a core at the exit — measured, a 2 ms burn ended by exiting +//! read 0 to 1.12 mJ per CPU-ms, under 0.05 in 11 of 40, where the same burn +//! ended by blocking read 0.81 to 1.20 in every pair (see `child_reading`) — +//! and it holds no work a system service did on the child's behalf. use std::time::Duration; @@ -70,7 +77,15 @@ pub struct Attribution { /// The direct child's own CPU energy, microjoules: what the kernel /// attributes to the child's threads (`ri_energy_nj`), read from the /// exited child before it was reaped. A per-process `HwShunt`-class - /// reading of the `Cpu` class, given only when (a) this host's per-process + /// reading of the `Cpu` class, and a PARTIAL one, a lower bound: the + /// child's exit folds its CPU time into the record and not the energy of + /// its threads' last time on a core, so the figure is short by up to a + /// scheduler quantum's energy per thread on a core at the exit (all of + /// a child that ran less than one; a few percent of one that ran for a + /// second), and work a system service did on its behalf is not in it. + /// Seal it as `Partial` where the receipt has a coverage field and, + /// where it has none, never as a hardware reading of the child's whole + /// energy. Given only when (a) this host's per-process /// energy counter is live /// ([`process_energy_status`](crate::probe::process_energy_status)), (b) /// the child reaped no descendant that used CPU time — its figure does not diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs index ff77d001b..d326d8235 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/mod.rs @@ -70,7 +70,9 @@ mod process; // member. The rule and its types are built and tested everywhere; only macOS // walks a tree. Public for its module docs: what a reading covers. pub mod tree; -pub use tree::{SpanEnd, TreeError, TreeGap, TreeMeter, TreeReading, TreeStart, SETTLE_BOUND, SETTLE_POLL}; +pub use tree::{ + SpanEnd, TreeError, TreeGap, TreeMeter, TreeReading, TreeStart, BILLED_HOLD_POLL, BILLED_HOLD_POLLS, SETTLE_BOUND, SETTLE_POLL, +}; // Every GPU client's GPU time from the I/O Registry: the GPU evidence of a // tree reading. Shares `ioreport`'s CoreFoundation bindings. #[cfg(all(target_os = "macos", target_arch = "aarch64"))] @@ -566,13 +568,37 @@ impl PowerMeter { /// else: each span is one `Cpu` record, `HwShunt`, of the energy the /// kernel attributes to this process's threads over the span — the thread /// the work ran on, and any other thread of this process that ran during - /// it (so a span is this process's figure, not one thread's). It does NOT + /// it (so a span is this process's figure, not one thread's). The kernel + /// folds a thread's energy into the count only when it leaves a core, + /// and a read of this process does not fold the thread reading, so each + /// read first takes the reading thread off its core — it sleeps, from + /// 50 µs up to 5 ms, until the thread's own energy count shows it was + /// folded, because a sleep does not always take a thread off its core — + /// and a read whose thread was not seen to fold fails, so the span is + /// estimated rather than read short. Work on the thread that opens and + /// closes the span is then read whole, and a span over it in a + /// multithreaded process is over that work's CPU energy by whatever the + /// other threads spent, not under it (each read costs the sleep and the + /// wait for a core after it, tens of microseconds on an idle host; see + /// `process`'s module docs for the measurements). It does NOT /// cover child processes: a subprocess's energy is never attributed to its /// parent, not even after it is reaped, so a span over a subprocess would /// read this process's waiting, near zero, as the subprocess's work. Use /// [`detect`](Self::detect) for subprocess work (its counters are /// machine-wide), or [`run_attributed`] for a single-process child. Nor - /// does it cover the GPU or the Neural Engine. The machine-wide probes are + /// does it cover the GPU or the Neural Engine, or work this process's + /// threads hand to another process: a system service that handles one + /// of their messages (a directory lookup, a metadata search, on-device + /// inference run by a daemon) does that work on its own threads, and the + /// kernel bills it to this process beside the count + /// (`ri_billed_energy`), not in it. This meter does not read the bill, + /// so it does not detect such work: a span over work that calls a + /// system service is short of that work by the service's share, and is + /// no whole reading of it, though its record is the same `HwShunt` one + /// — meter such work with [`detect`](Self::detect), or grade its figure + /// partial. A pure computation over this process's own memory (the + /// gateway's flow scan, this crate's `joule-meter` workload) calls no + /// service and is unaffected. The machine-wide probes are /// left out because a second CPU record would count the same work twice. /// [`Span::stop`]'s rule holds: a span over which the counter did not /// advance is estimated, never sealed as a measured zero. diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/process.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/process.rs index 7f6d3e39f..e96aa90d3 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/process.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/process.rs @@ -15,6 +15,63 @@ //! [`PowerMeter::detect_in_process`](super::PowerMeter::detect_in_process), //! for work that runs on this process's own threads. //! +//! **Folded before every read, and the fold checked.** The kernel folds a +//! thread's energy into the count only when the thread leaves a core, and a +//! process's read of ITSELF does not fold the thread that reads: its CPU +//! time is current at the read, its energy is not. Measured (M5 Max, macOS +//! 27.0.1): a thread burning 1 ms of its CPU between two reads of its own +//! process read the same energy at both in 28 and 29 of 40 tries, and up to +//! 9.4 mJ — a quantum's worth, spent mostly BEFORE the first read — in +//! others. So a span over short work read either nothing or energy from +//! before it. The probe therefore takes the reading thread off its core +//! before each read, by sleeping, and reads only once it has SEEN the +//! thread fold. A sleep alone does not always fold it: when the sleep's +//! timer fires before the thread has blocked, the thread goes on without +//! leaving its core. Measured at load averages of 85 to 138: after a 1 µs +//! sleep, 4 of about 44,000 showed no context switch and the read after +//! missed the whole burn before it, and 9 of 25,000 left the thread's own +//! energy count unmoved; after a 50 µs sleep, none of 12,000 showed no +//! switch. +//! +//! The check is the reading thread's own energy count +//! (`proc_pidinfo(PROC_PIDTHREADCOUNTS)`, below), which the kernel moves +//! only when it folds the thread: across a burn with no context switch it +//! held in 1,937 of 1,943 reads (the 6 that moved were folds without a +//! switch, at an interrupt, and are folds all the same), and it moved +//! across every sleep in which the thread switched. The probe sleeps +//! 50 µs, then 200 µs, 1 ms and 5 ms ([`FOLD_SLEEPS`]), until that count +//! moved across one, and then reads. A read whose thread did not fold +//! within them is no reading: the probe's read fails, and the span comes +//! back estimated, never a short figure graded as a reading. Not the +//! process's context-switch count (`getrusage`'s, `pti_csw`, the same +//! number): it counts every thread's switches, and with two other threads +//! of the process switching, it moved across 2 of the 12 sleeps (of +//! 25,000) after which the reading thread had not folded. After a checked +//! fold the read held the work before it: what landed in the count after +//! it, by a further sleep, was 11.5 to 12.8 µJ at the median and at most +//! 45 µJ, as much with no burn before the fold as with a 1 ms one (the +//! reads' own cost and the wake-up, not the work). The check rests on the +//! thread's count being folded as the process's is, which is what was +//! measured here; a host on which it never moves gets estimates, never +//! readings. Each read costs two reads of the thread's count (about +//! 0.3 µs each), the sleep and the wait for a core after it — tens of +//! microseconds on an idle host, up to about 2 ms at a load average of +//! 130 — and, on a read whose thread does not fold, all four sleeps +//! (6.25 ms) and their waits before it fails. +//! +//! Only the reading thread is folded: another thread of this process that +//! is on a core at a read is short by what it spent since its own last +//! fold there, so its share of a span can be off by up to a quantum at +//! each end. Work run on the thread that opens and closes the span +//! ([`PowerMeter::measure`](super::PowerMeter::measure)) is read whole; +//! every other thread that ran in the span adds what it spent, so a span +//! over work on its own thread in a busy multithreaded process is over that +//! work's CPU energy by the other threads', and not under it. Work this +//! process hands to a system service (a directory lookup, a metadata +//! search, on-device inference run by a daemon) is not in the count at all: +//! the kernel bills it to this process beside the count +//! (`ri_billed_energy`), so a span over such work is short of it. +//! //! **Used only when the counter is live** ([`process_energy_status`](super::process_energy_status)): //! the same sustained-advance rule as every other vendor counter, probed once //! per process — this process's counter advanced in at least five sample @@ -23,7 +80,8 @@ //! [`liveness`](super::liveness); this module only reads the integer. //! //! The same read, on a child that has exited but not yet been reaped, gives -//! that child's own energy: [`child_reading`] is the rule +//! that child's own energy, short of its threads' last time on a core (an +//! exit folds none of it: a partial reading): [`child_reading`] is the rule //! [`run_attributed`](super::run_attributed) applies to it. And the same read //! of any same-uid process, live or exited-unreaped, is what the //! [`TreeMeter`](super::TreeMeter) walks a process tree with @@ -34,7 +92,7 @@ use super::tree::Usage; use super::{CounterStatus, Probe, ProbeError, CPU_RAIL_LIVENESS_BUDGET}; use sandbox_schema::DeviceClass; use std::sync::atomic::{AtomicUsize, Ordering}; -use std::time::Instant; +use std::time::{Duration, Instant}; /// `RUSAGE_INFO_V6` in macOS ``. const RUSAGE_INFO_V6: libc::c_int = 6; @@ -132,6 +190,10 @@ pub(super) fn read_usage(pid: libc::pid_t) -> Result { start_abstime: info.ri_proc_start_abstime, exit_abstime: info.ri_proc_exit_abstime, neural_lifetime_max: info.ri_lifetime_max_neural_footprint, + billed_energy_nj: info.ri_billed_energy, + serviced_energy_nj: info.ri_serviced_energy, + billed_cpu: info.ri_billed_system_time, + serviced_cpu: info.ri_serviced_system_time, }) } @@ -162,10 +224,87 @@ fn real_run() -> RailWatch { ) } +/// The sleeps the reading thread takes, in turn, before [`ProcessEnergyProbe`] +/// reads its own process, until one is seen to fold it ([`fold`]): a +/// blocked thread leaves its core, and leaving folds its energy into the +/// count — but a sleep whose timer fires before the thread has blocked does +/// not take it off its core (see the module docs). Growing, so a sleep that +/// did not block is followed by one that much more surely does; 6.25 ms in +/// all on a read whose thread never folds. The liveness probe reads raw, +/// unfolded: it asks whether the count advances under a burn, which folds +/// by the quantum. +const FOLD_SLEEPS: [Duration; 4] = + [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1), Duration::from_millis(5)]; + +/// The rule for folding the reading thread: sleep each of `sleeps` in turn +/// until this thread's own energy count (`count`: production reads +/// [`this_thread_energy_nj`]) advanced across one, and say whether it did. +/// The count moves only when the kernel folds the thread, so an advance +/// across a sleep is a fold after the read before it, which follows the +/// work being read. A count that could not be read, or did not advance +/// across any sleep, is no evidence of a fold: `false`, and the caller +/// does not read. +fn fold(sleeps: &[Duration], mut count: impl FnMut() -> Option, mut sleep: impl FnMut(Duration)) -> bool { + for &d in sleeps { + let Some(before) = count() else { return false }; + sleep(d); + let Some(after) = count() else { return false }; + if after > before { + return true; + } + } + false +} + +/// `PROC_PIDTHREADCOUNTS`, a `proc_pidinfo` flavor the macOS SDK keeps in +/// its private header (`sys/proc_info_private.h`, macOS 13 and later): one +/// thread's counts, by its 64-bit thread id, per CPU performance level. +const PROC_PIDTHREADCOUNTS: libc::c_int = 34; +/// Its result: an 8-byte header whose first `u16` is the number of +/// performance levels, then one record per level of five `u64`s — +/// instructions, cycles, user time, system time and energy (nJ), in that +/// order (`struct proc_threadcounts_data`). +const THREADCOUNTS_HEADER: usize = 8; +const THREADCOUNTS_LEVEL: usize = 40; +const THREADCOUNTS_ENERGY: usize = 32; + +/// The calling thread's own CPU energy, nJ, summed over the performance +/// levels: the count [`fold`] watches. `None` if the call fails or returns a +/// size other than its header and one 40-byte record per level it names — +/// a layout this code does not know, read as no count at all rather than +/// as a misread field. Measured (M5 Max, macOS 27.0.1): 88 bytes, two +/// levels (`hw.nperflevels`), about 0.3 µs a read. +pub(super) fn this_thread_energy_nj() -> Option { + let mut tid: u64 = 0; + // SAFETY: `tid` is writable; `pthread_self` is the calling thread. + if unsafe { libc::pthread_threadid_np(libc::pthread_self(), &mut tid) } != 0 { + return None; + } + let mut buf = [0u8; 512]; + // SAFETY: `buf` is writable for its length, which the call is given. + let n = unsafe { + libc::proc_pidinfo(libc::getpid(), PROC_PIDTHREADCOUNTS, tid, buf.as_mut_ptr().cast(), buf.len() as libc::c_int) + }; + let levels = usize::from(u16::from_ne_bytes([buf[0], buf[1]])); + let size = THREADCOUNTS_HEADER + levels * THREADCOUNTS_LEVEL; + if levels == 0 || size > buf.len() || usize::try_from(n).ok() != Some(size) { + return None; + } + let energy = (0..levels).map(|l| { + let at = THREADCOUNTS_HEADER + l * THREADCOUNTS_LEVEL + THREADCOUNTS_ENERGY; + u64::from_ne_bytes(buf[at..at + 8].try_into().expect("8 bytes")) + }); + Some(energy.fold(0, u64::saturating_add)) +} + /// This process's own CPU energy counter, as a meter probe. pub struct ProcessEnergyProbe { /// This process, read once at construction. pid: libc::pid_t, + /// The reading thread's own energy count, which [`fold`] watches before + /// each read: [`this_thread_energy_nj`], but for a test of what a read + /// does when the count never moves. + thread_count: fn() -> Option, } impl ProcessEnergyProbe { @@ -173,8 +312,18 @@ impl ProcessEnergyProbe { /// uses, for this process's counter `status`, which production passes /// from the cached [`process_energy_status`](super::process_energy_status) /// and nowhere else: only when the counter is live ([`gated`]). + /// + /// The reading thread's own energy count ([`this_thread_energy_nj`]) must + /// be readable too: every read is checked against it ([`fold`]), and a + /// probe whose check could never pass would only ever estimate. pub(super) fn given(status: CounterStatus) -> Result { - gated("process energy", status, Self::open) + gated("process energy", status, || { + let probe = Self::open()?; + this_thread_energy_nj().ok_or_else(|| { + ProbeError::Unavailable("proc_pidinfo(PROC_PIDTHREADCOUNTS) gave no count for this thread".into()) + })?; + Ok(probe) + }) } /// This process's counter, with no liveness gate: one read must succeed. @@ -184,7 +333,7 @@ impl ProcessEnergyProbe { // SAFETY: `getpid` has no preconditions. let pid = unsafe { libc::getpid() }; usage_of(pid) - .map(|_| ProcessEnergyProbe { pid }) + .map(|_| ProcessEnergyProbe { pid, thread_count: this_thread_energy_nj }) .ok_or_else(|| ProbeError::Unavailable("proc_pid_rusage(RUSAGE_INFO_V6) failed for this process".into())) } @@ -199,7 +348,18 @@ impl Probe for ProcessEnergyProbe { "process-energy" } + /// This process's count, read once the reading thread is SEEN to have + /// left its core ([`fold`] over [`FOLD_SLEEPS`]), so the count holds all + /// that thread spent up to the read. A thread not seen to fold fails the + /// read: the meter then has no reading of the span, and estimates it. fn snapshot(&mut self) -> Result, ProbeError> { + if !fold(&FOLD_SLEEPS, self.thread_count, std::thread::sleep) { + return Err(ProbeError::Read( + "the reading thread's own energy count did not move across any fold sleep: it is not known to have \ + left its core, so the read could miss what it spent since it last did" + .into(), + )); + } let u = usage_of(self.pid).ok_or_else(|| ProbeError::Read("proc_pid_rusage failed".into()))?; Ok(vec![(DeviceClass::Cpu, u.energy_nj / 1_000)]) } @@ -208,6 +368,31 @@ impl Probe for ProcessEnergyProbe { /// The rule for a child's own energy, read from the child after it exited /// and before it was reaped: a reading in microjoules, or `None`. /// +/// The reading is PARTIAL, a lower bound of the child's own CPU energy: the +/// kernel folds a thread's energy into the count only when the thread leaves +/// a core, and a process's exit does not fold the last time its threads +/// spent on one — its CPU time is folded at exit, its energy is not. +/// Measured (M5 Max, macOS 27.0.1, 40 pairs over four runs), from one +/// settled live read of a child to its next read, a burn of its thread's +/// CPU ended either by exiting (read as a zombie) or by blocking (read live, +/// once off-core), the CPU time between the reads equal to 0.01 ms either +/// way: a 2 ms burn read 0.81 to 1.20 mJ per CPU-ms in every block, and 0 +/// to 1.12 in the exits — under 0.05 in 11 of the 40, exactly 0 nJ in +/// several; 60 ms burns read 0.85 to 1.12 against 0.87 to 1.15, the loss +/// then inside the spread. How much is lost depends on how long the thread +/// ran since it last left a core. So the figure is short by up to a +/// scheduler quantum's (10 ms) CPU energy for each thread on a core when +/// the child exits — all of a child that ran less, which may then read 0 +/// and is no reading (below), and a few percent at most of one that ran +/// for a second. Nor does it hold work a system +/// service did on the child's behalf, which the kernel bills to the child +/// beside this count and not in it. A caller that seals it seals it as a +/// partial reading of the child's work (`Partial` where its format has a +/// coverage field) and, where its format has none, never as a hardware +/// reading of the whole: it grades it down. A process tree's +/// [`TreeMeter`](super::TreeMeter) reads an exited member the same way, and +/// for the same reason lists it as a gap (`TreeGap::Exited`). +/// /// - Only while this host's per-process energy counter is live: the same /// kernel accounting, shown to advance under load in this process. /// - Only for a single-process child: if it reaped descendants that used CPU @@ -243,6 +428,10 @@ mod tests { assert_eq!(offset_of!(RusageInfoV6, ri_proc_exit_abstime), 88); assert_eq!(offset_of!(RusageInfoV6, ri_child_user_time), 96); assert_eq!(offset_of!(RusageInfoV6, ri_child_system_time), 104); + assert_eq!(offset_of!(RusageInfoV6, ri_billed_system_time), 216); + assert_eq!(offset_of!(RusageInfoV6, ri_serviced_system_time), 224); + assert_eq!(offset_of!(RusageInfoV6, ri_billed_energy), 264); + assert_eq!(offset_of!(RusageInfoV6, ri_serviced_energy), 272); assert_eq!(offset_of!(RusageInfoV6, ri_energy_nj), 336); assert_eq!(offset_of!(RusageInfoV6, ri_penergy_nj), 344); assert_eq!(offset_of!(RusageInfoV6, ri_lifetime_max_neural_footprint), 376); @@ -292,6 +481,76 @@ mod tests { } } + /// The fold rule: a read waits until this thread's own count advanced + /// across a sleep, sleeping each of the sleeps in turn, and a count that + /// never advanced, could not be read or went back is no fold. + #[test] + fn a_read_waits_for_the_thread_to_be_seen_to_fold() { + use std::cell::RefCell; + let sleeps = [Duration::from_micros(50), Duration::from_micros(200), Duration::from_millis(1)]; + // `counts` in turn for each read; the sleeps taken, recorded. + let run = |counts: Vec>| { + let counts = RefCell::new(counts.into_iter()); + let slept = RefCell::new(Vec::new()); + let folded = fold(&sleeps, || counts.borrow_mut().next().flatten(), |d| slept.borrow_mut().push(d)); + (folded, slept.into_inner()) + }; + assert_eq!(run(vec![Some(5), Some(9)]), (true, vec![sleeps[0]]), "moved across the first sleep"); + assert_eq!( + run(vec![Some(5), Some(5), Some(5), Some(5), Some(5), Some(6)]), + (true, sleeps.to_vec()), + "held twice (sleeps that did not block), moved across the third" + ); + assert_eq!(run(vec![Some(5); 6]), (false, sleeps.to_vec()), "never moved: no fold, after every sleep"); + assert_eq!(run(vec![Some(5), None]), (false, vec![sleeps[0]]), "unreadable after the sleep"); + assert_eq!(run(vec![None]), (false, vec![]), "unreadable before it"); + assert_eq!(run(vec![Some(5), Some(4), Some(4), Some(4), Some(4), Some(4)]), (false, sleeps.to_vec()), "went back"); + } + + /// This thread's own count reads on this host, in the layout the code + /// expects (one record per performance level, `hw.nperflevels` of them + /// where the host says), and a real read of the probe sees the thread + /// fold: the path every in-process read takes. + #[test] + fn the_reading_thread_is_seen_to_fold_on_this_host() { + let e = this_thread_energy_nj().expect("this thread's own count"); + let mut buf = [0u8; 512]; + let mut tid = 0u64; + // SAFETY: as in `this_thread_energy_nj`. + let n = unsafe { + libc::pthread_threadid_np(libc::pthread_self(), &mut tid); + libc::proc_pidinfo(libc::getpid(), PROC_PIDTHREADCOUNTS, tid, buf.as_mut_ptr().cast(), 512) + }; + let levels = u16::from_ne_bytes([buf[0], buf[1]]); + let mut perf: libc::c_int = 0; + let mut size = std::mem::size_of::(); + // SAFETY: `perf` is writable for `size` bytes. + let rc = unsafe { + libc::sysctlbyname(c"hw.nperflevels".as_ptr(), (&mut perf as *mut libc::c_int).cast(), &mut size, std::ptr::null_mut(), 0) + }; + eprintln!("thread counts: {n} bytes, {levels} levels (hw.nperflevels {perf}, rc {rc}), {e} nJ"); + assert_eq!(n as usize, THREADCOUNTS_HEADER + usize::from(levels) * THREADCOUNTS_LEVEL); + if rc == 0 { + assert_eq!(i32::from(levels), perf); + } + let mut p = ProcessEnergyProbe::open().expect("this process reads itself"); + assert!(p.snapshot().is_ok(), "the reading thread was not seen to fold within {FOLD_SLEEPS:?}"); + } + + /// A read whose thread is never seen to fold is no read: the probe's + /// snapshot fails (so the meter estimates the span) after every fold + /// sleep, and one whose count cannot be read fails at once. + #[test] + fn a_read_whose_thread_never_folds_fails() { + let mut p = ProcessEnergyProbe { thread_count: || Some(7), ..ProcessEnergyProbe::open().expect("this process") }; + let t = std::time::Instant::now(); + assert!(matches!(p.snapshot(), Err(ProbeError::Read(_)))); + let total: Duration = FOLD_SLEEPS.iter().sum(); + assert!(t.elapsed() >= total, "gave up after {:?}, before all {FOLD_SLEEPS:?}", t.elapsed()); + let mut p = ProcessEnergyProbe { thread_count: || None, ..p }; + assert!(matches!(p.snapshot(), Err(ProbeError::Read(_)))); + } + /// The gate declines a counter that is not live without reading it. #[test] fn only_a_live_status_builds_the_process_probe() { diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/tree.rs b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/tree.rs index 0a0a9973c..e19a88251 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/tree.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/src/probe/tree.rs @@ -9,23 +9,29 @@ //! host ([`process_energy_status`](super::process_energy_status)). //! //! **The domain, exactly.** A [`TreeReading`]'s figure is the CPU energy of -//! the processes in the tree over the span: every process present at both +//! the processes in the tree over the span — every process present at both //! ends (its advance) and every process born inside the span (its whole -//! count). Beside it, the reading claims an exact zero for the tree's GPU -//! time and for in-process Neural Engine use, and only where the evidence -//! says so: no member holding a GPU client at either end (a client whose -//! recorded time did not move is no such evidence: see below), and no -//! member that ever held Neural Engine model memory. It does NOT cover, and -//! cannot see: +//! count) — plus the CPU energy the kernel billed to them for work other +//! processes did on their behalf, less what it credited them for work they +//! did for other processes (see "Delegated work", below). Beside it, the +//! reading claims an exact zero for the tree's GPU time and for in-process +//! Neural Engine use, and only where the evidence says so: no member holding +//! a GPU client at either end (a client whose recorded time did not move is +//! no such evidence: see below), and no member that ever held Neural Engine +//! model memory. It does NOT cover, and cannot see: //! -//! - work the tree hands to a process outside it — a system service over -//! XPC, a database server, a remote API. On-device model inference run by -//! a system daemon drew about 1 W of Neural Engine power on an M5 Max -//! (macOS 27.0.1, `sudo powermetrics`) while its client showed no Neural -//! Engine footprint and its own CPU count advanced only by its own share, -//! tens of millijoules per request: a plausible figure, with nothing in it -//! to show the rest. The model's memory and work are charged to a system -//! service of another user, unreadable here; +//! - work the tree hands to a process outside it, beyond the CPU work that +//! process was billed to the tree for: a system service's GPU and Neural +//! Engine energy and its unbilled work (below), a server reached over a +//! socket or a pipe (no voucher travels on one), a remote API. On-device +//! model inference run by a system daemon drew about 1 W of Neural Engine +//! power on an M5 Max (macOS 27.0.1, `sudo powermetrics`) while its client +//! showed no Neural Engine footprint and its own CPU count advanced only +//! by its own share, tens of millijoules per request. The daemon's CPU +//! work for the request is billed to the client, 175 to 1,795 mJ a request +//! against the client's own 38 to 223 mJ, and is counted, with a gap +//! saying so; its Neural Engine energy (6.73 J, against 1.79 J billed, for +//! one long request) is in no counter this process can read; //! - DRAM, or any other rail: this is the CPU cores' energy as the kernel //! attributes it to threads; //! - a descendant that left the tree before the start was walked (a daemon @@ -36,14 +42,25 @@ //! differ from the tree's energy over the span: a process that came or went //! in a way whose energy cannot be read, a GPU or Neural Engine figure that //! is unknown or not zero, a member that could not be read or would not go -//! quiet. Each but one means the figure lacks energy; the one, -//! [`TreeGap::Unsettled`] at the start, means it may also hold up to a -//! quantum per running thread of energy spent just BEFORE the span, so a -//! figure with gaps is not always a lower bound. An empty list +//! quiet. Most mean the figure lacks energy. Three can put energy from +//! outside the span INTO it, so a figure with gaps is not always a lower +//! bound: [`TreeGap::Unsettled`] at the start, which may hold up to a +//! quantum per running thread spent just BEFORE the span; +//! [`TreeGap::Delegated`], a bill credited in the span for work a service +//! did before it (an earlier call's late credit), which is added; and +//! [`TreeGap::Serviced`], service credited in the span for work done +//! before it (subtracted: the figure short) or done in it and credited +//! after the stop (left in: the figure over). An empty list //! ([`TreeReading::is_whole`]) means nothing was seen missing, not that the -//! tree did no work elsewhere: whether the tree hands work outside itself is -//! something only its operator can declare, and that declaration belongs to -//! the caller (a gateway's configuration), never to this reading. +//! tree did no work elsewhere: the kernel's billing shows work handed to a +//! service that adopts the tree's voucher, and nothing else (a server on a +//! socket, a remote API, work billed to another originator), so whether the +//! tree hands work outside itself is still something only its operator can +//! declare, and that declaration belongs to the caller (a gateway's +//! configuration), never to this reading. Billing seen is the other way +//! round: a reading with [`TreeGap::Delegated`] SHOWS work done elsewhere, +//! whatever the operator declared, and its figure can be short of the +//! span's delegated work or over it (below). //! //! **A snapshot** walks the tree from the root: for each process, one read, //! its run state, a second read, then its children (`proc_listchildpids`, @@ -55,8 +72,9 @@ //! different process. From each read the snapshot keeps the energy, the //! process's own CPU time, the CPU time of descendants it reaped //! (`ri_child_user_time + ri_child_system_time`), its start and exit times -//! (an exit time is a zombie: exited, not yet reaped) and its lifetime -//! maximum Neural Engine footprint. One process costs about 15 µs, nearly all +//! (an exit time is a zombie: exited, not yet reaped), its lifetime +//! maximum Neural Engine footprint, and its billed and serviced energy and +//! CPU time (below). One process costs about 15 µs, nearly all //! of it the listing, which scans the host's process table. //! //! **Settling.** `ri_energy_nj` is folded into the count only when a thread @@ -111,7 +129,16 @@ //! core never reaches the record, while its CPU time does. Measured: a //! child that ran 3.3 ms of CPU and exited at once left a record of 0 to //! 0.32 mJ, some exactly 0 nJ, where the same work in a process that blocks -//! before it exits reads about 1.5 mJ per CPU-ms. So an exited member is a +//! before it exits reads about 1.5 mJ per CPU-ms. And paired, from one +//! settled live read of a child to its next read, the same 2 ms burn ended +//! by exiting (read as a zombie) or by blocking (read live, settled), its +//! CPU time equal to 0.01 ms either way, read 0 to 1.12 mJ per CPU-ms in +//! the exits — under 0.05 in 11 of 40 — and 0.81 to 1.20 in every block: +//! the exit loses what the thread spent since it last left a core, which +//! varies. A thread that exits in a process that lives on is folded (2 to +//! 30 ms burns averaged 1.04 to 1.17 mJ per CPU-ms, exiting at once or +//! blocking first; one 2 ms exit in 12 read low); the process's own exit is +//! not. So an exited member is a //! gap ([`TreeGap::Exited`]) for its energy as well as its GPU time. Nor //! does settling make the tree's work finished. A member waiting on I/O in the //! middle of its work, or a process still being started, is on no core and @@ -153,7 +180,91 @@ //! within a second of release, and the interval maximum can be reset by any //! process of this user, the monitored one included — so a process that //! ever held such memory is a gap for every span after, and one that hands -//! its model to a system daemon is not seen at all (see the domain above). +//! its model to a system daemon shows no footprint at all: the daemon's CPU +//! work for it is billed to it (below), its Neural Engine work is not. +//! +//! **Delegated work.** The kernel's bank ledgers bill CPU work one process +//! does on another's behalf to the other: a system service's thread that +//! adopts a client's voucher while it handles the client's message (an XPC +//! or other mach message carries one) is charged, when it next changes +//! voucher, with the CPU time and energy it spent since it last did. The +//! payer's `ri_billed_energy` (nJ, the scale of `ri_energy_nj`) and +//! `ri_billed_system_time` (mach ticks; user and system time both) rise by +//! it, and are not part of its own `ri_energy_nj`; the servicer's +//! `ri_serviced_energy` and `ri_serviced_system_time` rise by the same, and +//! are part of its own. Readable for any process of this user, an exited +//! and unreaped one too, without privilege, and the bill follows the +//! voucher across hops (a client, a model daemon, a compiler service it +//! called: billed to the client). Measured on an M5 Max (macOS 27.0.1): all +//! four exactly 0 in every CPU-only control; a client billed 4 to 45 times +//! its own energy for on-device model inference, about 200 times for a +//! file-metadata search, about 2.4 times for speech synthesis, and 0.83 to +//! 1.46 mJ for three directory-service lookups (`getpwnam`) against 0.57 +//! to 1.17 mJ of its own over the same round trip (10 round trips: this +//! crate's tree-energy test and a probe like it); +//! and the bills and the credits agreeing across the host (the sums over +//! every process within about 1% in a quiet window). +//! +//! So a member's count is `ri_energy_nj − ri_serviced_energy + +//! ri_billed_energy`, and the figure sums the members' advances of it, +//! signed: work a member did for other processes is theirs, work others did +//! for it is the tree's, and work one member does for another is counted +//! once, through the payer (the servicer's credit and the payer's bill land +//! together). A member whose net advance is below zero — credited inside the +//! span for service done before it — is counted as it is, and is a gap +//! ([`TreeGap::ServicedBeyondSpent`]). Whenever any counted member's +//! serviced energy or serviced CPU time moved, the reading carries +//! [`TreeGap::Serviced`], however the net came out: a servicing thread is +//! credited at its next voucher change, not as it works (a daemon's +//! serviced energy was 14 to 100% of its own energy over a window in which +//! its serviced CPU time was 93 to 99% of its CPU time: the energy credited +//! in a window is not that window's service), so a credit inside the span +//! need not be the span's service: the figure can be short by service +//! before the span credited in it, or over by service in it credited +//! after. Whenever any counted member's billed energy or billed CPU time +//! moved, the reading carries [`TreeGap::Delegated`]: the figure holds that +//! billed energy, which is neither a lower nor an upper bound of the span's +//! delegated work. It can hold bills for work done BEFORE the span: a bill +//! is credited when the servicing thread next changes voucher, so an +//! earlier call's late credit lands in whichever span is open, and is +//! added to that span's figure (over). And it leaves out (short): +//! +//! - the services' GPU and Neural Engine energy: no ledger carries any (the +//! inference request above: 6.73 J on the Neural Engine, 1.79 J billed); +//! - their work on threads that never adopt the voucher, or before they do: +//! starting a per-client speech service process went unbilled (1,029 mJ, +//! 276 mJ of it serviced), and a daemon's serviced energy was 14 to 100% +//! of its own energy over the same window, while its serviced CPU time was +//! 93 to 99% of its CPU time; +//! - credits that land after the stop: a servicing thread is credited at +//! its next voucher change (0.92 J of one 21.4 J metadata search landed in +//! the 1.5 s after it returned), and is then read in whichever span is +//! open — another span's figure, with this gap. A stop over which a bill +//! moved waits for the billed counts to hold ([`BILLED_HOLD_POLLS`] reads +//! at most, [`BILLED_HOLD_POLL`] apart: 100 ms on an idle host), so a +//! credit that lands while it reads falls in its own span; one that lands +//! after two of its reads agreed does not. Measured (M5 Max, macOS +//! 27.0.1): of 40 directory-scoped metadata searches, about 2 J billed +//! each, 5 had bills land after the reply — 0.40 J of one within 5 ms, +//! the others 0.03 to 0.44 mJ between 20 ms and 1.5 s after it — and no +//! directory-service lookup did. Over 30 such searches metered, the +//! calls with any bill landing after the stop were 3 without the wait +//! and 2 with it (separate runs), the late energy about 0.54 mJ either +//! way; the wait made a delegating call's stop 6.8 ms longer at the +//! median (9.6 ms against 2.7 ms, three directory lookups, 40 calls +//! each) and a pure-CPU call's no longer; +//! - work billed to another originator (background work a scheduling +//! daemon runs for a process is billed to that daemon, a policy daemon's +//! scan of a client's binary to the policy daemon), and work in a service +//! that gets no voucher or drops it, or runs off this host. +//! +//! The billed counts take no part in settling (`settled`): they move when +//! ANOTHER process's thread changes voucher, whatever the member is doing, +//! so no run state says they are complete, and a reading with any is a gap +//! already whose text says late credits are not in it. The stop's wait for +//! them (`hold_bills`) is apart from settling, after the stop walk has +//! settled, and reads nothing else. Nor do they take part in confirming a +//! walk, which compares the tree's shape, not its counts. // Off macOS no tree can be walked: the types and the rule are built, and // tested, for the rule's sake alone. @@ -178,6 +289,29 @@ pub const SETTLE_BOUND: Duration = Duration::from_millis(50); /// it waits and adds at most that much to the moment the tree went quiet. pub const SETTLE_POLL: Duration = Duration::from_micros(250); +/// The interval between two reads of the tree's billed counts while a +/// span's stop waits for them to hold: they have held when two reads this +/// far apart agree. Paid only by a span over which a member's billed counts +/// moved, and then at least once: a delegating call's stop takes at least +/// this much longer than it would. See [`BILLED_HOLD_POLLS`]. +pub const BILLED_HOLD_POLL: Duration = Duration::from_millis(5); + +/// How many times, at most, a span's stop reads the billed counts again +/// ([`BILLED_HOLD_POLL`] apart) for them to hold: 20, 100 ms on an idle +/// host. A servicing thread is credited when it next changes voucher, so a +/// call's own bill can land after its reply; waiting at the stop until two +/// reads agree lets a credit that lands while it reads fall in its own +/// span, rather than in whichever span is open next. It cannot wait for +/// them all — a credit can land after two reads agreed, up to a second and +/// more after the reply (0.92 J of one 21.4 J metadata search landed in the +/// 1.5 s after it returned) — and bills for work before the span still +/// land in it, so a reading with billed work stays a gap +/// ([`TreeGap::Delegated`]) either way; what the wait caught and cost, as +/// measured, is in the [module docs](self), "Delegated work". The wait is no part of settling +/// (`settled`): it reads only the billed counts, which another process's +/// thread moves, and only after the stop walk has settled. +pub const BILLED_HOLD_POLLS: u32 = 20; + /// What a tree snapshot reads of one process's `rusage_info_v6`, and what /// [`process`](super::process) reads of this process or an exited child. /// CPU times are in mach ticks (24 MHz on Apple Silicon: 2,409,625 ticks for @@ -203,6 +337,25 @@ pub(super) struct Usage { /// `ri_lifetime_max_neural_footprint`: the most Neural Engine model /// memory the process ever held, bytes. Never reset. pub(super) neural_lifetime_max: u64, + /// `ri_billed_energy`: the CPU energy, nJ (the scale of `ri_energy_nj`), + /// of work OTHER processes did on this one's behalf, which the kernel's + /// bank ledgers billed to it — a system service's thread that adopted + /// this process's voucher while it handled its message. Cumulative, and + /// not part of `energy_nj`: it is extra. Credited when the servicing + /// thread next changes voucher, so it can land after the work it pays + /// for (see the [module docs](self), "Delegated work"). + pub(super) billed_energy_nj: u64, + /// `ri_serviced_energy`: the CPU energy, nJ, of work this process's own + /// threads did on OTHER processes' behalf, which the kernel billed to + /// them. Cumulative, and part of `energy_nj` (a servicer's own count + /// holds it). + pub(super) serviced_energy_nj: u64, + /// `ri_billed_system_time`: the CPU time, mach ticks, user and system + /// both (despite the name), of the work billed to this process. + pub(super) billed_cpu: u64, + /// `ri_serviced_system_time`: the CPU time, mach ticks, user and system + /// both, of the work this process did for others. + pub(super) serviced_cpu: u64, } /// A process's threads at one instant, from `proc_pidinfo(PROC_PIDTASKINFO)`. @@ -217,13 +370,27 @@ pub(super) enum Threads { } /// Whether one process's reading is complete: two reads that agree in every -/// field with, between them, no thread on a core or queued for one — or, for -/// a process that has exited (it has no task), two agreeing reads of a -/// process whose exit time is set. A thread on a core at the first read and -/// off it at the run-state read left the core in between, and leaving folds -/// its CPU time and energy, so the second read would differ. +/// field the process's OWN threads move with, between them, no thread on a +/// core or queued for one — or, for a process that has exited (it has no +/// task), two agreeing reads of a process whose exit time is set. A thread on +/// a core at the first read and off it at the run-state read left the core in +/// between, and leaving folds its CPU time and energy, so the second read +/// would differ. +/// +/// The two billed fields are left out of the comparison: they are credited +/// by ANOTHER process's thread when it changes voucher, whatever this one's +/// threads are doing, and up to a second and more after the work they pay +/// for, so no run state of this process says when they are complete, and +/// waiting for them to hold would only stretch every span on a tree that +/// delegates without making its figure whole (a span with any billed work +/// is a gap, [`TreeGap::Delegated`], which says late credits are not in it). +/// The serviced fields stay in: they are credited at a voucher change by this +/// process's own thread, so they move only while it runs, as its energy +/// does; and were one to move while it was off-core, the member would read +/// as unsettled and be walked again, never read stale. pub(super) fn settled(first: &Usage, threads: Threads, second: &Usage) -> bool { - if first != second { + let own = |u: &Usage| Usage { billed_energy_nj: 0, billed_cpu: 0, ..*u }; + if own(first) != own(second) { return false; } match threads { @@ -296,7 +463,8 @@ impl Snapshot { /// exited, was reaped or left the tree in between, and none slipped /// between one member's read and its children's. The members' own /// counts are not compared: each is exact at its own settled read, - /// whenever another member is read. + /// whenever another member is read. Nor are the billed and serviced + /// counts, which are counts too, not shape. pub(super) fn agrees_with(&self, other: &Snapshot) -> bool { // Each member's pid, start time, parent, reaped time and exit time. fn members(s: &Snapshot) -> Vec<(u32, u64, u32, u64, u64)> { @@ -363,9 +531,13 @@ impl std::fmt::Display for SpanEnd { } /// One way a [`TreeReading`]'s figure was seen to differ from the tree's -/// whole energy over the span: short of it, for every kind but -/// [`Unsettled`](TreeGap::Unsettled) at the start, which may also put up to -/// a quantum per running thread from before the span into the figure. A +/// whole energy over the span: short of it, for every kind but three, which +/// can also put energy from outside the span into the figure — +/// [`Unsettled`](TreeGap::Unsettled) at the start (up to a quantum per +/// running thread from before the span), [`Delegated`](TreeGap::Delegated) +/// (a bill credited in the span for work done before it) and +/// [`Serviced`](TreeGap::Serviced) (a service credit that is not the span's +/// own, either way). A /// reading with none is whole for its domain (see the [module docs](self)): /// it does not say the tree handed no work outside itself. #[derive(Debug, Clone, PartialEq, Eq)] @@ -404,9 +576,9 @@ pub enum TreeGap { /// Whatever it spent between the start and its exit is not in the /// figure. Not raised for a process that had already exited at the start. Gone { pid: u32 }, - /// A member's energy count went backwards between the ends, which the - /// kernel's count never does for one process: its advance is not - /// counted. + /// A member's energy count — its own, or its billed or serviced count + /// (energy or CPU time) — went backwards between the ends, which the + /// kernel's counts never do for one process: its advance is not counted. EnergyWentBack { pid: u32 }, /// A member reaped descendants inside the span, whose CPU time (`cpu`) /// moved into its own reaped-descendants time and whose energy is in no @@ -439,6 +611,54 @@ pub enum TreeGap { /// lifetime maximum), so it may have run work on the Neural Engine, /// whose energy is in no counter this process can read. NeuralEngine { pid: u32, bytes: u64 }, + /// The tree's members were billed, over the span, for work other + /// processes did on their behalf: `billed_nj` of CPU energy and + /// `billed_cpu` of CPU time, as the kernel's bank ledgers credited it to + /// them (a system service's thread that adopted a member's voucher while + /// it handled the member's message). That energy IS in the figure: it is + /// the tree's work, done in another process. But the bill over a span is + /// not the span's delegated work, and the figure can be off EITHER way + /// by it (see the [module docs](self), "Delegated work"). Over: a bill is + /// credited when the servicing thread next changes voucher, so a bill + /// for work done before the span — an earlier call's late credit — lands + /// in it and is added. Short, by what the ledgers do not carry: the + /// services' GPU and Neural Engine energy, which no ledger holds; their + /// work on threads that never adopted the voucher, or before they did + /// (starting a per-client service process, say); credits that land + /// after the stop (up to a second and more after the reply; the stop + /// waits a little for them, [`BILLED_HOLD_POLLS`]); work billed to + /// another originator (background work a scheduler daemon runs for the + /// tree, a policy daemon's scan of its binary); and work done off this + /// host. Raised whenever a counted member's billed energy or billed CPU + /// time moved — also when the servicer was a member itself, which the + /// ledger does not name to an unprivileged reader: that work is no loss, + /// being counted once, through the payer. + Delegated { billed_nj: u64, billed_cpu: Duration }, + /// The tree's members were credited, over the span, with work they did + /// for other processes (their serviced counts): `serviced_nj` of CPU + /// energy and `serviced_cpu` of CPU time. That energy is part of their + /// own counts, and the figure subtracts it, as the other processes' + /// work. But a servicing thread is credited when it next changes + /// voucher, not as it works, so the credit over a span need not be the + /// service done in it: a credit for service done before the span + /// subtracts energy the span never held (the figure is short), and + /// service done in the span and credited after its stop stays in the + /// figure (it is over). So the figure can be off EITHER way, by up to + /// the service around the span. Raised whenever a counted member's + /// serviced energy or serviced CPU time moved, however the net came out + /// — also when the payer was a member too, whose bill then cancels the + /// credit in the sum (that work is counted once, through the payer, and + /// the reading carries [`Delegated`](TreeGap::Delegated) as well). + Serviced { serviced_nj: u64, serviced_cpu: Duration }, + /// A member was credited, over the span, with more work done for other + /// processes (its serviced count) than it spent plus was billed: its net + /// advance is `-excess_nj`. A servicing thread is credited when it next + /// changes voucher, so service done before the span can be credited + /// inside it. The member's net is counted as it is, signed — exact where + /// the payer is a member too, whose billed count moved by the same + /// credit — but where the payer is outside the tree the figure subtracts + /// energy spent before the span, and may be short. + ServicedBeyondSpent { pid: u32, excess_nj: u64 }, } impl std::fmt::Display for TreeGap { @@ -476,6 +696,22 @@ impl std::fmt::Display for TreeGap { TreeGap::NeuralEngine { pid, bytes } => { write!(f, "pid {pid} has held {bytes} bytes of Neural Engine model memory") } + TreeGap::Delegated { billed_nj, billed_cpu } => write!( + f, + "the tree was billed {billed_nj} nJ ({billed_cpu:?} of CPU) for work other processes did on its behalf: \ + counted; the figure may be short (their GPU and Neural Engine energy, unbilled work and credits after \ + the stop are not in it) or over (a credit landing in the span for work before it is)" + ), + TreeGap::Serviced { serviced_nj, serviced_cpu } => write!( + f, + "the tree was credited {serviced_nj} nJ ({serviced_cpu:?} of CPU) for work it did for other processes, \ + subtracted from the figure; credits land late, so the figure may be short or over by up to that service" + ), + TreeGap::ServicedBeyondSpent { pid, excess_nj } => write!( + f, + "pid {pid} was credited with {excess_nj} nJ more service to other processes than it spent, \ + so the figure may subtract energy spent before the span" + ), } } } @@ -490,10 +726,12 @@ pub enum TreeError { /// The root could not be read at an end. #[error("the tree's root, pid {pid}, could not be read (errno {errno})")] RootUnreadable { pid: u32, errno: i32 }, - /// The CPU energy the figure sums did not advance. Even a bare - /// request/response round trip reads microjoules on this counter, so a - /// zero is no reading of the span. `gaps` are the reading's gaps, for - /// the record. + /// The CPU energy the figure sums did not advance: its sum is zero, or + /// below zero (service credited to the tree for work before the span, + /// [`TreeGap::ServicedBeyondSpent`], outweighing all it spent). Even a + /// bare request/response round trip reads microjoules on this counter, + /// so such a sum is no reading of the span. `gaps` are the reading's + /// gaps, for the record. #[error("the tree's CPU energy did not advance over the span")] NotAdvanced { gaps: Vec }, } @@ -510,7 +748,12 @@ pub struct TreeReading { /// present at both ends with the same identity, plus the whole count of /// every process born inside the span (and nothing of a gap's process /// whose figure could not be separated: [`TreeGap::PredatesSpan`], - /// [`TreeGap::EnergyWentBack`]). + /// [`TreeGap::EnergyWentBack`]). A process's count is its own threads' + /// CPU energy, less the work it did for other processes (its serviced + /// energy), plus the work other processes did on its behalf (its billed + /// energy), summed signed over the members: see the + /// [module docs](self), "Delegated work". For a tree that neither + /// delegates nor serves, both are zero and this is its own CPU energy. pub cpu_nj: u64, /// How many processes [`cpu_nj`](Self::cpu_nj) sums. pub processes: usize, @@ -519,7 +762,8 @@ pub struct TreeReading { /// From the start walk settling to the stop walk settling. pub wall: Duration, /// Every way the figure was seen to differ from the tree's whole energy - /// over the span (see [`TreeGap`]: all but one mean energy is missing). + /// over the span (see [`TreeGap`]: most mean energy is missing; three + /// can mean the figure holds energy from outside the span). pub gaps: Vec, } @@ -644,12 +888,18 @@ pub(super) fn combine( .fold(0, u64::saturating_add) }; - let mut cpu_nj: u64 = 0; + // Signed: a member's net can be below zero (`ServicedBeyondSpent`), and + // is summed as it is, never wrapped. + let mut net_nj: i128 = 0; + let mut billed_nj: u64 = 0; + let mut billed_cpu: u64 = 0; + let mut serviced_nj: u64 = 0; + let mut serviced_cpu: u64 = 0; let mut pids: Vec = Vec::new(); for e in &end.members { let u = &e.usage; let (counted, reaped_in_span) = match start.same_process(e) { - Some(s) => match u.energy_nj.checked_sub(s.usage.energy_nj) { + Some(s) => match Advance::between(&s.usage, u) { Some(d) => (Some(d), u.reaped_descendants_cpu.saturating_sub(s.usage.reaped_descendants_cpu)), None => { gaps.push(TreeGap::EnergyWentBack { pid: e.pid }); @@ -658,14 +908,22 @@ pub(super) fn combine( }, // Not in the start walk (or its pid named another process then): // born in the span, or older and missed. - None if u.start_abstime >= start.taken => (Some(u.energy_nj), u.reaped_descendants_cpu), + None if u.start_abstime >= start.taken => (Some(Advance::whole(u)), u.reaped_descendants_cpu), None => { gaps.push(TreeGap::PredatesSpan { pid: e.pid }); (None, 0) } }; if let Some(d) = counted { - cpu_nj = cpu_nj.saturating_add(d); + let net = d.net(); + if net < 0 { + gaps.push(TreeGap::ServicedBeyondSpent { pid: e.pid, excess_nj: u64::try_from(-net).unwrap_or(u64::MAX) }); + } + net_nj += net; + billed_nj = billed_nj.saturating_add(d.billed_nj); + billed_cpu = billed_cpu.saturating_add(d.billed_cpu); + serviced_nj = serviced_nj.saturating_add(d.serviced_nj); + serviced_cpu = serviced_cpu.saturating_add(d.serviced_cpu); pids.push(e.pid); } let lost = reaped_in_span.saturating_sub(reaped_before(e.pid)); @@ -700,12 +958,73 @@ pub(super) fn combine( _ => gaps.push(TreeGap::GpuUnknown { pid: None }), } - if cpu_nj == 0 { + // Work other processes did on the tree's behalf: counted above, as + // billed in the span — which leaves out what no bill carries, and can + // hold a late bill for work before the span. + if billed_nj > 0 || billed_cpu > 0 { + gaps.push(TreeGap::Delegated { billed_nj, billed_cpu: end.cpu(billed_cpu) }); + } + // Work the tree did for other processes: subtracted above, and credited + // when the servicing thread next changes voucher, not as it works, so it + // need not be this span's service. + if serviced_nj > 0 || serviced_cpu > 0 { + gaps.push(TreeGap::Serviced { serviced_nj, serviced_cpu: end.cpu(serviced_cpu) }); + } + + if net_nj <= 0 { return Err(TreeError::NotAdvanced { gaps }); } + let cpu_nj = u64::try_from(net_nj).unwrap_or(u64::MAX); Ok(TreeReading { cpu_uj: cpu_nj.div_ceil(1_000), cpu_nj, processes: pids.len(), pids, wall, gaps }) } +/// One member's advance over the span, in the counts the figure sums. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +struct Advance { + /// Its own threads' CPU energy, nJ. + energy_nj: u64, + /// Work it did for other processes, nJ: part of `energy_nj`. + serviced_nj: u64, + /// The CPU time of that work, mach ticks. + serviced_cpu: u64, + /// Work other processes did on its behalf, nJ: not part of `energy_nj`. + billed_nj: u64, + /// The CPU time of that billed work, mach ticks. + billed_cpu: u64, +} + +impl Advance { + /// From `start` to `end`, two reads of the same process; `None` if any + /// of the counts it sums, or the billed or serviced CPU time, went + /// backwards, which no count of one process does. + fn between(start: &Usage, end: &Usage) -> Option { + Some(Advance { + energy_nj: end.energy_nj.checked_sub(start.energy_nj)?, + serviced_nj: end.serviced_energy_nj.checked_sub(start.serviced_energy_nj)?, + serviced_cpu: end.serviced_cpu.checked_sub(start.serviced_cpu)?, + billed_nj: end.billed_energy_nj.checked_sub(start.billed_energy_nj)?, + billed_cpu: end.billed_cpu.checked_sub(start.billed_cpu)?, + }) + } + + /// A process born in the span: all of its counts are the span's. + fn whole(u: &Usage) -> Advance { + Advance { + energy_nj: u.energy_nj, + serviced_nj: u.serviced_energy_nj, + serviced_cpu: u.serviced_cpu, + billed_nj: u.billed_energy_nj, + billed_cpu: u.billed_cpu, + } + } + + /// Its net, signed: its own energy, less the work it did for others, + /// plus the work others did for it. + fn net(&self) -> i128 { + i128::from(self.energy_nj) - i128::from(self.serviced_nj) + i128::from(self.billed_nj) + } +} + /// Walks (`walk`: production walks the tree; the tests give a sequence) /// until a walk with every member settled is confirmed by the one before it /// ([`Snapshot::agrees_with`]), and returns it; or, once `bound` has passed @@ -741,6 +1060,63 @@ pub(super) fn settle(mut walk: impl FnMut() -> Snapshot, bound: Duration, poll: } } +/// Each member's billed counts (energy nJ, CPU ticks) in the order of a +/// snapshot's members; `None` for a member that could not be read again as +/// the same process. +pub(super) type Bills = Vec>; + +/// Whether any member that [`combine`] would count had its billed energy or +/// billed CPU time move over the span: a member present at both ends whose +/// counts differ, or one born in the span with any. What makes a reading +/// [`TreeGap::Delegated`], and the stop wait for its bills. +pub(super) fn billed_moved(start: &Snapshot, end: &Snapshot) -> bool { + end.members.iter().any(|e| { + let u = &e.usage; + match start.same_process(e) { + Some(s) => (u.billed_energy_nj, u.billed_cpu) != (s.usage.billed_energy_nj, s.usage.billed_cpu), + None => u.start_abstime >= start.taken && (u.billed_energy_nj > 0 || u.billed_cpu > 0), + } + }) +} + +/// The stop's wait for the billed counts to hold: only if a bill moved over +/// the span ([`billed_moved`]), read them again (`read`: production reads +/// each end member; the tests give a sequence) every `poll` until two reads +/// in a row agree, at most `polls` times, and return `end` with each +/// member's billed counts from the last read (where it read the same +/// process, and never below what the stop walk read: the counts only +/// grow). With no bill moved, `end` as it is, and nothing read or slept. +pub(super) fn hold_bills( + start: &Snapshot, + end: Snapshot, + mut read: impl FnMut(&Snapshot) -> Bills, + polls: u32, + poll: Duration, + mut sleep: impl FnMut(Duration), +) -> Snapshot { + if !billed_moved(start, &end) { + return end; + } + let mut last: Bills = end.members.iter().map(|m| Some((m.usage.billed_energy_nj, m.usage.billed_cpu))).collect(); + for _ in 0..polls { + sleep(poll); + let now = read(&end); + let held = now == last; + last = now; + if held { + break; + } + } + let mut end = end; + for (m, b) in end.members.iter_mut().zip(&last) { + if let Some((nj, cpu)) = *b { + m.usage.billed_energy_nj = m.usage.billed_energy_nj.max(nj); + m.usage.billed_cpu = m.usage.billed_cpu.max(cpu); + } + } + end +} + /// The CPU energy of a live process tree rooted at another process: see the /// [module docs](self) for what a reading covers and how it is taken. #[derive(Debug, Clone)] @@ -804,11 +1180,30 @@ impl TreeMeter { } /// End a span: walk the tree until it is settled (or the bound runs - /// out), then read the GPU clients, and apply the rule. + /// out), then read the GPU clients; if a member's billed counts moved + /// over the span, wait for them to hold (`hold_bills`: at least + /// [`BILLED_HOLD_POLL`], at most [`BILLED_HOLD_POLLS`] of them), so a + /// credit for the span's own delegated work that lands just after the + /// reply is in it; and apply the rule. pub fn stop(&self, start: TreeStart) -> Result { - let end = sys::settled_walk(self.root, self.settle_bound); + self.stop_with(start, || sys::settled_walk(self.root, self.settle_bound), sys::gpu_clients, sys::bills, std::thread::sleep) + } + + /// [`stop`](Self::stop) with its reads given (production: the settled + /// walk, the GPU clients, each member's billed counts, a real sleep), so + /// the tests drive the order of the stop and its wait without a tree. + fn stop_with( + &self, + start: TreeStart, + walk: impl FnOnce() -> Snapshot, + gpu: impl FnOnce() -> Option>, + bills: impl FnMut(&Snapshot) -> Bills, + sleep: impl FnMut(Duration), + ) -> Result { + let end = walk(); let wall = start.started.elapsed(); - let gpu = sys::gpu_clients(); + let gpu = gpu(); + let end = hold_bills(&start.snapshot, end, bills, BILLED_HOLD_POLLS, BILLED_HOLD_POLL, sleep); combine((self.root, self.root_start), &start.snapshot, &end, start.gpu.as_deref(), gpu.as_deref(), wall) } @@ -982,6 +1377,18 @@ mod sys { super::settle(|| walk(root), bound, super::SETTLE_POLL) } + /// Each of `end`'s members' billed counts now, read again by pid; `None` + /// for one that cannot be read or whose pid names another process. + pub(super) fn bills(end: &Snapshot) -> super::Bills { + end.members + .iter() + .map(|m| { + let u = read_usage(libc::pid_t::try_from(m.pid).ok()?).ok()?; + (u.start_abstime == m.usage.start_abstime).then_some((u.billed_energy_nj, u.billed_cpu)) + }) + .collect() + } + /// Every GPU client now; `None` if the registry could not be read, and /// always off Apple Silicon, which has no reader here. pub(super) fn gpu_clients() -> Option> { @@ -1009,6 +1416,9 @@ mod sys { pub(super) fn settled_walk(_: u32, _: Duration) -> Snapshot { Snapshot::default() } + pub(super) fn bills(_: &Snapshot) -> super::Bills { + Vec::new() + } pub(super) fn gpu_clients() -> Option> { None } @@ -1412,6 +1822,302 @@ mod tests { assert_eq!(r.unwrap().cpu_nj, 1_000); } + /// `u` with its billed and serviced counts (energy nJ, CPU ticks) set. + fn ledgers(u: Usage, billed: (u64, u64), serviced: (u64, u64)) -> Usage { + Usage { + billed_energy_nj: billed.0, + billed_cpu: billed.1, + serviced_energy_nj: serviced.0, + serviced_cpu: serviced.1, + ..u + } + } + + /// Work a system service did on a member's behalf, billed to it, is + /// ADDED to the figure — it is the tree's work, done elsewhere — and the + /// reading carries `Delegated` with the billed energy and CPU time over + /// the span (the counts' advance, not their lifetime totals): the figure + /// holds it, and is short of whatever the bill does not carry. + #[test] + fn work_billed_to_a_member_is_added_and_is_a_gap() { + let start = snap(T0, vec![member(ROOT, 0, ledgers(usage(10, 5_000), (100, 24), (0, 0)))]); + let end = Snapshot { + timebase: (125, 3), + ..snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 6_000), (40_100, 2_424), (0, 0)))]) + }; + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::Delegated { billed_nj: 40_000, billed_cpu: Duration::from_micros(100) }]); + let r = r.unwrap(); + assert_eq!((r.cpu_nj, r.cpu_uj, r.processes), (41_000, 41, 1), "1,000 nJ of its own and 40,000 billed"); + assert!(!r.is_whole()); + } + + /// Billed CPU time with no billed energy (the energy credit can be 0 + /// while the CPU time is not) is delegation all the same: the gap + /// carries the time, and the figure is the member's own. + #[test] + fn billed_cpu_time_alone_is_delegation() { + let start = snap(T0, vec![member(ROOT, 0, ledgers(usage(10, 5_000), (700, 30), (0, 0)))]); + let end = snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 6_000), (700, 54), (0, 0)))]); + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::Delegated { billed_nj: 0, billed_cpu: Duration::from_nanos(24) }]); + assert_eq!(r.unwrap().cpu_nj, 1_000); + } + + /// Work a member did for a process outside the tree, credited to it as + /// serviced, is SUBTRACTED: it is part of the member's own count, and it + /// is the other process's work. And it is a gap, `Serviced`, with the + /// credit over the span, though the net stays above zero: a credit lands + /// when the servicing thread next changes voucher, so it need not be + /// this span's service, and the figure may be short or over by it. + /// Serviced CPU time alone moving is the same gap. + #[test] + fn work_a_member_did_for_others_is_subtracted_and_is_a_gap() { + let start = snap(T0, vec![member(ROOT, 0, ledgers(usage(10, 5_000), (0, 0), (1_000, 40)))]); + let end = snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 15_000), (0, 0), (5_000, 140)))]); + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::Serviced { serviced_nj: 4_000, serviced_cpu: Duration::from_nanos(100) }]); + let r = r.unwrap(); + assert_eq!(r.cpu_nj, 6_000, "10,000 nJ of its own, 4,000 of it for another process"); + assert!(!r.is_whole()); + + let end = snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 15_000), (0, 0), (1_000, 41)))]); + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::Serviced { serviced_nj: 0, serviced_cpu: Duration::from_nanos(1) }]); + assert_eq!(r.unwrap().cpu_nj, 10_000); + } + + /// One member serving another: the payer is billed what the servicer is + /// credited, so the work is counted once, through the payer — the sum is + /// the two members' own energy, exactly. The bill is still `Delegated` + /// and the credit `Serviced` (the ledger names neither party to this + /// reader), which loses nothing. + #[test] + fn work_one_member_does_for_another_is_counted_once() { + let start = snap( + T0, + vec![ + member(ROOT, 0, ledgers(usage(10, 5_000), (0, 0), (0, 0))), + member(101, ROOT, ledgers(usage(20, 70_000), (0, 0), (0, 0))), + ], + ); + let end = snap( + T0 + 900, + vec![ + member(ROOT, 0, ledgers(usage(10, 6_000), (3_000, 72), (0, 0))), + member(101, ROOT, ledgers(usage(20, 73_500), (0, 0), (3_000, 72))), + ], + ); + let r = read(&start, &end); + assert_eq!( + gaps(&r), + [ + TreeGap::Delegated { billed_nj: 3_000, billed_cpu: Duration::from_nanos(72) }, + TreeGap::Serviced { serviced_nj: 3_000, serviced_cpu: Duration::from_nanos(72) }, + ] + ); + let r = r.unwrap(); + assert_eq!(r.cpu_nj, 1_000 + 3_500, "each member's own energy, the service once"); + assert_eq!(r.processes, 2); + } + + /// A member credited, in the span, with more service than it spent and + /// was billed (a credit for service done before the span, landing in + /// it) has a net advance below zero. It is summed signed — never wrapped + /// into an enormous unsigned figure — and is a gap with the excess. A + /// tree whose signed sum is not above zero is no reading. + #[test] + fn a_member_credited_beyond_what_it_spent_is_a_gap_summed_signed() { + let start = snap( + T0, + vec![ + member(ROOT, 0, ledgers(usage(10, 5_000), (0, 0), (0, 0))), + member(101, ROOT, ledgers(usage(20, 70_000), (0, 0), (0, 0))), + ], + ); + let end = snap( + T0 + 900, + vec![ + member(ROOT, 0, ledgers(usage(10, 9_000), (0, 0), (0, 0))), + member(101, ROOT, ledgers(usage(20, 70_100), (0, 0), (900, 9))), + ], + ); + let serviced = TreeGap::Serviced { serviced_nj: 900, serviced_cpu: Duration::from_nanos(9) }; + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::ServicedBeyondSpent { pid: 101, excess_nj: 800 }, serviced.clone()]); + let r = r.unwrap(); + assert_eq!((r.cpu_nj, r.processes), (4_000 - 800, 2)); + + let end = snap( + T0 + 900, + vec![ + member(ROOT, 0, ledgers(usage(10, 5_000), (0, 0), (0, 0))), + member(101, ROOT, ledgers(usage(20, 70_100), (0, 0), (900, 9))), + ], + ); + assert_eq!( + read(&start, &end), + Err(TreeError::NotAdvanced { gaps: vec![TreeGap::ServicedBeyondSpent { pid: 101, excess_nj: 800 }, serviced] }), + "a sum below zero is no reading" + ); + } + + /// A member born in the span counts all of its counts: its own energy, + /// less its whole serviced count, plus its whole billed count. + #[test] + fn a_member_born_in_the_span_counts_its_whole_ledgers() { + let start = snap(T0, vec![member(ROOT, 0, usage(10, 5_000))]); + let born = ledgers(usage(T0 + 5, 2_000), (7_000, 240), (500, 12)); + let end = snap(T0 + 900, vec![member(ROOT, 0, usage(10, 6_000)), member(102, ROOT, born)]); + let r = read(&start, &end); + assert_eq!( + gaps(&r), + [ + TreeGap::Delegated { billed_nj: 7_000, billed_cpu: Duration::from_nanos(240) }, + TreeGap::Serviced { serviced_nj: 500, serviced_cpu: Duration::from_nanos(12) }, + ] + ); + assert_eq!(r.unwrap().cpu_nj, 1_000 + 2_000 - 500 + 7_000); + } + + /// A billed or serviced count (energy or CPU time) that went backwards + /// is no count the kernel keeps: that member's advance is not counted, + /// and it is `EnergyWentBack`. + #[test] + fn a_ledger_count_that_went_back_is_a_gap_and_not_counted() { + let start = snap( + T0, + vec![ + member(ROOT, 0, usage(10, 5_000)), + member(101, ROOT, ledgers(usage(20, 70_000), (9_000, 90), (400, 40))), + ], + ); + for (what, back) in [ + ("billed energy", ledgers(usage(20, 75_000), (8_000, 90), (400, 40))), + ("billed CPU", ledgers(usage(20, 75_000), (9_000, 89), (400, 40))), + ("serviced energy", ledgers(usage(20, 75_000), (9_000, 90), (300, 40))), + ("serviced CPU", ledgers(usage(20, 75_000), (9_000, 90), (400, 39))), + ] { + let end = snap(T0 + 900, vec![member(ROOT, 0, usage(10, 6_000)), member(101, ROOT, back)]); + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::EnergyWentBack { pid: 101 }], "{what}"); + assert_eq!(r.unwrap().cpu_nj, 1_000, "{what}: the member is not counted"); + } + } + + /// The billed counts are credited by ANOTHER process's thread, whatever + /// this one is doing: a credit landing between a member's two reads + /// does not unsettle it. Its serviced counts move only when its own + /// thread changes voucher, so one that moved does. + #[test] + fn a_bill_landing_between_two_reads_does_not_unsettle_a_member() { + let a = ledgers(usage(10, 5_000), (100, 10), (50, 5)); + for billed in [ledgers(a, (900, 10), (50, 5)), ledgers(a, (100, 11), (50, 5))] { + assert!(settled(&a, Threads::Running(0), &billed), "{billed:?}"); + } + for serviced in [ledgers(a, (100, 10), (60, 5)), ledgers(a, (100, 10), (50, 6))] { + assert!(!settled(&a, Threads::Running(0), &serviced), "{serviced:?}"); + } + // The second read is what is kept: the bill that landed is in it. + let mut zombie = ledgers(a, (100, 10), (50, 5)); + zombie.exit_abstime = 77; + assert!(settled(&zombie, Threads::NoTask, &ledgers(zombie, (300, 12), (50, 5)))); + } + + /// A bill moved over the span when a counted member's billed energy or + /// CPU time differs between the ends, or a member born in the span has + /// any; a member that only predates the span, or no bill at all, is no + /// movement. + #[test] + fn a_bill_moved_only_when_a_counted_members_billed_counts_did() { + let a = ledgers(usage(10, 5_000), (100, 10), (0, 0)); + let start = snap(T0, vec![member(ROOT, 0, a)]); + let same = snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 6_000), (100, 10), (7, 7)))]); + assert!(!billed_moved(&start, &same), "own energy and service moved, no bill"); + for moved in [ledgers(a, (101, 10), (0, 0)), ledgers(a, (100, 11), (0, 0))] { + assert!(billed_moved(&start, &snap(T0 + 900, vec![member(ROOT, 0, moved)])), "{moved:?}"); + } + let born = |b| snap(T0 + 900, vec![member(ROOT, 0, a), member(102, ROOT, ledgers(usage(T0 + 5, 9), b, (0, 0)))]); + assert!(billed_moved(&start, &born((1, 0)))); + assert!(!billed_moved(&start, &born((0, 0)))); + let older = snap(T0 + 900, vec![member(ROOT, 0, a), member(103, ROOT, ledgers(usage(3, 9), (50, 5), (0, 0)))]); + assert!(!billed_moved(&start, &older), "a member that predates the span is not counted"); + } + + /// The stop waits for the billed counts to hold only when a bill moved + /// over the span: it reads them again every poll until two reads in a + /// row agree, at most `polls` times, and the reading takes the last + /// read — so a credit for the span's own work landing just after the + /// reply is in its own span. With no bill moved, nothing is read or + /// slept. The counts never go below the stop walk's, and a member that + /// cannot be read again keeps them. + #[test] + fn the_stop_waits_for_the_bills_to_hold_when_a_bill_moved() { + use std::cell::RefCell; + let poll = Duration::from_millis(5); + let start = snap(T0, vec![member(ROOT, 0, ledgers(usage(10, 5_000), (100, 10), (0, 0)))]); + let at_stop = |b| snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 6_000), b, (0, 0)))]); + // `reads` in turn; the sleeps taken. + let run = |end: Snapshot, reads: Vec, polls: u32| { + let reads = RefCell::new(reads.into_iter()); + let slept = RefCell::new(0u32); + let end = hold_bills(&start, end, |_| reads.borrow_mut().next().expect("a read"), polls, poll, |d| { + assert_eq!(d, poll); + *slept.borrow_mut() += 1; + }); + (end.members[0].usage.billed_energy_nj, end.members[0].usage.billed_cpu, slept.into_inner()) + }; + // No bill moved: nothing read (the read would panic), nothing slept. + assert_eq!(run(at_stop((100, 10)), vec![], 20), (100, 10, 0)); + // Held at once: one poll, the cost of every delegating call. + assert_eq!(run(at_stop((900, 40)), vec![vec![Some((900, 40))]], 20), (900, 40, 1)); + // A late credit lands after the stop walk, then holds: the reading + // takes it. + let late = vec![vec![Some((1_500, 52))], vec![Some((2_000, 60))], vec![Some((2_000, 60))]]; + assert_eq!(run(at_stop((900, 40)), late, 20), (2_000, 60, 3)); + // Never holding: the bound ends it, with the last read. + let creeping: Vec = (1..=4).map(|i| vec![Some((900 + i, 40))]).collect(); + assert_eq!(run(at_stop((900, 40)), creeping, 4), (904, 40, 4)); + // Unreadable again: the stop walk's counts stand. + assert_eq!(run(at_stop((900, 40)), vec![vec![None], vec![None]], 20), (900, 40, 2)); + + // And the rule reads the held bill as the span's. + let end = hold_bills(&start, at_stop((900, 40)), |_| vec![Some((2_000, 60))], 20, poll, |_| ()); + let end = Snapshot { timebase: (1, 1), ..end }; + let r = read(&start, &end); + assert_eq!(gaps(&r), [TreeGap::Delegated { billed_nj: 1_900, billed_cpu: Duration::from_nanos(50) }]); + assert_eq!(r.unwrap().cpu_nj, 1_000 + 1_900); + } + + /// A meter's stop reads the bills after its walk when one moved, and the + /// reading holds the bill that landed after the walk; with none moved, + /// it reads none and sleeps not at all. + #[test] + fn a_stop_takes_the_bill_that_landed_after_its_walk() { + use std::cell::Cell; + let meter = TreeMeter { root: ROOT, root_start: ROOT_ID.1, settle_bound: SETTLE_BOUND }; + let begin = |b| TreeStart { + snapshot: snap(T0, vec![member(ROOT, 0, ledgers(usage(10, 5_000), b, (0, 0)))]), + gpu: Some(Vec::new()), + started: Instant::now(), + }; + let walked = |b| snap(T0 + 900, vec![member(ROOT, 0, ledgers(usage(10, 6_000), b, (0, 0)))]); + let slept = Cell::new(0u32); + let r = meter.stop_with(begin((100, 10)), || walked((900, 40)), || Some(Vec::new()), |_| vec![Some((2_000, 60))], |_| { + slept.set(slept.get() + 1) + }); + assert_eq!(gaps(&r), [TreeGap::Delegated { billed_nj: 1_900, billed_cpu: Duration::from_nanos(50) }]); + assert_eq!(r.unwrap().cpu_nj, 1_000 + 1_900, "the bill that landed after the walk is the span's"); + assert_eq!(slept.get(), 2, "read until two reads agreed"); + + slept.set(0); + let r = meter.stop_with(begin((100, 10)), || walked((100, 10)), || Some(Vec::new()), |_| panic!("a bill read"), |_| { + slept.set(slept.get() + 1) + }); + assert_eq!(whole(&r).cpu_nj, 1_000); + assert_eq!(slept.get(), 0, "no bill moved: no wait"); + } + fn client(id: u64, pid: u32, gpu_ns: Option) -> GpuClient { GpuClient { id, pid, gpu_ns } } diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/tests/process_energy.rs b/sandbox/sandbox-rs/crates/sandbox-meter/tests/process_energy.rs index 8cda244f9..d9e34607f 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/tests/process_energy.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/tests/process_energy.rs @@ -131,6 +131,62 @@ fn an_in_process_burn_is_a_hardware_reading_of_its_energy() { assert!(uj <= outer / 1_000 + 1, "the span read more ({uj} µJ) than the oracle around it ({outer} nJ)"); } +/// This process's context switches, every thread's: `getrusage`'s +/// voluntary and involuntary counts. +fn switches() -> libc::c_long { + // SAFETY: an all-zero `rusage` is a valid out-parameter. + let mut ru: libc::rusage = unsafe { std::mem::zeroed() }; + // SAFETY: `ru` is writable for the call. + assert_eq!(unsafe { libc::getrusage(libc::RUSAGE_SELF, &mut ru) }, 0); + ru.ru_nvcsw + ru.ru_nivcsw +} + +/// The oracle's own read of this process, after taking this thread off its +/// core in a way that shares nothing with the meter's: a sleep of 1 ms or +/// more, then 2, 4 and 8 ms, until this process's context-switch count moved +/// across one. A sleep of a millisecond does not end before the thread has +/// blocked (the timer would have to fire before the block, a millisecond +/// after it was set), and the count moving says a switch happened; the +/// meter instead watches its thread's own energy count after sleeps from +/// 50 µs. A thread never seen to switch is the oracle's failure, said so. +fn folded_oracle_nj() -> u64 { + for ms in [1, 2, 4, 8] { + let before = switches(); + std::thread::sleep(Duration::from_millis(ms)); + if switches() > before { + return oracle_energy_nj(me()).expect("oracle read"); + } + } + panic!("the oracle's thread was not seen to switch across sleeps of 1, 2, 4 and 8 ms"); +} + +/// A short span is read whole on the thread that runs it. The kernel folds +/// a thread's energy into the count only when the thread leaves a core, and +/// a read of this process does not fold the thread reading (its CPU time is +/// current, its energy is not), so the meter takes that thread off its core +/// before each read and checks that it left. 1 ms of this thread's CPU, +/// metered 20 times, is a `Cpu` hardware reading every time — never the +/// estimator a count that held gives — and inside the oracle's reading +/// around it, which folds on its own and by its own check +/// ([`folded_oracle_nj`]), short of it by no more than a quarter: the +/// meter's reads and wake-ups, a few tens of microjoules. +#[test] +fn a_short_in_process_span_is_read_whole_on_its_own_thread() { + let _one = alone(); + let mut meter = PowerMeter::detect_in_process(); + for rep in 0..20 { + let before = folded_oracle_nj(); + let ((), m) = meter.measure(|| burn_cpu(Duration::from_millis(1))); + let outer = folded_oracle_nj() - before; + eprintln!("1 ms in-process burn rep {rep}: span {:?}, oracle around it {outer} nJ", m.devices); + let uj = the_reading(&m); + // The probe's µJ are its nJ floored at each end: within 1 µJ of the + // nJ advance. + assert!(uj * 1_000 <= outer + 1_000, "the span read more ({uj} µJ) than the oracle around it ({outer} nJ)"); + assert!((uj + 1) * 1_000 * 4 >= outer * 3, "the span ({uj} µJ) is short of the oracle around it ({outer} nJ)"); + } +} + /// A 200 ms sleep in this process is a reading under 0.1 J: the counter /// covers this process's threads, and they did next to nothing. #[test] diff --git a/sandbox/sandbox-rs/crates/sandbox-meter/tests/tree_energy.rs b/sandbox/sandbox-rs/crates/sandbox-meter/tests/tree_energy.rs index 6538ddf51..89fec42c2 100644 --- a/sandbox/sandbox-rs/crates/sandbox-meter/tests/tree_energy.rs +++ b/sandbox/sandbox-rs/crates/sandbox-meter/tests/tree_energy.rs @@ -6,7 +6,9 @@ //! The oracle shares no code with the meter: the tree's members from `ps`, //! each member's `proc_pid_rusage(pid, RUSAGE_INFO_V6)` read into a raw //! buffer and taken at the SDK's byte offsets (energy at 336, start time at -//! 80, exit time at 88, reaped-descendant CPU time at 96 and 104), read only +//! 80, exit time at 88, reaped-descendant CPU time at 96 and 104, billed and +//! serviced CPU time at 216 and 224, billed and serviced energy at 264 and +//! 272), read only //! once the oracle has seen every member quiet on its own terms: no thread on //! a core or queued (`proc_pidinfo(PROC_PIDTASKINFO)` into a raw buffer, //! `pti_numrunning` at byte 88) at two reads 20 ms apart whose energy agrees. @@ -60,6 +62,27 @@ fn reaped_cpu_ticks(ru: &[u64; 64]) -> u64 { ru[96 / 8] + ru[104 / 8] } +/// `ri_billed_system_time`: the CPU time (mach ticks) of work other +/// processes did on this one's behalf, billed to it. +fn billed_ticks(ru: &[u64; 64]) -> u64 { + ru[216 / 8] +} + +/// `ri_serviced_system_time`: the CPU time of work it did for others. +fn serviced_ticks(ru: &[u64; 64]) -> u64 { + ru[224 / 8] +} + +/// `ri_billed_energy`, nJ: the energy of work billed to it. +fn billed_nj(ru: &[u64; 64]) -> u64 { + ru[264 / 8] +} + +/// `ri_serviced_energy`, nJ: the energy of work it did for others. +fn serviced_nj(ru: &[u64; 64]) -> u64 { + ru[272 / 8] +} + /// `pti_numrunning` of `pid`: `proc_pidinfo(pid, PROC_PIDTASKINFO = 4)` into /// a raw 96-byte buffer, the int32 at byte 88. `None` if the call fails (an /// exited process has no task). @@ -220,20 +243,27 @@ fn log(what: &str, rep: usize, r: &TreeReading, oracle_nj: u64) { /// over round trips from a bare echo to ~10 ms of CPU: each reading is /// whole (one process, no GPU client, no Neural Engine memory, settled), not /// zero, and equal to the oracle's advance across the round trip. +/// +/// It is also the control for delegated work: pure CPU work, over which +/// the oracle sees the server's billed and serviced counts hold, carries no +/// `Delegated` gap (each reading is whole) and its figure is the server's +/// own energy, to the nanojoule. #[test] fn a_single_process_server_reads_whole_and_exactly() { let _one = alone(); let mut s = Server::spawn("/usr/bin/awk", &["{ for (i = 0; i < $1; i++) x += i; print x + 0; fflush() }"]); let meter = s.meter(); let pid = s.pid(); - let mut before = energy_nj(&quiet(&[pid])[0]); + let mut before = quiet(&[pid])[0]; for (rep, n) in [0u32, 1, 20_000, 100_000, 300_000, 0].into_iter().enumerate() { let (reply, r) = meter.measure(|| s.ask(&n.to_string())); let r = r.expect("a reading of the round trip"); - let after = energy_nj(&quiet(&[pid])[0]); - let oracle = after - before; + let after = quiet(&[pid])[0]; + let oracle = energy_nj(&after) - energy_nj(&before); log(&format!("single process, loop {n}"), rep, &r, oracle); assert!(!reply.is_empty()); + let ledgers = |ru: &[u64; 64]| (billed_nj(ru), billed_ticks(ru), serviced_nj(ru), serviced_ticks(ru)); + assert_eq!(ledgers(&after), ledgers(&before), "setup: pure CPU work billed or serviced nothing"); assert!(r.is_whole(), "{:?}", r.gaps); assert_eq!((r.processes, r.pids.as_slice()), (1, &[pid as u32][..])); assert!(r.cpu_nj > 0, "{r:?}"); @@ -664,3 +694,174 @@ fn a_server_holding_a_gpu_client_never_reads_whole() { } } } + +/// A server for the delegated-work test, built from this source when it +/// first runs: it prints `ready`, then answers each request line with one +/// line. `cpu N` burns an N-iteration loop in this process and replies +/// `ok 0`. `delegate K` looks up K account names no account has +/// (`getpwnam`): a system directory service does each lookup, on a message +/// that carries this process's voucher, so the kernel bills the service's +/// CPU work for it to this process. It then waits — up to 5 s, in 1 ms +/// sleeps — for its own billed counts to move before it replies `ok `: a servicing thread is credited when it next changes voucher, +/// which can be after the reply, and the test is of how the meter counts a +/// bill that landed in its span, not of when the kernel lands it. Plain C, +/// with the compiler every macOS Rust build links with. +const DELEGATING_SERVER: &str = r##"#include +#include +#include +#include +#include +#include +#include +static void billed(unsigned long long *nj, unsigned long long *ticks) { + struct rusage_info_v6 r; + memset(&r, 0, sizeof r); + proc_pid_rusage(getpid(), RUSAGE_INFO_V6, (rusage_info_t *)&r); + *nj = r.ri_billed_energy; + *ticks = r.ri_billed_system_time; +} +int main(void) { + char line[256]; + unsigned long seq = 0; + printf("ready\n"); fflush(stdout); + while (fgets(line, sizeof line, stdin)) { + if (strncmp(line, "cpu ", 4) == 0) { + long n = atol(line + 4); + volatile unsigned long long x = 1; + for (long i = 0; i < n; i++) x = x * 6364136223846793005ULL + 1; + printf("ok 0\n"); fflush(stdout); + } else if (strncmp(line, "delegate ", 9) == 0) { + long k = atol(line + 9); + unsigned long long nj0, t0, nj1, t1; + billed(&nj0, &t0); + for (long i = 0; i < k; i++) { + char name[96]; + snprintf(name, sizeof name, "no-such-account-%d-%lu", (int)getpid(), seq++); + (void)getpwnam(name); + } + int waited = 0; + for (; waited < 5000; waited++) { + billed(&nj1, &t1); + if (nj1 > nj0 || t1 > t0) break; + usleep(1000); + } + printf("ok %d\n", waited); fflush(stdout); + } else { + printf("?\n"); fflush(stdout); + } + } + return 0; +} +"##; + +/// The delegating server, built once per test run into Cargo's scratch +/// directory for integration tests. +fn delegating_server() -> &'static str { + static BUILT: std::sync::OnceLock = std::sync::OnceLock::new(); + BUILT.get_or_init(|| { + let dir = std::path::Path::new(env!("CARGO_TARGET_TMPDIR")); + let source = dir.join("tree_energy_delegating_server.c"); + let binary = dir.join(format!("tree_energy_delegating_server-{}", std::process::id())); + std::fs::write(&source, DELEGATING_SERVER).expect("write the delegating server's source"); + let out = Command::new("/usr/bin/cc").args(["-O2", "-o"]).arg(&binary).arg(&source).output().expect("run the C compiler"); + assert!(out.status.success(), "the delegating server did not build:\n{}", String::from_utf8_lossy(&out.stderr)); + binary.to_string_lossy().into_owned() + }) +} + +/// `pid`'s rusage once its billed counts have held for 300 ms: whatever was +/// billed for its start, which can land late, has landed. Panics after 20 s. +fn billed_quiet(pid: i32) -> [u64; 64] { + let deadline = Instant::now() + Duration::from_secs(20); + loop { + let a = oracle_rusage(pid).expect("oracle read"); + std::thread::sleep(Duration::from_millis(300)); + let b = oracle_rusage(pid).expect("oracle read"); + if (billed_nj(&a), billed_ticks(&a)) == (billed_nj(&b), billed_ticks(&b)) { + return b; + } + assert!(Instant::now() < deadline, "the oracle never saw {pid}'s billed counts hold"); + } +} + +/// Work a system service does for a tree member is billed to it by the +/// kernel, and the meter counts it and says so. One process, the delegating +/// server above, metered over two kinds of round trip: +/// +/// - `cpu`, first (once anything billed for its start has landed): pure CPU +/// work, the control. No `Delegated` gap — the reading is whole — and the +/// figure is the server's own advance, exactly, as the oracle reads it. +/// - `delegate`: the server has a system service look up account names. The +/// reading carries `Delegated` and nothing else, its billed energy and CPU +/// time at least what the oracle saw billed inside the span (the oracle +/// reads inside the meter's span, after its start and before its stop, so +/// a bill landing late is in the meter's and maybe not the oracle's), and +/// the figure is at least the oracle's own advance less its serviced plus +/// its billed — and, less the gap's billed energy, exactly the server's +/// own advance less what it serviced: the bill is added once, on top of +/// an exact own count. +#[test] +fn work_a_system_service_does_for_a_member_is_counted_and_flagged() { + let _one = alone(); + let mut s = Server::spawn(delegating_server(), &[]); + assert_eq!(s.read_line(), "ready", "setup: the delegating server started"); + let pid = s.pid(); + let meter = s.meter(); + let (numer, denom) = timebase(); + let ticks = |t: u64| Duration::from_nanos(t * numer / denom); + billed_quiet(pid); + for rep in 0..3 { + let span = meter.start(); + let before = quiet(&[pid])[0]; + let reply = s.ask("cpu 2000000"); + let after = quiet(&[pid])[0]; + let stopping = Instant::now(); + let r = meter.stop(span).expect("a reading of the control"); + let stop_took = stopping.elapsed(); + let own = energy_nj(&after) - energy_nj(&before); + eprintln!( + "tree meter: delegating server, cpu control rep {rep}: {} nJ, oracle own {own} nJ, billed {} nJ / {} ticks; stop took {stop_took:?}; gaps {:?}", + r.cpu_nj, + billed_nj(&after) - billed_nj(&before), + billed_ticks(&after) - billed_ticks(&before), + r.gaps + ); + assert_eq!(reply, "ok 0"); + assert_eq!((billed_nj(&after), billed_ticks(&after)), (billed_nj(&before), billed_ticks(&before)), "setup: the control billed nothing"); + assert!(!r.gaps.iter().any(|g| matches!(g, TreeGap::Delegated { .. })), "pure CPU work read as delegated: {:?}", r.gaps); + assert!(r.is_whole(), "{:?}", r.gaps); + assert_eq!(r.cpu_nj, own, "the control's figure is the server's own advance"); + } + for rep in 0..4 { + let span = meter.start(); + let before = quiet(&[pid])[0]; + let reply = s.ask("delegate 3"); + let after = quiet(&[pid])[0]; + let stopping = Instant::now(); + let r = meter.stop(span).expect("a reading of the delegating round trip"); + let stop_took = stopping.elapsed(); + let own = i128::from(energy_nj(&after) - energy_nj(&before)); + let serviced = i128::from(serviced_nj(&after) - serviced_nj(&before)); + let billed = billed_nj(&after) - billed_nj(&before); + let billed_cpu = ticks(billed_ticks(&after) - billed_ticks(&before)); + let gap = r.gaps.iter().find_map(|g| match g { + TreeGap::Delegated { billed_nj, billed_cpu } => Some((*billed_nj, *billed_cpu)), + _ => None, + }); + eprintln!( + "tree meter: delegating server, delegate rep {rep} ({reply}): {} nJ; oracle own {own} nJ, serviced {serviced} nJ, billed {billed} nJ / {billed_cpu:?}; gap {gap:?}; stop took {stop_took:?}; gaps {:?}", + r.cpu_nj, r.gaps + ); + assert!(reply.starts_with("ok "), "{reply}"); + assert!(billed > 0 || billed_cpu > Duration::ZERO, "setup: the oracle saw no work billed to the server"); + let (gap_nj, gap_cpu) = gap.unwrap_or_else(|| panic!("no Delegated gap for work billed to the server: {:?}", r.gaps)); + assert_eq!(r.gaps.len(), 1, "only the delegation is missing: {:?}", r.gaps); + assert!(!r.is_whole()); + assert!(gap_nj >= billed && gap_cpu >= billed_cpu, "the gap's bill ({gap_nj} nJ, {gap_cpu:?}) is under the oracle's"); + let figure = i128::from(r.cpu_nj); + assert!(figure >= own - serviced + i128::from(billed), "the figure is under the oracle's own + billed − serviced"); + assert_eq!(figure - i128::from(gap_nj), own - serviced, "the figure less its bill is the server's own advance less its service"); + assert!(r.cpu_nj > own as u64, "the bill was added to the server's own energy"); + } +}