diff --git a/.github/workflows/standards-build.yml b/.github/workflows/standards-build.yml index b5272685d..71cc4dc77 100644 --- a/.github/workflows/standards-build.yml +++ b/.github/workflows/standards-build.yml @@ -347,7 +347,8 @@ jobs: eoc/eoc-rs/target jouleclaw/jouleclaw-rs/target sandbox/sandbox-rs/target - key: standards-macos-energy-${{ hashFiles('jcp/jcp-rs/Cargo.lock', 'proof/proof-rs/Cargo.lock', 'eoc/eoc-rs/Cargo.lock', 'jouleclaw/jouleclaw-rs/Cargo.lock', 'sandbox/sandbox-rs/Cargo.lock', 'rust-toolchain.toml') }} + joule-code/joule-code-rs/target + key: standards-macos-energy-${{ hashFiles('jcp/jcp-rs/Cargo.lock', 'proof/proof-rs/Cargo.lock', 'eoc/eoc-rs/Cargo.lock', 'jouleclaw/jouleclaw-rs/Cargo.lock', 'sandbox/sandbox-rs/Cargo.lock', 'joule-code/joule-code-rs/Cargo.lock', 'rust-toolchain.toml') }} restore-keys: | standards-macos-energy- @@ -448,3 +449,32 @@ jobs: log=$(mktemp) cargo test -p sandbox-proof -- --nocapture 2>&1 | tee "$log" grep -q 'local engine tree:' "$log" + + # joule-fix meters its L3 model on the model's own process tree. The + # joule-code-rs matrix entry runs on linux-arm64, where there is no tree + # meter, so its oracle test (the model's reading against the stand-in's + # own energy count) takes its fallback branch there and runs nowhere + # else. It prints this line only where it checked the reading. + - name: joule-code-remediate (L3 model process tree) + shell: bash + working-directory: joule-code/joule-code-rs + run: | + set -o pipefail + log=$(mktemp) + cargo test -p joule-code-remediate l3_ -- --nocapture 2>&1 | tee "$log" + grep -q 'l3 model process:' "$log" + + # Feature AND platform gated: `fabric-meter`, which no other job passes, + # and macOS. The fabric calibration rows' macOS stamp, and a CPU member + # priced on this process's own counters against its own energy count + # (tests/process_calibration.rs), each print their line only there. + - name: jouleclaw-loader-gguf (fabric-meter, process calibration) + shell: bash + working-directory: jouleclaw/jouleclaw-rs + run: | + set -o pipefail + log=$(mktemp) + cargo test -p jouleclaw-loader-gguf --features "rayon fabric-meter" marginal_energy -- --nocapture 2>&1 | tee "$log" + cargo test -p jouleclaw-loader-gguf --features "rayon fabric-meter" --test process_calibration -- --nocapture 2>&1 | tee -a "$log" + grep -q 'calibration row stamped on macOS:' "$log" + grep -q 'process calibration: CPU member' "$log" diff --git a/joule-code/examples/l3-jouleclaw/Cargo.lock b/joule-code/examples/l3-jouleclaw/Cargo.lock index 95a850371..36d0ba076 100644 --- a/joule-code/examples/l3-jouleclaw/Cargo.lock +++ b/joule-code/examples/l3-jouleclaw/Cargo.lock @@ -279,6 +279,7 @@ checksum = "70e796c081cee67dc755e1a36a0a172b897fab85fc3f6bc48307991f64e4eca9" dependencies = [ "curve25519-dalek", "ed25519", + "rand_core", "serde", "sha2", "subtle", @@ -500,11 +501,14 @@ dependencies = [ "joule-code-cascade", "joule-code-receipt", "joule-code-schema", + "jouleclaw-backend-apple", "jouleclaw-energy", "jouleclaw-fabric", "jouleclaw-llm", "jouleclaw-loader-gguf", "jouleclaw-runtime", + "libc", + "sandbox-meter", "serde_json", ] @@ -514,6 +518,16 @@ version = "0.2.189" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3eaf3ede3fee6db1a4c2ee091bf8a8b4dccdc6d17f656fb07896ee72867612f2" +[[package]] +name = "libloading" +version = "0.8.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d7c4b02199fee7c5d21a5ae7d8cfa79a6ef5bb2fc834d6e9058e89c825efdc55" +dependencies = [ + "cfg-if", + "windows-link", +] + [[package]] name = "memchr" version = "2.8.3" @@ -734,6 +748,29 @@ dependencies = [ "semver", ] +[[package]] +name = "sandbox-meter" +version = "0.1.0" +dependencies = [ + "ed25519-dalek", + "libc", + "libloading", + "sandbox-schema", + "serde", + "thiserror", +] + +[[package]] +name = "sandbox-schema" +version = "0.1.0" +dependencies = [ + "base64", + "blake3", + "ciborium", + "serde", + "thiserror", +] + [[package]] name = "semver" version = "1.0.28" @@ -891,6 +928,12 @@ version = "0.11.1+wasi-snapshot-preview1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ccf3ec651a847eb01de73ccad15eb7d99f80485de043efb2f370cd654f4ea44b" +[[package]] +name = "windows-link" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f0805222e57f7521d6a62e36fa9163bc891acd422f971defe97d64e70d0a4fe5" + [[package]] name = "windows-sys" version = "0.59.0" diff --git a/joule-code/examples/l3-jouleclaw/Cargo.toml b/joule-code/examples/l3-jouleclaw/Cargo.toml index 4e0dddea4..bed3a13c5 100644 --- a/joule-code/examples/l3-jouleclaw/Cargo.toml +++ b/joule-code/examples/l3-jouleclaw/Cargo.toml @@ -26,4 +26,16 @@ jouleclaw-loader-gguf = { path = "../../../jouleclaw/jouleclaw-rs/crates/joulecl # The grades (`Measured` / `Benchmarked` / `Estimated`) the fabric ledger prices # a call from, which the L3 stage grades the call's projected energy by. jouleclaw-fabric = { path = "../../../jouleclaw/jouleclaw-rs/crates/jouleclaw-fabric" } +# The GPU load the in-process meter's GPU-counter liveness probe runs +# (`gpu_liveness_load`): the `run` binary meters the in-process engine on this +# process's own CPU and GPU (`jouleclaw_energy::span::ProcessSpanMeter`). +jouleclaw-backend-apple = { path = "../../../jouleclaw/jouleclaw-rs/crates/jouleclaw-backend-apple" } +# The llama engine's subprocess, read on its own process tree where the host +# counts each process's CPU energy (macOS): `TreeMeter`. +sandbox-meter = { path = "../../../sandbox/sandbox-rs/crates/sandbox-meter" } serde_json = "1" + +# macOS: the llama engine's process is waited for without being reaped +# (`waitid` with `WNOWAIT`), so the tree meter reads its exited count. +[target.'cfg(target_os = "macos")'.dependencies] +libc = "0.2" diff --git a/joule-code/examples/l3-jouleclaw/README.md b/joule-code/examples/l3-jouleclaw/README.md index 24ea69f5e..fdcad1334 100644 --- a/joule-code/examples/l3-jouleclaw/README.md +++ b/joule-code/examples/l3-jouleclaw/README.md @@ -39,21 +39,36 @@ JOULE_CODE_L3_ENGINE=llama cargo run --release --bin run -- /path/to/model.gguf ``` The `run` binary generates with the local model, content-addresses the result as -a `CodingOp` (tier L3), and puts the **host** energy spent during the inference on -the receipt, tagged with the provenance of whatever metered it: +a `CodingOp` (tier L3), and puts the energy of the inference on the receipt, read +as close to the work as the host allows and graded by how much of the inference +the reading covers: -- **Apple Silicon whose IOReport CPU energy rail is live** — JouleClaw's IOReport - counter, a live vendor energy counter: a real local measurement, tagged - `HwShunt` (with `measured_uj` set). -- **Apple Silicon whose CPU rail is not live** — macOS 27.0.1 for an unprivileged - process, observed on an M5 Max and an M3 Ultra — JouleClaw's load-average - estimator, tagged `Estimator`. Not a measurement. -- **Anywhere else**, Linux and Windows included — the token-count estimate, - tagged `Estimator`. This binding builds `jouleclaw-energy` with the `ioreport` - feature only, so it reads no RAPL or NVML counter even where one exists. +- **In-process engine (default)** — metered on this process's own CPU and GPU + (`jouleclaw_energy::span::ProcessSpanMeter`): the CPU energy the kernel counts + for this process's threads, plus its GPU energy — an exact zero where it spent + no GPU time, the GPU rail where it had the GPU to itself. A span that covers the + whole inference is a hardware reading, `HwShunt` with `measured_uj` set. One + that covers part of it (the GPU shared with another process, so the CPU alone) + is an estimate of the whole, `Estimator`: the reading plus the host meter's + figure over the same window. +- **llama engine** — the subprocess is read on its own process tree + (`sandbox_meter::TreeMeter`) where the host counts each process's CPU energy + (macOS). That reading is never whole: it is the process's CPU only, not the GPU + the binary may offload to, and the process exits in its window, so its record + lacks its last time on a core — a lower bound. So it is always an estimate of + the whole, the reading plus the host meter's figure, never `HwShunt`. +- **No reading of the engine's own process** — no per-process counter, or, for + the in-process engine, this process's counters not live (the span then falls + back to a host meter, whose figure is the machine's, not the engine's): the + host meter's figure as it is. That is JouleClaw's IOReport counter where its + CPU energy rail is live (`HwShunt`), its load-average estimator where it is not + (macOS 27.0.1 for an unprivileged process, `Estimator`), and the token-count + estimate anywhere else (Linux and Windows included; this binding builds + `jouleclaw-energy` with the `ioreport` feature only). -The printout names the meter that ran and the IOReport status, and says whether -the figure was measured or estimated. +The receipt has no coverage field, so a partial reading is never sealed as a +hardware reading of the whole. The printout names the engine, the host meter and +the IOReport status, and says how the figure was obtained. Verified live: the llama.cpp path against a local 350M GGUF, and the in-process from-scratch runtime against `ternary-bonsai-1.7b-q2_0` (qwen3, Q2_0) — real text @@ -68,3 +83,11 @@ cargo test # EchoBackend path — no model required JOULE_BONSAI=/path/to/ternary-bonsai-1.7b-q2_0.gguf \ cargo test --release --test runtime_l3 -- --ignored --nocapture ``` + +The `run` binary's meter tests check each engine's reading against an oracle +sharing no code with the meter — the process's own energy count, read from +inside it — and assert it only where this host counts each process's energy +(Apple Silicon macOS, the per-process counter live); elsewhere they check the +fallback. CI tests this workspace on Linux only, where they take the fallback, +so the oracle assertions are not in CI and run only locally: run +`cargo test -- --nocapture` on an Apple Silicon Mac to see them. diff --git a/joule-code/examples/l3-jouleclaw/src/bin/run.rs b/joule-code/examples/l3-jouleclaw/src/bin/run.rs index 52adaf3a2..6a256e825 100644 --- a/joule-code/examples/l3-jouleclaw/src/bin/run.rs +++ b/joule-code/examples/l3-jouleclaw/src/bin/run.rs @@ -7,17 +7,39 @@ //! By default it runs the model **in-process on JouleClaw's own from-scratch GGUF //! tensor runtime** (`jouleclaw-runtime`); set `JOULE_CODE_L3_ENGINE=llama` to use //! the `llama.cpp` shell-out backend instead. Either way it content-addresses the -//! result as a `CodingOp` and puts the **host** energy spent during the inference -//! on the receipt, from JouleClaw's best counter on this host and tagged with that -//! counter's provenance: a measurement where the host exposes a live counter -//! (IOReport on Apple Silicon whose CPU rail advances, `HwShunt`), an estimate -//! from host load where it does not (Apple Silicon whose IOReport CPU rail is -//! frozen, as on macOS 27.0.1), and the token-count estimate where there is no -//! counter at all. The printed receipt says which. +//! result as a `CodingOp` and puts the energy of the inference on the receipt, +//! read as close to the work as this host allows and graded by how much of it the +//! reading covers ([`grade`]): +//! +//! - **The in-process engine** is metered on this process's own CPU and GPU +//! (`jouleclaw_energy::span::ProcessSpanMeter`): the CPU energy the kernel +//! counts for this process's threads, plus its GPU energy — an exact zero where +//! it spent no GPU time, the GPU rail where it had the GPU to itself. A span +//! that covers the whole inference keeps that grade (`HwShunt` for the two +//! counters). One that covers part of it — the GPU shared with another +//! process, so the CPU alone — is an estimate of the whole, never a reading. +//! - **The llama engine** runs in a subprocess, which this process's counters do +//! not see; its own process is read instead (`sandbox_meter::TreeMeter`), where +//! the host counts each process's CPU energy. That reading is never whole: it is +//! the process's CPU only, not the GPU the binary may offload to, and the +//! process exits in its window, so its record lacks its last time on a core (a +//! lower bound). It is always an estimate of the whole. +//! +//! An estimate of the whole is the reading plus the host meter's figure over the +//! same window (or, with no host counter, the token-count estimate): never less +//! than was read. The receipt has no coverage field, so a partial reading is +//! never sealed as a hardware reading. Where the engine's own process gives no +//! figure — no per-process counter, or this process's counters not live (the +//! span then falls back to a host meter, whose figure is the machine's, not the +//! engine's) — the host meter's figure (a measurement where it is a live +//! counter, an estimate from host load where it is not) or, with no host +//! counter, the token-count estimate stands. The printed receipt says which. use jouleclaw_energy::meter::EnergyMeter; -use jouleclaw_energy::Provenance as JcProvenance; -use jouleclaw_llm::{LlmBackend, LlmRequest}; +use jouleclaw_energy::span::{ProcessSpanMeter, SpanEnergy, SpanSource, SpanUses}; +use jouleclaw_energy::{Coverage, EnergyError, Provenance as JcProvenance}; +use jouleclaw_llm::{LlmBackend, LlmRequest, LlmResponse}; +use sandbox_meter::{TreeError, TreeReading}; use joule_code_cargo::{Anchor, CodingOp, Edit}; use joule_code_receipt::{Energy, Provenance, Receipt}; @@ -26,16 +48,16 @@ use joule_code_schema::{ContentId, Tier, ALG_ED25519}; use l3_jouleclaw_binding::llama_backend::LlamaCompletionBackend; use l3_jouleclaw_binding::runtime_backend::JouleclawRuntimeBackend; -/// The host's best energy counter, or None where unavailable (e.g. CI/Linux). +/// The host's best energy counter, or None where unavailable (e.g. CI/Linux): +/// the meter of the rest of the host over the inference, which a partial reading +/// of the engine's own process is graded with, and the figure that stands where +/// the engine's own process gives none ([`grade`]). /// -/// Not this process's own CPU-energy counter (`jouleclaw_energy::process`, the -/// in-process meter), although that one is live on macOS 27.0.1 where IOReport's -/// CPU rail is not: neither engine's inference runs on this process's threads -/// alone. `llama` runs in a `llama-completion` subprocess, and the in-process -/// `jouleclaw-runtime` registers the Apple backend's GPU kernels (Metal and MPS -/// matmuls, the quantized GEMVs that serve decode), whose energy is the GPU's. -/// A per-process CPU figure would bill that work nothing, or claim a domain its -/// counter does not read. +/// Not, on its own, the inference's meter: this process's CPU counter alone +/// would bill the in-process engine's GPU kernels (Metal and MPS matmuls, the +/// quantized GEMVs that serve decode) nothing, and the llama engine's subprocess +/// all of nothing. Those are read by [`ProcessSpanMeter`] and the llama +/// backend's own tree meter. fn host_counter() -> Option> { #[cfg(all(target_os = "macos", target_arch = "aarch64"))] { @@ -96,6 +118,137 @@ fn map_provenance(p: JcProvenance) -> Provenance { } } +/// What the engine's own process read over the inference. +enum Own { + /// The in-process engine: this process's CPU and GPU over the call + /// ([`ProcessSpanMeter`], [`SpanUses::CpuGpu`]). + Process(Result), + /// The llama engine's subprocess: its own process tree, `None` where the + /// host has no per-process counter. + Child { reading: Option> }, +} + +/// Why a reading of the llama engine's process tree is partial although the +/// tree meter saw no gap in it: the process had not exited when it was read +/// (the wait for its exit failed). One read at its exit always carries the +/// exit's own gap instead. +const NOT_READ_AT_EXIT: &str = "the model had not exited when its process tree was read"; + +/// The receipt's energy for the inference, and how it was obtained: the one +/// place it is graded. `rest` is the host meter's figure over the same window, +/// or the token-count estimate ([`receipt_energy`]), with its note. +/// +/// - **Whole** — the in-process span covers the whole inference on this +/// process's own counters (this process the GPU's effective sole user, or no +/// GPU time at all): the reading at its own grade, `HwShunt` with +/// `measured_uj` for a hardware reading. +/// - **Partial** — the CPU alone (the GPU shared, a client vanished), or the +/// child's tree, which is never read whole (it exits in its window): an +/// estimate of the whole, `Estimator`, the reading plus `rest` — never less +/// than was read, nothing outside the reading left out; it errs high by at most +/// the reading, `rest` covering the host. The rule mesh's in-process meter +/// bills a partial span by. +/// - **None** — no figure from the engine's own process, including a span that +/// fell back to a host meter because this process's counters gave none (that +/// figure is the machine's, not the engine's): `rest` as it is, so the host +/// figure is read the one way, [`host_counter`], whichever engine ran. +fn grade(own: &Own, rest: (Energy, String)) -> (Energy, String) { + let reading = |uj: u64, provenance: Provenance| Energy { + measured_uj: (provenance == Provenance::HwShunt).then_some(uj), + estimated_uj: uj, + provenance, + }; + let estimate = |uj: u64| Energy { measured_uj: None, estimated_uj: uj, provenance: Provenance::Estimator }; + let (rest, rest_note) = rest; + match own { + Own::Process(Ok(SpanEnergy { source: SpanSource::Fallback { why, .. }, .. })) => { + (rest, format!("{rest_note} (this process's counters gave no figure: {why})")) + } + Own::Process(Ok(s)) if s.coverage == Coverage::Whole => { + let note = match &s.source { + SpanSource::Process { cpu_uj, gpu } => format!( + "measured on this process's CPU ({cpu_uj} µJ) and GPU ({} µJ), the whole inference", + gpu.uj + ), + // (A fallback is graded as no reading, above.) + SpanSource::CpuOnly { why, .. } | SpanSource::Fallback { why, .. } => { + format!("this process's CPU ({why})") + } + }; + (reading(s.uj, map_provenance(s.provenance)), note) + } + Own::Process(Ok(s)) => { + let why = match &s.source { + SpanSource::CpuOnly { why, .. } => why.clone(), + _ => "a span that covers part of the inference".to_string(), + }; + let note = format!( + "estimated: this process's CPU read {} µJ, not all of the inference ({why}), plus {} µJ {rest_note}", + s.uj, rest.estimated_uj + ); + (estimate(s.uj.saturating_add(rest.estimated_uj)), note) + } + Own::Process(Err(e)) => (rest, format!("{rest_note} (this process's counters: {e})")), + Own::Child { reading: Some(Ok(r)) } => { + let cpu_uj = r.cpu_nj.div_ceil(1_000); + let mut because: Vec = r.gaps.iter().map(ToString::to_string).collect(); + if because.is_empty() { + because.push(NOT_READ_AT_EXIT.to_string()); + } + let note = format!( + "estimated: the model's own process read {cpu_uj} µJ of CPU, not all of the inference ({}), plus {} \ + µJ {rest_note}", + because.join("; "), + rest.estimated_uj + ); + (estimate(cpu_uj.saturating_add(rest.estimated_uj)), note) + } + Own::Child { reading: Some(Err(e)) } => (rest, format!("{rest_note} (the model's own process: {e})")), + Own::Child { reading: None } => (rest, rest_note), + } +} + +/// The engine that runs the model. +enum Engine { + Runtime(Box), + Llama(LlamaCompletionBackend), +} + +impl Engine { + fn model_name(&self) -> &str { + match self { + Engine::Runtime(b) => b.model_name(), + Engine::Llama(b) => b.model_name(), + } + } +} + +/// Run in-process `work` — the engine's decode, its CPU threads and the Metal +/// kernels it dispatches and waits on — under `meter`, as running on this +/// process's CPU and GPU and nothing else. +fn in_process(meter: &ProcessSpanMeter, work: impl FnOnce() -> T) -> (T, Own) { + let (out, energy) = meter.measure(SpanUses::CpuGpu, work); + (out, Own::Process(energy)) +} + +/// Run `request` on `engine`, read on the engine's own process: the in-process +/// engine by `span` (built before any window opens: its first construction +/// probes the counters), the llama engine by its subprocess's tree. +fn infer( + engine: &Engine, + span: Option<&ProcessSpanMeter>, + request: &LlmRequest, +) -> (Result, Own) { + match (engine, span) { + (Engine::Runtime(b), Some(meter)) => in_process(meter, || b.complete(request)), + (Engine::Runtime(b), None) => (b.complete(request), Own::Process(Err(EnergyError::NotCurrent))), + (Engine::Llama(b), _) => { + let (response, reading) = b.complete_metered(request); + (response, Own::Child { reading }) + } + } +} + fn main() { let mut args = std::env::args().skip(1); // Model path: first arg, else $JOULE_CODE_L3_MODEL. @@ -113,17 +266,21 @@ fn main() { }); // Backend: in-process from-scratch runtime by default; llama.cpp on request. - let engine = std::env::var("JOULE_CODE_L3_ENGINE").unwrap_or_else(|_| "runtime".to_string()); - let backend: Box = match engine.as_str() { - "llama" => Box::new(LlamaCompletionBackend::new(&model)), + let engine_name = std::env::var("JOULE_CODE_L3_ENGINE").unwrap_or_else(|_| "runtime".to_string()); + let engine = match engine_name.as_str() { + "llama" => Engine::Llama(LlamaCompletionBackend::new(&model)), _ => match JouleclawRuntimeBackend::from_path(&model) { - Ok(b) => Box::new(b), + Ok(b) => Engine::Runtime(Box::new(b)), Err(e) => { eprintln!("failed to load model on jouleclaw-runtime: {e}"); std::process::exit(1); } }, }; + // The in-process engine's meter, built (and its counters probed) before any + // window opens. + let span = matches!(engine, Engine::Runtime(_)) + .then(|| ProcessSpanMeter::new(jouleclaw_backend_apple::gpu_liveness_load)); let counter = host_counter(); let counter_name = counter.as_ref().map_or("none", |c| c.name()); @@ -137,7 +294,8 @@ fn main() { let _ = read(&counter); // prime let before = read(&counter); - let response = match backend.complete(&LlmRequest::from_prompt(&intent, 256)) { + let (response, own) = infer(&engine, span.as_ref(), &LlmRequest::from_prompt(&intent, 256)); + let response = match response { Ok(r) => r, Err(e) => { eprintln!("L3 inference failed: {e}"); @@ -162,14 +320,17 @@ fn main() { }; let op_id = op.op_id().expect("op_id"); - // Receipt energy: the host counter's figure at its provenance, else the - // token-based estimate (honest fallback). - let (energy, from_counter) = receipt_energy( + // Receipt energy: the engine's own reading, graded by how much of the + // inference it covers, with the host counter's figure (else the token-based + // estimate) for the rest. + let (rest, from_counter) = receipt_energy( before, after, response.input_tokens as u64, response.output_tokens as u64, ); + let rest_note = energy_note(&rest, counter_name, from_counter); + let (energy, note) = grade(&own, (rest, rest_note)); let receipt = Receipt { op_id: op_id.clone(), tier: Tier::L3, @@ -179,7 +340,8 @@ fn main() { }; println!("== Joule Code L3 (local model) =="); - println!("model : {}", backend.model_name()); + println!("model : {}", engine.model_name()); + println!("engine : {engine_name}"); println!("intent : {intent}"); println!("--- generated ---"); println!("{}", response.text); @@ -188,7 +350,7 @@ fn main() { println!("edits : {} (GENERATED.rs)", op.edits.len()); println!("tier : {}", receipt.tier); println!( - "meter : {counter_name} (IOReport: {:?})", + "host meter : {counter_name} (IOReport: {:?})", jouleclaw_energy::ioreport_status() ); println!( @@ -196,10 +358,9 @@ fn main() { response.input_tokens, response.output_tokens ); println!( - "energy : {:.3} J ({:?}, {})", + "energy : {:.3} J ({:?}, {note})", receipt.energy.estimated_uj as f64 / 1_000_000.0, receipt.energy.provenance, - energy_note(&receipt.energy, counter_name, from_counter) ); } @@ -251,6 +412,213 @@ mod tests { assert_eq!(energy_note(&measured, "rapl", true), "measured by rapl"); } + fn est(uj: u64) -> (Energy, String) { + (Energy { measured_uj: None, estimated_uj: uj, provenance: Provenance::Estimator }, "the rest".into()) + } + + fn span(uj: u64, provenance: JcProvenance, coverage: Coverage, source: SpanSource) -> Own { + Own::Process(Ok(SpanEnergy { uj, provenance, coverage, source })) + } + + fn tree(cpu_nj: u64, gaps: Vec) -> Option> { + Some(Ok(TreeReading { + cpu_uj: cpu_nj.div_ceil(1_000), + cpu_nj, + processes: 1, + pids: vec![7], + wall: std::time::Duration::from_secs(1), + gaps, + })) + } + + /// The grading, pure: a reading keeps its hardware grade only when it covers + /// the whole inference; a partial one is an estimate, the reading plus the + /// rest; no reading is the rest as it is. The receipt never seals a partial + /// reading as `HwShunt`. + #[test] + fn a_reading_keeps_its_hardware_grade_only_when_it_covers_the_whole_inference() { + use jouleclaw_energy::process_gpu::GpuShare; + let gpu = GpuShare { uj: 700, self_ns: 9, rail_uj: Some(710), all_ns: Some(9) }; + let whole = span(1_000, JcProvenance::HwShunt, Coverage::Whole, SpanSource::Process { cpu_uj: 300, gpu }); + let (e, note) = grade(&whole, est(40_000)); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (Some(1_000), 1_000, Provenance::HwShunt)); + assert!(note.starts_with("measured on this process's CPU (300 µJ) and GPU (700 µJ)"), "{note}"); + + let cpu_only = SpanSource::CpuOnly { cpu_uj: 300, why: "process GPU: shared".into() }; + let (e, note) = grade(&span(300, JcProvenance::HwShunt, Coverage::Partial, cpu_only), est(40_000)); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (None, 40_300, Provenance::Estimator)); + assert!(note.contains("shared") && note.starts_with("estimated"), "{note}"); + e.check_provenance().unwrap(); + + // A span that fell back to a host meter (off macOS, the 28.6 W × wall + // estimator) is no reading of the engine: the rest stands, as it is. + let fallback = SpanSource::Fallback { meter: "estimation", why: "process CPU: not live".into() }; + let (e, note) = grade(&span(5_000, JcProvenance::Estimator, Coverage::Whole, fallback), est(40_000)); + assert_eq!(e, est(40_000).0, "the fallback's figure stood in for the rest"); + assert!(note.starts_with("the rest") && note.contains("process CPU: not live"), "{note}"); + let hw_fallback = SpanSource::Fallback { meter: "rapl", why: "process CPU: not live".into() }; + let (e, _) = grade(&span(5_000, JcProvenance::HwShunt, Coverage::Whole, hw_fallback), est(40_000)); + assert_eq!(e, est(40_000).0, "a machine-wide reading is not the engine's own"); + + let (e, note) = grade(&Own::Process(Err(EnergyError::NotAdvanced)), est(40_000)); + assert_eq!(e, est(40_000).0); + assert!(note.starts_with("the rest"), "{note}"); + + // The llama engine's subprocess: never read whole. + let exited = vec![sandbox_meter::TreeGap::Exited { pid: 7 }]; + let child = |reading| Own::Child { reading }; + let (e, note) = grade(&child(tree(9_000_001, exited.clone())), est(40_000)); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (None, 49_001, Provenance::Estimator), "{note}"); + assert!(note.contains("not all of the inference") && note.contains("pid 7 exited"), "{note}"); + let (e, note) = grade(&child(tree(9_000_000, vec![])), est(40_000)); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (None, 49_000, Provenance::Estimator), "{note}"); + assert!(note.contains(NOT_READ_AT_EXIT), "{note}"); + // A hardware host figure does not make the sum a reading. + let hw = (Energy { measured_uj: Some(40_000), estimated_uj: 40_000, provenance: Provenance::HwShunt }, "r".into()); + let (e, _) = grade(&child(tree(9_000_000, exited)), hw.clone()); + assert_eq!((e.measured_uj, e.provenance), (None, Provenance::Estimator)); + for reading in [None, Some(Err(TreeError::RootGone { pid: 7 }))] { + let (e, _) = grade(&child(reading), hw.clone()); + assert_eq!(e, hw.0, "no reading: the host meter's figure as it is"); + } + } + + /// This process's own CPU energy count, nJ: `proc_pid_rusage(getpid(), + /// RUSAGE_INFO_V6)`'s `ri_energy_nj`, read with a bare buffer of the struct's + /// 464 bytes at its SDK offset, 336. Written out here, sharing no code with + /// the meters it checks. + #[cfg(target_os = "macos")] + fn own_energy_nj() -> u64 { + extern "C" { + fn proc_pid_rusage(pid: i32, flavor: i32, buffer: *mut std::ffi::c_void) -> i32; + } + let mut buf = [0u64; 58]; + // SAFETY: `buf` is 464 writable bytes, the size of `rusage_info_v6`. + let rc = unsafe { proc_pid_rusage(std::process::id() as i32, 6, buf.as_mut_ptr().cast()) }; + assert_eq!(rc, 0, "proc_pid_rusage on this process"); + buf[336 / 8] + } + + #[cfg(not(target_os = "macos"))] + fn own_energy_nj() -> u64 { + 0 + } + + /// A fixed amount of CPU work: about a second of one core, unoptimized. + fn burn() -> u64 { + let mut x = 1u64; + for i in 0..150_000_000u64 { + x = std::hint::black_box(x.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(i)); + } + x + } + + /// The in-process engine's meter ([`in_process`], as `main` runs the engine) on + /// CPU work, against an oracle sharing no code with it: this process's own + /// count, read around the same work. The work uses + /// no GPU, so its GPU share is an exact zero and the span covers it whole, a + /// hardware reading of this process — the oracle's window holds the span's, so + /// the reading is at most the oracle and short of it only by the meter's own + /// snapshots. Twice. Where the counters are not live it is the fallback's. + #[test] + fn the_in_process_engine_is_read_on_this_process_as_its_own_count_says() { + let meter = ProcessSpanMeter::new(jouleclaw_backend_apple::gpu_liveness_load); + let metered = meter.is_metered(); + for round in 1..=2 { + let before = own_energy_nj(); + let (x, own) = in_process(&meter, burn); + std::thread::sleep(std::time::Duration::from_millis(20)); + let oracle_uj = (own_energy_nj() - before) / 1_000; + std::hint::black_box(x); + let (e, note) = grade(&own, est(1)); + let Own::Process(energy) = own else { unreachable!() }; + eprintln!("in-process round {round}: oracle {oracle_uj} µJ; span {energy:?}; receipt {e:?} ({note})"); + if metered { + let s = energy.expect("a metered span has a figure"); + let (cpu_uj, gpu) = s.parts().expect("this process's own counters"); + assert_eq!((gpu.uj, gpu.self_ns), (0, 0), "CPU work spent no GPU time"); + assert_eq!((s.coverage, s.provenance), (Coverage::Whole, JcProvenance::HwShunt)); + let ratio = cpu_uj as f64 / oracle_uj as f64; + assert!(oracle_uj > 100_000, "setup: the burn read {oracle_uj} µJ"); + assert!((0.8..=1.02).contains(&ratio), "the span read {cpu_uj} µJ of {oracle_uj} µJ"); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (Some(cpu_uj), cpu_uj, Provenance::HwShunt)); + } else { + assert_ne!(e.provenance, Provenance::HwShunt, "no live counter, yet a reading: {e:?}"); + } + } + } + + /// The stand-in model's marker and report, in its working directory. + const STAND_IN_MARKER: &str = ".llama-stand-in"; + const STAND_IN_REPORT: &str = ".llama-stand-in-report"; + + /// Not a test of its own: the stand-in llama engine, run as a subprocess by + /// [`the_llama_engine_is_read_on_its_own_process_as_its_own_count_says`] (this + /// test binary, filtered to this test, behind a script that takes the engine's + /// arguments). It does a fixed amount of CPU work, leaves the core (which folds + /// its count), and writes its own count to its working directory. Anywhere + /// without its marker it returns at once. + #[test] + #[ignore = "a subprocess stand-in, run by the llama engine's energy test"] + fn llama_stand_in() { + if !std::path::Path::new(STAND_IN_MARKER).exists() { + return; + } + let x = burn(); + std::thread::sleep(std::time::Duration::from_millis(20)); + std::fs::write(STAND_IN_REPORT, format!("{} {x}", own_energy_nj())).expect("the report"); + } + + /// The llama engine's subprocess, read on its own process: the stand-in burns a + /// fixed amount of CPU and reports its own count from inside before it exits — + /// the oracle, sharing no code with the tree meter. Where this host reads the + /// process (macOS, the per-process counter live) the reading agrees with that + /// count to within the shells' start-up and the stand-in's tear-down, and the + /// receipt is an estimate (the process exited in its window), never `HwShunt`. + #[test] + fn the_llama_engine_is_read_on_its_own_process_as_its_own_count_says() { + let dir = std::env::temp_dir().join(format!("l3-llama-stand-in-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).unwrap(); + std::fs::write(dir.join(STAND_IN_MARKER), "").unwrap(); + let exe = std::env::current_exe().expect("this test binary"); + let script = dir.join("stand-in-llama"); + std::fs::write( + &script, + format!("#!/bin/sh\ncd '{}' || exit 1\nexec '{}' tests::llama_stand_in --exact --ignored\n", dir.display(), exe.display()), + ) + .unwrap(); + assert!(std::process::Command::new("chmod").arg("+x").arg(&script).status().unwrap().success()); + let reads_processes = + cfg!(target_os = "macos") && sandbox_meter::process_energy_status() == sandbox_meter::CounterStatus::Live; + let engine = Engine::Llama(LlamaCompletionBackend::new(dir.join("model.gguf")).with_binary(script.display().to_string())); + + for round in 1..=2 { + let (response, own) = infer(&engine, None, &LlmRequest::from_prompt("fib", 16)); + let response = response.expect("the stand-in ran"); + assert!(response.text.contains("1 passed"), "{}", response.text); + let report = std::fs::read_to_string(dir.join(STAND_IN_REPORT)).expect("the stand-in's report"); + let _ = std::fs::remove_file(dir.join(STAND_IN_REPORT)); + let oracle_uj = report.split_whitespace().next().unwrap().parse::().unwrap() / 1_000; + let (e, note) = grade(&own, est(40_000)); + eprintln!("llama engine round {round}: oracle {oracle_uj} µJ; receipt {e:?} ({note})"); + let Own::Child { reading } = own else { panic!("the llama engine is read as a child") }; + if reads_processes { + let r = reading.expect("a tree meter on this host").expect("a reading of the model's process"); + let read = r.cpu_nj.div_ceil(1_000); + assert!(oracle_uj > 100_000, "setup: the stand-in's work read {oracle_uj} µJ"); + let ratio = read as f64 / oracle_uj as f64; + assert!((0.8..=1.25).contains(&ratio), "read {read} µJ of a process that counted {oracle_uj} µJ"); + assert!(!r.is_whole(), "an exited process is never read whole: {r:?}"); + assert_eq!((e.measured_uj, e.estimated_uj, e.provenance), (None, read + 40_000, Provenance::Estimator)); + } else { + assert!(reading.is_none()); + assert_eq!(e, est(40_000).0); + } + } + let _ = std::fs::remove_dir_all(&dir); + } + /// On this host: the IOReport counter is used only where its CPU rail is live. /// Elsewhere on Apple Silicon (macOS 27.0.1 on an M5 Max and an M3 Ultra) the /// load estimator runs and meters the burn, and the receipt says Estimator; with diff --git a/joule-code/examples/l3-jouleclaw/src/llama_backend.rs b/joule-code/examples/l3-jouleclaw/src/llama_backend.rs index b3060446a..bb5a9b197 100644 --- a/joule-code/examples/l3-jouleclaw/src/llama_backend.rs +++ b/joule-code/examples/l3-jouleclaw/src/llama_backend.rs @@ -3,18 +3,35 @@ //! datacenter, no network. This is the production-shaped alternative to //! `EchoBackend`: it implements the same JouleClaw trait, so it drops into the //! same cascade slot. +//! +//! [`LlamaCompletionBackend::complete_metered`] also reads the subprocess's own +//! CPU energy where this host counts each process's ([`sandbox_meter::TreeMeter`]: +//! macOS, the per-process counter live): the model's process, not this one and +//! not the machine. The reading covers that process's CPU only — not the GPU the +//! binary may offload to — and the process exits in its window, so its record +//! lacks its last time on a core: it is never a reading of the whole inference, +//! and the `run` binary grades it as an estimate. use std::path::PathBuf; -use std::process::Command; +use std::process::{Command, Stdio}; use jouleclaw_llm::{FinishReason, LlmBackend, LlmError, LlmRequest, LlmResponse}; +use sandbox_meter::{TreeError, TreeMeter, TreeReading}; /// Drives a local GGUF model via the `llama-completion` binary. pub struct LlamaCompletionBackend { model_path: PathBuf, model_name: String, + /// The binary run: `llama-completion` on `PATH` unless set otherwise. + bin: String, } +/// What the model's process runs as: `sh` waits for a gate line on its stdin, +/// then `exec`s the binary (`$0`) with its arguments (`$@`, passed as argv, +/// never re-parsed), so the model is the very process the tree meter is rooted +/// at and the shell's own start-up is outside the meter's span. +const GATED_EXEC: &str = "IFS= read -r l3_gate || exit 1; exec \"$0\" \"$@\""; + impl LlamaCompletionBackend { /// Back the L3 tier with the GGUF at `model_path`. pub fn new(model_path: impl Into) -> Self { @@ -27,17 +44,50 @@ impl LlamaCompletionBackend { Self { model_path, model_name, + bin: "llama-completion".to_string(), } } -} -impl LlmBackend for LlamaCompletionBackend { - fn model_name(&self) -> &str { - &self.model_name + /// Run `bin` instead of `llama-completion` (a build of it elsewhere, or a + /// stand-in that takes its arguments). + pub fn with_binary(mut self, bin: impl Into) -> Self { + self.bin = bin.into(); + self } - fn complete(&self, request: &LlmRequest) -> Result { - let output = Command::new("llama-completion") + /// [`LlmBackend::complete`], and the model process's own CPU-energy reading + /// over the call: `None` where this host has no per-process counter (off + /// macOS, or not live), else the [`TreeMeter`]'s span from the moment the + /// process is let go to its exit. + /// + /// The process is spawned waiting on its gate ([`GATED_EXEC`]); the tree + /// meter is rooted at it and reads it at rest; the gate line lets it go and + /// its stdin closes. Its stdout and stderr are drained to the end, it is + /// waited for without being reaped, so its exited count is still readable, + /// the meter's span is stopped on it, and then it is reaped. + /// + /// A binary that cannot be run — not on `PATH`, not a file, not executable + /// — is [`LlmError::Unavailable`], as a failed spawn of it would be, and + /// nothing is spawned: `sh` failing to `exec` it would otherwise exit 127, + /// which reads as the model's own failure. + pub fn complete_metered( + &self, + request: &LlmRequest, + ) -> (Result, Option>) { + use std::io::{Read, Write}; + let Some(bin) = executable(&self.bin) else { + return ( + Err(LlmError::Unavailable(format!("spawn {}: no executable file by that name", self.bin))), + None, + ); + }; + // The per-process counter's liveness probe burns about 300 ms of CPU on + // this thread the first time: here, before anything is spawned. + let _ = sandbox_meter::process_energy_status(); + let spawned = Command::new("sh") + .arg("-c") + .arg(GATED_EXEC) + .arg(&bin) .arg("-m") .arg(&self.model_path) .arg("-p") @@ -46,45 +96,145 @@ impl LlmBackend for LlamaCompletionBackend { .arg(request.max_tokens.to_string()) .arg("--temp") .arg("0") - .output() - .map_err(|e| LlmError::Unavailable(format!("spawn llama-completion: {e}")))?; - if !output.status.success() { - return Err(LlmError::Upstream(format!( - "llama-completion exited {:?}", - output.status.code() - ))); + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn(); + let mut child = match spawned { + Ok(c) => c, + Err(e) => return (Err(LlmError::Unavailable(format!("spawn {}: {e}", self.bin))), None), + }; + let pid = child.id(); + let tree = TreeMeter::for_process(pid); + let start = tree.as_ref().map(TreeMeter::start); + if let Some(mut stdin) = child.stdin.take() { + let _ = stdin.write_all(b"\n"); } + // stderr on a thread of its own: the binary logs there while it writes + // stdout, and a full pipe would stall it. + let stderr = child.stderr.take().map(|mut e| { + std::thread::spawn(move || { + let mut v = Vec::new(); + let _ = e.read_to_end(&mut v); + v + }) + }); + let mut stdout = Vec::new(); + if let Some(mut out) = child.stdout.take() { + let _ = out.read_to_end(&mut stdout); + } + let stderr = stderr.and_then(|t| t.join().ok()).unwrap_or_default(); + let reading = match (&tree, start) { + (Some(tree), Some(start)) => { + let _ = wait_exited_unreaped(pid); + Some(tree.stop(start)) + } + _ => None, + }; + let status = child.wait(); + let response = match status { + Err(e) => Err(LlmError::Unavailable(format!("wait for {}: {e}", self.bin))), + Ok(s) if !s.success() => Err(LlmError::Upstream(format!("{} exited {:?}", self.bin, s.code()))), + Ok(_) => Ok(parse_completion(request, &stdout, &stderr)), + }; + (response, reading) + } +} - let stdout = String::from_utf8_lossy(&output.stdout); - let stderr = String::from_utf8_lossy(&output.stderr); +/// The file `bin` names, as `exec` would find it: a path (any name with a `/`) +/// as given, else the first match on `PATH`; `None` unless it is a regular +/// file this process may execute. +fn executable(bin: &str) -> Option { + fn runnable(p: &std::path::Path) -> bool { + let Ok(meta) = std::fs::metadata(p) else { return false }; + #[cfg(unix)] + { + use std::os::unix::fs::PermissionsExt; + meta.is_file() && meta.permissions().mode() & 0o111 != 0 + } + #[cfg(not(unix))] + { + meta.is_file() + } + } + if bin.is_empty() { + return None; + } + if bin.contains('/') { + let p = PathBuf::from(bin); + return runnable(&p).then_some(p); + } + std::env::split_paths(&std::env::var_os("PATH")?).map(|dir| dir.join(bin)).find(|p| runnable(p)) +} - // The chat template wraps output as "...assistant\n{completion}\n> EOF...". - let after = stdout - .rsplit_once("assistant\n") - .map(|(_, c)| c) - .unwrap_or(&stdout); - let text = after - .split("\n> EOF") - .next() - .unwrap_or(after) - .trim() - .to_string(); +/// Wait for child `pid` to exit WITHOUT reaping it (`waitid` with `WNOWAIT`), +/// so its count stays readable for the tree meter's stop walk. The caller reaps +/// it afterwards. `false` if the wait failed. +#[cfg(target_os = "macos")] +fn wait_exited_unreaped(pid: u32) -> bool { + loop { + // SAFETY: an all-zero `siginfo_t` is a valid out-parameter. + let mut info: libc::siginfo_t = unsafe { std::mem::zeroed() }; + // SAFETY: `info` is writable for the call; `pid` is this process's child. + let rc = unsafe { libc::waitid(libc::P_PID, pid as libc::id_t, &mut info, libc::WEXITED | libc::WNOWAIT) }; + if rc == 0 { + return true; + } + if std::io::Error::last_os_error().raw_os_error() != Some(libc::EINTR) { + return false; + } + } +} - // Real token counts from llama.cpp's timing lines; fall back to a coarse - // char/4 estimate if the format shifts. - let input_tokens = - count_before(&stderr, "tokens").unwrap_or((request.prompt.len() / 4) as u32); - let output_tokens = count_before(&stderr, "runs").unwrap_or((text.len() / 4) as u32); +/// No tree meter exists off macOS, so there is nothing to read before the reap. +#[cfg(not(target_os = "macos"))] +fn wait_exited_unreaped(_pid: u32) -> bool { + false +} - Ok(LlmResponse { - text, - finish_reason: FinishReason::Stop, - input_tokens, - output_tokens, - // The backend itself does not meter joules; the caller measures host - // energy over the call (see the `run` binary), keeping provenance honest. - energy_joules: None, - }) +impl LlmBackend for LlamaCompletionBackend { + fn model_name(&self) -> &str { + &self.model_name + } + + fn complete(&self, request: &LlmRequest) -> Result { + self.complete_metered(request).0 + } +} + +/// The completion in llama-completion's output. +fn parse_completion(request: &LlmRequest, stdout: &[u8], stderr: &[u8]) -> LlmResponse { + let stdout = String::from_utf8_lossy(stdout); + let stderr = String::from_utf8_lossy(stderr); + + // The chat template wraps output as "...assistant\n{completion}\n> EOF...". + let after = stdout + .rsplit_once("assistant\n") + .map(|(_, c)| c) + .unwrap_or(&stdout); + let text = after + .split("\n> EOF") + .next() + .unwrap_or(after) + .trim() + .to_string(); + + // Real token counts from the binary's timing lines; fall back to a coarse + // char/4 estimate if the format shifts. + let input_tokens = + count_before(&stderr, "tokens").unwrap_or((request.prompt.len() / 4) as u32); + let output_tokens = count_before(&stderr, "runs").unwrap_or((text.len() / 4) as u32); + + LlmResponse { + text, + finish_reason: FinishReason::Stop, + input_tokens, + output_tokens, + // The backend puts no joule figure on the response: its reading of the + // model's process ([`LlamaCompletionBackend::complete_metered`]) is + // partial, and the caller grades it with the rest (see the `run` + // binary), keeping provenance honest. + energy_joules: None, } } @@ -103,3 +253,36 @@ fn count_before(stderr: &str, unit: &str) -> Option { } None } + +#[cfg(test)] +mod tests { + use super::*; + + /// A binary that cannot be run is `Unavailable`, as a failed spawn of it is, + /// with no reading: never the `Upstream` failure of a model that ran, which + /// `sh` exiting 127 on a failed `exec` would read as. + #[test] + fn a_binary_that_cannot_run_is_unavailable_not_a_model_failure() { + let dir = std::env::temp_dir().join(format!("l3-unrunnable-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).unwrap(); + let not_executable = dir.join("llama-completion"); + std::fs::write(¬_executable, "#!/bin/sh\necho hi\n").unwrap(); + let bins = [ + "/nonexistent/llama-completion".to_string(), + "l3-jouleclaw-no-such-binary-on-path".to_string(), + not_executable.display().to_string(), + dir.display().to_string(), + ]; + for bin in bins { + let backend = LlamaCompletionBackend::new(dir.join("model.gguf")).with_binary(bin.clone()); + let (response, reading) = backend.complete_metered(&LlmRequest::from_prompt("fib", 4)); + match response { + Err(LlmError::Unavailable(why)) => assert!(why.contains(&bin), "{why}"), + other => panic!("{bin}: {other:?}"), + } + assert!(reading.is_none(), "{bin}: nothing ran, yet a reading"); + } + let _ = std::fs::remove_dir_all(&dir); + } +} diff --git a/joule-code/joule-code-rs/Cargo.lock b/joule-code/joule-code-rs/Cargo.lock index 9b6eea4e3..3b3c147cf 100644 --- a/joule-code/joule-code-rs/Cargo.lock +++ b/joule-code/joule-code-rs/Cargo.lock @@ -1307,6 +1307,7 @@ dependencies = [ "joulecontract-receipt", "joulecontract-schema", "joulecontract-wire", + "libc", "proof-cascade", "proof-schema", "proof-solvers", diff --git a/joule-code/joule-code-rs/crates/joule-code-remediate/Cargo.toml b/joule-code/joule-code-rs/crates/joule-code-remediate/Cargo.toml index c2e15276f..b83ecaca9 100644 --- a/joule-code/joule-code-rs/crates/joule-code-remediate/Cargo.toml +++ b/joule-code/joule-code-rs/crates/joule-code-remediate/Cargo.toml @@ -35,6 +35,11 @@ proof-cascade = { path = "../../../../proof/proof-rs/crates/proof-cascade" } proof-solvers = { path = "../../../../proof/proof-rs/crates/proof-solvers" } proof-schema = { path = "../../../../proof/proof-rs/crates/proof-schema" } +# macOS: the L3 model's process is waited for without being reaped +# (`waitid` with `WNOWAIT`), so the tree meter reads its exited count. +[target.'cfg(target_os = "macos")'.dependencies] +libc = "0.2" + [[bin]] name = "joule-fix" path = "src/bin/joule_fix.rs" diff --git a/joule-code/joule-code-rs/crates/joule-code-remediate/src/bin/joule_fix.rs b/joule-code/joule-code-rs/crates/joule-code-remediate/src/bin/joule_fix.rs index 35285fac0..5c69b27db 100644 --- a/joule-code/joule-code-rs/crates/joule-code-remediate/src/bin/joule_fix.rs +++ b/joule-code/joule-code-rs/crates/joule-code-remediate/src/bin/joule_fix.rs @@ -42,6 +42,22 @@ fn main() { report.meter_source, ); } + if let Some(l3) = &report.l3 { + match l3.process_cpu_uj { + Some(read) => println!( + " of which the L3 model's window: {:.3} J (an estimate: its own process tree read {:.3} J of CPU, \ + partial: {}; plus the machine-wide figure)", + l3.figure_uj as f64 / 1e6, + read as f64 / 1e6, + l3.partial_because.join("; "), + ), + None => println!( + " of which the L3 model's window: {:.3} J (machine-wide only{})", + l3.figure_uj as f64 / 1e6, + l3.partial_because.first().map(|w| format!("; {w}")).unwrap_or_default(), + ), + } + } if let Some(uj) = report.uj_per_verified_fix() { println!( "energy per verified fix: {:.3} J ({})", diff --git a/joule-code/joule-code-rs/crates/joule-code-remediate/src/lib.rs b/joule-code/joule-code-rs/crates/joule-code-remediate/src/lib.rs index 79ff38c0f..afe26b72f 100644 --- a/joule-code/joule-code-rs/crates/joule-code-remediate/src/lib.rs +++ b/joule-code/joule-code-rs/crates/joule-code-remediate/src/lib.rs @@ -38,7 +38,8 @@ use joulecontract_schema::{ Ceiling, ContentAddress, Contract, EnergyClass, GovernanceClass, ObligationKind, Profile, Rigor, }; -use sandbox_meter::{run_attributed, Attribution, PowerMeter}; +use sandbox_meter::{run_attributed, Attribution, PowerMeter, TreeError, TreeMeter, TreeReading}; +use sandbox_schema::DeviceClass; use serde::{Deserialize, Serialize}; // The formally-verified fix tier. `DischargeStatus`/`Formalization`/ // `ContractDischarge` come from the proof bridge; the bridge's own @@ -53,37 +54,48 @@ use std::path::PathBuf; use std::process::Command; use std::time::{Duration, Instant}; -/// Accumulates per-process energy attribution across a run's cargo -/// subprocesses (the real compute). The harness's `run()` helper feeds this -/// for every `cargo` invocation; git and rustfmt are negligible overhead and -/// run unmetered. +/// Accumulates per-process energy attribution across a run's subprocesses +/// (the real compute): every `cargo` invocation, which the harness's `run()` +/// helper feeds, and the L3 model's command, which [`Harness::run_l3`] feeds. +/// git and rustfmt are negligible overhead and run unmetered. struct MeterAcc { /// `PowerMeter::detect()`, machine-wide, and deliberately not /// `detect_in_process()`: the metered work is `cargo` and the `rustc` - /// processes it runs, and this process's own energy counter covers no - /// child process. `run_attributed`'s per-child reading does not reach - /// them either: it covers a single-process child, and `cargo` runs its - /// work in descendants. + /// processes it runs, and the L3 model's process, and this process's own + /// energy counter covers no child process. `run_attributed`'s per-child + /// reading does not reach cargo's work either: it covers a single-process + /// child, and `cargo` runs its work in descendants. meter: PowerMeter, /// This run's metered windows, reset at the start of each run. tally: EnergyTally, + /// This run's L3 window, when the model was consulted: how it was metered + /// and what it added to `tally`. Reset with it. + l3: Option, } -/// The energy of one run's metered cargo windows, and the figure and grades -/// the receipts carry for it. +/// The energy of one run's metered windows — its cargo windows and its L3 +/// window — and the figure and grades the receipts carry for it. /// -/// A window is attributed when a hardware CPU reading that advanced was -/// apportioned to the child's process tree (`ModelBased`). Otherwise its +/// A cargo window is attributed when a hardware CPU reading that advanced +/// was apportioned to the child's process tree (`ModelBased`). Otherwise its /// figure is not a reading of this workload. It is the meter's wall × TDP /// estimate where the host exposes no live CPU counter (every macOS 27.0.1 /// host checked), or where the counter held; or it is a machine-wide figure -/// the meter could not apportion. The run is `ModelBased` only when every -/// window was attributed, because a sum is only as good as its weakest part. -#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)] +/// the meter could not apportion. The L3 window is never attributed: its +/// model's own process tree is never read whole ([`grade_l3`]). The run is +/// `ModelBased` only when every window was attributed, because a sum is only +/// as good as its weakest part. +#[derive(Clone, Debug, Default, PartialEq, Eq)] struct EnergyTally { - /// Σ machine-wide SoC-CPU figure over the windows (the upper bound). + /// Σ each window's figure as an estimate of its work: over a cargo + /// window the machine-wide SoC-CPU figure (an upper bound: every process + /// on the host), over the L3 window [`L3Energy::figure_uj`]. soc_uj: u64, - /// Σ figure apportioned to this run's process trees. + /// The part of `soc_uj` in device classes other than the CPU, per class: + /// what the machine-wide meter read of them over an L3 window (a GPU + /// rail, NVML's GPUs). A cargo window's figure is the CPU's alone. + non_cpu_uj: std::collections::BTreeMap, + /// Σ figure apportioned or read for this run's process trees. attr_uj: u64, windows: u64, attributed_windows: u64, @@ -91,10 +103,30 @@ struct EnergyTally { impl EnergyTally { fn add(&mut self, a: &Attribution) { - self.soc_uj = self.soc_uj.saturating_add(a.soc_cpu_uj); - self.attr_uj = self.attr_uj.saturating_add(a.attributed_uj); + self.add_window(a.soc_cpu_uj, a.attributed_uj, a.attributed); + } + + /// The L3 window: its figure, an estimate, never attributed, with the + /// machine-wide meter's figure for each class other than the CPU kept + /// apart, so the sealed record names the class it was read on. + fn add_l3(&mut self, l3: &L3Energy) { + self.add_window(l3.figure_uj, l3.attributed_uj(), false); + for &(class, uj) in &l3.machine_by_class { + if class != DeviceClass::Cpu { + let sum = self.non_cpu_uj.entry(class).or_default(); + *sum = sum.saturating_add(uj); + } + } + } + + /// One window: its figure as an estimate (`estimate_uj`), its figure as + /// a reading or apportionment of its own process tree (`attributed_uj`), + /// and whether that one is the window's honest figure (`attributed`). + fn add_window(&mut self, estimate_uj: u64, attributed_uj: u64, attributed: bool) { + self.soc_uj = self.soc_uj.saturating_add(estimate_uj); + self.attr_uj = self.attr_uj.saturating_add(attributed_uj); self.windows += 1; - if a.attributed { + if attributed { self.attributed_windows += 1; } } @@ -119,20 +151,29 @@ impl EnergyTally { } } - /// The sandbox JCR-1 meter record for the figure. It is `ModelBased` for - /// an attribution, and otherwise the `Estimator` grade with no measured - /// figure. - fn meter_record(&self) -> sandbox_meter::DeviceEnergy { - sandbox_meter::DeviceEnergy { - class: sandbox_schema::DeviceClass::Cpu, + /// The sandbox JCR-1 meter records for the figure, one per device class, + /// summing to it. An attribution is one `ModelBased` CPU record (every + /// window attributed, so no L3 window and nothing off the CPU). An + /// estimate is an `Estimator` record with no measured figure for the CPU + /// and one for each other class the L3 window's machine-wide meter read: + /// a GPU's energy is never sealed as the CPU's. + fn meter_records(&self) -> Vec { + let record = |class, estimated_uj, provenance| sandbox_meter::DeviceEnergy { + class, measured_uj: None, - estimated_uj: self.figure_uj(), - provenance: if self.attributed() { - sandbox_meter::Provenance::ModelBased - } else { - sandbox_meter::Provenance::Estimator - }, + estimated_uj, + provenance, + }; + if self.attributed() { + return vec![record(DeviceClass::Cpu, self.attr_uj, sandbox_meter::Provenance::ModelBased)]; } + let non_cpu: u64 = self.non_cpu_uj.values().fold(0, |a, &b| a.saturating_add(b)); + let mut records = + vec![record(DeviceClass::Cpu, self.soc_uj.saturating_sub(non_cpu), sandbox_meter::Provenance::Estimator)]; + records.extend( + self.non_cpu_uj.iter().map(|(&class, &uj)| record(class, uj, sandbox_meter::Provenance::Estimator)), + ); + records } /// The JouleContract energy class for the figure. It is `ModelBased`, @@ -148,6 +189,194 @@ impl EnergyTally { } } +/// The L3 model's window: how its energy was read, and what it adds to the +/// run's figure ([`RunReport::total_uj`], and so +/// [`RunReport::uj_per_verified_fix`] and both receipts). +/// +/// Two meters span the window, from the moment the command is let go (see +/// [`Harness::l3_cmd`]) to the moment it has exited and been reaped: the +/// machine-wide meter, as over a cargo window, and — where this host counts +/// each process's CPU energy (macOS, its per-process counter live) — a +/// [`TreeMeter`] rooted at the command's own process, which reads the CPU +/// energy of that process and its descendants and lists every way that +/// figure was seen to fall short of their whole energy. [`grade_l3`] turns +/// the two into the window's figure, in one place. +#[derive(Clone, Debug, PartialEq, Eq)] +pub struct L3Energy { + /// The machine-wide meter's figure over the window, every device class + /// it reads, µJ: a hardware reading where the host has a live + /// machine-wide counter (RAPL, NVML on Linux), its wall-clock × TDP + /// estimate where it has none (every macOS 27.0.1 host checked). Like a + /// cargo window's, it is the whole host's, other processes included. + pub machine_uj: u64, + /// The same figure per device class, as the meter read them (the CPU, + /// and a GPU where it reads one); `machine_uj` is their sum. The run's + /// sealed records keep the classes apart. + pub machine_by_class: Vec<(DeviceClass, u64)>, + /// The CPU energy of the model's own process tree over the window, µJ + /// (the [`TreeReading`]'s nanojoules rounded up), where the host counts + /// it. `None` off macOS, where the per-process counter is not live, and + /// when the span gave no reading (`partial_because` says why). It covers + /// the model's CPU only: not its GPU or Neural Engine work, not work it + /// hands to a process outside its tree, and not the last time on a core + /// of a thread that exits (the kernel never folds it), which a model that + /// exits in the window always has. + pub process_cpu_uj: Option, + /// Why `process_cpu_uj` is not the model's whole energy over the window: + /// each gap the tree meter saw, as it words it — a model that exits in + /// its window always has one, so its reading is never whole — or, where + /// it saw none, [`NOT_READ_AT_EXIT`]; or why there is no reading at all. + /// Never empty for a reading. + pub partial_because: Vec, + /// Whether the command ran as the shell's `exec` — a plain argv — so the + /// model's process IS the process the tree meter is rooted at, and its + /// own count is read. A command that is not (a pipeline, a list, quoting, + /// a redirect) runs as the shell's script: what the shell forks and + /// reaps is a gap, its energy in no counter. + pub direct_child: bool, + /// What the window adds to the run's figure (see [`grade_l3`]), µJ: an + /// estimate, never attributed. + pub figure_uj: u64, +} + +/// Why a reading of the L3 command's process tree is partial although the +/// tree meter saw no gap in it: the model had not exited when it was read +/// (the wait for its exit failed), so the reading may stop short of its +/// work. A model read at its exit always carries the exit's own gap instead. +pub const NOT_READ_AT_EXIT: &str = + "the model had not exited when its process tree was read, so the reading may stop short of its work"; + +impl L3Energy { + /// What the window's process reading added to the run's tree figures: + /// the reading itself, a floor, else nothing. + fn attributed_uj(&self) -> u64 { + self.process_cpu_uj.unwrap_or(0) + } + + /// The window in one line, for [`RunReport::meter_source`]. + fn describe(&self) -> String { + let j = |uj: u64| uj as f64 / 1e6; + match self.process_cpu_uj { + Some(read) => format!( + "L3 model's own process tree read {:.3} J of CPU, partial ({}), so the window is an estimate: that \ + reading plus the machine-wide {:.3} J, {:.3} J", + j(read), + self.partial_because.join("; "), + j(self.machine_uj), + j(self.figure_uj) + ), + None => format!( + "L3 model metered machine-wide only, {:.3} J ({})", + j(self.machine_uj), + if self.partial_because.is_empty() { + "no per-process counter on this host".to_string() + } else { + self.partial_because.join("; ") + } + ), + } + } +} + +/// The L3 window's figure: the one place it is decided. It is always an +/// estimate of the window, never attributed. +/// +/// - **A reading** — never whole. The model is read at its exit, and an +/// exiting process's record lacks its last time on a core (the kernel +/// never folds it), so the reading is a lower bound on the model's own CPU +/// energy; its GPU time is unknown, and work it hands outside its tree is +/// in no reading of it. The figure is the reading plus the machine-wide +/// meter's figure over the same window — never less than was read, and +/// nothing the model drew outside its CPU left out — the rule mesh's +/// in-process meter bills a partial span by. The machine-wide figure +/// covers the model's CPU too, so this errs high, by at most the reading. +/// - **No reading** — no per-process counter (Linux, a counter that is not +/// live) or the span's [`TreeError`]: the machine-wide figure, exactly as +/// a cargo window's (it is the whole host's). +fn grade_l3( + reading: Option<&Result>, + machine_by_class: Vec<(DeviceClass, u64)>, + direct_child: bool, +) -> L3Energy { + let machine_uj = machine_by_class.iter().fold(0u64, |a, &(_, uj)| a.saturating_add(uj)); + match reading { + Some(Ok(r)) => { + let read = r.cpu_nj.div_ceil(1_000); + let mut because: Vec = r.gaps.iter().map(ToString::to_string).collect(); + if because.is_empty() { + because.push(NOT_READ_AT_EXIT.to_string()); + } + L3Energy { + machine_uj, + machine_by_class, + process_cpu_uj: Some(read), + partial_because: because, + direct_child, + figure_uj: read.saturating_add(machine_uj), + } + } + Some(Err(e)) => L3Energy { + machine_uj, + machine_by_class, + process_cpu_uj: None, + partial_because: vec![format!("no reading of the model's process tree: {e}")], + direct_child, + figure_uj: machine_uj, + }, + None => L3Energy { + machine_uj, + machine_by_class, + process_cpu_uj: None, + partial_because: Vec::new(), + direct_child, + figure_uj: machine_uj, + }, + } +} + +/// The shell script an L3 command runs as, and whether it makes the model +/// the direct child. +/// +/// The script first waits on a gate — one line on its stdin, which +/// [`Harness::run_l3`] writes once the tree meter has read the waiting +/// shell — so the window opens before the model starts and the shell's own +/// start-up stays outside it. Then, for a plain argv (letters, digits, +/// spaces and `/._-:,+@` only: no quoting, expansion, assignment, redirect +/// or list), the shell `exec`s it, so the model is the same process the +/// meter is rooted at. Anything else runs as the rest of the script, as +/// `sh -c` would have run it: what it forks and reaps is in no counter. +fn l3_script(cmd: &str) -> (String, bool) { + let cmd = cmd.trim(); + let plain = !cmd.is_empty() && cmd.chars().all(|c| c.is_ascii_alphanumeric() || " /._-:,+@".contains(c)); + let body = if plain { format!("exec {cmd}") } else { cmd.to_string() }; + (format!("IFS= read -r joule_fix_gate || exit 1\n{body}\n"), plain) +} + +/// Wait for child `pid` to exit WITHOUT reaping it (`waitid` with +/// `WNOWAIT`), so its count stays readable for the tree meter's stop walk. +/// The caller reaps it afterwards. `false` if the wait failed. +#[cfg(target_os = "macos")] +fn wait_exited_unreaped(pid: u32) -> bool { + loop { + // SAFETY: an all-zero `siginfo_t` is a valid out-parameter. + let mut info: libc::siginfo_t = unsafe { std::mem::zeroed() }; + // SAFETY: `info` is writable for the call; `pid` is this process's child. + let rc = unsafe { libc::waitid(libc::P_PID, pid as libc::id_t, &mut info, libc::WEXITED | libc::WNOWAIT) }; + if rc == 0 { + return true; + } + if std::io::Error::last_os_error().raw_os_error() != Some(libc::EINTR) { + return false; + } + } +} + +/// No tree meter exists off macOS, so there is nothing to read before the reap. +#[cfg(not(target_os = "macos"))] +fn wait_exited_unreaped(_pid: u32) -> bool { + false +} + #[derive(Debug, thiserror::Error)] pub enum HarnessError { #[error("not a git work tree: {0} (the harness needs revert-ability before it will touch anything)")] @@ -237,18 +466,27 @@ pub struct RunReport { pub shipped: bool, /// The branch carrying the fix, when shipped. pub branch: Option, - /// Energy apportioned to this run's process trees, microjoules. When - /// `attributed`, it is a `ModelBased` apportionment of a real SoC reading: + /// Energy apportioned to, or read for, this run's process trees, + /// microjoules: each cargo window's apportionment, and the L3 model's + /// own process-tree reading where there is one ([`L3Energy`]). When + /// `attributed`, it is a `ModelBased` figure resting on real readings: /// the receipts' figure, and the honest per-workload cost. Otherwise it is - /// at best an estimate, and is context only. + /// at best an estimate or a floor, and is context only. pub attributed_uj: u64, - /// Machine-wide SoC-CPU figure over the metered windows, microjoules — the - /// upper bound. When not `attributed`, this is the receipts' figure, as an - /// estimate. + /// Each metered window's figure as an estimate, summed, microjoules: + /// over a cargo window the machine-wide SoC-CPU figure (an upper bound, + /// every process on the host), over the L3 window + /// [`L3Energy::figure_uj`]. When not `attributed`, this is the receipts' + /// figure, as an estimate. pub soc_cpu_uj: u64, /// True when every metered window rested on real per-process accounting /// of a hardware CPU reading. False means the receipts carry an estimate. pub attributed: bool, + /// The L3 model's window, when the model was consulted: its machine-wide + /// figure, its own process tree's reading and why that is partial, and + /// what it added to this run's figure. Its energy is in `soc_cpu_uj`, + /// `attributed_uj` and the receipts. + pub l3: Option, pub wall: Duration, pub meter_source: String, pub contract: Contract, @@ -268,10 +506,11 @@ pub struct RunReport { impl RunReport { /// Microjoules for the whole verified run (measure → fix → gate), the - /// figure the receipts carry. When `attributed`, it is the energy - /// ATTRIBUTED to this run's process trees, not the machine-wide total. - /// Otherwise it is the machine-wide figure over the metered windows, which - /// is then an estimate and is sealed as one (`Estimator`, `Unaccounted`). + /// figure the receipts carry: every cargo window and the L3 model's + /// window. When `attributed`, it is the energy ATTRIBUTED to this run's + /// process trees, not the machine-wide total. Otherwise it is each + /// window's estimate summed ([`soc_cpu_uj`](Self::soc_cpu_uj)), which is + /// then an estimate and is sealed as one (`Estimator`, `Unaccounted`). /// It is never an apportioned zero for work that ran. pub fn total_uj(&self) -> u64 { if self.attributed { @@ -374,6 +613,18 @@ pub struct Harness { /// a federation leg) — and whatever comes back faces the same gates as /// the deterministic tier, which is what makes a weak model SAFE to run. /// Defaults from `JOULE_FIX_L3_CMD`; `None` disables the tier. + /// + /// The command is metered ([`L3Energy`]) and its energy is part of the + /// run's figure. It runs under `sh`, which waits for a gate line before + /// it starts the command (so the meter opens on a shell at rest) and then + /// `exec`s a plain argv — `granite-fix /path/to/snapshot` — so the model + /// is the shell's own process and its own energy count is readable. A + /// command that needs the shell (a pipeline, a list, quoting) runs as the + /// shell's script instead, and what the shell forks and reaps is energy + /// no counter holds: the reading says so. The reading is never whole — + /// the model exits in its window, and an exiting process's record lacks + /// its last time on a core — so the window is always an estimate + /// ([`grade_l3`]). pub l3_cmd: Option, /// Where induced skills persist. Defaults from `JOULE_FIX_SKILLS`, else /// `~/.joule-fix/skills.json`; the store is created on first induction. @@ -427,6 +678,7 @@ impl Harness { meter: RefCell::new(MeterAcc { meter: PowerMeter::detect(), tally: EnergyTally::default(), + l3: None, }), #[cfg(test)] cargo_target_dir, @@ -445,7 +697,7 @@ impl Harness { if program == "cargo" { let args = self.cargo_args(args); let mut acc = self.meter.borrow_mut(); - let MeterAcc { meter, tally } = &mut *acc; + let MeterAcc { meter, tally, .. } = &mut *acc; let (ok, text, a) = run_attributed(meter, program, &args, &self.workspace) .map_err(|e| HarnessError::Spawn(format!("{program}: {e}")))?; tally.add(&a); @@ -546,12 +798,17 @@ impl Harness { let prior_rev = self.git_head()?; let prior = ContentId::of_bytes(prior_rev.as_bytes()); - // Reset the per-run tally, all of it; this run's cargo calls feed it. - // An earlier run's windows are not this run's energy: without the - // reset, a second run on this Harness would seal the first run's - // cargo figure into its own receipts (on every host, estimated or - // not), and an attributed earlier window could grade this one. - self.meter.borrow_mut().tally = EnergyTally::default(); + // Reset the per-run tally, all of it; this run's cargo calls and its + // L3 window feed it. An earlier run's windows are not this run's + // energy: without the reset, a second run on this Harness would seal + // the first run's figure into its own receipts (on every host, + // estimated or not), and an attributed earlier window could grade + // this one. + { + let mut acc = self.meter.borrow_mut(); + acc.tally = EnergyTally::default(); + acc.l3 = None; + } let wall_start = Instant::now(); // ---- Stage 0: baseline (the `pre` obligation's evidence). @@ -787,17 +1044,18 @@ impl Harness { }; // ---- Energy: the per-window accounting accumulated across the run's - // cargo subprocesses. When every window was attributed, the receipts - // carry the ATTRIBUTED figure (ModelBased — an apportionment of a real - // SoC reading), not the machine-wide total. Otherwise they carry an - // estimate and grade it as one — never a figure signed as a reading. - let (tally, meter_sources) = { + // cargo subprocesses and its L3 model. When every window was + // attributed, the receipts carry the ATTRIBUTED figure (ModelBased — + // resting on real readings), not the machine-wide total. Otherwise + // they carry an estimate and grade it as one — never a figure signed + // as a reading. + let (tally, meter_sources, l3) = { let acc = self.meter.borrow(); - (acc.tally, acc.meter.sources()) + (acc.tally.clone(), acc.meter.sources(), acc.l3.clone()) }; let (soc_cpu_uj, attributed_uj, attributed) = (tally.soc_uj, tally.attr_uj, tally.attributed()); let wall = wall_start.elapsed(); - let meter_source = if attributed { + let base_source = if attributed { "attributed(ModelBased over IOReport HwShunt)".to_string() } else if meter_sources.is_empty() { "estimated(Unaccounted): wall-clock × TDP, no live energy counter on this host".to_string() @@ -808,6 +1066,10 @@ impl Harness { meter_sources.join("+") ) }; + let meter_source = match &l3 { + Some(l3) => format!("{base_source}; {}", l3.describe()), + None => base_source, + }; // The sandbox meter receipt seals the receipts' figure with its grade: // ModelBased for an attribution, the Estimator grade for an estimate. @@ -815,7 +1077,7 @@ impl Harness { let meter_receipt = sandbox_meter::Receipt::build( sandbox_schema::ContentId::of_bytes(prior_rev.as_bytes()), sandbox_schema::Tier::S0, - vec![tally.meter_record()], + tally.meter_records(), 1, [3u8; 8], ) @@ -848,6 +1110,7 @@ impl Harness { attributed_uj, soc_cpu_uj, attributed, + l3, wall, meter_source, contract, @@ -1080,9 +1343,10 @@ impl Harness { /// One L3 consultation: prompt = the remaining findings plus the touched /// files' contents; reply = SEARCH/REPLACE blocks, applied verbatim. /// Returns true when the model changed anything. The GATES decide whether - /// any of it survives — this function trusts nothing it applies. + /// any of it survives — this function trusts nothing it applies. The + /// model's command is metered and its energy enters the run's figure + /// ([`run_l3`](Self::run_l3)). fn l3_pass(&self) -> Result { - use std::io::Write; let cmd = self.l3_cmd.as_ref().expect("caller checked"); let all = self.current_findings()?; @@ -1117,21 +1381,7 @@ impl Harness { } } - let mut child = Command::new("sh") - .args(["-c", cmd]) - .current_dir(&self.workspace) - .stdin(std::process::Stdio::piped()) - .stdout(std::process::Stdio::piped()) - .stderr(std::process::Stdio::null()) - .spawn() - .map_err(|e| HarnessError::Spawn(format!("L3 cmd: {e}")))?; - if let Some(stdin) = child.stdin.as_mut() { - let _ = stdin.write_all(prompt.as_bytes()); - } - let out = child - .wait_with_output() - .map_err(|e| HarnessError::Spawn(format!("L3 cmd: {e}")))?; - let reply = String::from_utf8_lossy(&out.stdout).into_owned(); + let reply = self.run_l3(cmd, prompt.as_bytes())?; if self.apply_search_replace(&reply) { return Ok(true); @@ -1142,6 +1392,68 @@ impl Harness { Ok(false) } + /// Run the L3 command on `prompt` and meter it: its stdout, with the + /// window's [`L3Energy`] added to this run's tally. + /// + /// The command is spawned as [`l3_script`] says, waiting on its gate. + /// The tree meter (where this host has one) is rooted at that process and + /// reads it at rest; the machine-wide span opens; the gate line and the + /// prompt go to its stdin, and it runs. Its stdout is read to the end, it + /// is waited for without being reaped, so its exited count is still + /// readable, and the tree meter's span is stopped on it; then it is + /// reaped and the machine-wide span closed. [`grade_l3`] grades the two. + fn run_l3(&self, cmd: &str, prompt: &[u8]) -> Result { + use std::io::{Read, Write}; + let (script, direct_child) = l3_script(cmd); + // The per-process counter's liveness probe burns about 300 ms of CPU + // on this thread the first time: here, before anything is spawned. + let _ = sandbox_meter::process_energy_status(); + let mut child = Command::new("sh") + .args(["-c", &script]) + .current_dir(&self.workspace) + .stdin(std::process::Stdio::piped()) + .stdout(std::process::Stdio::piped()) + .stderr(std::process::Stdio::null()) + .spawn() + .map_err(|e| HarnessError::Spawn(format!("L3 cmd: {e}")))?; + let pid = child.id(); + // `None` off macOS, where the per-process counter is not live, or + // where the process cannot be read. + let tree = TreeMeter::for_process(pid); + let tree_start = tree.as_ref().map(TreeMeter::start); + + let mut acc = self.meter.borrow_mut(); + let machine = acc.meter.start(); + if let Some(mut stdin) = child.stdin.take() { + // The gate, then the prompt; dropping stdin closes it. A command + // that stops reading early closes the pipe, and the rest of the + // prompt is its own business, as it always was. + let _ = stdin.write_all(b"\n").and_then(|()| stdin.write_all(prompt)); + } + let mut reply = Vec::new(); + if let Some(mut out) = child.stdout.take() { + let _ = out.read_to_end(&mut reply); + } + let reading = match (&tree, tree_start) { + (Some(tree), Some(start)) => { + // Exited and not reaped: the stop walk reads its final record. + // Should the wait fail, the walk reads whatever the process is + // then, and its gaps say so. + let _ = wait_exited_unreaped(pid); + Some(tree.stop(start)) + } + _ => None, + }; + let status = child.wait(); + let m = machine.stop(&mut acc.meter); + let by_class = m.devices.iter().map(|d| (d.class, d.measured_uj.unwrap_or(d.estimated_uj))).collect(); + let l3 = grade_l3(reading.as_ref(), by_class, direct_child); + acc.tally.add_l3(&l3); + acc.l3 = Some(l3); + status.map_err(|e| HarnessError::Spawn(format!("L3 cmd: {e}")))?; + Ok(String::from_utf8_lossy(&reply).into_owned()) + } + /// Apply a whole-file reply: the first fenced code block becomes the /// file's new contents. Trusts nothing — the gates judge the result. fn apply_fenced_file(&self, reply: &str, path: &str) -> bool { @@ -1523,7 +1835,9 @@ fn answers() { assert_eq!(answer(), 42); } assert!(!t.attributed()); assert_eq!(t.figure_uj(), 60_000_000, "the unapportioned estimate"); assert_eq!(t.energy_class(), EnergyClass::Unaccounted); - let r = t.meter_record(); + let records = t.meter_records(); + assert_eq!(records.len(), 1, "cargo windows are the CPU's alone: {records:?}"); + let r = &records[0]; assert_eq!(r.provenance, sandbox_meter::Provenance::Estimator); assert_eq!((r.measured_uj, r.estimated_uj), (None, 60_000_000)); r.check_provenance().unwrap(); @@ -1582,15 +1896,17 @@ fn answers() { assert_eq!(answer(), 42); } assert!(all.attributed()); assert_eq!(all.figure_uj(), 10_000_000, "the apportioned reading"); assert_eq!(all.energy_class(), EnergyClass::ModelBased); - assert_eq!(all.meter_record().provenance, sandbox_meter::Provenance::ModelBased); - all.meter_record().check_provenance().unwrap(); + let records = all.meter_records(); + assert_eq!(records.len(), 1, "{records:?}"); + assert_eq!((records[0].class, records[0].provenance), (DeviceClass::Cpu, sandbox_meter::Provenance::ModelBased)); + records[0].check_provenance().unwrap(); let mut mixed = all; mixed.add(&window(20_000_000, 0, false)); assert!(!mixed.attributed()); assert_eq!(mixed.figure_uj(), 60_000_000, "the unapportioned estimate"); assert_eq!(mixed.energy_class(), EnergyClass::Unaccounted); - assert_eq!(mixed.meter_record().provenance, sandbox_meter::Provenance::Estimator); + assert_eq!(mixed.meter_records()[0].provenance, sandbox_meter::Provenance::Estimator); // Nothing metered is not an attribution either. assert!(!EnergyTally::default().attributed()); @@ -1635,6 +1951,256 @@ fn answers() { assert_eq!(answer(), 42); } let src = std::fs::read_to_string(dir.join("src/main.rs")).unwrap(); assert!(src.contains("std::f64::consts::PI")); + // The model's window was metered and is in the run's figure. The + // mock is a shell script that forks `cat`: on a host that reads the + // model's own process, that reaped `cat` is a gap, so the window is + // an estimate holding the reading and the machine-wide figure. + let l3 = report.l3.clone().expect("the L3 window was metered"); + eprintln!("l3 window: {l3:?}; run total {} µJ ({})", report.total_uj(), report.meter_source); + assert!(l3.machine_uj > 0 && l3.figure_uj >= l3.machine_uj, "{l3:?}"); + assert!(l3.direct_child, "`./mock-l3.sh` is a plain argv"); + assert!(!report.attributed, "an L3 window is never attributed"); + assert!(report.total_uj() >= l3.figure_uj, "{} µJ total < the L3 window's {l3:?}", report.total_uj()); + assert!(report.meter_source.contains("L3 model"), "{}", report.meter_source); + if let Some(read) = l3.process_cpu_uj { + assert_eq!(l3.figure_uj, read + l3.machine_uj, "{l3:?}"); + assert!(l3.partial_because.iter().any(|w| w.contains("reaped")), "the forked `cat`: {l3:?}"); + assert!(l3.partial_because.iter().any(|w| w.contains("exited")), "the script exited: {l3:?}"); + } + + let _ = std::fs::remove_dir_all(&dir); + } + + /// The L3 window's grading, pure: a reading of the model's process tree + /// is never attributed — whatever the gaps, it is an estimate of the + /// window, the reading plus the machine-wide figure, and it always says + /// why it is partial; no reading is the machine-wide figure alone. + #[test] + fn the_l3_window_is_never_attributed_and_a_reading_is_an_estimate() { + use sandbox_meter::TreeGap; + let reading = |cpu_nj: u64, gaps: Vec| TreeReading { + cpu_uj: cpu_nj.div_ceil(1_000), + cpu_nj, + processes: 1, + pids: vec![4242], + wall: Duration::from_secs(2), + gaps, + }; + let machine = 40_000_000; + let cpu = || vec![(DeviceClass::Cpu, machine)]; + + // The shape every model that exits in its window has. + let exited = grade_l3(Some(&Ok(reading(3_000_000_001, vec![TreeGap::Exited { pid: 4242 }]))), cpu(), true); + assert_eq!(exited.partial_because, vec![TreeGap::Exited { pid: 4242 }.to_string()]); + assert_eq!((exited.process_cpu_uj, exited.figure_uj), (Some(3_000_001), 3_000_001 + machine), "rounded up"); + + // No gap seen: the model was not read at its exit. Still an estimate. + let no_gap = grade_l3(Some(&Ok(reading(3_000_000_000, vec![]))), cpu(), true); + assert_eq!(no_gap.partial_because, vec![NOT_READ_AT_EXIT.to_string()]); + assert_eq!(no_gap.figure_uj, 3_000_000 + machine); + + let gpu = grade_l3(Some(&Ok(reading(5_000, vec![TreeGap::Exited { pid: 1 }, TreeGap::Gpu { ns: 9 }]))), cpu(), false); + assert_eq!(gpu.partial_because.len(), 2, "{gpu:?}"); + assert_eq!(gpu.figure_uj, 5 + machine); + assert!(!gpu.direct_child); + + let no_reading = grade_l3(Some(&Err(TreeError::RootGone { pid: 4242 })), cpu(), true); + assert_eq!((no_reading.process_cpu_uj, no_reading.figure_uj), (None, machine)); + assert!(no_reading.partial_because[0].contains("no reading"), "{no_reading:?}"); + + let no_meter = grade_l3(None, cpu(), true); + assert_eq!((no_meter.process_cpu_uj, no_meter.figure_uj), (None, machine)); + assert!(no_meter.partial_because.is_empty()); + + // In the tally: an estimate, as `run_l3` adds it. + for l3 in [&exited, &no_gap, &no_meter] { + let mut t = EnergyTally::default(); + t.add_l3(l3); + assert!(!t.attributed(), "{l3:?}"); + assert_eq!(t.figure_uj(), l3.figure_uj, "{l3:?}"); + assert_eq!(t.energy_class(), EnergyClass::Unaccounted, "never a reading of a partial window"); + } + } + + /// The L3 window's machine-wide figure is sealed one record per device + /// class: a GPU the meter read (an Apple GPU rail, NVML on Linux) is a + /// `Gpu` record, never folded into the CPU's. The records sum to the + /// run's figure, and the receipt builds from them. + #[test] + fn the_l3_windows_device_classes_are_sealed_apart() { + use sandbox_meter::TreeGap; + let reading = TreeReading { + cpu_uj: 3_000_000, + cpu_nj: 3_000_000_000, + processes: 1, + pids: vec![7], + wall: Duration::from_secs(1), + gaps: vec![TreeGap::Exited { pid: 7 }], + }; + let machine = vec![(DeviceClass::Cpu, 30_000_000), (DeviceClass::Gpu, 10_000_000)]; + let l3 = grade_l3(Some(&Ok(reading)), machine, true); + assert_eq!((l3.machine_uj, l3.figure_uj), (40_000_000, 43_000_000), "{l3:?}"); + + let mut t = EnergyTally::default(); + t.add(&window(20_000_000, 5_000_000, true)); + t.add_l3(&l3); + assert_eq!(t.figure_uj(), 63_000_000); + let records = t.meter_records(); + let by_class: Vec<(DeviceClass, Option, u64, sandbox_meter::Provenance)> = + records.iter().map(|r| (r.class, r.measured_uj, r.estimated_uj, r.provenance)).collect(); + let est = sandbox_meter::Provenance::Estimator; + assert_eq!( + by_class, + [(DeviceClass::Cpu, None, 53_000_000, est), (DeviceClass::Gpu, None, 10_000_000, est)], + "the CPU: the cargo window, the reading and the machine's CPU; the GPU apart" + ); + let receipt = sandbox_meter::Receipt::build( + sandbox_schema::ContentId::of_bytes(b"prior"), + sandbox_schema::Tier::S0, + records, + 1, + [3u8; 8], + ) + .expect("one record per class"); + assert_eq!(receipt.total.estimated_uj, t.figure_uj()); + + // A second L3 window adds to its class's record. + t.add_l3(&l3); + assert_eq!(t.meter_records()[1].estimated_uj, 20_000_000); + assert_eq!(t.meter_records().iter().map(|r| r.estimated_uj).sum::(), t.figure_uj()); + } + + /// A plain argv is `exec`ed after the gate, so the model is the meter's + /// root process; anything that needs the shell runs as its script. + #[test] + fn a_plain_l3_command_is_execed_after_the_gate_and_a_shell_command_is_not() { + let (script, direct) = l3_script(" granite-fix /models/granite-4.0-h_snapshot "); + assert!(direct); + assert_eq!(script, "IFS= read -r joule_fix_gate || exit 1\nexec granite-fix /models/granite-4.0-h_snapshot\n"); + assert!(l3_script("./mock-l3.sh").1); + assert!(l3_script("/bin/model --threads 8 -m a.gguf").1); + for shell in [ + "model | tee log", + "model; true", + "MODEL_THREADS=8 model", + "model > out", + "model \"a b\"", + "model $HOME/x", + "~/bin/model", + "model &", + "", + ] { + let (script, direct) = l3_script(shell); + assert!(!direct, "{shell:?}"); + assert!(script.starts_with("IFS= read -r joule_fix_gate || exit 1\n"), "{script}"); + assert!(!script.contains("exec "), "{script}"); + } + } + + /// The stand-in model's marker and report, in its working directory (the + /// scratch workspace). + const STAND_IN_MARKER: &str = ".l3-stand-in"; + const STAND_IN_REPORT: &str = ".l3-stand-in-report"; + + /// This process's own CPU energy count, nJ: `proc_pid_rusage(getpid(), + /// RUSAGE_INFO_V6)`'s `ri_energy_nj`, read with a bare buffer of the + /// struct's 464 bytes at its SDK offset, 336. Written out here, sharing + /// no code with the meter it checks. + #[cfg(target_os = "macos")] + fn own_energy_nj() -> u64 { + extern "C" { + fn proc_pid_rusage(pid: i32, flavor: i32, buffer: *mut std::ffi::c_void) -> i32; + } + let mut buf = [0u64; 58]; + // SAFETY: `buf` is 464 writable bytes, the size of `rusage_info_v6`. + let rc = unsafe { proc_pid_rusage(std::process::id() as i32, 6, buf.as_mut_ptr().cast()) }; + assert_eq!(rc, 0, "proc_pid_rusage on this process"); + buf[336 / 8] + } + + #[cfg(not(target_os = "macos"))] + fn own_energy_nj() -> u64 { + 0 + } + + /// Not a test of its own: the stand-in L3 model, run as a subprocess by + /// [`the_l3_models_energy_enters_the_run_total_as_its_own_count_says`] + /// (this test binary, filtered to this test). It reads its prompt to the + /// end, does a fixed amount of CPU work, leaves the core (which folds its + /// count), and writes its own count and the prompt's length to its + /// working directory. Anywhere without its marker it returns at once. + #[test] + #[ignore = "a subprocess stand-in, run by the L3 energy test"] + fn l3_stand_in_model() { + use std::io::Read; + let Ok(iterations) = std::fs::read_to_string(STAND_IN_MARKER) else { return }; + let iterations: u64 = iterations.trim().parse().expect("the marker holds an iteration count"); + let mut prompt = Vec::new(); + std::io::stdin().read_to_end(&mut prompt).expect("the prompt"); + let mut x = 1u64; + for i in 0..iterations { + x = std::hint::black_box(x.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(i)); + } + std::thread::sleep(Duration::from_millis(20)); + std::fs::write(STAND_IN_REPORT, format!("{} {} {x}", own_energy_nj(), prompt.len())).expect("the report"); + } + + /// The L3 model's energy is now in the run's figure. The model here is a + /// stand-in that burns a fixed amount of CPU and then reports its own + /// energy count, read from inside it before it exits: the oracle, which + /// shares no code with the tree meter. Where this host reads the model's + /// process (macOS, the per-process counter live) the window's reading of + /// it agrees with that count to within the shell's start-up before the + /// gate (in the oracle, not the window) and the stand-in's tear-down + /// after its report (in the window, not the oracle); the window is an + /// estimate, partial because the model exited in it; and its figure, the + /// reading plus the machine-wide figure, is what the run's tally holds. + /// Elsewhere it is the machine-wide figure. Two windows, accumulated. + #[test] + fn the_l3_models_energy_enters_the_run_total_as_its_own_count_says() { + // About a second of one core, unoptimized; a fixed amount of work, + // however loaded the host. + const ITERATIONS: u64 = 150_000_000; + let dir = scratch_crate("l3-energy"); + std::fs::write(dir.join(STAND_IN_MARKER), ITERATIONS.to_string()).unwrap(); + let exe = std::env::current_exe().expect("this test binary"); + let cmd = format!("{} tests::l3_stand_in_model --exact --ignored", exe.display()); + let h = Harness::new(&dir).unwrap(); + let prompt = vec![b'p'; 100_000]; + let reads_processes = + cfg!(target_os = "macos") && sandbox_meter::process_energy_status() == sandbox_meter::CounterStatus::Live; + + let mut figures = 0u64; + for window in 1..=2u64 { + let reply = h.run_l3(&cmd, &prompt).expect("the stand-in ran"); + assert!(reply.contains("1 passed"), "the stand-in did not run: {reply}"); + let report = std::fs::read_to_string(dir.join(STAND_IN_REPORT)).expect("the stand-in's report"); + let mut fields = report.split_whitespace().map(|f| f.parse::().unwrap()); + let (oracle_nj, prompt_len) = (fields.next().unwrap(), fields.next().unwrap()); + assert_eq!(prompt_len, prompt.len() as u64, "the model read the whole prompt, and not the gate"); + let acc = h.meter.borrow(); + let l3 = acc.l3.clone().expect("the window was metered"); + eprintln!("l3 window {window}: oracle {oracle_nj} nJ (the model's own count); {l3:?}"); + figures += l3.figure_uj; + assert_eq!(acc.tally.windows, window); + assert_eq!(acc.tally.figure_uj(), figures, "the run's figure holds every L3 window"); + assert!(!acc.tally.attributed()); + assert!(l3.machine_uj > 0, "{l3:?}"); + if reads_processes { + assert!(l3.direct_child, "setup: {cmd} is a plain argv"); + let read = l3.process_cpu_uj.unwrap_or_else(|| panic!("no reading of the model: {l3:?}")); + let oracle_uj = oracle_nj / 1_000; + let ratio = read as f64 / oracle_uj as f64; + assert!(oracle_uj > 100_000, "setup: the stand-in's work read {oracle_uj} µJ"); + assert!((0.8..=1.25).contains(&ratio), "the window read {read} µJ of a model that counted {oracle_uj} µJ"); + assert!(l3.partial_because.iter().any(|w| w.contains("exited")), "{l3:?}"); + assert_eq!(l3.figure_uj, read + l3.machine_uj); + // CI's macOS energy job greps for this line: the oracle ran. + eprintln!("l3 model process: window {window} read {read} µJ of a model that counted {oracle_uj} µJ"); + } else { + assert_eq!((l3.process_cpu_uj, l3.figure_uj), (None, l3.machine_uj), "{l3:?}"); + } + } let _ = std::fs::remove_dir_all(&dir); } diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/fabric_calibrate.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/fabric_calibrate.rs index 8c4a6a8c1..f9c4c5289 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/fabric_calibrate.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/fabric_calibrate.rs @@ -2,33 +2,60 @@ //! //! Runs the same BF16 matmul workloads on every serving //! local member — NEON, AMX (Accelerate), Metal GPU -//! (resident-weight MPS) — under the IOReport SoC energy -//! counter, and writes the measured µJ/GFLOP table the -//! placer loads at discovery -//! (`~/.jouleclaw/fabric-calibration.json`). +//! (resident-weight MPS) — under an energy meter, and +//! writes the measured µJ/GFLOP table the placer loads at +//! discovery (`~/.jouleclaw/fabric-calibration.json`). //! -//! Honesty about the method, printed and recorded: the SoC -//! counter is machine-wide. Marginal energy per op = -//! ΔE_busy − P_idle·Δt, with P_idle sampled immediately -//! before the runs — an idle-subtraction MODEL on top of a -//! hardware reading, the same caveat the joule-fix fleet -//! dataset records. Run this on a quiet machine or the -//! numbers are someone else's workload. +//! Two meters, chosen as the live autotuner chooses +//! (`fabric_dispatch::tune_shape_live`): //! -//! It writes nothing, and exits non-zero saying why, unless -//! every figure is a measurement: the IOReport counter must -//! be available (on Apple Silicon, its CPU energy rail must -//! advance — `jouleclaw_energy::ioreport_status`), the idle -//! baseline must advance, and every member's marginal -//! energy must be positive (`marginal_energy`). A zero, -//! clamped or not, would be loaded as a measured placement -//! cost. +//! - **The IOReport SoC counter, where its CPU energy rail +//! is live.** It is machine-wide, so marginal energy per +//! op = ΔE_busy − P_idle·Δt, with P_idle sampled +//! immediately before the runs — an idle-subtraction MODEL +//! on top of a hardware reading, the same caveat the +//! joule-fix fleet dataset records. Run this on a quiet +//! machine or the numbers are someone else's workload. +//! Every figure must be a measurement or nothing is +//! written: the idle baseline must advance and every +//! member's marginal energy must be positive +//! (`marginal_energy`); a zero, clamped or not, would be +//! loaded as a measured placement cost. +//! - **This process's own CPU and GPU counters, where it is +//! not** (macOS 27.0.1: the rail is frozen for an +//! unprivileged reader): each member's loop is one +//! `ProcessSpanMeter` span, its figure this process's CPU +//! energy plus its GPU energy, with no idle to subtract +//! (`marginal_energy::measure_member_process`). A member is +//! written only from a span metered whole: a CPU member's +//! GPU share an exact zero, a GPU member's the GPU rail +//! while this process was the GPU's sole user. Any other +//! member is refused, saying why, and the rest are still +//! written. The domain is this process's CPU and GPU, not +//! the SoC: DRAM is outside it, and AMX work through +//! Accelerate is counted as the kernel attributes it to the +//! calling threads' CPU energy, which is not checked +//! against a rail here — the row's method says so. //! //! Each row it writes declares its grade — the meter's, so a -//! live IOReport reading (`HwShunt`) is `Measured` — and -//! records its method, its date, and the OS and chip it was -//! taken on (`marginal_energy::calibration_row`); the fabric -//! loads it at that grade and carries the rest along. +//! live reading (`HwShunt`) is `Measured` — and records its +//! method, its date, and the OS and chip it was taken on +//! (`marginal_energy::calibration_row`); the fabric loads it +//! at that grade and carries the rest along. The file's rows +//! for the three members this example measures +//! (`marginal_energy::FABRIC_CALIBRATE_MEMBERS`) are all +//! replaced (`marginal_energy::merge_calibration`): a member +//! written now by its new row, and a member refused or +//! skipped by none, so the fabric places it on its seeded +//! figure — never on a row an earlier run took, which may be +//! of another domain, grade or shape than the rows written +//! beside it. Rows of members it does not measure +//! (`local/metal-mpp`, which `mpp_energy` writes) stay as +//! they were. +//! +//! Exit status: 0 when every member was written; 2 when +//! some were and others were refused or skipped (absent at +//! warm-up); 1, having written nothing, when none could be. //! //! ```bash //! cargo run --release --features "rayon fabric-meter" \ @@ -36,10 +63,13 @@ //! ``` use jouleclaw_energy::apple_ioreport::AppleIoReportCounter; +use jouleclaw_energy::span::ProcessSpanMeter; use jouleclaw_energy::EnergyCounter; use jouleclaw_loader_gguf::marginal_energy::{ - calibration_row, idle_draw_uw, marginal_uj, refusal, NotMeasured, + calibration_row, idle_draw_uw, marginal_uj, measure_member_process, merge_calibration, process_method, refusal, + MemberRuns, NotMeasured, FABRIC_CALIBRATE_MEMBERS, }; +use std::collections::BTreeMap; use std::time::Instant; /// Write nothing: say why, with the IOReport status, on stderr and exit non-zero. @@ -53,6 +83,15 @@ fn read_uj(counter: &AppleIoReportCounter) -> Result { counter.read().map(|r| r.uj).map_err(|e| NotMeasured::ReadFailed(e.to_string())) } +/// The meter every member is priced on. +enum Meter { + /// The machine-wide IOReport SoC counter, its CPU rail live, and the idle draw + /// sampled before the runs, µW. + IoReport { counter: AppleIoReportCounter, idle_uw: f64 }, + /// This process's own CPU and GPU counters. + Process(ProcessSpanMeter), +} + struct Shape { label: &'static str, m: usize, @@ -60,6 +99,11 @@ struct Shape { k: usize, } +/// A member's row, for the AMX member's method: what this process's CPU counter +/// covers of work it hands to Accelerate. +const AMX_NOTE: &str = "; AMX work through Accelerate counted as the kernel attributes it to the calling \ + threads' CPU energy, not checked against a rail"; + fn main() { // Decode GEMV at the lm_head class (wave 66's open // question) and a prefill batch shape. @@ -73,21 +117,41 @@ fn main() { let path = format!("{dir}/fabric-calibration.json"); let counter = AppleIoReportCounter::new(); - if !counter.is_available() { - refuse(&path, NotMeasured::CounterUnavailable("apple-ioreport declined".into())); - } - - // Idle baseline: 3 s of nothing. - let idle_uw = { - let e0 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); - let t0 = Instant::now(); - std::thread::sleep(std::time::Duration::from_secs(3)); - let e1 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); - idle_draw_uw(e0, e1, t0.elapsed().as_secs_f64()).unwrap_or_else(|e| refuse(&path, e)) + let meter = if counter.is_available() { + // Idle baseline: 3 s of nothing. + let idle_uw = { + let e0 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); + let t0 = Instant::now(); + std::thread::sleep(std::time::Duration::from_secs(3)); + let e1 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); + idle_draw_uw(e0, e1, t0.elapsed().as_secs_f64()).unwrap_or_else(|e| refuse(&path, e)) + }; + println!("idle draw: {:.2} W (machine-wide SoC)", idle_uw / 1e6); + Meter::IoReport { counter, idle_uw } + } else { + let span = ProcessSpanMeter::new(jouleclaw_backend_apple::gpu_liveness_load); + if !span.is_metered() { + refuse( + &path, + NotMeasured::CounterUnavailable( + "apple-ioreport declined, and this process's own CPU and GPU counters are not both live".into(), + ), + ); + } + println!( + "IOReport declined ({:?}): pricing each member on this process's own CPU and GPU counters", + jouleclaw_energy::ioreport_status() + ); + Meter::Process(span) }; - println!("idle draw: {:.2} W (machine-wide SoC)", idle_uw / 1e6); - let mut entries: Vec = Vec::new(); + // Per member, the row from its LAST shape (the batch shape for + // matrix members reflects their serving regime; the decode + // shape stays in the printout for the record). A member whose + // last shape was refused or skipped has no row: neither an + // earlier shape's figure nor an earlier run's stands in for it. + let mut latest: BTreeMap = BTreeMap::new(); + let mut refused: BTreeMap = BTreeMap::new(); for shape in &shapes { let (m, n, k) = (shape.m, shape.n, shape.k); @@ -108,9 +172,10 @@ fn main() { let mut out = vec![0f32; m * n]; type Runner<'a> = Box bool + 'a>; - let members: Vec<(&str, Runner)> = vec![ + let members: Vec<(&str, MemberRuns, Runner)> = vec![ ( "local/cpu-neon", + MemberRuns::Cpu, Box::new(|out: &mut [f32]| { jouleclaw_loader_gguf::matmul_bf16::matmul_bf16_neon(&a, &w, &[], m, n, k, out); true @@ -118,69 +183,124 @@ fn main() { ), ( "local/amx", + MemberRuns::Cpu, Box::new(|out: &mut [f32]| { jouleclaw_loader_gguf::fabric_dispatch::matmul_bf16_amx(&a, &w, &[], m, n, k, out) }), ), ( "local/metal-gpu", + MemberRuns::Gpu, Box::new(|out: &mut [f32]| { jouleclaw_loader_gguf::fabric_dispatch::matmul_bf16_gpu(&a, &w, &[], m, n, k, out) }), ), ]; - for (member, run) in &members { + for (member, runs, run) in &members { // Warm up (and for the GPU: pay the residency // upload OUTSIDE the measured window — calibration // prices the steady state; the upload amortizes). if !run(&mut out) { println!("{member:>18}: honestly absent / refused — skipped"); + latest.remove(*member); + refused.insert(member.to_string(), format!("{}: absent or refused at warm-up", shape.label)); continue; } run(&mut out); - // Measure ≥ 2 s of work. - let mut iters = 0u64; - let e0 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); - let t0 = Instant::now(); - while t0.elapsed().as_secs_f64() < 2.0 { - run(&mut out); - iters += 1; + match &meter { + Meter::IoReport { counter, idle_uw } => { + // Measure ≥ 2 s of work. + let mut iters = 0u64; + let e0 = read_uj(counter).unwrap_or_else(|e| refuse(&path, e)); + let t0 = Instant::now(); + while t0.elapsed().as_secs_f64() < 2.0 { + run(&mut out); + iters += 1; + } + let dt = t0.elapsed().as_secs_f64(); + let e1 = read_uj(counter).unwrap_or_else(|e| refuse(&path, e)); + let marginal = marginal_uj(e0, e1, dt, *idle_uw) + .unwrap_or_else(|e| refuse(&path, format!("{member} on {}: {e}", shape.label))); + let uj_per_op = marginal / iters as f64; + let uj_per_gflop = uj_per_op / gflop; + println!( + "{member:>18}: {iters:>5} ops in {dt:.2}s → {:.0} µJ/op, {:.0} µJ/GFLOP ({:.1} ms/op)", + uj_per_op, uj_per_gflop, dt * 1e3 / iters as f64, + ); + refused.remove(*member); + latest.insert( + member.to_string(), + calibration_row( + member, + "matmul", + uj_per_gflop, + counter.provenance(), + format!( + "IOReport SoC ΔE − idle({:.2} W)·Δt over {} ops of {} — \ + idle-subtraction model on a hardware reading; IOReport {:?}", + idle_uw / 1e6, iters, shape.label, jouleclaw_energy::ioreport_status(), + ), + ), + ); + } + Meter::Process(span) => { + // ≥ 2 s of work, one span. + match measure_member_process(span, *runs, gflop, 2.0, || { + run(&mut out); + }) { + Ok(f) => { + println!( + "{member:>18}: {:>5} ops in {:.2}s → {:.0} µJ/op, {:.0} µJ/GFLOP ({:.1} ms/op; \ + CPU {} µJ + GPU {} µJ)", + f.ops, + f.secs, + f.uj_per_gflop * gflop, + f.uj_per_gflop, + f.secs * 1e3 / f.ops as f64, + f.cpu_uj, + f.gpu_uj, + ); + let mut method = process_method(&f, *runs, shape.label); + if *member == "local/amx" { + method.push_str(AMX_NOTE); + } + refused.remove(*member); + latest.insert( + member.to_string(), + calibration_row(member, "matmul", f.uj_per_gflop, f.provenance, method), + ); + } + Err(why) => { + println!("{member:>18}: refused — {why}"); + latest.remove(*member); + refused.insert(member.to_string(), format!("{}: {why}", shape.label)); + } + } + } } - let dt = t0.elapsed().as_secs_f64(); - let e1 = read_uj(&counter).unwrap_or_else(|e| refuse(&path, e)); - let marginal = marginal_uj(e0, e1, dt, idle_uw) - .unwrap_or_else(|e| refuse(&path, format!("{member} on {}: {e}", shape.label))); - let uj_per_op = marginal / iters as f64; - let uj_per_gflop = uj_per_op / gflop; - println!( - "{member:>18}: {iters:>5} ops in {dt:.2}s → {:.0} µJ/op, {:.0} µJ/GFLOP ({:.1} ms/op)", - uj_per_op, uj_per_gflop, dt * 1e3 / iters as f64, - ); - entries.push(calibration_row( - member, - "matmul", - uj_per_gflop, - counter.provenance(), - format!( - "IOReport SoC ΔE − idle({:.2} W)·Δt over {} ops of {} — \ - idle-subtraction model on a hardware reading; IOReport {:?}", - idle_uw / 1e6, iters, shape.label, jouleclaw_energy::ioreport_status(), - ), - )); } } - // Keep the LAST measurement per member (the batch shape - // for matrix members reflects their serving regime); the - // decode shape stays in the printout for the record. - let mut latest: std::collections::BTreeMap = - Default::default(); - for e in entries { - latest.insert(e.member_id.clone(), e); + if latest.is_empty() { + let why: Vec = refused.iter().map(|(m, w)| format!("{m} ({w})")).collect(); + refuse(&path, format!("no member was measured whole: {}", why.join("; "))); } - let out_entries: Vec<_> = latest.into_values().collect(); + // Every row of a member this example measures is replaced: by + // its row from this run, or by none. Other members' rows stay. + let existing: Vec = std::fs::read(&path) + .ok() + .and_then(|b| serde_json::from_slice(&b).ok()) + .unwrap_or_default(); + let written: Vec = latest.keys().cloned().collect(); + let rows = merge_calibration(existing, &FABRIC_CALIBRATE_MEMBERS, latest.into_values().collect()); std::fs::create_dir_all(&dir).expect("mkdir"); - std::fs::write(&path, serde_json::to_vec_pretty(&out_entries).unwrap()).expect("write"); - println!("\nwrote {path} — Fabric::discover() now places on measured figures."); + std::fs::write(&path, serde_json::to_vec_pretty(&rows).unwrap()).expect("write"); + println!("\nwrote {} to {path} — Fabric::discover() places them on these figures.", written.join(", ")); + if !refused.is_empty() { + for (member, why) in &refused { + eprintln!("not written: {member} — {why}; its row was dropped, so it is placed on its seeded figure"); + } + std::process::exit(2); + } } diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/mpp_energy.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/mpp_energy.rs index 32e6c3192..657944639 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/mpp_energy.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/examples/mpp_energy.rs @@ -1,19 +1,30 @@ //! Honest µJ/GFLOP of the Metal-4 matmul2d prefill path vs the -//! threaded-NEON CPU path, via the IOReport SoC energy counter. -//! Run on a QUIET box: marginal energy = ΔE_busy − P_idle·Δt. +//! threaded-NEON CPU path. //! `cargo run --release --features "rayon fabric fabric-meter" --example mpp_energy` //! -//! It writes nothing, and exits non-zero saying why, unless both figures are -//! measurements: the IOReport counter available (its CPU energy rail live — -//! `jouleclaw_energy::ioreport_status`), an idle baseline that advances, and a -//! positive marginal for the GPU **and** the CPU run. A CPU run that draws nothing -//! above idle means the meter cannot see CPU work, so its SoC figure for the GPU run -//! is not a whole-SoC figure either. +//! Two meters, chosen as the live autotuner chooses (`fabric_dispatch::tune_shape_live`): +//! +//! - **The IOReport SoC counter, where its CPU energy rail is live.** Run on a QUIET +//! box: marginal energy = ΔE_busy − P_idle·Δt. It writes nothing, and exits non-zero +//! saying why, unless both figures are measurements: an idle baseline that advances, +//! and a positive marginal for the GPU **and** the CPU run. A CPU run that draws +//! nothing above idle means the meter cannot see CPU work, so its SoC figure for the +//! GPU run is not a whole-SoC figure either. +//! - **This process's own CPU and GPU counters, where it is not** (macOS 27.0.1: the +//! rail is frozen for an unprivileged reader): each run is one `ProcessSpanMeter` +//! span, this process's CPU energy plus its GPU energy, no idle to subtract +//! (`marginal_energy::measure_member_process`). The GPU run's figure is written only +//! from a span metered whole — the GPU rail while this process was the GPU's sole +//! user — else nothing is written. The CPU run (its GPU share must be an exact zero) +//! stands on its own span and gives the ratio; its refusal is printed and does not +//! void the GPU figure, which needs no idle baseline to be this process's alone. #[cfg(all(feature = "fabric", feature = "fabric-meter"))] fn main() { + use jouleclaw_energy::span::ProcessSpanMeter; use jouleclaw_energy::EnergyCounter; use jouleclaw_loader_gguf::marginal_energy::{ - calibration_row, energy_ratio, idle_draw_uw, marginal_uj, refusal, NotMeasured, + calibration_row, energy_ratio, idle_draw_uw, marginal_uj, measure_member_process, process_method, refusal, + MemberRuns, NotMeasured, }; use std::time::{Duration, Instant}; fn f32_to_bf16(v: f32) -> u16 { let b = v.to_bits(); (((b + (((b >> 16) & 1) + 0x7fff)) >> 16)) as u16 } @@ -28,7 +39,7 @@ fn main() { }); let counter = jouleclaw_energy::apple_ioreport::AppleIoReportCounter::new(); if !counter.is_available() { - refuse(&path, NotMeasured::CounterUnavailable("apple-ioreport declined".into())); + return process_counters(&path); } let read_uj = || counter.read().map(|r| r.uj).map_err(|e| NotMeasured::ReadFailed(e.to_string())); let idle_uw = { @@ -109,11 +120,6 @@ fn main() { // calibration file under local/metal-mpp, so the placer + // ledger price the prefill path at its TRUE cost (not the // borrowed MPSMatrix metal-gpu figure). Merge, don't clobber. - let mut entries: Vec = std::fs::read(&path) - .ok() - .and_then(|b| serde_json::from_slice(&b).ok()) - .unwrap_or_default(); - entries.retain(|e| e.member_id != "local/metal-mpp"); let row = calibration_row( "local/metal-mpp", "matmul", @@ -125,13 +131,87 @@ fn main() { jouleclaw_energy::ioreport_status() ), ); - let grade = row.loaded_provenance(); - entries.push(row); - if let Some(dir) = std::path::Path::new(&path).parent() { - let _ = std::fs::create_dir_all(dir); + write_row(&path, row); + + /// Merge `row` into the calibration file under its member, replacing that member's + /// row and leaving every other row as it was (merge, don't clobber). + fn write_row(path: &str, row: jouleclaw_fabric::CalibrationEntry) { + let mut entries: Vec = std::fs::read(path) + .ok() + .and_then(|b| serde_json::from_slice(&b).ok()) + .unwrap_or_default(); + entries.retain(|e| e.member_id != row.member_id); + let (member, ujpgf, grade) = (row.member_id.clone(), row.uj_per_gflop, row.loaded_provenance()); + entries.push(row); + if let Some(dir) = std::path::Path::new(path).parent() { + let _ = std::fs::create_dir_all(dir); + } + if std::fs::write(path, serde_json::to_vec_pretty(&entries).unwrap()).is_ok() { + println!("wrote {member} = {ujpgf:.0} µJ/GFLOP ({grade:?}) → {path}"); + } } - if std::fs::write(&path, serde_json::to_vec_pretty(&entries).unwrap()).is_ok() { - println!("wrote local/metal-mpp = {:.0} µJ/GFLOP ({grade:?}) → {path}", gpu_ujpgf); + + /// The same two runs on this process's own CPU and GPU counters, each one span + /// ([`measure_member_process`]): the GPU run's figure is written only from a span + /// metered whole, and the CPU run, on its own span, gives the ratio. + fn process_counters(path: &str) { + let meter = ProcessSpanMeter::new(jouleclaw_backend_apple::gpu_liveness_load); + if !meter.is_metered() { + refuse( + path, + NotMeasured::CounterUnavailable( + "apple-ioreport declined, and this process's own CPU and GPU counters are not both live".into(), + ), + ); + } + println!( + "IOReport declined ({:?}): each run metered on this process's own CPU and GPU counters", + jouleclaw_energy::ioreport_status() + ); + let (m, n, k) = (256usize, 4096usize, 4096usize); + let a: Vec = (0..m * k).map(|i| ((i % 101) as f32 / 50.0) - 1.0).collect(); + let w: Vec = (0..n * k) + .flat_map(|i| f32_to_bf16(((i % 97) as f32 / 48.0 - 1.0) * 0.1).to_le_bytes()) + .collect(); + let gflop = 2.0 * m as f64 * n as f64 * k as f64 / 1e9; + let mut out = vec![0f32; m * n]; + let gpu_run = |o: &mut [f32]| { + let ok = jouleclaw_loader_gguf::fabric_dispatch::matmul_bf16_mpp_bt(&a, &w, m, n, k, o); + assert!(ok, "mpp_bt fell back — set JOULECLAW_FABRIC=1 on a Metal-4 box"); + }; + gpu_run(&mut out); // warm, outside the span + let gpu = measure_member_process(&meter, MemberRuns::Gpu, gflop, 3.0, || gpu_run(&mut out)); + let cpu_run = |o: &mut [f32]| { + // Assert it ran, as the GPU run does: a refused shape would meter an empty loop. + jouleclaw_loader_gguf::matmul_bf16::matmul_bf16_threaded(&a, &w, &[], m, n, k, o) + .expect("threaded-NEON matmul refused this shape"); + }; + cpu_run(&mut out); + let cpu = measure_member_process(&meter, MemberRuns::Cpu, gflop, 3.0, || cpu_run(&mut out)); + + println!("shape {m}x{n}x{k}"); + for (label, r) in [("matmul2d (metal-gpu)", &gpu), ("threaded-NEON (cpu) ", &cpu)] { + match r { + Ok(f) => println!( + " {label}: {:>9.0} µJ/GFLOP {:>7.1} GFLOP/s (CPU {} µJ + GPU {} µJ)", + f.uj_per_gflop, + gflop * f.ops as f64 / f.secs, + f.cpu_uj, + f.gpu_uj + ), + Err(e) => println!(" {label}: not measured — {e}"), + } + } + match (&gpu, &cpu) { + (Ok(g), Ok(c)) => match energy_ratio(c.uj_per_gflop, g.uj_per_gflop) { + Some(ratio) => println!(" energy ratio (CPU/GPU per GFLOP): {ratio:.2}×"), + None => println!(" energy ratio (CPU/GPU per GFLOP): n/a"), + }, + _ => println!(" energy ratio (CPU/GPU per GFLOP): n/a — both runs must be measured"), + } + let g = gpu.unwrap_or_else(|e| refuse(path, format!("the matmul2d (metal-gpu) run: {e}"))); + let method = process_method(&g, MemberRuns::Gpu, &format!("matmul2d {m}×{n}×{k}")); + write_row(path, calibration_row("local/metal-mpp", "matmul", g.uj_per_gflop, g.provenance, method)); } } #[cfg(not(all(feature = "fabric", feature = "fabric-meter")))] diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/src/marginal_energy.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/src/marginal_energy.rs index 3915913c2..ea61241c7 100644 --- a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/src/marginal_energy.rs +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/src/marginal_energy.rs @@ -1,5 +1,11 @@ //! Marginal energy on a machine-wide cumulative energy counter, and when there is none. //! +//! Where there is none — an Apple Silicon host whose IOReport CPU rail is frozen for an +//! unprivileged reader, as on macOS 27.0.1 — a member is priced on this process's own +//! counters instead ([`measure_member_process`], the `fabric-meter` feature): one span +//! of the member's work, this process's CPU energy plus its GPU energy, with no idle to +//! subtract, every figure being this process's alone. +//! //! The live autotuner ([`crate::fabric_dispatch`]'s `tune_shape_live`) and the //! calibration examples (`fabric_calibrate`, `mpp_energy`) price work the same way: //! sample the counter across an idle window for the idle draw, then across a busy @@ -47,6 +53,24 @@ pub enum NotMeasured { /// Operations in the window. ops: u64, }, + /// This process's span gave no figure; the payload says why. + SpanFailed(String), + /// This process's span covered only part of the member's work: the CPU alone, its + /// GPU energy unmeasured (the GPU was shared with another process, a GPU client + /// vanished, the GPU counter is not live). The payload says why. + NotWhole(String), + /// This process's own counters gave no figure, and the span fell back to the host + /// meter, whose figure is the machine's, not the member's. The payload says why. + NotOwnCounters(String), + /// A member that runs on the CPU spent GPU time over its span: its figure would + /// hold GPU energy that is not its own. + CpuMemberUsedGpu { + /// This process's GPU time over the span, ns. + self_ns: u64, + }, + /// A member that runs on the GPU spent no GPU time over its span: what ran was not + /// the member's GPU work. + GpuMemberUsedNoGpu, } impl fmt::Display for NotMeasured { @@ -80,6 +104,22 @@ impl fmt::Display for NotMeasured { Self::BelowResolution { marginal_uj, ops } => { write!(f, "{marginal_uj:.0} µJ over {ops} ops is below 1 µJ per op") } + Self::SpanFailed(why) => write!(f, "this process's span gave no figure: {why}"), + Self::NotWhole(why) => write!( + f, + "this process's span covered only part of the work, so it is no figure of it: {why}" + ), + Self::NotOwnCounters(why) => write!( + f, + "this process's own counters gave no figure, and the host meter's is the machine's: {why}" + ), + Self::CpuMemberUsedGpu { self_ns } => write!( + f, + "a CPU member spent {self_ns} ns of GPU time over its span, so its figure is not its own" + ), + Self::GpuMemberUsedNoGpu => { + f.write_str("a GPU member spent no GPU time over its span: its work did not run on the GPU") + } } } } @@ -208,6 +248,169 @@ pub fn calibration_row( } } +/// The members `fabric_calibrate` measures, and so owns the calibration rows of. +/// `local/metal-mpp` is not among them: `mpp_energy` writes that row. +#[cfg(feature = "fabric-meter")] +pub const FABRIC_CALIBRATE_MEMBERS: [&str; 3] = ["local/cpu-neon", "local/amx", "local/metal-gpu"]; + +/// The calibration file's rows after a run that owns the rows of the `owned` members +/// and measured `measured`: every row of an owned member is dropped and the measured +/// rows are added, so a member the run owns but refused, or skipped, has no row and is +/// placed on its seeded figure — never on a row an earlier run took, which may be of +/// another domain (the SoC's marginal draw, not this process's own energy), grade, +/// shape or OS than the rows written beside it. Rows of members the run does not own +/// stay as they were. A measured member outside `owned` still replaces its own row. +#[cfg(feature = "fabric-meter")] +pub fn merge_calibration( + existing: Vec, + owned: &[&str], + measured: Vec, +) -> Vec { + let mut rows: Vec<_> = existing + .into_iter() + .filter(|e| !owned.contains(&e.member_id.as_str()) && !measured.iter().any(|m| m.member_id == e.member_id)) + .collect(); + rows.extend(measured); + rows +} + +/// Where a fabric member's work runs, for [`process_figure`]: on this process's CPU +/// threads (NEON; AMX through Accelerate), or on the GPU. +#[cfg(feature = "fabric-meter")] +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum MemberRuns { + /// On this process's CPU threads: its GPU share must be an exact zero. + Cpu, + /// On the GPU, dispatched and waited on by this process: it must have spent GPU + /// time, and had the GPU to itself for the span to be whole. + Gpu, +} + +/// A fabric member's figure on this process's own CPU and GPU counters +/// ([`process_figure`]). +#[cfg(feature = "fabric-meter")] +#[derive(Debug, Clone, PartialEq)] +pub struct ProcessFigure { + /// The span's energy over its operations' GFLOPs, µJ/GFLOP. + pub uj_per_gflop: f64, + /// The span's grade, which the calibration row is written at + /// ([`calibration_row`]): `HwShunt` for this process's live counters. + pub provenance: jouleclaw_energy::Provenance, + /// This process's CPU energy over the span, µJ. + pub cpu_uj: u64, + /// This process's GPU energy over the span, µJ: an exact zero for a CPU member; + /// for a GPU member, the GPU rail's advance over a span this process all but owned. + pub gpu_uj: u64, + /// Operations in the span. + pub ops: u64, + /// The span's length, s. + pub secs: f64, +} + +/// A member's figure from one span of its work on this process's own counters +/// (`jouleclaw_energy::span::ProcessSpanMeter`, [`SpanUses::CpuGpu`]), `ops` operations +/// of `gflop_per_op` GFLOP each over `secs` — or why there is none. A figure is given +/// only for a span metered **whole** on this process's own counters: +/// +/// - the span must have a figure, cover the whole work ([`Coverage::Whole`]: CPU and +/// GPU both read), and come from this process's counters, not the host meter it +/// falls back to; +/// - a CPU member's GPU share must be an exact zero (no GPU time at all), and a GPU +/// member must have spent GPU time — its GPU figure then the rail's advance over a +/// span this process was the GPU's effective sole user of. +/// +/// No idle is subtracted: both counters are this process's alone. The figure is the +/// span's energy per GFLOP, at the span's grade. Pure, so every refusal is tested +/// without hardware. +/// +/// [`SpanUses::CpuGpu`]: jouleclaw_energy::span::SpanUses::CpuGpu +/// [`Coverage::Whole`]: jouleclaw_energy::Coverage::Whole +#[cfg(feature = "fabric-meter")] +pub fn process_figure( + span: Result, + runs: MemberRuns, + ops: u64, + secs: f64, + gflop_per_op: f64, +) -> Result { + use jouleclaw_energy::span::SpanSource; + if ops == 0 || !(secs.is_finite() && secs > 0.0) || !(gflop_per_op.is_finite() && gflop_per_op > 0.0) { + return Err(NotMeasured::EmptyWindow); + } + let s = span.map_err(|e| NotMeasured::SpanFailed(e.to_string()))?; + if s.coverage != jouleclaw_energy::Coverage::Whole { + return Err(NotMeasured::NotWhole(match &s.source { + SpanSource::CpuOnly { why, .. } => why.clone(), + _ => "the work used what the meter does not read".to_string(), + })); + } + let (cpu_uj, gpu) = match &s.source { + SpanSource::Process { cpu_uj, gpu } => (*cpu_uj, gpu), + SpanSource::Fallback { meter, why } => { + return Err(NotMeasured::NotOwnCounters(format!("{why}; fell back to `{meter}`"))) + } + SpanSource::CpuOnly { why, .. } => return Err(NotMeasured::NotWhole(why.clone())), + }; + match runs { + MemberRuns::Cpu if gpu.uj != 0 || gpu.self_ns != 0 => { + return Err(NotMeasured::CpuMemberUsedGpu { self_ns: gpu.self_ns }) + } + MemberRuns::Gpu if gpu.self_ns == 0 => return Err(NotMeasured::GpuMemberUsedNoGpu), + _ => {} + } + if s.uj == 0 { + return Err(NotMeasured::SpanFailed("it read 0 µJ".to_string())); + } + Ok(ProcessFigure { + uj_per_gflop: s.uj as f64 / (ops as f64 * gflop_per_op), + provenance: s.provenance, + cpu_uj, + gpu_uj: gpu.uj, + ops, + secs, + }) +} + +/// Run a member's work `run` (one operation of `gflop_per_op` GFLOP a call) for at +/// least `secs` as one span on `meter`, and take its figure ([`process_figure`]). The +/// span holds everything this process runs meanwhile, so nothing else of this +/// process should run then. +#[cfg(feature = "fabric-meter")] +pub fn measure_member_process( + meter: &jouleclaw_energy::span::ProcessSpanMeter, + runs: MemberRuns, + gflop_per_op: f64, + secs: f64, + mut run: impl FnMut(), +) -> Result { + let start = meter.start(); + let t0 = std::time::Instant::now(); + let mut ops = 0u64; + while t0.elapsed().as_secs_f64() < secs { + run(); + ops += 1; + } + let dt = t0.elapsed().as_secs_f64(); + process_figure(meter.finish(start, jouleclaw_energy::span::SpanUses::CpuGpu), runs, ops, dt, gflop_per_op) +} + +/// A calibration row's `method` for a [`ProcessFigure`] of `workload`: the domain (this +/// process's CPU and GPU energy, not the SoC's marginal draw), how the GPU part was +/// read, and that nothing was subtracted. +#[cfg(feature = "fabric-meter")] +pub fn process_method(fig: &ProcessFigure, runs: MemberRuns, workload: &str) -> String { + let gpu = match runs { + MemberRuns::Cpu => "an exact GPU zero (no GPU time)".to_string(), + MemberRuns::Gpu => format!("{} µJ of GPU rail while this process was its sole user", fig.gpu_uj), + }; + format!( + "this process's own energy over {} ops of {workload} in {:.2} s: {} µJ of CPU (the per-process CPU \ + counter) + {gpu}; no idle subtraction, every figure this process's alone (ProcessSpanMeter, CpuGpu, \ + whole)", + fig.ops, fig.secs, fig.cpu_uj + ) +} + /// The first line a command prints, trimmed, if it ran and printed one. #[cfg(feature = "fabric-meter")] fn command_line(program: &str, args: &[&str]) -> Option { @@ -388,6 +591,126 @@ mod tests { assert_eq!(rfc3339_utc(4_102_444_799), "2099-12-31T23:59:59Z"); } + /// A member's process-span figure, pure: given only for a span metered whole on this + /// process's own counters — a CPU member's GPU share an exact zero, a GPU member's + /// GPU time spent — and refused, saying why, for every other span. + #[cfg(feature = "fabric-meter")] + #[test] + fn a_member_is_priced_on_this_process_only_from_a_whole_span_of_its_own_work() { + use jouleclaw_energy::process_gpu::GpuShare; + use jouleclaw_energy::span::{SpanEnergy, SpanSource}; + use jouleclaw_energy::{Coverage, EnergyError, Provenance}; + let zero = GpuShare { uj: 0, self_ns: 0, rail_uj: None, all_ns: None }; + let sole = GpuShare { uj: 700, self_ns: 9_000, rail_uj: Some(710), all_ns: Some(9_010) }; + let whole = |cpu_uj: u64, gpu: GpuShare| -> Result { + Ok(SpanEnergy { + uj: cpu_uj + gpu.uj, + provenance: Provenance::HwShunt, + coverage: Coverage::Whole, + source: SpanSource::Process { cpu_uj, gpu }, + }) + }; + + // 4 ops of 0.5 GFLOP: 2 GFLOP. + let cpu = process_figure(whole(3_000, zero), MemberRuns::Cpu, 4, 2.0, 0.5).unwrap(); + assert_eq!((cpu.uj_per_gflop, cpu.provenance, cpu.cpu_uj, cpu.gpu_uj), (1_500.0, Provenance::HwShunt, 3_000, 0)); + let gpu = process_figure(whole(300, sole), MemberRuns::Gpu, 4, 2.0, 0.5).unwrap(); + assert_eq!((gpu.uj_per_gflop, gpu.gpu_uj), (500.0, 700)); + let method = process_method(&gpu, MemberRuns::Gpu, "m=16"); + assert!(method.contains("4 ops of m=16") && method.contains("700 µJ of GPU rail") && method.contains("no idle"), "{method}"); + + // A CPU member that spent GPU time, a GPU member that spent none. + assert_eq!( + process_figure(whole(3_000, sole), MemberRuns::Cpu, 4, 2.0, 0.5), + Err(NotMeasured::CpuMemberUsedGpu { self_ns: 9_000 }) + ); + assert_eq!(process_figure(whole(3_000, zero), MemberRuns::Gpu, 4, 2.0, 0.5), Err(NotMeasured::GpuMemberUsedNoGpu)); + + // The GPU shared: the CPU alone, partial. + let shared = Ok(SpanEnergy { + uj: 300, + provenance: Provenance::HwShunt, + coverage: Coverage::Partial, + source: SpanSource::CpuOnly { cpu_uj: 300, why: "process GPU: shared 115 ns of 1000 ns".into() }, + }); + let why = process_figure(shared, MemberRuns::Gpu, 4, 2.0, 0.5).unwrap_err(); + assert!(matches!(&why, NotMeasured::NotWhole(w) if w.contains("shared")), "{why}"); + assert!(why.to_string().contains("only part of the work"), "{why}"); + + // Both counters read, but the work declared Neural Engine use, which none reads. + let ane = Ok(SpanEnergy { + uj: 1_000, + provenance: Provenance::HwShunt, + coverage: Coverage::Partial, + source: SpanSource::Process { cpu_uj: 300, gpu: sole }, + }); + let why = process_figure(ane, MemberRuns::Gpu, 4, 2.0, 0.5).unwrap_err(); + assert!(matches!(why, NotMeasured::NotWhole(_)), "{why}"); + + // The host meter's fallback: whole for its own domain, which is the machine's. + let fallback = Ok(SpanEnergy { + uj: 4_000, + provenance: Provenance::Estimator, + coverage: Coverage::Whole, + source: SpanSource::Fallback { meter: "apple-silicon", why: "process CPU: not live".into() }, + }); + let why = process_figure(fallback, MemberRuns::Cpu, 4, 2.0, 0.5).unwrap_err(); + assert!(matches!(&why, NotMeasured::NotOwnCounters(w) if w.contains("apple-silicon")), "{why}"); + + let why = process_figure(Err(EnergyError::NotAdvanced), MemberRuns::Cpu, 4, 2.0, 0.5).unwrap_err(); + assert!(matches!(why, NotMeasured::SpanFailed(_)), "{why}"); + for (ops, secs, gflop) in [(0, 2.0, 0.5), (4, 0.0, 0.5), (4, 2.0, 0.0), (4, f64::NAN, 0.5)] { + let empty = process_figure(whole(3_000, zero), MemberRuns::Cpu, ops, secs, gflop); + assert_eq!(empty, Err(NotMeasured::EmptyWindow), "{ops} {secs} {gflop}"); + } + } + + /// A calibration run's rows replace every row of the members it owns: a member it + /// refused (or skipped) is left with none, so it falls back to its seeded figure, + /// and an earlier run's SoC-marginal row (no declared grade, loaded `Benchmarked`) + /// never stands beside the per-process `Measured` rows written now. The shape of + /// this host's file before such a run, with `local/metal-mpp` (another example's + /// row) kept as it was. + #[cfg(feature = "fabric-meter")] + #[test] + fn a_calibration_run_drops_every_row_it_owns_and_keeps_the_rest() { + use jouleclaw_fabric::{CalibrationEntry, EnergyProvenance as Grade}; + let old = |member: &str, uj_per_gflop: f64| CalibrationEntry { + member_id: member.to_string(), + op: "matmul".to_string(), + uj_per_gflop, + method: "IOReport SoC ΔE − idle(100.17 W)·Δt over 1428 ops of prefill-batch (m=16)".to_string(), + provenance: None, + date: None, + os: None, + chip: None, + }; + let existing = vec![ + old("local/amx", 868_359.0), + old("local/cpu-neon", 3_774_424.8), + old("local/metal-gpu", 161_682.8), + old("local/metal-mpp", 90_000.0), + ]; + // This run: the two CPU members measured, the GPU member refused (shared GPU). + let now = |member: &str| calibration_row(member, "matmul", 246_741.4, jouleclaw_energy::Provenance::HwShunt, "m".into()); + let measured = vec![now("local/amx"), now("local/cpu-neon")]; + let rows = merge_calibration(existing, &FABRIC_CALIBRATE_MEMBERS, measured); + let ids: Vec<&str> = rows.iter().map(|r| r.member_id.as_str()).collect(); + assert_eq!(ids, ["local/metal-mpp", "local/amx", "local/cpu-neon"], "the refused GPU member's old row stayed"); + assert!( + rows.iter() + .filter(|r| FABRIC_CALIBRATE_MEMBERS.contains(&r.member_id.as_str())) + .all(|r| r.loaded_provenance() == Grade::Measured), + "a row this run owns is not one it wrote: {rows:?}" + ); + assert_eq!(rows[0].uj_per_gflop, 90_000.0, "a row it does not own stays as it was"); + + // A measured member outside the owned set still replaces its own row, once. + let rows = merge_calibration(rows, &[], vec![now("local/metal-mpp")]); + assert_eq!(rows.iter().filter(|r| r.member_id == "local/metal-mpp").count(), 1); + assert_eq!(rows.last().map(|r| r.uj_per_gflop), Some(246_741.4)); + } + /// Only a hardware reading becomes a `Measured` row; nothing is upgraded. #[cfg(feature = "fabric-meter")] #[test] @@ -406,6 +729,8 @@ mod tests { if cfg!(target_os = "macos") { assert!(row.os.as_deref().is_some_and(|os| os.starts_with("macOS ")), "{:?}", row.os); assert!(row.chip.is_some(), "the chip was not recorded"); + // CI's macOS energy job greps for this line: the macOS stamp was checked. + eprintln!("calibration row stamped on macOS: os={:?} chip={:?}", row.os, row.chip); } eprintln!("a calibration row on this host: date={:?} os={:?} chip={:?}", row.date, row.os, row.chip); } diff --git a/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/tests/process_calibration.rs b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/tests/process_calibration.rs new file mode 100644 index 000000000..4bb226f3b --- /dev/null +++ b/jouleclaw/jouleclaw-rs/crates/jouleclaw-loader-gguf/tests/process_calibration.rs @@ -0,0 +1,84 @@ +//! A fabric member priced on this process's own counters +//! (`marginal_energy::measure_member_process`, what `fabric_calibrate` and +//! `mpp_energy` fall back to where the IOReport CPU rail is frozen), against an +//! oracle sharing no code with the meter: this process's own CPU energy count, +//! read around the same span with a bare `proc_pid_rusage`. +//! +//! One test in its own binary, so no other test's thread runs in this process +//! during the span (the span, and the oracle, read every thread of it). + +#![cfg(feature = "fabric-meter")] + +use jouleclaw_energy::span::ProcessSpanMeter; +use jouleclaw_loader_gguf::marginal_energy::{measure_member_process, MemberRuns, NotMeasured}; + +/// This process's own CPU energy count, nJ: `proc_pid_rusage(getpid(), +/// RUSAGE_INFO_V6)`'s `ri_energy_nj`, read with a bare buffer of the struct's 464 +/// bytes at its SDK offset, 336. Written out here, sharing no code with the meter +/// it checks. +#[cfg(target_os = "macos")] +fn own_energy_nj() -> u64 { + unsafe extern "C" { + fn proc_pid_rusage(pid: i32, flavor: i32, buffer: *mut std::ffi::c_void) -> i32; + } + let mut buf = [0u64; 58]; + // SAFETY: `buf` is 464 writable bytes, the size of `rusage_info_v6`. + let rc = unsafe { proc_pid_rusage(std::process::id() as i32, 6, buf.as_mut_ptr().cast()) }; + assert_eq!(rc, 0, "proc_pid_rusage on this process"); + buf[336 / 8] +} + +#[cfg(not(target_os = "macos"))] +fn own_energy_nj() -> u64 { + 0 +} + +/// A CPU member (the NEON BF16 matmul) priced on this process: where both of this +/// process's counters are live, the figure is given, its GPU part an exact zero, and +/// its CPU part agrees with the oracle, read inside the span at the first operation's +/// start and the last one's end — so the span holds the oracle's window and differs +/// from it only by the meter's last and first reads around it — and the per-GFLOP +/// figure is that energy over the work. Where they are not, the member is refused, +/// never priced on the host meter. Twice, three seconds each, however loaded the host. +#[test] +fn a_cpu_member_is_priced_on_this_process_as_its_own_count_says() { + use std::cell::Cell; + let meter = ProcessSpanMeter::new(jouleclaw_backend_apple::gpu_liveness_load); + let (m, n, k) = (16usize, 512usize, 512usize); + let gflop = 2.0 * (m * n * k) as f64 / 1e9; + let a: Vec = (0..m * k).map(|i| ((i % 101) as f32 / 50.0) - 1.0).collect(); + let w: Vec = (0..n * k) + .flat_map(|i| jouleclaw_loader_gguf::matmul_bf16::f32_to_bf16_rne(((i % 97) as f32 / 48.0 - 1.0) * 0.1).to_le_bytes()) + .collect(); + let mut out = vec![0f32; m * n]; + for round in 1..=2 { + let (first, last) = (Cell::new(None), Cell::new(0u64)); + let figure = measure_member_process(&meter, MemberRuns::Cpu, gflop, 3.0, || { + if first.get().is_none() { + first.set(Some(own_energy_nj())); + } + jouleclaw_loader_gguf::matmul_bf16::matmul_bf16_neon(&a, &w, &[], m, n, k, &mut out); + last.set(own_energy_nj()); + }); + let oracle_uj = (last.get() - first.get().expect("the work ran")) / 1_000; + eprintln!("CPU member round {round}: oracle {oracle_uj} µJ; metered={} {figure:?}", meter.is_metered()); + if meter.is_metered() { + let f = figure.expect("a CPU member on live counters is priced"); + assert_eq!(f.gpu_uj, 0, "the NEON matmul spent GPU energy: {f:?}"); + assert_eq!(f.provenance, jouleclaw_energy::Provenance::HwShunt); + assert!(oracle_uj > 100_000, "setup: the work read {oracle_uj} µJ"); + let ratio = f.cpu_uj as f64 / oracle_uj as f64; + assert!((0.9..=1.1).contains(&ratio), "the span read {} µJ of {oracle_uj} µJ", f.cpu_uj); + let total = f.uj_per_gflop * f.ops as f64 * gflop; + assert!((total - f.cpu_uj as f64).abs() <= 1.0, "{total} µJ priced of {} µJ read", f.cpu_uj); + // CI's macOS energy job greps for this line: the oracle ran on live counters. + eprintln!("process calibration: CPU member round {round} read {} µJ of {oracle_uj} µJ", f.cpu_uj); + } else { + let why = figure.expect_err("no live counters, yet a figure"); + assert!( + matches!(why, NotMeasured::NotWhole(_) | NotMeasured::NotOwnCounters(_) | NotMeasured::SpanFailed(_)), + "{why}" + ); + } + } +} diff --git a/jouledesk/jouledesk-rs/Cargo.lock b/jouledesk/jouledesk-rs/Cargo.lock index b5eb9e6ff..ab19c9b07 100644 --- a/jouledesk/jouledesk-rs/Cargo.lock +++ b/jouledesk/jouledesk-rs/Cargo.lock @@ -226,6 +226,33 @@ version = "1.5.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6e4de3bc4ea267985becf712dc6d9eed8b04c953b3fcfb339ebc87acd9804901" +[[package]] +name = "ciborium" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "42e69ffd6f0917f5c029256a24d0161db17cea3997d185db0d35926308770f0e" +dependencies = [ + "ciborium-io", + "ciborium-ll", + "serde", +] + +[[package]] +name = "ciborium-io" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "05afea1e0a06c9be33d539b876f1ce3692f4afea2cb41f740e7743225ed1c757" + +[[package]] +name = "ciborium-ll" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "57663b653d948a338bfb3eeba9bb2fd5fcfaecb9e199e87e1eda4d9e8b240fd9" +dependencies = [ + "ciborium-io", + "half", +] + [[package]] name = "clap" version = "4.6.6" @@ -350,6 +377,12 @@ version = "0.8.22" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "61803da095bee82a81bb1a452ecc25d3b2f1416d1897eb86430c6159ef717c17" +[[package]] +name = "crunchy" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "460fbee9c2c2f33933d720630a6a0bac33ba7053db5344fac858d4b8952d77d5" + [[package]] name = "crypto-common" version = "0.1.7" @@ -784,6 +817,17 @@ version = "0.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e4eba85ea1d0a966a983acd07deee566e67395d2d96b6fb39e62b5a833f1eb0b" +[[package]] +name = "half" +version = "2.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6ea2d84b969582b4b1864a92dc5d27cd2b77b622a8d79306834f1be5ba20d84b" +dependencies = [ + "cfg-if", + "crunchy", + "zerocopy", +] + [[package]] name = "hashbrown" version = "0.17.1" @@ -1266,6 +1310,8 @@ dependencies = [ "jcp-efficiency", "jouleclaw-energy", "jouledesk", + "libc", + "sandbox-meter", "serde_json", "tiny_http", "ureq", @@ -2302,6 +2348,29 @@ dependencies = [ "winapi-util", ] +[[package]] +name = "sandbox-meter" +version = "0.1.0" +dependencies = [ + "ed25519-dalek", + "libc", + "libloading", + "sandbox-schema", + "serde", + "thiserror 2.0.20", +] + +[[package]] +name = "sandbox-schema" +version = "0.1.0" +dependencies = [ + "base64 0.22.1", + "blake3", + "ciborium", + "serde", + "thiserror 2.0.20", +] + [[package]] name = "schannel" version = "0.1.29" diff --git a/jouledesk/jouledesk-rs/crates/jouledesk-github/Cargo.toml b/jouledesk/jouledesk-rs/crates/jouledesk-github/Cargo.toml index 80a623aa4..cc0925d3b 100644 --- a/jouledesk/jouledesk-rs/crates/jouledesk-github/Cargo.toml +++ b/jouledesk/jouledesk-rs/crates/jouledesk-github/Cargo.toml @@ -20,10 +20,18 @@ jouledesk = { path = "../jouledesk" } # The host's best energy meter: Apple-Silicon IOReport where its CPU rail is live, # else the load-average estimator (sealed and posted as an estimate). jouleclaw-energy = { path = "../../../../jouleclaw/jouleclaw-rs/crates/jouleclaw-energy", default-features = false, features = ["ioreport"] } +# The model subprocess's own CPU energy, where the host counts each process's +# (macOS): `TreeMeter`, rooted at the model's process. +sandbox-meter = { path = "../../../../sandbox/sandbox-rs/crates/sandbox-meter" } serde_json = "1" ureq = { version = "2", features = ["json"] } tiny_http = "0.12" +# macOS: the model's process is waited for without being reaped (`waitid` with +# `WNOWAIT`), so the tree meter reads its exited count. +[target.'cfg(target_os = "macos")'.dependencies] +libc = "0.2" + [dev-dependencies] # Tests read the sealed efficiency/1 receipt back to check its provenance. jcp-efficiency = { path = "../../../../jcp/jcp-rs/crates/jcp-efficiency" } diff --git a/jouledesk/jouledesk-rs/crates/jouledesk-github/src/lib.rs b/jouledesk/jouledesk-rs/crates/jouledesk-github/src/lib.rs index 8bd589e48..632cb73c0 100644 --- a/jouledesk/jouledesk-rs/crates/jouledesk-github/src/lib.rs +++ b/jouledesk/jouledesk-rs/crates/jouledesk-github/src/lib.rs @@ -9,6 +9,15 @@ //! estimated — and sealed and posted as an estimate — where it does not (Apple Silicon //! whose IOReport CPU rail does not advance, for one). A human can actually tag `@joule` //! and get an accountable answer. +//! +//! The model runs in a subprocess (`llama-completion`), and where this host counts each +//! process's CPU energy (macOS, its per-process counter live) that process is read on +//! its own ([`sandbox_meter::TreeMeter`]) beside the host meter. The reading is never +//! whole: it covers the model's CPU only, not the GPU a model binary may offload to, and +//! the model exits in its window, so its record lacks its last time on a core — a lower +//! bound on its CPU energy. An `efficiency/1` receipt has no coverage field, so the +//! reading is never sealed as a hardware figure of the work: it is sealed as an +//! estimate, the reading plus the host meter's figure ([`grade_work`]). use std::time::{Duration, Instant}; @@ -16,6 +25,7 @@ use jouleclaw_energy::meter::CompositeMeter; use jouleclaw_energy::{EnergyReading, Provenance}; use jouledesk::surface::{parse_event, Surface}; use jouledesk::{EnergyProvenance, Skill, SkillOutcome, TagOutcome, Teammate}; +use sandbox_meter::{TreeError, TreeMeter, TreeReading}; use serde_json::{json, Value}; /// The Slack binding — the same core ([`do_work`] + [`seal`]) on a second surface. @@ -41,6 +51,20 @@ fn configured_model() -> String { panic!("a unit test reached the configured model ({DEFAULT_MODEL} unless JOULEDESK_MODEL); pass a model path") } +/// The binary that runs a model, `JOULEDESK_LLAMA`, else `llama-completion`. Read only +/// when a model file is there to run. +#[cfg(not(test))] +fn configured_llama() -> String { + std::env::var("JOULEDESK_LLAMA").unwrap_or_else(|_| "llama-completion".into()) +} + +/// Unit tests give the binary themselves ([`do_work_via`]): none may read the +/// process-global environment, which tests running in parallel would race on. +#[cfg(test)] +fn configured_llama() -> String { + panic!("a unit test reached the configured llama binary; pass one to do_work_via") +} + /// The work product: a real answer and the energy this machine's meter puts on it (not /// a constant) — a reading or an estimate, as `provenance` says. pub struct Work { @@ -57,8 +81,39 @@ pub struct Work { pub model: String, /// Why the meter produced no figure for the work, when `provenance` is `unmetered`. pub unmetered: Option, + /// The model's own process, read where this host counts it: its CPU energy over the + /// run and why that is not the work's whole energy. `None` for the fallback (no model + /// file, or a model that gave no answer, its binary missing among them), off macOS, + /// where the per-process counter is not live, or when the span gave no reading. + pub model_process: Option, } +/// What the model's own process tree read over its run ([`sandbox_meter::TreeMeter`]). +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct ModelProcess { + /// The CPU energy of the model's process and its descendants over the run, µJ (the + /// reading's nanojoules rounded up): a lower bound. Its CPU only: not its GPU or + /// Neural Engine work, not work handed to a process outside its tree, and not the + /// last time on a core of a thread that exits, which a model that exits in its + /// window always has. + pub cpu_uj: u64, + /// Why `cpu_uj` is not the model's whole energy: each gap the meter saw, as it words + /// it — a model that exits in its window always has one, so its reading is never + /// whole — or, where it saw none, [`NOT_READ_AT_EXIT`]. Never empty. + pub partial_because: Vec, +} + +/// Why a reading of the model's process tree is partial although the tree meter saw no +/// gap in it: the model had not exited when it was read (the wait for its exit failed), +/// so the reading may stop short of its work. A model read at its exit always carries +/// the exit's own gap instead. +pub const NOT_READ_AT_EXIT: &str = + "the model had not exited when its process tree was read, so the reading may stop short of its work"; + +/// The meter name a work's figure carries when the model's own process tree was read: +/// joined with the host meter's name, whose figure is in it too. +const MODEL_PROCESS_TREE: &str = "model-process-tree"; + /// `Work::provenance` for work whose meter produced no figure for it. const UNMETERED: &str = "unmetered"; @@ -71,22 +126,123 @@ pub fn do_work(question: &str) -> Work { /// [`do_work`] with the model given as the path to a local GGUF; a path that does not /// exist answers with the deterministic fallback, and runs no subprocess. -/// -/// The meter is the host's, `jouleclaw_energy::meter::detect_meter`, and never the -/// in-process meter (`detect_in_process_meter`): the model runs in a subprocess -/// (`llama-completion`), and this process's own CPU-energy counter reads this -/// process's threads alone, so it would bill the inference nothing. pub(crate) fn do_work_with(question: &str, model: &str) -> Work { + let bin = std::path::Path::new(model).exists().then(configured_llama); + do_work_via(question, model, bin.as_deref()) +} + +/// [`do_work_with`] with the binary that runs the model given: `None` answers with the +/// deterministic fallback, and runs no subprocess. A model that gives no answer (its +/// binary missing, for one) also answers with the fallback, which carries no reading of +/// the model's process: the reply names no model, so it shows no model's energy. +/// +/// Two meters span the work. The host's, `jouleclaw_energy::meter::detect_meter`, and +/// never the in-process meter (`detect_in_process_meter`): the model runs in a +/// subprocess, and this process's own CPU-energy counter reads this process's threads +/// alone, so it would bill the inference nothing. And, where this host counts each +/// process's CPU energy, the model's own process tree ([`run_model`]). [`grade_work`] +/// grades the two. +pub(crate) fn do_work_via(question: &str, model: &str, bin: Option<&str>) -> Work { + // The per-process counter's liveness probe burns about 300 ms of CPU on this thread + // the first time: here, before the host meter's window opens. + if bin.is_some() { + let _ = sandbox_meter::process_energy_status(); + } let meter = jouleclaw_energy::meter::detect_meter(); - let ((answer, model), figure) = metered(&meter, || match run_model(question, model) { - Some(a) => (a, model_label(model)), - None => (fallback_answer(question), "deterministic-extract".to_string()), + let ((answer, label, reading), figure) = metered(&meter, || match bin { + Some(bin) => { + let run = run_model(question, model, bin); + match run.answer { + Some(a) => (a, model_label(model), run.reading), + None => (fallback_answer(question), "deterministic-extract".to_string(), None), + } + } + None => (fallback_answer(question), "deterministic-extract".to_string(), None), }); - let (measured_uj, provenance, unmetered) = match figure { - Ok((uj, provenance)) => (uj, provenance.to_string(), None), - Err(why) => (0, UNMETERED.to_string(), Some(why)), + let graded = grade_work(figure, reading.as_ref(), meter.active_name()); + Work { + answer, + measured_uj: graded.measured_uj, + provenance: graded.provenance, + meter: graded.meter, + model: label, + unmetered: graded.unmetered, + model_process: graded.model_process, + } +} + +/// A work's figure, as [`grade_work`] decides it. +#[derive(Debug, Clone, PartialEq, Eq)] +struct Graded { + measured_uj: u64, + provenance: String, + meter: String, + unmetered: Option, + model_process: Option, +} + +/// The work's figure, provenance and meter from its two meters: the one place they are +/// decided. `figure` is the host meter's ([`window_energy`]), `reading` the model's own +/// process tree's where there is one. +/// +/// - **A reading** — never whole: the model exits in its window, so its record lacks +/// its last time on a core, and a model that offloads to the GPU leaves GPU time the +/// reading does not cover. So it is an estimate of the work, never a hardware figure +/// of it, because an `efficiency/1` receipt has no coverage field and its figure +/// stands for the whole. The figure is the reading plus the host meter's figure over +/// the same window (the rule mesh's in-process meter bills a partial span by): never +/// less than was read, and nothing the model drew outside its CPU left out; it errs +/// high, by at most the reading, the host figure covering the model's CPU too. +/// `Estimator`, metered by `model-process-tree+`. Where the host meter +/// has no figure, the reading alone cannot stand for the work: no figure, and the +/// work is not sealed. +/// - **No reading** — no per-process counter (off macOS, a counter that is not live), +/// the span's [`TreeError`], or the fallback: the host meter's figure as it is. +fn grade_work( + figure: Result<(u64, Provenance), String>, + reading: Option<&Result>, + host_meter: &str, +) -> Graded { + let host = |figure: Result<(u64, Provenance), String>, model_process| match figure { + Ok((uj, provenance)) => Graded { + measured_uj: uj, + provenance: provenance.to_string(), + meter: host_meter.to_string(), + unmetered: None, + model_process, + }, + Err(why) => Graded { + measured_uj: 0, + provenance: UNMETERED.to_string(), + meter: host_meter.to_string(), + unmetered: Some(why), + model_process, + }, }; - Work { answer, measured_uj, provenance, meter: meter.active_name().to_string(), model, unmetered } + let Some(Ok(r)) = reading else { return host(figure, None) }; + let cpu_uj = r.cpu_nj.div_ceil(1_000); + let mut partial_because: Vec = r.gaps.iter().map(ToString::to_string).collect(); + if partial_because.is_empty() { + partial_because.push(NOT_READ_AT_EXIT.to_string()); + } + let process = ModelProcess { cpu_uj, partial_because }; + match figure { + Ok((uj, _)) => Graded { + measured_uj: cpu_uj.saturating_add(uj), + provenance: Provenance::Estimator.to_string(), + meter: format!("{MODEL_PROCESS_TREE}+{host_meter}"), + unmetered: None, + model_process: Some(process), + }, + Err(why) => { + let why = format!( + "the model's own process read {cpu_uj} µJ of CPU, which is not all of its work ({}), and the host \ + meter put no figure on the rest: {why}", + process.partial_because.join("; ") + ); + host(Err(why), Some(process)) + } + } } /// Run `work` under `meter`: its result, and the meter's figure for it (see @@ -183,29 +339,106 @@ fn unmetered_line(work: &Work) -> String { /// The outcome of work that was not sealed because its meter put no figure on it. const NOT_SEALED: &str = "not sealed (no energy figure)"; +/// A reply's line for the model's own process reading, when there is one: what it read, +/// and why it is not all of the work. +fn model_process_line(work: &Work) -> Option { + let p = work.model_process.as_ref()?; + let mj = p.cpu_uj as f64 / 1000.0; + Some(format!( + "{mj:.1} mJ ({} µJ) of CPU read on its own process tree, not all of its work ({}), so the energy above is \ + an estimate", + p.cpu_uj, + p.partial_because.join("; ") + )) +} + /// The model a reply names: the file name of its path. fn model_label(model: &str) -> String { model.rsplit('/').next().unwrap_or("model").to_string() } -/// Generate an answer with the local model at `model` via `llama-completion` (the -/// reference model hook — swap for Mesh / JouleClaw in production). `None` if there is -/// no model file there. -fn run_model(question: &str, model: &str) -> Option { - if !std::path::Path::new(model).exists() { - return None; - } - let bin = std::env::var("JOULEDESK_LLAMA").unwrap_or_else(|_| "llama-completion".into()); +/// One run of the model: its answer, `None` if it printed none (or could not be run), +/// and its own process tree's reading where this host has one. +struct ModelRun { + answer: Option, + reading: Option>, +} + +/// What the model's process runs as: `sh` waits for a gate line on its stdin, then +/// `exec`s the binary (`$0`) with its arguments (`$@`, passed as argv, never re-parsed), +/// so the model is the same process the tree meter is rooted at and the shell's own +/// start-up is outside the meter's span. +const GATED_EXEC: &str = "IFS= read -r jouledesk_gate || exit 1; exec \"$0\" \"$@\""; + +/// Generate an answer with the local model at `model` via `bin` (`llama-completion`, the +/// reference model hook — swap for Mesh / JouleClaw in production), its own process +/// read where this host counts it. +/// +/// The process is spawned waiting on its gate ([`GATED_EXEC`]); the tree meter (macOS, +/// the per-process counter live) is rooted at it and reads it at rest; the gate line +/// lets it go, and its stdin closes. Its stdout is read to the end, it is waited for +/// without being reaped, so its exited count is still readable, the meter's span is +/// stopped on it, and then it is reaped. Its stderr (the binary's log) is discarded. +fn run_model(question: &str, model: &str, bin: &str) -> ModelRun { + use std::io::{Read, Write}; + use std::process::{Command, Stdio}; let prompt = format!("user\n{question}\nmodel\n"); - let out = std::process::Command::new(&bin) + let spawned = Command::new("sh") + .args(["-c", GATED_EXEC, bin]) .args([ "-m", model, "-p", &prompt, "-n", "160", "--temp", "0.2", "-r", "", "--no-display-prompt", ]) - .output() - .ok()?; - let text = String::from_utf8_lossy(&out.stdout).replace("", "").trim().to_string(); - (!text.is_empty()).then_some(text) + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .stderr(Stdio::null()) + .spawn(); + let Ok(mut child) = spawned else { return ModelRun { answer: None, reading: None } }; + let pid = child.id(); + let tree = TreeMeter::for_process(pid); + let start = tree.as_ref().map(TreeMeter::start); + if let Some(mut stdin) = child.stdin.take() { + let _ = stdin.write_all(b"\n"); + } + let mut out = Vec::new(); + if let Some(mut stdout) = child.stdout.take() { + let _ = stdout.read_to_end(&mut out); + } + let reading = match (&tree, start) { + (Some(tree), Some(start)) => { + let _ = wait_exited_unreaped(pid); + Some(tree.stop(start)) + } + _ => None, + }; + let _ = child.wait(); + let text = String::from_utf8_lossy(&out).replace("", "").trim().to_string(); + ModelRun { answer: (!text.is_empty()).then_some(text), reading } +} + +/// Wait for child `pid` to exit WITHOUT reaping it (`waitid` with `WNOWAIT`), so its +/// count stays readable for the tree meter's stop walk. The caller reaps it afterwards. +/// `false` if the wait failed. +#[cfg(target_os = "macos")] +fn wait_exited_unreaped(pid: u32) -> bool { + loop { + // SAFETY: an all-zero `siginfo_t` is a valid out-parameter. + let mut info: libc::siginfo_t = unsafe { std::mem::zeroed() }; + // SAFETY: `info` is writable for the call; `pid` is this process's child. + let rc = unsafe { libc::waitid(libc::P_PID, pid as libc::id_t, &mut info, libc::WEXITED | libc::WNOWAIT) }; + if rc == 0 { + return true; + } + if std::io::Error::last_os_error().raw_os_error() != Some(libc::EINTR) { + return false; + } + } +} + +/// No tree meter exists off macOS, so there is nothing to read before the reap. +#[cfg(not(target_os = "macos"))] +fn wait_exited_unreaped(_pid: u32) -> bool { + false } /// Honest fallback when no model is configured — still real work, still metered. @@ -313,11 +546,13 @@ fn compose_github(who: &str, work: &Work, outcome: &str, verified: bool) -> Stri "no ledger entry".to_string(), ), }; + let process = model_process_line(work).map(|l| format!("- **model process:** {l}\n")).unwrap_or_default(); format!( "🔷 **@joule** — {outcome}, @{who}.\n\n{answer}\n\n---\n\ _{how_done}._\n\ - **model:** `{model}`\n\ - **energy:** {energy}\n\ + {process}\ - **decision:** {outcome} · {ledger}" ) } @@ -424,6 +659,7 @@ pub(crate) mod tests { model: "a-model".into(), unmetered: (provenance == UNMETERED) .then(|| "the work took 200 µs, shorter than the 100 ms window it can resolve".into()), + model_process: None, } } @@ -589,6 +825,7 @@ pub(crate) mod tests { meter: name.to_string(), model: "a-model".into(), unmetered: None, + model_process: None, }; let (label, sealed_uj) = sealed(&w); let body = compose_github("dana", &w, "completed", true); @@ -625,6 +862,211 @@ pub(crate) mod tests { assert_eq!(w.meter, jouleclaw_energy::meter::detect_meter().active_name()); } + fn tree_reading(cpu_nj: u64, gaps: Vec) -> TreeReading { + TreeReading { cpu_uj: cpu_nj.div_ceil(1_000), cpu_nj, processes: 1, pids: vec![4242], wall: SECOND, gaps } + } + + /// The grading, pure: a reading of the model's process is never sealed as a hardware + /// reading — it is an estimate, the reading plus the host meter's figure, or no figure + /// where the host has none — and it always says why it is partial; no reading leaves + /// the host meter's figure as it is. + #[test] + fn a_model_process_reading_is_never_a_hardware_figure() { + use sandbox_meter::TreeGap; + let est = Ok((40_000, Provenance::Estimator)); + // A model on the GPU, exited in its window. + let gpu = vec![TreeGap::Exited { pid: 4242 }, TreeGap::Gpu { ns: 2_000_000 }]; + let g = grade_work(est.clone(), Some(&Ok(tree_reading(9_000_001, gpu.clone()))), "apple-silicon"); + assert_eq!((g.measured_uj, g.provenance.as_str(), g.unmetered), (49_001, "estimator", None), "rounded up"); + assert_eq!(g.meter, "model-process-tree+apple-silicon"); + let because: Vec = gpu.iter().map(ToString::to_string).collect(); + assert_eq!(g.model_process, Some(ModelProcess { cpu_uj: 9_001, partial_because: because })); + + // No gap seen: the model was not read at its exit. Still an estimate, saying so. + let no_gap = grade_work(est.clone(), Some(&Ok(tree_reading(9_000_000, vec![]))), "apple-silicon"); + assert_eq!((no_gap.measured_uj, no_gap.provenance.as_str()), (49_000, "estimator")); + assert_eq!(no_gap.model_process.unwrap().partial_because, vec![NOT_READ_AT_EXIT.to_string()]); + + // A hardware machine-wide figure does not make the sum a hardware reading. + let hw = grade_work(Ok((40_000, Provenance::HwShunt)), Some(&Ok(tree_reading(9_000_000, gpu.clone()))), "rapl"); + assert_eq!((hw.measured_uj, hw.provenance.as_str()), (49_000, "estimator")); + + // A reading with no host figure is no figure: nothing is sealed. + let short = grade_work(Err("too short".into()), Some(&Ok(tree_reading(9_000_000, gpu))), "apple-silicon"); + assert_eq!((short.measured_uj, short.provenance.as_str()), (0, UNMETERED)); + let why = short.unmetered.unwrap(); + assert!(why.contains("9000 µJ of CPU") && why.contains("too short"), "{why}"); + assert!(short.model_process.is_some()); + + // No reading: the host meter's figure, as it is. + for reading in [None, Some(&Err(TreeError::RootGone { pid: 4242 }))] { + let g = grade_work(est.clone(), reading, "apple-silicon"); + assert_eq!((g.measured_uj, g.provenance.as_str(), g.meter.as_str()), (40_000, "estimator", "apple-silicon")); + assert_eq!(g.model_process, None); + } + let g = grade_work(Ok((40_000, Provenance::HwShunt)), None, "rapl"); + assert_eq!(g.provenance, "hw_shunt", "a live machine-wide counter with no process reading is unchanged"); + } + + /// A partial model-process figure is sealed and posted as an estimate, with the + /// reading and why it is partial on its own line. + #[test] + fn a_partial_model_process_figure_is_sealed_and_posted_as_an_estimate() { + let partial = Some(&Ok(tree_reading(9_000_000, vec![sandbox_meter::TreeGap::Exited { pid: 7 }]))); + let g = grade_work(Ok((40_000, Provenance::Estimator)), partial, "apple-silicon"); + let w = Work { + answer: "an answer".into(), + measured_uj: g.measured_uj, + provenance: g.provenance, + meter: g.meter, + model: "a-model".into(), + unmetered: g.unmetered, + model_process: g.model_process, + }; + assert_eq!(sealed(&w), ("Estimator".to_string(), 49_000)); + let body = compose_github("dana", &w, "completed", true); + assert!(body.contains("49.0 mJ (49000 µJ) — estimated by `model-process-tree+apple-silicon`"), "{body}"); + let line = body.lines().find(|l| l.starts_with("- **model process:** ")).expect("a model-process line"); + assert!(line.contains("9.0 mJ (9000 µJ) of CPU read on its own process tree, not all of its work"), "{line}"); + assert!(line.contains("pid 7 exited") && line.contains("estimate"), "{line}"); + assert!(!body.contains("measured"), "{body}"); + let slack = slack_compose(&w); + assert!(slack.contains("• *model process:* 9.0 mJ (9000 µJ) of CPU"), "{slack}"); + } + + fn slack_compose(w: &Work) -> String { + crate::slack::tests::compose_for_test(w) + } + + /// The stand-in model's marker and report, in its working directory. + const STAND_IN_MARKER: &str = ".model-stand-in"; + const STAND_IN_REPORT: &str = ".model-stand-in-report"; + + /// This process's own CPU energy count, nJ: `proc_pid_rusage(getpid(), + /// RUSAGE_INFO_V6)`'s `ri_energy_nj`, read with a bare buffer of the struct's 464 + /// bytes at its SDK offset, 336. Written out here, sharing no code with the meter it + /// checks. + #[cfg(target_os = "macos")] + fn own_energy_nj() -> u64 { + extern "C" { + fn proc_pid_rusage(pid: i32, flavor: i32, buffer: *mut std::ffi::c_void) -> i32; + } + let mut buf = [0u64; 58]; + // SAFETY: `buf` is 464 writable bytes, the size of `rusage_info_v6`. + let rc = unsafe { proc_pid_rusage(std::process::id() as i32, 6, buf.as_mut_ptr().cast()) }; + assert_eq!(rc, 0, "proc_pid_rusage on this process"); + buf[336 / 8] + } + + #[cfg(not(target_os = "macos"))] + fn own_energy_nj() -> u64 { + 0 + } + + /// Not a test of its own: the stand-in model, run as a subprocess by + /// [`a_model_subprocess_is_read_on_its_own_process_as_its_own_count_says`] (this + /// test binary, filtered to this test, behind a script that takes the model's + /// arguments). It does a fixed amount of CPU work, leaves the core (which folds its + /// count), and writes its own count to its working directory. Anywhere without its + /// marker it returns at once. + #[test] + #[ignore = "a subprocess stand-in, run by the model-process energy test"] + fn model_stand_in() { + let Ok(iterations) = std::fs::read_to_string(STAND_IN_MARKER) else { return }; + let iterations: u64 = iterations.trim().parse().expect("the marker holds an iteration count"); + let mut x = 1u64; + for i in 0..iterations { + x = std::hint::black_box(x.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(i)); + } + std::thread::sleep(Duration::from_millis(20)); + std::fs::write(STAND_IN_REPORT, format!("{} {x}", own_energy_nj())).expect("the report"); + } + + /// End to end with a model subprocess: the stand-in burns a fixed amount of CPU and + /// reports its own energy count, read from inside it before it exits — the oracle, + /// sharing no code with the tree meter. Where this host reads the model's process + /// (macOS, the per-process counter live), the reading agrees with that count to + /// within the shells' start-up and the stand-in's tear-down; it is partial (the model + /// exited in its window), so the work is sealed and posted as an estimate, the + /// reading plus the host meter's figure. Elsewhere the host meter's figure stands. + /// Twice. + #[test] + fn a_model_subprocess_is_read_on_its_own_process_as_its_own_count_says() { + // About a second of one core, unoptimized; a fixed amount of work. + const ITERATIONS: u64 = 150_000_000; + let dir = std::env::temp_dir().join(format!("jouledesk-model-stand-in-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).unwrap(); + std::fs::write(dir.join(STAND_IN_MARKER), ITERATIONS.to_string()).unwrap(); + let exe = std::env::current_exe().expect("this test binary"); + let script = dir.join("stand-in-llama"); + std::fs::write( + &script, + format!("#!/bin/sh\ncd '{}' || exit 1\nexec '{}' tests::model_stand_in --exact --ignored\n", dir.display(), exe.display()), + ) + .unwrap(); + let chmod = std::process::Command::new("chmod").arg("+x").arg(&script).status().unwrap(); + assert!(chmod.success()); + let model = dir.join(STAND_IN_MARKER); // a file that exists: the "model" + let reads_processes = + cfg!(target_os = "macos") && sandbox_meter::process_energy_status() == sandbox_meter::CounterStatus::Live; + + let bin = script.display().to_string(); + for round in 1..=2 { + let w = do_work_via("what changed?", model.to_str().unwrap(), Some(&bin)); + let report = std::fs::read_to_string(dir.join(STAND_IN_REPORT)).expect("the stand-in's report"); + let _ = std::fs::remove_file(dir.join(STAND_IN_REPORT)); + let oracle_nj: u64 = report.split_whitespace().next().unwrap().parse().unwrap(); + eprintln!( + "model subprocess round {round}: oracle {oracle_nj} nJ; {} µJ {} by {} ({:?})", + w.measured_uj, w.provenance, w.meter, w.model_process + ); + assert!(w.answer.contains("1 passed"), "the stand-in did not run: {}", w.answer); + assert_eq!(w.model, STAND_IN_MARKER, "the model's answer, not the fallback"); + if reads_processes { + let p = w.model_process.clone().unwrap_or_else(|| panic!("no reading of the model's process: {:?}", w.unmetered)); + let oracle_uj = oracle_nj / 1_000; + assert!(oracle_uj > 100_000, "setup: the stand-in's work read {oracle_uj} µJ"); + let ratio = p.cpu_uj as f64 / oracle_uj as f64; + assert!((0.8..=1.25).contains(&ratio), "read {} µJ of a model that counted {oracle_uj} µJ", p.cpu_uj); + assert!(p.partial_because.iter().any(|g| g.contains("exited")), "{p:?}"); + assert_eq!(w.provenance, Provenance::Estimator.to_string(), "a partial reading sealed above an estimate"); + assert!(w.meter.starts_with("model-process-tree+"), "{}", w.meter); + assert!(w.measured_uj > p.cpu_uj, "the host meter's figure is in the sum: {} µJ", w.measured_uj); + assert_eq!(sealed(&w), ("Estimator".to_string(), w.measured_uj)); + // The stand-in's answer is test-runner output: check the reply's own lines. + let body = compose_github("dana", &w, "completed", true); + let energy = body.lines().find(|l| l.starts_with("- **energy:** ")).expect("an energy line"); + assert!(energy.contains("estimated by `model-process-tree+") && !energy.contains("measured"), "{energy}"); + assert!(body.lines().any(|l| l.starts_with("- **model process:** ")), "{body}"); + } else { + assert_eq!(w.model_process, None); + assert_eq!(w.meter, jouleclaw_energy::meter::detect_meter().active_name()); + } + } + let _ = std::fs::remove_dir_all(&dir); + } + + /// A model binary that cannot be run answers with the deterministic fallback, and the + /// fallback carries no reading of the model's process: `sh` failing to `exec` the + /// binary is no model's energy, and the reply, which names no model, shows none. + #[test] + fn a_model_binary_that_cannot_run_falls_back_with_no_model_reading() { + let dir = std::env::temp_dir().join(format!("jouledesk-missing-binary-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).unwrap(); + let model = dir.join("model.gguf"); + std::fs::write(&model, b"").unwrap(); // a file that exists: the "model" + let w = do_work_via("what changed?", model.to_str().unwrap(), Some("/nonexistent/llama-completion")); + eprintln!("missing binary: model={} model_process={:?} meter={}", w.model, w.model_process, w.meter); + assert_eq!(w.model, "deterministic-extract"); + assert_eq!(w.model_process, None, "the fallback carried a model reading"); + assert!(!w.meter.starts_with(MODEL_PROCESS_TREE), "{}", w.meter); + let body = compose_github("dana", &w, "completed", true); + assert!(!body.contains("model process"), "{body}"); + let _ = std::fs::remove_dir_all(&dir); + } + #[test] fn ignores_comments_that_dont_address_the_handle() { let event = json!({ "comment": { "user": { "login": "x" }, "body": "just chatting" } }); diff --git a/jouledesk/jouledesk-rs/crates/jouledesk-github/src/slack.rs b/jouledesk/jouledesk-rs/crates/jouledesk-github/src/slack.rs index 552fe6dd4..73ea51569 100644 --- a/jouledesk/jouledesk-rs/crates/jouledesk-github/src/slack.rs +++ b/jouledesk/jouledesk-rs/crates/jouledesk-github/src/slack.rs @@ -75,11 +75,13 @@ fn compose(who: &str, work: &super::Work, outcome: &str, verified: bool) -> Stri "no ledger entry".to_string(), ), }; + let process = super::model_process_line(work).map(|l| format!("• *model process:* {l}\n")).unwrap_or_default(); format!( "🔷 *@joule* — {outcome}, <@{who}>.\n\n{answer}\n\n\ _{how_done}_\n\ • *model:* `{model}`\n\ • *energy:* {energy}\n\ + {process}\ • *decision:* {outcome} · {ledger}" ) } @@ -111,9 +113,14 @@ impl Slack { } #[cfg(test)] -mod tests { +pub(crate) mod tests { use super::*; + /// The Slack reply for `work`, for the core's tests. + pub(crate) fn compose_for_test(work: &super::super::Work) -> String { + compose("U123", work, "completed", true) + } + /// The same end-to-end path as the GitHub binding's: the deterministic fallback is /// too fast for any meter here to resolve, so the Slack reply says it was not /// metered, and why, and seals nothing — never a figure, never "measured".