From d9fa5c3436e4720a88a568e876c7ff6d432c21b9 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Sun, 30 Aug 2026 21:25:59 +0000 Subject: [PATCH 01/13] perf(rules): compile a forbid row's matcher once per rule, and report what each rule cost MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `batten-check` is 465s of the `ci` job's 1327s and emits two lines while it runs. Nothing reported a per-rule duration and every `command` child's streams are `Stdio::null()`, so the largest item in this repository's CI was unattributable from its own output — two sessions guessed at it and both were wrong, by 4.5x and by 56x, and the answer only came out of a scratch worktree with the ruleset hand-edited. Two changes, and the census is first because it is what proves the second. THE CENSUS. `run` times each `run_rule` dispatch and takes a delta over two new process-global read counters, on `DOCUMENTS_ACQUIRED`'s idiom and for its reason: a counter beats a clock where the thing being counted is well inside the noise of a process start, and a delta needs no accumulator threaded through nine read sites. Sound because the loop is serial, which is a measured verdict rather than an accident. Rendered on the `-vv` rung and nowhere else: a duration is not byte-stable, so it must never reach `-J`, a pointer line or stdout (§6). `RuleCost` hand-writes `PartialEq` to skip the clock, so `Scan`'s derived equality stays the byte-stability property it was and does not quietly become timing-dependent. THE MATCHER. `forbid_in_file` took one path and was called once per file, and it called `Matcher::for_rule` — so `Regex::new` ran once per (rule, file) pair, ~3,300 compilations of 17 expressions over this repository's own ruleset. The comment on that call said the compile had been hoisted out of the LINE loop because "`Regex::new` is the expensive half"; it was right about the cost and stopped one loop short. The expression is a property of the row, so `forbid_in_files` takes the matched set and compiles it where the row is. A config fault now also refuses before any file is read rather than after the first. Findings are unchanged: same rules, same order, same pointers, same keyed identities. `matched` is already ordered and the outer sort is untouched. `run_rules` bought its line back by dropping a duplicate — `base_ref` and `config_from` bound the identical `overrides.config_from.as_deref()` under two names, so one value had two spellings in one function. Refs: CLOUD-1217 --- crates/batten/src/lib.rs | 68 +++++++++++- crates/batten/src/rules.rs | 213 ++++++++++++++++++++++++++++++------- 2 files changed, 240 insertions(+), 41 deletions(-) diff --git a/crates/batten/src/lib.rs b/crates/batten/src/lib.rs index cc5945b31..26d22b733 100644 --- a/crates/batten/src/lib.rs +++ b/crates/batten/src/lib.rs @@ -8117,6 +8117,65 @@ fn announce_config(mode: Mode, err: &mut dyn Write, config: &resolve::Resolved) announce_degrade(mode, err, config.base.as_ref()) } +/// Report what each rule cost, on the `-vv` rung (CLOUD-1217). +/// +/// **This exists because the largest item in this repository's CI was a silent +/// span.** `batten-check` ran 465s of a 1327s job and emitted two lines, so the +/// cost was unattributable from its own output; two sessions guessed at it and +/// both were wrong, and the answer only came out of a scratch worktree with the +/// ruleset hand-edited. This turns that bisect into a flag. +/// +/// **`Debug`, not `Verbose`, and never the answer channel.** A duration is not +/// byte-stable, so it must not reach `-J`, a pointer line or stdout — house-style +/// §6. It is a measurement about the run, not a finding about the tree, and the +/// two channels stay separate. +/// +/// Sorted by cost descending, ties broken by rule id, because the question this +/// answers is "what is the pole" and a reader should not have to sort 84 lines. +/// The tiebreak is what keeps two runs over one tree reading the same. +/// +/// Pointer-only (non-negotiable rule 4): an id, two counts and a duration. Never +/// a path, never a scanned byte. +fn report_rule_costs(mode: Mode, err: &mut dyn Write, scan: &rules::Scan) -> Result<()> { + if scan.costs.is_empty() { + return Ok(()); + } + let mut ranked: Vec<&rules::RuleCost> = scan.costs.iter().collect(); + ranked.sort_by(|a, b| { + b.elapsed + .cmp(&a.elapsed) + .then_with(|| a.rule.as_str().cmp(b.rule.as_str())) + }); + for cost in &ranked { + output::message( + mode, + Verbosity::Debug, + err, + &format!( + "rule cost: {} {}ms {} file(s) {} byte(s)", + cost.rule, + cost.elapsed.as_millis(), + cost.files_read, + cost.bytes_read + ), + )?; + } + let elapsed: std::time::Duration = scan.costs.iter().map(|cost| cost.elapsed).sum(); + let files: usize = scan.costs.iter().map(|cost| cost.files_read).sum(); + let bytes: usize = scan.costs.iter().map(|cost| cost.bytes_read).sum(); + output::message( + mode, + Verbosity::Debug, + err, + &format!( + "rule cost: {} rule(s) {}ms {files} file(s) {bytes} byte(s)", + scan.costs.len(), + elapsed.as_millis(), + ), + )?; + Ok(()) +} + #[expect( clippy::too_many_lines, reason = "the one funnel `check` and `enforce` share, and it reads as one sequence: \ @@ -8166,6 +8225,7 @@ fn run_rules( scope: &scope, }; let scan = runner(&selected, &config.provisions, vocabulary, &root, opts)?; + report_rule_costs(mode, err, &scan)?; perform_requested_sinks(surface, &root, &scan); let mut findings = scan.findings.clone(); @@ -8238,9 +8298,11 @@ fn run_rules( // The baseline filter (CLOUD-67), immediately before the waiver filter. let findings = apply_baseline(findings, &scan, &root, mode, err)?; - // The admission filter (CLOUD-1120), between the two — see its own doc. - let config_from = overrides.config_from.as_deref(); - let findings = apply_admissions(findings, &scan, &root, config_from, mode, err)?; + // The admission filter (CLOUD-1120), between the two — see its own doc. It + // reads `base_ref`, bound once at the top: this used to rebind the identical + // `overrides.config_from.as_deref()` under a second name, so one value had + // two spellings in one function and a reader had to prove they agreed. + let findings = apply_admissions(findings, &scan, &root, base_ref, mode, err)?; // The waiver filter (CLOUD-208), applied HERE and nowhere else. This function // is the single funnel `check` and `enforce` share — they differ only in the diff --git a/crates/batten/src/rules.rs b/crates/batten/src/rules.rs index 4c7ad89f6..076ed22ed 100644 --- a/crates/batten/src/rules.rs +++ b/crates/batten/src/rules.rs @@ -4775,6 +4775,20 @@ pub struct Scan { /// native refusal and every consumer `[[rule]]` row; those are simply not /// admissible, because there is no token an admission could bind. pub classes: BTreeMap, + /// What each evaluated rule cost (CLOUD-1217), in declaration order. + /// + /// **This exists because a 463s run emitted two lines.** No rule kind + /// reported its own duration and every `command` child's streams are + /// `Stdio::null()`, so the largest item in this repository's CI was + /// unattributable from its own output — and two sessions in a row guessed at + /// it, wrongly, before a scratch worktree and a hand-rolled bisect produced + /// the answer. This field is what makes that bisect a command. + /// + /// Rendered on the `-vv` rung and **nowhere else**: a duration is not + /// byte-stable, so it must never reach `-J` or a pointer line, which is + /// house-style §6's contract and the reason this is not folded into the + /// findings document. + pub costs: Vec, /// The rules a declared input-precondition held back, and which requirement /// went unmet (CLOUD-125). A subset of [`Scan::not_evaluated`]'s keys. /// @@ -4930,6 +4944,41 @@ fn isolate(body: impl FnOnce() -> anyhow::Result>) -> Isolat } } +/// What one rule cost, as a pointer rather than a payload (non-negotiable rule 4). +/// +/// A rule id, two counts and a duration. No path list and no scanned bytes — the +/// census answers *how much*, and the findings answer *where*. +#[derive(Debug, Clone)] +pub struct RuleCost { + /// The rule's id. + pub rule: String, + /// Wall clock for this rule's whole evaluation, including whatever it spawned. + pub elapsed: std::time::Duration, + /// Files this rule caused to be read. + pub files_read: usize, + /// Bytes those reads returned. + pub bytes_read: usize, +} + +/// Equality over the DETERMINISTIC half, deliberately skipping [`RuleCost::elapsed`]. +/// +/// [`Scan`] derives `PartialEq`, and two runs over one unchanged tree are the +/// same scan — that is the property byte-stability rests on. A derived +/// comparison here would make it timing-dependent and quietly false, so the +/// clock is excluded and the counts, which ARE deterministic, are what compare. +/// That asymmetry is the whole reason the duration is a measurement and the +/// counts are the assertion, which `.claude/rules/rust.md` states as a standing +/// rule for this crate. +impl PartialEq for RuleCost { + fn eq(&self, other: &Self) -> bool { + self.rule == other.rule + && self.files_read == other.files_read + && self.bytes_read == other.bytes_read + } +} + +impl Eq for RuleCost {} + /// The name of the verb that runs process-spawning rule kinds, quoted in the /// refusal [`run_static`] emits. Named once so the message and the surface /// cannot drift. @@ -5500,6 +5549,23 @@ fn evaluate_rules( // // The scan's three mutable maps are destructured inside the block so // their borrows end before `not_evaluated` is written below. + // THE CENSUS IS TAKEN AROUND THE DISPATCH, not inside each kind + // (CLOUD-1217). One site sees every rule, so a kind added later is + // measured without anyone remembering to instrument it — the inverse of + // the state this row found, where nothing reported and the largest item + // in CI was a silent span. + // + // Deltas over the process-global counters rather than an accumulator + // threaded through nine read sites. Sound because this loop is serial, + // which `.claude/rules/rust.md` records as a measured verdict rather + // than an accident. + // + // AROUND `isolate` RATHER THAN AROUND `run_rule`, which is where the + // precondition skip above puts it: a rule held back by an unmet + // requirement never enters the body, so it has no cost to report and a + // zero row for it would read as "evaluated, and free". + let started = std::time::Instant::now(); + let (files_before, bytes_before) = (files_read(), bytes_read()); let outcome = { let Scan { findings, @@ -5509,6 +5575,12 @@ fn evaluate_rules( } = &mut *scan; isolate(|| run_rule(rule, root, inputs, findings, attributed, classes)) }; + scan.costs.push(RuleCost { + rule: rule.id.clone(), + elapsed: started.elapsed(), + files_read: files_read().saturating_sub(files_before), + bytes_read: bytes_read().saturating_sub(bytes_before), + }); match outcome { Isolated::Evaluated => {} Isolated::NotEvaluated(why) => { @@ -5814,11 +5886,7 @@ fn run_rule( return Ok(Some(NotObserved::RuleSkipped)); } match rule.kind { - RuleKind::Forbid => { - for path in matched { - forbid_in_file(rule, root, path, findings)?; - } - } + RuleKind::Forbid => forbid_in_files(rule, root, &matched, findings)?, RuleKind::Command => command_rule(rule, root, &matched, findings)?, RuleKind::Document => { for path in matched { @@ -6001,6 +6069,47 @@ pub fn documents_acquired() -> usize { DOCUMENTS_ACQUIRED.load(Ordering::Relaxed) } +/// How many working-tree files this process has read on a rule's behalf +/// (CLOUD-1217), and how many bytes those reads returned. +/// +/// **Two counters beside [`DOCUMENTS_ACQUIRED`] rather than one widened counter**, +/// because they answer different questions. That one is bounded to the document +/// cache and is what `document_read_count.rs` asserts; these cover every read a +/// rule kind performs for itself — the `forbid` scan, both of a `ratchet`'s +/// passes, and the two conservation walks — which is precisely the population the +/// cache never covered. +/// +/// **Monotonic and process-global, read as a DELTA around one rule**, which is +/// what makes the per-rule attribution possible without threading an accumulator +/// through nine call sites. Sound only because [`run`]'s loop is serial; a +/// concurrent second run in the same process would interleave, which is why the +/// test that reads them lives in its own binary, exactly as +/// `document_read_count.rs` does and for the same reason. +static FILES_READ: AtomicUsize = AtomicUsize::new(0); +static BYTES_READ: AtomicUsize = AtomicUsize::new(0); + +/// Record one read of `bytes` bytes against the counters above. +/// +/// Called at each site that reads on a rule's behalf, after the read has +/// succeeded — a read that failed spent an `open` and returned nothing, and +/// counting it would make an absent file indistinguishable from an empty one. +fn count_read(bytes: usize) { + FILES_READ.fetch_add(1, Ordering::Relaxed); + BYTES_READ.fetch_add(bytes, Ordering::Relaxed); +} + +/// How many files this process has read on a rule's behalf. +#[must_use] +pub fn files_read() -> usize { + FILES_READ.load(Ordering::Relaxed) +} + +/// How many bytes those reads returned. +#[must_use] +pub fn bytes_read() -> usize { + BYTES_READ.load(Ordering::Relaxed) +} + /// **The one function that acquires a document** (CLOUD-849). /// /// Every `Fact::Document` in this crate is read and parsed here and nowhere @@ -7641,6 +7750,12 @@ fn ratchet_rule( let mut base_text: BTreeMap = BTreeMap::new(); let retires_with = rule.retires_with.as_deref(); crate::git::for_each_blob_at_rev(root, base, glob, |path, text| { + // Counted here rather than inside the walker: a blob decompressed out of + // the object store is a read this rule caused, and the census must not + // report a ratchet as cheaper than a forbid merely because its bytes came + // from git. Counting it in `git.rs` would also point that module at this + // one, which the layering table declares the wrong way round. + count_read(text.len()); base_counts.insert(path.to_owned(), text.matches(pattern).count()); // Held only for the columns that read it: a ratchet with neither // `retires_with` nor `conserves` must not start buffering the base @@ -7663,6 +7778,7 @@ fn ratchet_rule( let mut working_declared: BTreeSet<&str> = BTreeSet::new(); for path in matched { let text = fs::read_to_string(root.join(path)).unwrap_or_default(); + count_read(text.len()); let count = text.matches(pattern).count(); working_count += count; working_counts.insert(path.as_str(), count); @@ -8173,6 +8289,7 @@ fn claimed_cases(root: &Path, conserves: &Conserves, files: &[String]) -> Claime let Ok(text) = fs::read_to_string(root.join(path)) else { continue; }; + count_read(text.len()); for (index, line) in text.lines().enumerate() { let trimmed = line.trim_start(); for &(arm, token) in &arms { @@ -8454,6 +8571,7 @@ fn conserve_case_names( // for the cases it dropped and nothing for the ones still standing, so // the surviving names have to be read rather than assumed absent. let survivors = fs::read_to_string(root.join(path)).unwrap_or_default(); + count_read(survivors.len()); let mapping = Mapping { conserves, claimed, @@ -9264,49 +9382,68 @@ impl Matcher { } } -fn forbid_in_file( +/// Evaluate a [`RuleKind::Forbid`] row against every path its glob selected. +/// +/// **The whole matched set, not one path** (CLOUD-1217), and that boundary is +/// the fix rather than a refactor. The predecessor took one `rel_path` and was +/// called once per file from [`run_rule`], so [`Matcher::for_rule`] — and with +/// it `Regex::new` — ran once per *(rule, file)* pair. Over this repository's own +/// ruleset that is ~3 300 compilations per run, of 17 expressions. +/// +/// The comment that used to sit on that call said the compile was hoisted out of +/// the *line* loop because "`Regex::new` is the expensive half". It was right +/// about the cost and stopped one loop short; the expression is a property of the +/// ROW, so it is compiled where the row is. +fn forbid_in_files( rule: &Rule, root: &Path, - rel_path: &str, + paths: &[&String], findings: &mut Vec, ) -> anyhow::Result<()> { - let contents = match fs::read(root.join(rel_path)) { - Ok(bytes) => bytes, - Err(err) if err.kind() == std::io::ErrorKind::NotFound => return Ok(()), - Err(err) => return Err(err.into()), - }; - let Ok(text) = String::from_utf8(contents) else { - return Ok(()); - }; - // Compiled once per file, never per line: an expression recompiled inside - // the loop would make the scan's cost a function of the tree's size times - // the pattern's, and `Regex::new` is the expensive half. + // Compiled once per RULE, never per file and never per line. // // `Rule::validate` has already refused a malformed expression and the // both-columns row, so these are defence in depth on the same reading // `run_rule` applies — the runner re-validates rather than trusting that - // every path reached it through the loader. + // every path reached it through the loader. Hoisting it here also moves that + // refusal from "once the first matched file is read" to "before any file is + // read", which is the direction a config fault should travel. let (matcher, exclude) = Matcher::for_rule(rule)?; let mode = span_mode(rule); - for (index, line) in text.lines().enumerate() { - // Excluded lines are dropped AFTER matching, never instead of it: the - // exclusion is about what a matched line turns out to be — a comment, - // a case pattern — not about narrowing what counts as a match. - if matcher.matches(line) && !exclude.as_ref().is_some_and(|re| re.is_match(line)) { - // The whole matched line is the span, which is exactly what the - // churn pack hashed test-side before this existed — so its fixtures - // keep their assertions, and that unchanged-ness is the evidence the - // engine picks the same span. - let default = identity::code_fingerprint(&rule.id, rel_path, line, mode)?; - findings.push(Finding { - rule: rule.id.clone(), - severity: rule.severity(), - path: rel_path.to_owned(), - line: Some(index + 1), - identity: identity_of(rule, identity::FindingKind::Code, default), - check: rule.settling_check().unwrap_or(Check::Reevaluate), - remediation: rule.remediation(), - }); + for rel_path in paths { + let rel_path = rel_path.as_str(); + let contents = match fs::read(root.join(rel_path)) { + Ok(bytes) => bytes, + // A path the walk listed and the read cannot find is a tree that + // moved under us, not a finding — the same silence as before, per + // file rather than per call. + Err(err) if err.kind() == std::io::ErrorKind::NotFound => continue, + Err(err) => return Err(err.into()), + }; + count_read(contents.len()); + let Ok(text) = String::from_utf8(contents) else { + continue; + }; + for (index, line) in text.lines().enumerate() { + // Excluded lines are dropped AFTER matching, never instead of it: the + // exclusion is about what a matched line turns out to be — a comment, + // a case pattern — not about narrowing what counts as a match. + if matcher.matches(line) && !exclude.as_ref().is_some_and(|re| re.is_match(line)) { + // The whole matched line is the span, which is exactly what the + // churn pack hashed test-side before this existed — so its fixtures + // keep their assertions, and that unchanged-ness is the evidence the + // engine picks the same span. + let default = identity::code_fingerprint(&rule.id, rel_path, line, mode)?; + findings.push(Finding { + rule: rule.id.clone(), + severity: rule.severity(), + path: rel_path.to_owned(), + line: Some(index + 1), + identity: identity_of(rule, identity::FindingKind::Code, default), + check: rule.settling_check().unwrap_or(Check::Reevaluate), + remediation: rule.remediation(), + }); + } } } Ok(()) From 30caf4a891a2c5a5649aa508b2b5f573b76a5202 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Sun, 30 Aug 2026 21:37:01 +0000 Subject: [PATCH 02/13] perf(policy): memoize two per-path scans that were being re-run once per line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The census this branch just landed named the pole on its first run, and it was neither of the things this work had been chasing. Two Rego modules, both with the same defect: a FUNCTION that scans the whole file, bound inside a per-line loop, so the scan ran once per line. shell-hygiene 28252ms -> 1919ms (14.4x) remedy-authorship 10984ms -> 1842ms (6.0x) batten enforce 65.25s -> 37.22s `sibling-resolves.rego`'s arm 3 called `dir_vars(path)` — a scan of every line — from `var_names(path, line)`, which `constructed` evaluates per line. O(lines**2) per selected file, over ~140 shell programs. `remedy-authorship.rego`'s `stderr_block` bound `openers_for(path)` the same way and then `closes_to_stderr` scanned again on top. Both are now partial rules keyed by path. A partial rule is evaluated once and indexed; a function is called. Nothing else about either predicate moved, and that is what the modules' own cases check — 262 pass, and `batten enforce`'s whole output is byte-identical before and after: same findings, same order, same pointers. WHAT THIS CORRECTS. The row this branch carries was filed blaming `no-secrets` (3%), then rewritten blaming `forbid` and `ratchet` read amplification (82%). The second attribution came from a kind bisect in a scratch worktree whose arms were not paired — arm one paid a cold page cache and the rest did not, so warmth was read as a rule-kind cost. The census measures directly and says every `forbid` and `ratchet` row together is ~150ms: `no-new-ignores` reads 400 files and 15.9MB in 32ms. The 7.3x read amplification is real and it is worth milliseconds. The matcher hoist in the previous commit stands on its own terms — ~3,300 needless `Regex::new` calls is still wrong — but it is not where the time was, and nothing here should be quoted as if it were. Refs: CLOUD-1217 --- .../shell-hygiene/sibling-resolves.rego | 29 +++++++++++++++---- policy/remedy-authorship.rego | 20 +++++++++---- 2 files changed, 38 insertions(+), 11 deletions(-) diff --git a/crates/batten/src/policy/presets/shell-hygiene/sibling-resolves.rego b/crates/batten/src/policy/presets/shell-hygiene/sibling-resolves.rego index 155f56ba1..506411cad 100644 --- a/crates/batten/src/policy/presets/shell-hygiene/sibling-resolves.rego +++ b/crates/batten/src/policy/presets/shell-hygiene/sibling-resolves.rego @@ -88,15 +88,32 @@ expansion_names(line) := {m[1] | # A variable whose assignment reaches for `/..` is excluded: it holds the PARENT # of this script's directory, so a name hung off it is not a sibling and would # resolve against the wrong prefix. -dir_vars(path) := {m[1] | - some line in input.tree.lines[path] - script_dir_line(line) - not contains(line, "/..") - some m in regex.find_all_string_submatch_n(`^[\t ]*([A-Za-z_][A-Za-z0-9_]*)=`, line, -1) +# +# A PARTIAL RULE KEYED BY PATH, NOT A FUNCTION, AND THAT IS A PERFORMANCE +# CONTRACT RATHER THAN A STYLE CHOICE (CLOUD-1217). This scans every line of the +# file, and `var_names` below is evaluated once per line — so as a FUNCTION it was +# re-scanned per line and the arm cost O(lines²) for every selected file. Over +# this repository's own ~140 shell programs that measured **28.2s**, which was 42% +# of `batten enforce` and the single largest rule in the set, dwarfing every +# spawning row beside it. +# +# A partial rule is evaluated once and indexed, so the same predicate costs +# O(lines). The rule body is otherwise unchanged, and the module's own cases are +# what prove that: the arm-3 tests below pin both the finding and the allow, so a +# rewrite that changed WHAT this selects fails at load rather than quietly +# widening or narrowing a preset that ships to every consumer. +dir_vars[path] := names if { + some path, _ in input.tree.lines + names := {m[1] | + some line in input.tree.lines[path] + script_dir_line(line) + not contains(line, "/..") + some m in regex.find_all_string_submatch_n(`^[\t ]*([A-Za-z_][A-Za-z0-9_]*)=`, line, -1) + } } var_names(path, line) := {m[1] | - some variable in dir_vars(path) + some variable in dir_vars[path] some m in regex.find_all_string_submatch_n( sprintf(`\$\{?%s\}?/%s`, [variable, name_capture]), line, diff --git a/policy/remedy-authorship.rego b/policy/remedy-authorship.rego index d90f7d06b..02c98ae3b 100644 --- a/policy/remedy-authorship.rego +++ b/policy/remedy-authorship.rego @@ -121,7 +121,7 @@ stderr_block[path][i] := line if { some path, ls in lines_of endswith(path, ".sh") some i, line in ls - some j in openers_for(path) + some j in openers_for[path] j < i closes_to_stderr(path, j, i) } @@ -129,10 +129,20 @@ stderr_block[path][i] := line if { # Every bare `{` on its own line: a brace group opener. A `{` in any other # position is a parameter expansion, a brace expansion, or a literal, and is not # a group — which is why the whole trimmed line must be the brace. -openers_for(path) := [j | - some j, line in lines_of[path] - trim_space(line) == "{" -] +# A PARTIAL RULE KEYED BY PATH, NOT A FUNCTION, FOR `sibling-resolves`'s REASON +# (CLOUD-1217). `stderr_block` binds this inside its own per-line loop, so as a +# function it re-scanned the whole file once per line and the rule cost +# O(lines**2) before `closes_to_stderr` scanned again. Measured over this +# repository's own tree at **11.0s**, the second-largest rule in the set. A +# partial rule is evaluated once and indexed; the selected openers are identical, +# which the cases below are what prove. +openers_for[path] := opens if { + some path, ls in lines_of + opens := [j | + some j, line in ls + trim_space(line) == "{" + ] +} # The group opened at `j` is still open at `i`, and its closer redirects to # stderr. A closer between them ends the group; the FIRST one is what counts. From 5eb6011a5edaa7ecc2fbd622528f8293f2c2ee9d Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Sun, 30 Aug 2026 22:36:55 +0000 Subject: [PATCH 03/13] test(rules): gate the per-rule cost census, and show it able to fail MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The census landed in 99420ba with no case under it, which makes it a log rather than a mechanism — non-negotiable rule 2 refuses exactly that. Three cases, in their own binary for `document_read_count.rs`'s reason: the counters are process-global and read as a delta, so a sibling case reading a file in the same process would race them under a threading harness. every_rule_gets_one_census_row_in_declaration_order a_rule_reports_one_read_per_file_its_glob_selected the_census_measures_the_run_rather_than_identifying_it SHOWN ABLE TO FAIL rather than asserted to be. Dropping `count_read` from `forbid_in_files` and re-running gives `left: 0, right: 3` on the second case — 2 passed, 1 failed — so the count tracks the engine rather than a constant. Each case also names its own mutation in a comment, and the second carries an anti-vacuity arm that widens the glob and watches both counts move. The third case is the one that is easy to skip and should not be: `Scan` derives `PartialEq` and two runs over one unchanged tree are the same scan, which is what byte-stability rests on. `RuleCost` therefore compares on its deterministic half and skips `elapsed`; deriving it would make scan equality differ by a nanosecond and be quietly false. Also corrects `Scan::costs`'s own doc: it says every rule, not every EVALUATED rule, because a rule whose glob selected nothing still earns a row reporting zero. "This rule cost nothing" and "this rule is missing from the report" are different answers, and the first case pins that. Refs: CLOUD-1217 --- crates/batten/src/rules.rs | 7 +- crates/batten/tests/rule_cost_census.rs | 187 ++++++++++++++++++++++++ 2 files changed, 193 insertions(+), 1 deletion(-) create mode 100644 crates/batten/tests/rule_cost_census.rs diff --git a/crates/batten/src/rules.rs b/crates/batten/src/rules.rs index 076ed22ed..accb25141 100644 --- a/crates/batten/src/rules.rs +++ b/crates/batten/src/rules.rs @@ -4775,7 +4775,12 @@ pub struct Scan { /// native refusal and every consumer `[[rule]]` row; those are simply not /// admissible, because there is no token an admission could bind. pub classes: BTreeMap, - /// What each evaluated rule cost (CLOUD-1217), in declaration order. + /// What each rule cost (CLOUD-1217), in declaration order. + /// + /// **Every rule, including one whose glob selected nothing.** "This rule + /// cost nothing" and "this rule is missing from the report" are different + /// answers, and collapsing them is how a rule that stopped running would + /// read as cheap. /// /// **This exists because a 463s run emitted two lines.** No rule kind /// reported its own duration and every `command` child's streams are diff --git a/crates/batten/tests/rule_cost_census.rs b/crates/batten/tests/rule_cost_census.rs new file mode 100644 index 000000000..846e81b06 --- /dev/null +++ b/crates/batten/tests/rule_cost_census.rs @@ -0,0 +1,187 @@ +//! CLOUD-1217: the engine reports what each rule cost, so a slow gate is +//! attributable from its own output. +//! +//! **Why this exists at all.** `batten-check` ran 465s of a 1327s CI job and +//! emitted two lines. No rule kind reported its own duration and every +//! `command`-rule child has `Stdio::null()` on both streams, so the largest item +//! in this repository's CI was unattributable *by construction*. Two sessions in +//! a row attributed it confidently and wrongly — once to `no-secrets` (which +//! measures 3%) and once to `forbid`/`ratchet` read amplification (which +//! measures ~150ms) — before an instrument existed to ask. The census is that +//! instrument and this is its gate: without a case under it, it is a log rather +//! than a mechanism, which non-negotiable rule 2 refuses. +//! +//! **Its own test binary, for `document_read_count.rs`'s reason exactly**: +//! `rules::files_read` and `rules::bytes_read` are process-global counters read +//! as a delta, so a sibling case reading a file in the same process would race +//! the deltas below under a harness that threads rather than forks. +//! +//! **Counts are the assertion, never the clock.** `RuleCost::elapsed` is a +//! measurement and varies run to run; the counts are deterministic. Asserting a +//! duration here would discriminate nothing, which is the standing rule in +//! `.claude/rules/rust.md` and the reason `RuleCost`'s `PartialEq` skips +//! `elapsed`. +//! +//! Asserted through `run_static` — the surface a consumer reaches — rather than +//! by widening anything to `pub` for a test's convenience. + +// Panicking on setup failure is the idiomatic way for a test to fail loudly. +#![allow(clippy::unwrap_used, clippy::expect_used)] + +use std::fs; +use std::path::{Path, PathBuf}; + +use batten::rules::{self, Rule}; + +/// An empty vocabulary: every row here is a native `forbid`, which raises no +/// declared verdict token, and `load` refuses a table naming a token nothing +/// raises. +fn vocabulary() -> batten::policy::Vocabulary<'static> { + batten::policy::Vocabulary { + patterns: &[], + verdicts: &[], + recorders: &[], + } +} + +/// A `forbid` row over `glob`, looking for a literal that is never present — the +/// census is about what a rule READ, so a row that finds nothing still has to +/// report the files it opened to find that out. +fn row(id: &str, glob: &str) -> Rule { + serde_json::from_value(serde_json::json!({ + "id": id, + "kind": "forbid", + "scope": "tree", + "glob": glob, + "pattern": "a-literal-no-fixture-carries", + "severity": "deny", + })) + .expect("a tree-scoped forbid row the loader accepts") +} + +fn scratch(name: &str) -> PathBuf { + let dir = std::env::temp_dir().join(format!("batten-census-{name}-{}", std::process::id())); + let _ = fs::remove_dir_all(&dir); + fs::create_dir_all(dir.join("policy")).expect("scratch"); + dir +} + +/// Write `count` files of known, distinct sizes and return their total bytes. +fn seed(root: &Path, count: usize) -> usize { + (0..count) + .map(|i| { + let body = "x".repeat(i + 1); + fs::write(root.join(format!("f{i}.txt")), &body).expect("fixture"); + body.len() + }) + .sum() +} + +#[test] +fn every_rule_gets_one_census_row_in_declaration_order() { + // A rule whose glob selects nothing is SKIPPED, and it still earns a row + // reporting zero. That is deliberate rather than incidental: "this rule cost + // nothing" and "this rule is missing from the report" are different answers, + // and collapsing them is how a rule that stopped running would look cheap. + // + // Fails by: pushing the cost inside the `if let Some(why)` arm, which drops + // every rule that ran clean. + let root = scratch("order"); + seed(&root, 2); + + let scan = rules::run_static( + &[ + row("reads-the-txt", "*.txt"), + row("matches-nothing", "*.no-such-extension"), + row("reads-the-txt-again", "*.txt"), + ], + &[], + vocabulary(), + &root, + ) + .expect("the read surface runs the rows"); + + let ids: Vec<&str> = scan.costs.iter().map(|cost| cost.rule.as_str()).collect(); + assert_eq!( + ids, + ["reads-the-txt", "matches-nothing", "reads-the-txt-again"], + "one census row per rule, in declaration order — a skipped rule included" + ); + let skipped = scan + .costs + .iter() + .find(|cost| cost.rule == "matches-nothing") + .expect("the skipped rule has a row"); + assert_eq!( + (skipped.files_read, skipped.bytes_read), + (0, 0), + "a rule that selected nothing read nothing, and says so rather than being absent" + ); + + let _ = fs::remove_dir_all(&root); +} + +#[test] +fn a_rule_reports_one_read_per_file_its_glob_selected() { + // THE PROPERTY THE CENSUS IS FOR. Attribution is only worth anything if the + // counts track what a rule actually opened, so this pins the count to the + // matched set and the byte total to those files' sizes. + // + // Fails by: dropping the `count_read` call in `forbid_in_files`, which makes + // both deltas zero while the rule still runs. + let root = scratch("counts"); + let bytes = seed(&root, 3); + + let scan = rules::run_static(&[row("reads-three", "*.txt")], &[], vocabulary(), &root) + .expect("the read surface runs the row"); + + let cost = scan.costs.first().expect("the row has a census entry"); + assert_eq!( + cost.files_read, 3, + "three matched files is three reads — the census counts what was opened" + ); + assert_eq!( + cost.bytes_read, bytes, + "the byte total is those files' own sizes, so a count cannot drift from what was read" + ); + + // ANTI-VACUITY, in the same function: a counter wired to a constant would + // satisfy the assertions above however the engine behaved. + let extra = "yyyy"; + fs::write(root.join("f3.txt"), extra).expect("fixture"); + let widened = rules::run_static(&[row("reads-four", "*.txt")], &[], vocabulary(), &root) + .expect("the read surface runs the row"); + let widened = widened.costs.first().expect("the row has a census entry"); + assert_eq!( + (widened.files_read, widened.bytes_read), + (4, bytes + extra.len()), + "adding a file to the glob moves both counts, so the assertions above assert something" + ); + + let _ = fs::remove_dir_all(&root); +} + +#[test] +fn the_census_measures_the_run_rather_than_identifying_it() { + // `Scan` derives `PartialEq` and two runs over one unchanged tree are the + // same scan — that is what byte-stability rests on. `RuleCost` therefore + // compares on its DETERMINISTIC half and skips the clock, because a derived + // comparison would make scan equality timing-dependent and quietly false. + // + // Fails by: deriving `PartialEq` on `RuleCost`, which makes these two unequal + // whenever the two runs differ by a nanosecond — which is almost always. + let root = scratch("equality"); + seed(&root, 2); + + let first = rules::run_static(&[row("reads-two", "*.txt")], &[], vocabulary(), &root) + .expect("the read surface runs the row"); + let second = rules::run_static(&[row("reads-two", "*.txt")], &[], vocabulary(), &root) + .expect("the read surface runs the row"); + + assert_eq!( + first.costs, second.costs, + "two runs over one unchanged tree carry the same census, whatever the clock said" + ); + + let _ = fs::remove_dir_all(&root); +} From fb63036594d413554f1b25673477c228fafaebd6 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Sun, 30 Aug 2026 22:50:43 +0000 Subject: [PATCH 04/13] refactor(rules): take the cost census off `Scan`, where `semver` was right to refuse it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `batten semver check` refused the branch with `constructible_struct_adds_field`: `costs` was a `pub` field added to `pub struct Scan`, and a consumer constructing `Scan { .. }` cannot keep compiling across that. The gate was right about the API, and reading it settled the design too. A census is a MEASUREMENT ABOUT a run, not part of the run's value. The tell was already in the diff: keeping it on `Scan` forced a hand-written `PartialEq` that skipped `elapsed`, so scan equality would not become timing-dependent — and a value type that has to lie about one of its fields to stay comparable is carrying something that is not its own. `RuleCost` derives `PartialEq` now, because nothing compares a census for identity. So it moves to `RULE_COSTS`, beside the two counters it is assembled from and on the idiom the module already cites for them. The one thing a per-rule LIST owes over those counters: they are monotonic and read as a delta, and a list read that way would hand a caller the previous run's rows as well — so `run` CLEARS the store before it fills it, and a reader gets the run that just finished. `the_census_describes_the_last_run_rather_than_accumulating` is that property, replacing the `PartialEq` case the move made moot. Declaring the break instead was the alternative and it would have been the wrong trade: a version bump spent so a diagnostic could live in a value type it does not belong in. The public surface is unchanged; `rules::rule_costs()` is new, and adding a function is not a break. Refs: CLOUD-1217 --- crates/batten/src/lib.rs | 23 ++++--- crates/batten/src/rules.rs | 85 +++++++++++++------------ crates/batten/tests/rule_cost_census.rs | 70 +++++++++++++------- 3 files changed, 106 insertions(+), 72 deletions(-) diff --git a/crates/batten/src/lib.rs b/crates/batten/src/lib.rs index 26d22b733..fd44ea204 100644 --- a/crates/batten/src/lib.rs +++ b/crates/batten/src/lib.rs @@ -8130,17 +8130,24 @@ fn announce_config(mode: Mode, err: &mut dyn Write, config: &resolve::Resolved) /// §6. It is a measurement about the run, not a finding about the tree, and the /// two channels stay separate. /// +/// Read from `rules::rule_costs()` rather than off the `Scan`: a census is a +/// measurement ABOUT a run, not part of its value, and `batten semver check` +/// refused the field on that public struct — correctly, and the refusal named the +/// design as well as the API. Read immediately after the runner returns, because +/// the store holds the run that just finished. +/// /// Sorted by cost descending, ties broken by rule id, because the question this /// answers is "what is the pole" and a reader should not have to sort 84 lines. /// The tiebreak is what keeps two runs over one tree reading the same. /// /// Pointer-only (non-negotiable rule 4): an id, two counts and a duration. Never /// a path, never a scanned byte. -fn report_rule_costs(mode: Mode, err: &mut dyn Write, scan: &rules::Scan) -> Result<()> { - if scan.costs.is_empty() { +fn report_rule_costs(mode: Mode, err: &mut dyn Write) -> Result<()> { + let costs = rules::rule_costs(); + if costs.is_empty() { return Ok(()); } - let mut ranked: Vec<&rules::RuleCost> = scan.costs.iter().collect(); + let mut ranked: Vec<&rules::RuleCost> = costs.iter().collect(); ranked.sort_by(|a, b| { b.elapsed .cmp(&a.elapsed) @@ -8160,16 +8167,16 @@ fn report_rule_costs(mode: Mode, err: &mut dyn Write, scan: &rules::Scan) -> Res ), )?; } - let elapsed: std::time::Duration = scan.costs.iter().map(|cost| cost.elapsed).sum(); - let files: usize = scan.costs.iter().map(|cost| cost.files_read).sum(); - let bytes: usize = scan.costs.iter().map(|cost| cost.bytes_read).sum(); + let elapsed: std::time::Duration = costs.iter().map(|cost| cost.elapsed).sum(); + let files: usize = costs.iter().map(|cost| cost.files_read).sum(); + let bytes: usize = costs.iter().map(|cost| cost.bytes_read).sum(); output::message( mode, Verbosity::Debug, err, &format!( "rule cost: {} rule(s) {}ms {files} file(s) {bytes} byte(s)", - scan.costs.len(), + costs.len(), elapsed.as_millis(), ), )?; @@ -8225,7 +8232,7 @@ fn run_rules( scope: &scope, }; let scan = runner(&selected, &config.provisions, vocabulary, &root, opts)?; - report_rule_costs(mode, err, &scan)?; + report_rule_costs(mode, err)?; perform_requested_sinks(surface, &root, &scan); let mut findings = scan.findings.clone(); diff --git a/crates/batten/src/rules.rs b/crates/batten/src/rules.rs index accb25141..a07d93482 100644 --- a/crates/batten/src/rules.rs +++ b/crates/batten/src/rules.rs @@ -42,6 +42,7 @@ use std::collections::{BTreeMap, BTreeSet}; use std::fs; use std::path::Path; +use std::sync::Mutex; use std::sync::atomic::{AtomicUsize, Ordering}; use clap::ValueEnum; @@ -4775,25 +4776,6 @@ pub struct Scan { /// native refusal and every consumer `[[rule]]` row; those are simply not /// admissible, because there is no token an admission could bind. pub classes: BTreeMap, - /// What each rule cost (CLOUD-1217), in declaration order. - /// - /// **Every rule, including one whose glob selected nothing.** "This rule - /// cost nothing" and "this rule is missing from the report" are different - /// answers, and collapsing them is how a rule that stopped running would - /// read as cheap. - /// - /// **This exists because a 463s run emitted two lines.** No rule kind - /// reported its own duration and every `command` child's streams are - /// `Stdio::null()`, so the largest item in this repository's CI was - /// unattributable from its own output — and two sessions in a row guessed at - /// it, wrongly, before a scratch worktree and a hand-rolled bisect produced - /// the answer. This field is what makes that bisect a command. - /// - /// Rendered on the `-vv` rung and **nowhere else**: a duration is not - /// byte-stable, so it must never reach `-J` or a pointer line, which is - /// house-style §6's contract and the reason this is not folded into the - /// findings document. - pub costs: Vec, /// The rules a declared input-precondition held back, and which requirement /// went unmet (CLOUD-125). A subset of [`Scan::not_evaluated`]'s keys. /// @@ -4953,7 +4935,7 @@ fn isolate(body: impl FnOnce() -> anyhow::Result>) -> Isolat /// /// A rule id, two counts and a duration. No path list and no scanned bytes — the /// census answers *how much*, and the findings answer *where*. -#[derive(Debug, Clone)] +#[derive(Debug, Clone, PartialEq, Eq)] pub struct RuleCost { /// The rule's id. pub rule: String, @@ -4965,25 +4947,6 @@ pub struct RuleCost { pub bytes_read: usize, } -/// Equality over the DETERMINISTIC half, deliberately skipping [`RuleCost::elapsed`]. -/// -/// [`Scan`] derives `PartialEq`, and two runs over one unchanged tree are the -/// same scan — that is the property byte-stability rests on. A derived -/// comparison here would make it timing-dependent and quietly false, so the -/// clock is excluded and the counts, which ARE deterministic, are what compare. -/// That asymmetry is the whole reason the duration is a measurement and the -/// counts are the assertion, which `.claude/rules/rust.md` states as a standing -/// rule for this crate. -impl PartialEq for RuleCost { - fn eq(&self, other: &Self) -> bool { - self.rule == other.rule - && self.files_read == other.files_read - && self.bytes_read == other.bytes_read - } -} - -impl Eq for RuleCost {} - /// The name of the verb that runs process-spawning rule kinds, quoted in the /// refusal [`run_static`] emits. Named once so the message and the surface /// cannot drift. @@ -5496,6 +5459,9 @@ fn run( }; let mut scan = Scan::default(); + // CLEARED, not appended to: the census describes THIS run, and a caller + // reading rows from the previous one would be reading a different tree. + costs_lock().clear(); evaluate_rules(rules, root, &inputs, &mut scan)?; // BEFORE the sort, deliberately (CLOUD-396): the sort is what makes the // output byte-stable, so a dedup running after it would be reading an order @@ -5580,7 +5546,7 @@ fn evaluate_rules( } = &mut *scan; isolate(|| run_rule(rule, root, inputs, findings, attributed, classes)) }; - scan.costs.push(RuleCost { + costs_lock().push(RuleCost { rule: rule.id.clone(), elapsed: started.elapsed(), files_read: files_read().saturating_sub(files_before), @@ -6115,6 +6081,45 @@ pub fn bytes_read() -> usize { BYTES_READ.load(Ordering::Relaxed) } +/// What each rule of the LAST run cost (CLOUD-1217), in declaration order. +/// +/// **Out of [`Scan`] deliberately, and the gate is what settled it.** It was a +/// `pub` field on that struct for one commit; `batten semver check` refused the +/// branch with `constructible_struct_adds_field`, because a consumer +/// constructing `Scan { .. }` cannot keep compiling across the addition. The +/// refusal was right on the API, and reading it also settled the design +/// question: a census is a MEASUREMENT ABOUT a run, not part of the run's value, +/// and the tell was that keeping it on `Scan` forced a hand-written `PartialEq` +/// that skipped the clock so scan equality would not become timing-dependent. A +/// value type that has to lie about one of its fields to stay comparable is +/// carrying something that is not its own. +/// +/// **Cleared at the top of every [`run`], not appended to forever**, which is the +/// one thing this owes over the two counters above: they are monotonic and read +/// as a delta, and a per-rule LIST read that way would hand a caller the previous +/// run's rows as well. Reading it therefore means "the run that just finished", +/// and a caller reads it immediately after the runner returns. +/// +/// Process-global for the counters' reason, with the counters' consequence: the +/// test that reads it lives in its own binary. +static RULE_COSTS: Mutex> = Mutex::new(Vec::new()); + +/// Take the lock, treating a poisoned one as the data it still holds. +/// +/// A panic in another thread says nothing about whether this census is readable, +/// and the workspace lints refuse an `unwrap` on a reachable path besides. +fn costs_lock() -> std::sync::MutexGuard<'static, Vec> { + RULE_COSTS + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) +} + +/// What each rule of the last [`run`] cost, in declaration order. +#[must_use] +pub fn rule_costs() -> Vec { + costs_lock().clone() +} + /// **The one function that acquires a document** (CLOUD-849). /// /// Every `Fact::Document` in this crate is read and parsed here and nowhere diff --git a/crates/batten/tests/rule_cost_census.rs b/crates/batten/tests/rule_cost_census.rs index 846e81b06..7ac351927 100644 --- a/crates/batten/tests/rule_cost_census.rs +++ b/crates/batten/tests/rule_cost_census.rs @@ -19,8 +19,7 @@ //! **Counts are the assertion, never the clock.** `RuleCost::elapsed` is a //! measurement and varies run to run; the counts are deterministic. Asserting a //! duration here would discriminate nothing, which is the standing rule in -//! `.claude/rules/rust.md` and the reason `RuleCost`'s `PartialEq` skips -//! `elapsed`. +//! `.claude/rules/rust.md`. //! //! Asserted through `run_static` — the surface a consumer reaches — rather than //! by widening anything to `pub` for a test's convenience. @@ -89,7 +88,7 @@ fn every_rule_gets_one_census_row_in_declaration_order() { let root = scratch("order"); seed(&root, 2); - let scan = rules::run_static( + rules::run_static( &[ row("reads-the-txt", "*.txt"), row("matches-nothing", "*.no-such-extension"), @@ -101,14 +100,14 @@ fn every_rule_gets_one_census_row_in_declaration_order() { ) .expect("the read surface runs the rows"); - let ids: Vec<&str> = scan.costs.iter().map(|cost| cost.rule.as_str()).collect(); + let costs = rules::rule_costs(); + let ids: Vec<&str> = costs.iter().map(|cost| cost.rule.as_str()).collect(); assert_eq!( ids, ["reads-the-txt", "matches-nothing", "reads-the-txt-again"], "one census row per rule, in declaration order — a skipped rule included" ); - let skipped = scan - .costs + let skipped = costs .iter() .find(|cost| cost.rule == "matches-nothing") .expect("the skipped rule has a row"); @@ -132,10 +131,11 @@ fn a_rule_reports_one_read_per_file_its_glob_selected() { let root = scratch("counts"); let bytes = seed(&root, 3); - let scan = rules::run_static(&[row("reads-three", "*.txt")], &[], vocabulary(), &root) + rules::run_static(&[row("reads-three", "*.txt")], &[], vocabulary(), &root) .expect("the read surface runs the row"); - let cost = scan.costs.first().expect("the row has a census entry"); + let costs = rules::rule_costs(); + let cost = costs.first().expect("the row has a census entry"); assert_eq!( cost.files_read, 3, "three matched files is three reads — the census counts what was opened" @@ -149,9 +149,10 @@ fn a_rule_reports_one_read_per_file_its_glob_selected() { // satisfy the assertions above however the engine behaved. let extra = "yyyy"; fs::write(root.join("f3.txt"), extra).expect("fixture"); - let widened = rules::run_static(&[row("reads-four", "*.txt")], &[], vocabulary(), &root) + rules::run_static(&[row("reads-four", "*.txt")], &[], vocabulary(), &root) .expect("the read surface runs the row"); - let widened = widened.costs.first().expect("the row has a census entry"); + let widened = rules::rule_costs(); + let widened = widened.first().expect("the row has a census entry"); assert_eq!( (widened.files_read, widened.bytes_read), (4, bytes + extra.len()), @@ -162,25 +163,46 @@ fn a_rule_reports_one_read_per_file_its_glob_selected() { } #[test] -fn the_census_measures_the_run_rather_than_identifying_it() { - // `Scan` derives `PartialEq` and two runs over one unchanged tree are the - // same scan — that is what byte-stability rests on. `RuleCost` therefore - // compares on its DETERMINISTIC half and skips the clock, because a derived - // comparison would make scan equality timing-dependent and quietly false. +fn the_census_describes_the_last_run_rather_than_accumulating() { + // THE ONE THING A PER-RULE LIST OWES OVER THE TWO COUNTERS IT IS BUILT FROM. + // `files_read`/`bytes_read` are monotonic and read as a delta; a list read + // that way would hand a caller the previous run's rows as well, so `run` + // clears the store before it fills it. A caller therefore reads "the run that + // just finished" rather than "every run this process has done". // - // Fails by: deriving `PartialEq` on `RuleCost`, which makes these two unequal - // whenever the two runs differ by a nanosecond — which is almost always. - let root = scratch("equality"); + // Fails by: dropping the `costs_lock().clear()` in `run`, which makes the + // second census six rows rather than one. + let root = scratch("perrun"); seed(&root, 2); - let first = rules::run_static(&[row("reads-two", "*.txt")], &[], vocabulary(), &root) - .expect("the read surface runs the row"); - let second = rules::run_static(&[row("reads-two", "*.txt")], &[], vocabulary(), &root) - .expect("the read surface runs the row"); + rules::run_static( + &[ + row("first", "*.txt"), + row("second", "*.txt"), + row("third", "*.txt"), + ], + &[], + vocabulary(), + &root, + ) + .expect("the read surface runs the rows"); + assert_eq!( + rules::rule_costs().len(), + 3, + "three rows, three census entries" + ); + rules::run_static(&[row("alone", "*.txt")], &[], vocabulary(), &root) + .expect("the read surface runs the row"); + let after = rules::rule_costs(); + assert_eq!( + after.len(), + 1, + "the second run's census is its own, not appended to the first's" + ); assert_eq!( - first.costs, second.costs, - "two runs over one unchanged tree carry the same census, whatever the clock said" + after[0].rule, "alone", + "and it names the rule that actually ran" ); let _ = fs::remove_dir_all(&root); From ecfab0ea6ab4bf90377c7685f04aba6e52873058 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:05:41 +0000 Subject: [PATCH 05/13] perf(ci): build the binary in `test:bats` and feed the seam seven programs already declare MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `[tasks."test:bats"]` declared `depends = ["doctor --no-targets"]` — the submodule checkout — and nothing else, so it NEVER built the binary. Every gate it drives that needs `batten` paid `cargo run` process startup per case, and worse, whichever artifact happened to be lying in `target/` decided what the suite tested. `tests/helpers.bash:105` asserted the opposite in a comment for its whole life: "`test:bats` builds the DEBUG binary", true only transitively via whatever ran before. That is CLOUD-592's and CLOUD-699's stale-binary class from both ends, and closing it is this change's case. The comment is corrected in the same commit rather than left to read as though it were describing the new behaviour all along. `hooks-wiring-check.sh:212-214` insists its gate judge "the WORKING TREE's engine and config together, which is the pair that ships". A freshly built binary is therefore the CORRECTNESS precondition for the injection, not an optimisation detail — which is why the build is guarded and the export is guarded separately. ## Why it lives here and only here `$BATTEN_BIN` is honoured by seven `mise-tasks/` programs and by the Rust tier at `common/mod.rs:154`; `hooks-wiring-check.sh:219` declares the same seam under its own name and only 2 of its 36 cases ever set it. Exporting both from the ungoverned task reaches every already-honouring program with ZERO governed-file edits — `V-SHELL-RULE-EDITED` refuses touching any of them, one route, no override, which is the whole reason the change has this shape. Inline rather than a `depends`, for two reasons already recorded in this body: a `depends` re-runs in whatever process invokes the task, and when that is hk's step it is a CHILD mise process — CLOUD-220's race — and a build in the DAG would contend with the cargo chain for the target-dir lock `hk.pkl` serialises. `build:release` is the wrong task besides: it produces the RELEASE binary for the mediated-call hot path, while `helpers.bash:119-134` and `common/mod.rs:154` both resolve a debug one. Guarded explicitly, because this body runs under `/bin/sh` with no `set -e`. An unguarded build would leave the suite running against a stale artifact and reporting green — the exact failure the change exists to remove. The perf bonus is the row's ~23s reachable figure, NOT the 135.1s it was filed on; that correction is already on the issue and is not re-argued here. The measurement the row's acceptance demands is reported separately. Refs: CLOUD-1198, CLOUD-592, CLOUD-699, CLOUD-1160 --- mise.toml | 45 +++++++++++++++++++++++++++++++++++++++++++++ tests/helpers.bash | 13 ++++++++++--- 2 files changed, 55 insertions(+), 3 deletions(-) diff --git a/mise.toml b/mise.toml index 35c0fb054..bdc25a7a7 100644 --- a/mise.toml +++ b/mise.toml @@ -1709,6 +1709,51 @@ depends = ["doctor --no-targets"] # changed no bytes still skips, and any content change anywhere re-runs. run = ''' if ./mise-tasks/step-receipt.sh check test:bats; then exit 0; fi +# BUILD ONCE, THEN FEED THE SEAM THE PROGRAMS ALREADY DECLARE (CLOUD-1198). +# +# This task's only build dependency was `doctor --no-targets` — the submodule +# checkout — so it NEVER built the binary. Every gate it drives that needs +# `batten` paid `cargo run` process startup per case, and worse, whichever +# artifact happened to be lying in `target/` decided what the suite tested. +# `tests/helpers.bash` asserted the opposite in a comment for its whole life: +# "test:bats builds the DEBUG binary", true only transitively via whatever ran +# before. That is CLOUD-592's and CLOUD-699's stale-binary class, and closing it +# is this change's case — the ~23s of avoided startup is the bonus, not the +# argument. `hooks-wiring-check.sh:212-214` insists the gate judge "the WORKING +# TREE's engine and config together, which is the pair that ships", so a freshly +# built binary is the CORRECTNESS precondition for the injection below rather +# than an optimisation detail. +# +# INLINE RATHER THAN A `depends`, for two measured reasons. A `depends` here +# re-runs in whatever process invokes this task, and when that is hk's step it is +# a CHILD mise process — the race CLOUD-220 records for `doctor` one clause up. +# And a build in the DAG would contend with the cargo chain for the target-dir +# lock `hk.pkl` deliberately serialises. `build:release` is the wrong task +# besides: it produces the RELEASE binary for the mediated-call hot path, while +# `helpers.bash:119-134` and `common/mod.rs:154` both resolve a debug one. +# +# Guarded explicitly: this body runs under `/bin/sh` with no `set -e`, so an +# unguarded build would leave the suite running against a stale artifact and +# reporting green — the exact failure this clause exists to remove. +if ! cargo build --quiet -p batten; then + echo "::error:: test:bats: the debug binary did not build, so the suite would run against a stale artifact or none. That is CLOUD-592/699's class and the reason this step builds at all." >&2 + exit 1 +fi +# BOTH SPELLINGS OF THE ONE SEAM. `$BATTEN_BIN` is honoured by seven +# `mise-tasks/` programs and by the Rust tier; `hooks-wiring-check.sh:219` +# declares the same seam under its own name for its `doctor hooks -J` call and +# only 2 of its 36 cases ever set it. Exported here so every already-honouring +# program is reached with ZERO governed-file edits — `V-SHELL-RULE-EDITED` +# refuses touching any of them, which is the whole reason this change lives in +# the ungoverned task and nowhere else. +BATTEN_BIN="$PWD/target/debug/batten" +if [ ! -x "$BATTEN_BIN" ]; then + echo "::error:: test:bats: $BATTEN_BIN is missing or not executable after a successful build — the seam would silently fall back to the stale-artifact resolution this change exists to close." >&2 + exit 1 +fi +export BATTEN_BIN +HOOKS_WIRING_DIAGNOSIS="$BATTEN_BIN doctor hooks -J" +export HOOKS_WIRING_DIAGNOSIS # WHICH SUITES, before how many cases (CLOUD-886). The glob that selects this # step is `mise-tasks/**`, so any byte under there ran all 151 suites — measured, # correcting one sentence in `land`'s lap-cap message bought a full matrix. diff --git a/tests/helpers.bash b/tests/helpers.bash index 7d2ff73cc..65d2622ae 100644 --- a/tests/helpers.bash +++ b/tests/helpers.bash @@ -101,9 +101,16 @@ run_timeout() { # # Five suites carried the same chain — `$BATTEN_BIN`, then release, then debug, # first hit wins — and release-first is a measured false green. `test:bats` -# builds the DEBUG binary; a release binary left over from an earlier session -# shadows it, so a suite reports on a build that predates the change it exists to -# catch. Measured on this very change: `tests/review-answered.bats` passed all +# builds the DEBUG binary and exports `$BATTEN_BIN` at it (CLOUD-1198); a release +# binary left over from an earlier session shadows it, so a suite reports on a +# build that predates the change it exists to catch. +# +# THAT FIRST CLAUSE WAS FALSE WHEN IT WAS WRITTEN AND IS TRUE NOW, which is worth +# stating in that order. `test:bats` declared only `doctor --no-targets` and never +# built anything, so "builds the DEBUG binary" held only transitively, via whatever +# happened to run before — the stale-artifact class CLOUD-592 and CLOUD-699 each +# record from their own end. CLOUD-1198 made the sentence true by building in the +# task, so the fallback chain below is now a fallback rather than the live path. Measured on this very change: `tests/review-answered.bats` passed all # twelve cases against a release binary nine hours older than the code under # test, and `tests/fact-record-keying.bats` only failed loudly because it asserts # behaviour the stale build does not have. From 002821eeb2836c44bc8650f8aaf85a1e311cafec Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:07:06 +0000 Subject: [PATCH 06/13] test(bench): report the Rust suite in four terms, and refuse to name the fourth MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The shell suite has had an instrument since CLOUD-386 — `mise run suite-bench`, `bench/suites/RESULTS.md`, 144 suites, 1440.9s serial. The Rust suite has had none, so `mise run test:cargo` emits ONE duration for a step that is four costs and the per-step receipt makes even that unobservable on a hit. Every claim about what that suite costs, this bundle's siblings included, was a hand measurement somebody took once. total wall = build + execute + ## The fourth term is the whole reason this exists Measured warm, the suite is 231s wall against a 127.0s `Summary` and a 5.9s freshness check, leaving ~98s — 42% of the loop — that nothing in this repository could attribute. CLOUD-1208 has now been wrong about that residue twice: 1. Filed quoting 1376s wall and "~90% is compile and link", both from guessing when the run started and ended. Wrong by 4.5x, corrected by `stat`. 2. Then quoting the residue as nextest's per-binary list phase — reasoned from how nextest works, never measured. Wrong by 56x: a zero-match filter run pays the freshness check AND the full enumeration and totals 1.75s. Both were confident, both were plausible, and a harness printing `list phase: 97.7s` would have shipped the second as fact. So the report prints the residue as a subtraction and prints what it is NOT, every run, rather than leaving that in a comment. A report emitting only the `Summary` would declare a 127s suite that takes 231s. ## A sensor, never a gate A duration ceiling is met by deleting assertions, which is strictly worse than a slow suite because the result also has to be maintained — `[tasks.coverage]`'s recorded argument, and non-negotiable rule 2's "a log without a gate is sensor only". No threshold, absent from `verify` and from `final`'s `needs:`, absent from `$CI_REQUIRED_CHECKS`. ## Shape A `bench/rust/sweep.py` driven by a single-line task, copying `[tasks.acquisition-bench]` exactly, because that is the shape left available: `V-SHELL-RULE-ADDED` refuses adding a `mise-tasks/*.sh` program, and a helper under a task directory would publish a second entry point running the sweep with no `BENCH_METRIC` set. A single-line body also leaves `inline-task-bodies-not-growing` flat. `crates/batten/tests/suite_metric.rs` is `acquisition_metric.rs`'s assertion for the third series, and the third is what turns a pair into a rule: it pins that the stamp is set, that it is set on the task that actually runs the harness, and that the three series are pairwise distinct — asserted against the sibling's LIVE stamp rather than a second literal, since the claim is about the two tasks disagreeing. ## Found by running it The first real run failed with "nextest printed no Summary line" over a suite that had just reported `Summary [ 143.437s] 3194 tests run`: nextest colours that line, so every `\s*` in the pattern was looking at an SGR escape. Fixed with both halves — `--color never` so the common path is clean, and a strip for whatever still arrives — and the fix is proven against the captured bytes rather than by a re-run: raw fails, stripped yields `143.437 / 3194 / 122`. Losing the Summary silently would have reported the residue as the whole non-build cost, which is precisely the mislabelling this row is about. The scheduled workflow §3 asks for is NOT in this commit: `.github/workflows/**` is in `protected`, `V-PROTECTED-MUTATION` declares no override route, and the engine's hatch is not settable from inside a tool call. Raised rather than worked around. Refs: CLOUD-1208, CLOUD-365, CLOUD-111, CLOUD-386, CLOUD-935 --- .prettierignore | 5 + bench/rust/sweep.py | 256 ++++++++++++++++++++++++++++ crates/batten/tests/suite_metric.rs | 119 +++++++++++++ mise.toml | 34 ++++ 4 files changed, 414 insertions(+) create mode 100755 bench/rust/sweep.py create mode 100644 crates/batten/tests/suite_metric.rs diff --git a/.prettierignore b/.prettierignore index 05b6dea57..254c38c3a 100644 --- a/.prettierignore +++ b/.prettierignore @@ -14,3 +14,8 @@ bench/tokens/RESULTS.md # lands unformatted, gets rewritten by prettier, and has to be regenerated again # to stay byte-stable — churn in a file nobody hand-edits. bench/suites/RESULTS.md + +# `bench/rust/RESULTS.md` is the Rust suite's half of that pair, generated by +# `mise run suite-bench-rust` (CLOUD-1208). Same generator-owns-the-bytes reason +# as its shell sibling directly above. +bench/rust/RESULTS.md diff --git a/bench/rust/sweep.py b/bench/rust/sweep.py new file mode 100755 index 000000000..c5ea0e3ae --- /dev/null +++ b/bench/rust/sweep.py @@ -0,0 +1,256 @@ +#!/usr/bin/env python3 +"""Four-term cost of the Rust suite, with its own repeat-run null. + +CLOUD-1208. `mise run test:cargo` emits ONE duration for a step that is four +costs, and the per-step receipt makes even that unobservable on a hit. The shell +side has had `mise run suite-bench` and `bench/suites/RESULTS.md` since +CLOUD-386; the Rust side has had nothing, so every claim about what that suite +costs — including the ones in this row's siblings — is a hand measurement +somebody took once. + +## Why four terms, and why the fourth is the point + + total wall = build + execute + + +`perf`/`perf-pair` measure the BINARY's invocation latency, which is a different +question one layer down; conflating the two is the error `.claude/rules/rust.md` +records for `acquisition-wall-clock` vs `wall-clock`. A report emitting only +nextest's `Summary` would declare a 127s suite that takes 231s. + +**THE RESIDUE IS REPORTED AND NEVER LABELLED, and that is this harness's whole +reason to exist.** CLOUD-1208 has been wrong about it twice: + + 1. Filed quoting 1376s wall and "~90% is compile and link" — both from + guessing when the run started and ended. Wrong by 4.5x, corrected by `stat` + on a log file. + 2. Then quoting the 97.7s residue as nextest's per-binary list phase — + reasoned from how nextest works, never measured. Wrong by 56x: a zero-match + filter run pays the freshness check AND the full enumeration and then runs + nothing, and totals 1.75s. + +Two independent attributions, both confident, both wrong, both caught only by an +ad-hoc experiment nobody was obliged to run. A harness printing +`list phase: 97.7s` would have shipped the second as fact. So this prints the +residue as a residue, and prints what it is NOT. + +## Why a `bench/` helper driven by a one-line task + +`policy/shell-retirement.rego` refuses ADDING an authored shell rule at `deny` +(`V-SHELL-RULE-ADDED`) with no override, so a `mise-tasks/*.sh` program is +unavailable — the same constraint that forced `[tasks.semver]`, +`[tasks.prose-only-check]`, `[tasks.policy-test]` and `bench/acquisition/sweep.py` +into their shapes. Under `bench/` rather than `mise-tasks/` for a second reason +that one records: mise makes every executable in a task directory a file task +named by its basename AND its stem, so a helper there would publish a second +entry point that runs this with no `BENCH_METRIC` set — stamping the invocation +series' default into the suite series, which is the one thing the stamp exists to +prevent. + +## A SENSOR, NEVER A GATE + +A duration ceiling is met by deleting assertions, which is strictly worse than a +slow suite because the result also has to be maintained. That is +`[tasks.coverage]`'s recorded argument against a coverage threshold, and +non-negotiable rule 2's "a log without a gate is sensor only" anticipates exactly +this case. So this draws no conclusion, exits 0 on any measurement it completed, +and is deliberately absent from `verify` and from `final`'s `needs:`. + +## Output + +Pointer-only per non-negotiable rule 4: durations, counts and target names. No +test names, no command lines, no cargo chatter. +""" + +from __future__ import annotations + +import os +import re +import shutil +import subprocess +import sys +import time +from pathlib import Path + +# Two warm arms, so the null is a measured spread rather than a number in a +# comment. `perf-compare`'s 0.966–1.102 came from n=30 of a much cheaper arm; +# a suite arm is minutes, so the count is what is affordable and the spread is +# reported with its own `pairs=` so a reader knows how thin it is. +NULL_PAIRS = 2 + +RESULTS = Path("bench/rust/RESULTS.md") + +# nextest's own execute term, e.g. `Summary [ 127.000s] 3167 tests run: ...`. +SUMMARY = re.compile(r"Summary\s*\[\s*([0-9.]+)s\]\s*(\d+)\s+tests?\s+run") +# `Starting 3167 tests across 119 binaries`, which is the target count the +# residue has repeatedly been blamed on. +STARTING = re.compile(r"Starting\s+(\d+)\s+tests?\s+across\s+(\d+)\s+binar") + +# SGR escapes, stripped before either pattern is applied. +# +# Measured rather than anticipated: the first real run of this harness failed with +# "nextest printed no Summary line" over a suite that had just reported +# `Summary [ 143.437s] 3194 tests run`. nextest colours that line, so the bytes are +# `\x1b[32;1m Summary\x1b[0m \x1b[1m3194\x1b[0m …` and every `\s*` in the +# patterns above is looking at an escape sequence. +# +# BOTH HALVES, because either alone is a single point of failure for the one term +# this harness exists to report: `--color never` is passed below so the common path +# produces clean bytes, and this strips whatever still arrives — a `CLICOLOR_FORCE` +# in the environment, or a future nextest that colours a stream it does not today. +# Losing the Summary silently would mean reporting the residue as the whole +# non-build cost, which is the mislabelling this row is about. +ANSI = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") + + +def fail(message: str, code: int = 2) -> None: + print(f"::error:: suite-bench-rust: {message}", file=sys.stderr) + sys.exit(code) + + +def run(argv: list[str]) -> tuple[float, str, int]: + """Wall clock, combined and de-escaped output, and status of one command.""" + started = time.monotonic() + result = subprocess.run(argv, capture_output=True, text=True, check=False) + elapsed = time.monotonic() - started + return elapsed, ANSI.sub("", result.stdout + result.stderr), result.returncode + + +def arm(label: str) -> dict[str, float]: + """One reading of all four terms, taken back to back on one machine. + + The `--no-run` call goes FIRST and its wall clock is the build term. On a + warm tree that is the freshness check (CLOUD-1208 measured 5.9s); on a cold + or partial one it is build-and-link. Either way the term is what it is — + naming it "the build" and then quoting a cold number as a warm one is the + first of the two defects above, so the arm records which it was by reporting + the number rather than a word. + """ + build_wall, _build_out, build_rc = run( + ["cargo", "nextest", "run", "--workspace", "--no-run", "--color", "never"] + ) + if build_rc != 0: + # No `-i` equivalent and no tolerance: a suite that does not build is + # perfectly timeable, which is how a broken tree would otherwise be + # published as a fast number. + fail(f"arm {label}: the suite did not build, so nothing here is a measurement", 1) + + total_wall, out, _ = run( + ["cargo", "nextest", "run", "--workspace", "--no-fail-fast", "--color", "never"] + ) + # A red suite is still a valid COST measurement — this is a sensor, and + # refusing to report because a test failed would make the instrument + # unavailable exactly when somebody is bisecting a slow failing suite. The + # status is reported so the reading is not mistaken for a green one. + summary = SUMMARY.search(out) + if summary is None: + fail(f"arm {label}: nextest printed no Summary line, so the execute term is unknown", 1) + execute = float(summary.group(1)) + cases = int(summary.group(2)) + + starting = STARTING.search(out) + binaries = int(starting.group(2)) if starting else 0 + + return { + "build": build_wall, + "execute": execute, + "total": total_wall, + # NOT an explanation. Subtraction, and nothing else is claimed about it. + "residue": total_wall - build_wall - execute, + "cases": float(cases), + "binaries": float(binaries), + } + + +def record(label: str, terms: dict[str, float]) -> None: + print( + f"arm={label} build={terms['build']:.1f}s execute={terms['execute']:.1f}s " + f"total={terms['total']:.1f}s residue={terms['residue']:.1f}s " + f"cases={int(terms['cases'])} binaries={int(terms['binaries'])}" + ) + + +def write_results(arms: list[dict[str, float]], nulls: list[float]) -> None: + first = arms[0] + share = (first["residue"] / first["total"] * 100) if first["total"] > 0 else 0.0 + lines = [ + "# Four-term cost of the Rust suite", + "", + "Generated by `mise run suite-bench-rust`. Do not hand-edit.", + "", + "`total` is wall clock for the whole run. `build` is a `--no-run` call", + "taken first, so on a warm tree it is the freshness check rather than a", + "compile. `execute` is nextest's own `Summary`. **`residue` is the", + "subtraction and nothing more — this report does not name its cause.**", + "", + "Two attempts to name it were wrong by 4.5x and 56x (CLOUD-1208). It is", + "measured NOT to be nextest's per-binary list phase: a zero-match filter", + "run pays the freshness check and the full enumeration and totals 1.75s.", + "", + f"- arms: {len(arms)}", + f"- cases: {int(first['cases'])} across {int(first['binaries'])} binaries", + f"- residue share of the first arm: {share:.1f}%", + ] + if nulls: + lines.append( + f"- repeat-run null: {min(nulls):.3f}–{max(nulls):.3f} over {len(nulls)} pairs" + ) + lines += [ + "", + "| arm | build | execute | total | residue |", + "| ---: | ---: | ---: | ---: | ---: |", + ] + for index, terms in enumerate(arms): + lines.append( + f"| {index} | {terms['build']:.1f}s | {terms['execute']:.1f}s " + f"| {terms['total']:.1f}s | {terms['residue']:.1f}s |" + ) + RESULTS.parent.mkdir(parents=True, exist_ok=True) + RESULTS.write_text("\n".join(lines) + "\n", encoding="utf-8") + + +def main() -> int: + root = subprocess.run( + ["git", "rev-parse", "--show-toplevel"], capture_output=True, text=True, check=False + ) + if root.returncode != 0: + fail("not a git repository, so there is no suite to measure") + os.chdir(root.stdout.strip()) + + if shutil.which("cargo") is None: + fail("cargo is not on PATH — run this through `mise run suite-bench-rust`") + + arms = [] + for index in range(NULL_PAIRS): + terms = arm(str(index)) + record(str(index), terms) + arms.append(terms) + + # THE NULL IS A SPREAD, and it is over `total` because that is the term every + # sibling row quotes a delta against. Consecutive identical arms, so the + # ratio is 1.0 plus pure noise by construction — the same construction + # `perf-pair --null` uses, and the reason a sibling's number can be read at + # all. A delta inside this spread has measured "no effect", which is a result. + nulls = [ + arms[index + 1]["total"] / arms[index]["total"] + for index in range(len(arms) - 1) + if arms[index]["total"] > 0 + ] + for index, value in enumerate(nulls): + print(f"ratio=null{index} value={value:.3f}") + if nulls: + print(f"null-spread low={min(nulls):.3f} high={max(nulls):.3f} pairs={len(nulls)}") + + # WHAT THE RESIDUE IS NOT, printed every run rather than left in a comment. + # This is the line that stops the next reader doing what the last two did. + print( + "residue-is-unattributed note=not-the-list-phase " + "measured=1.75s-for-a-zero-match-filter-run" + ) + + write_results(arms, nulls) + print(f"wrote={RESULTS}") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/crates/batten/tests/suite_metric.rs b/crates/batten/tests/suite_metric.rs new file mode 100644 index 000000000..681b34567 --- /dev/null +++ b/crates/batten/tests/suite_metric.rs @@ -0,0 +1,119 @@ +//! The suite series cannot be diffed against the invocation series (CLOUD-1208). +//! +//! # The hazard +//! +//! `mise-tasks/perf-record.sh` appends measurements to `refs/notes/perf` and +//! stamps each entry with `metric=`, read from `BENCH_METRIC` and defaulting to +//! `wall-clock`. That default is the INVOCATION series — `noop`, `hook`, +//! `wired`, measured over two committed fixtures in milliseconds. +//! +//! CLOUD-1208 measures the Rust SUITE: minutes of build and execute over the +//! whole workspace. The two share a unit and share nothing else. If both stamped +//! `wall-clock`, a reader plotting the series would put a 231-second suite arm +//! next to a `--help` invocation and read the gap as a regression — a step +//! change that never happened, in a series nobody re-derives. +//! +//! This is `acquisition_metric.rs`'s assertion for the third series, and the +//! third is what turns a pair into a rule: `.claude/rules/rust.md` records the +//! same hazard for a future instruction-count series, which is why `metric=` +//! exists at all. +//! +//! # Why over `mise.toml` rather than over the helper +//! +//! The stamp is set by the task, not by the Python. A test reading the helper +//! would pass while the task that invokes it lost the variable — and the task is +//! the only caller, so the task is where the claim lives. + +// Panicking on setup failure is the idiomatic way for a test to fail loudly. +#![allow(clippy::unwrap_used, clippy::expect_used)] + +mod common; + +/// The default `perf-record` falls back to, and one of the two values this task +/// must not carry. Spelled here rather than read out of the shell, because the +/// point is that they are DIFFERENT — deriving one from the other would make the +/// assertion vacuous the day somebody changed the default. +const INVOCATION_METRIC: &str = "wall-clock"; + +/// The sibling sweep's stamp. A suite arm sharing THIS one would be the same +/// defect one axis over — `acquisition-bench` measures a generated fixture +/// family in milliseconds, and this measures the committed workspace in minutes. +const ACQUISITION_METRIC: &str = "acquisition-wall-clock"; + +fn task_body(task: &str) -> String { + let manifest = std::fs::read_to_string(common::at_root("mise.toml")) + .expect("the manifest is where every task in this repository is declared"); + // `toml::from_str`, which is the idiom every reader in `config.rs` and + // `facts.rs` uses. `str::parse` resolves to a different impl here and reports + // "unexpected content, expected nothing" over a manifest that is valid. + let parsed: toml::Value = toml::from_str(&manifest).expect("mise.toml parses as TOML"); + parsed + .get("tasks") + .and_then(|tasks| tasks.get(task)) + .and_then(|task| task.get("run")) + .and_then(toml::Value::as_str) + .unwrap_or_else(|| panic!("[tasks.{task}] declares a run body")) + .to_owned() +} + +fn stamp(task: &str) -> String { + task_body(task) + .split_whitespace() + .find_map(|word| word.strip_prefix("BENCH_METRIC=").map(str::to_owned)) + .unwrap_or_else(|| { + panic!( + "[tasks.{task}] sets BENCH_METRIC — without it perf-record stamps \ + the invocation series' default and the two become diffable" + ) + }) +} + +#[test] +fn the_suite_series_is_stamped_with_its_own_metric() { + let suite = stamp("suite-bench-rust"); + + assert!( + !suite.is_empty(), + "an empty stamp is the default by another route" + ); + assert_ne!( + suite, INVOCATION_METRIC, + "the suite series must not share the invocation series' stamp: a reader \ + plotting `{INVOCATION_METRIC}` would put a whole-workspace suite arm \ + beside a `--help` invocation and read the gap as a regression" + ); +} + +/// The three series are pairwise distinct, which is the property the pair of +/// assertions above only gets halfway to. Asserted against the sibling's LIVE +/// stamp rather than a second literal, because the claim is about the two tasks +/// disagreeing rather than about either one's spelling. +#[test] +fn the_suite_and_acquisition_series_do_not_share_a_stamp() { + let suite = stamp("suite-bench-rust"); + let acquisition = stamp("acquisition-bench"); + + assert_eq!( + acquisition, ACQUISITION_METRIC, + "the sibling's stamp moved, so this comparison is no longer the one \ + `acquisition_metric.rs` pins — reconcile the two before loosening either" + ); + assert_ne!( + suite, acquisition, + "a minutes-long workspace suite arm and a milliseconds-long generated \ + fixture arm would be diffable under a shared stamp" + ); +} + +/// ANTI-VACUITY. The cases above pass over any string that is not one of two +/// literals — including one set by a task that does not run the harness at all. +/// This pins that the body carrying the stamp is the one invoking the +/// measurement, which is `acquisition_metric.rs`'s own second case. +#[test] +fn the_stamp_is_set_on_the_task_that_runs_the_harness() { + let body = task_body("suite-bench-rust"); + assert!( + body.contains("bench/rust/sweep.py"), + "the body carrying the stamp is the one invoking the measurement: {body}" + ); +} diff --git a/mise.toml b/mise.toml index bdc25a7a7..47805cfae 100644 --- a/mise.toml +++ b/mise.toml @@ -1298,6 +1298,40 @@ description = "Measure tree-surface acquisition cost as declared-document count depends = ["build:release"] run = "BENCH_METRIC=acquisition-wall-clock ./bench/acquisition/sweep.py" +[tasks.suite-bench-rust] +description = "Report: the Rust suite's cost in four terms — build, execute, total, and the residue between them (CLOUD-1208)" +# CLOUD-1208. The shell suite has had an instrument since CLOUD-386 +# (`suite-bench`, `bench/suites/RESULTS.md`, 144 suites); the Rust suite has had +# none, so `test:cargo` emits ONE duration for four costs and the per-step +# receipt makes even that unobservable on a hit. +# +# A REPORT, NEVER A GATE, for `[tasks.coverage]`'s recorded reason one screen up: +# a duration ceiling is met by deleting assertions, which is strictly worse than +# a slow suite. Deliberately absent from `[tasks.verify]` and from `final`'s +# `needs:` in ci.yml, surfaced on a schedule instead — CLOUD-111's placement, and +# `report-only-check` is the sensor on it. +# +# THE FOURTH TERM IS WHY THIS EXISTS. Measured warm, the suite is 231s wall +# against a 127.0s `Summary` and a 5.9s freshness check, leaving ~98s — 42% of the +# loop — that nothing in this repository could attribute. Two attempts to name it +# were wrong by 4.5x and 56x, so the harness prints it as a residue and prints +# what it is NOT. A report emitting only the `Summary` would declare a 127s suite +# that takes 231s. +# +# ONE LINE, over `bench/rust/sweep.py`, for `acquisition-bench`'s two reasons +# above: `V-SHELL-RULE-ADDED` refuses adding a `mise-tasks/*.sh` program, and a +# helper under a task directory would publish a second entry point running the +# sweep with no `BENCH_METRIC` set. `inline-task-bodies-not-growing` counts +# `run = '''` bodies non-increasing, which a single-line body does not touch. +# +# BENCH_METRIC IS THE LOAD-BEARING WORD, for the reason `acquisition-bench` states: +# `perf-record.sh` stamps it into every series entry and defaults to `wall-clock`, +# the INVOCATION series. A suite arm and a `--help` invocation share a unit and +# nothing else, so a shared stamp would let a reader diff them and read a step +# change that never happened. `crates/batten/tests/suite_metric.rs` asserts this +# task sets it rather than trusting that it does. +run = "BENCH_METRIC=suite-wall-clock ./bench/rust/sweep.py" + [tasks."install:local"] description = "Put the built binary where the hook registrations resolve it — `install.sh`'s own destination" depends = ["build:release"] From 3b504c971dbd53021132424507db01977cf48b66 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:07:31 +0000 Subject: [PATCH 07/13] =?UTF-8?q?perf(build):=20drop=20dev=20debuginfo=20?= =?UTF-8?q?=E2=80=94=209.4x=20off=20the=20linked=20test=20artifacts,=20mea?= =?UTF-8?q?sured?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `[profile.dev]` is one dial for two populations: the library under iteration, and ~118 integration test targets nobody attaches a debugger to. Nothing counted the second population's bytes until CLOUD-766 hit a full disk. MEASURED on one container, same `mise run test:cargo` both ways, counting `target/debug/deps`' extension-less linked binaries — the population `crates/batten/src/prune.rs:262-269` already reads: debug = 1 122 artifacts 15.11 GB mean 123.8 MB target/debug 19.18 GB debug = 0 123 artifacts 1.60 GB mean 13.0 MB target/debug 4.14 GB **9.4x off the linked artifacts and 4.6x off the whole tree**, suite green both ways (3194 tests). CLOUD-1211 was refined against "an arm that halves 14.1 GB"; this is well past that, which is why the byte delta is a SEPARATE acceptance test from the time delta — an arm this large is worth adopting whatever its wall clock does, and the wall clock is reported against CLOUD-1208's null rather than quoted from a hand timing. ## Two corrections to the row, both recorded in the manifest `debug = 1` was ALREADY a reduction: cargo's dev default is `2`, so line-tables-only was the saving the profile's comment was written about and that comment was correct as written. The remaining headroom was 1 → 0, not 2 → 0. And §3 asked for `debug` "scoped to test targets", which cargo cannot express: profiles are per-PACKAGE, not per-target-kind. `[profile.dev.package."*"]` is the nearest expressible split — dependencies stripped, workspace code keeping its symbols — and is the arm to reach for if a backtrace ever needs them back. The linker claim this row was FILED on stays withdrawn and stays recorded so it is not re-proposed: rust-lld has been the default on this host triple since Rust 1.90, this repository pins 1.97.1, and `readelf -p .comment` reports `Linker: LLD 22.1.6`. ## The gate `crates/batten/tests/dev_profile.rs`. The regression it catches is silent by construction — restoring `debug = 1`, or dropping the key so it falls back to cargo's `2`, costs nothing a test run can observe. The only symptom is `target/debug` growing back by an order of magnitude until a session runs out of disk, arriving as an unrelated rustc IO error inside somebody else's test run, which is the misattribution CLOUD-766 records. So the absent-key case is asserted directly rather than left to the happy path: a defaulting lookup would read a missing `debug` as satisfied and pass over cargo's `2`, and that anti-vacuity case is the one that would actually catch the drift. `[profile.release]` and `[profile.dist]` are pinned untouched, since a test-loop change must not reach the shipped artifact's profile. Refs: CLOUD-1211, CLOUD-1208, CLOUD-766, CLOUD-1210 --- Cargo.toml | 36 ++++++++- crates/batten/tests/dev_profile.rs | 124 +++++++++++++++++++++++++++++ 2 files changed, 158 insertions(+), 2 deletions(-) create mode 100644 crates/batten/tests/dev_profile.rs diff --git a/Cargo.toml b/Cargo.toml index c57c2bd9f..9f5fc66b3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -548,9 +548,41 @@ yaml-rust2 = "0.11" lto = "thin" strip = true -# Faster incremental builds for the compile-heavy fmt -> lint -> test hook chain. +# Faster incremental builds for the compile-heavy fmt -> lint -> test hook chain, +# and 118 test binaries' worth of bytes off `target/debug` (CLOUD-1211). +# +# `debug = 1` was already a REDUCTION — cargo's dev default is `debug = 2`, so +# line-tables-only was the saving this comment was originally written about, and +# it was correct as written. What it never accounted for is the POPULATION: one +# dial for two groups, the library under iteration and ~118 integration test +# targets nobody attaches a debugger to. Nothing counted the second group's bytes +# until CLOUD-766 hit a full disk. +# +# MEASURED on this container, 2026-08-30, over the same `mise run test:cargo` +# both ways — the artifact census is `target/debug/deps`' extension-less linked +# binaries, which is the population `crates/batten/src/prune.rs:262-269` reads: +# +# debug = 1 122 artifacts 15.11 GB mean 123.8 MB target/debug 19.18 GB +# debug = 0 123 artifacts 1.60 GB mean 13.0 MB target/debug 4.14 GB +# +# A 9.4x reduction in linked artifacts and 4.6x on the whole tree, with the suite +# green both ways. That is far past the "halves 14.1 GB" this row was refined +# against, and it is why the byte delta is a SEPARATE acceptance test from the +# time delta: an arm this large is worth adopting whatever its wall clock does. +# +# THE CARGO CONSTRAINT, recorded because the row's §3 asked for something cargo +# cannot express: profiles are per-PACKAGE, not per-target-kind, so there is no +# way to say "debug off for test targets only". `[profile.dev.package."*"]` is +# the nearest expressible split (dependencies only, workspace code keeps its +# debuginfo) and is the arm to reach for if a backtrace ever needs the symbols +# back. Scoping "away from targets nothing debugs" is not available. +# +# The linker claim this row was FILED on is withdrawn and stays recorded so it is +# not re-proposed: rust-lld has been the default on this host triple since Rust +# 1.90, this repository pins 1.97.1, and `readelf -p .comment` over a built +# artifact reports `Linker: LLD 22.1.6`. The build already links with lld. [profile.dev] -debug = 1 +debug = 0 # The profile the distributed single binary is built with: maximal optimization # and the smallest artifact. Distinct from `release` (used for local/dev release diff --git a/crates/batten/tests/dev_profile.rs b/crates/batten/tests/dev_profile.rs new file mode 100644 index 000000000..cffe9cf34 --- /dev/null +++ b/crates/batten/tests/dev_profile.rs @@ -0,0 +1,124 @@ +//! `[profile.dev]` declares what CLOUD-1211's adopted arm set. +//! +//! # Why a case rather than a comment +//! +//! CLOUD-1211's §7 asks for "a case asserting that whatever the adopted arms set +//! is what the committed profile declares — the shape `msrv-pin-agreement` uses +//! to hold two authorities together — so a later edit that drops a setting is a +//! finding rather than a silent regression." +//! +//! The regression this catches is silent by construction. Restoring `debug = 1` +//! (or letting it fall back to cargo's dev default of `2`) costs nothing a test +//! run can observe: the suite still passes, every gate still exits 0, and the +//! only symptom is `target/debug` growing back by an order of magnitude until a +//! session runs out of disk — which arrives as an unrelated rustc IO error +//! inside somebody else's test run, the misattribution CLOUD-766 records. +//! +//! # The measurement this pins +//! +//! Same `mise run test:cargo` both ways on one container, 2026-08-30, counting +//! `target/debug/deps`' extension-less linked binaries — the population +//! `crates/batten/src/prune.rs:262-269` reads: +//! +//! | `debug` | artifacts | linked bytes | `target/debug` | +//! | ------- | --------- | ------------ | -------------- | +//! | `1` | 122 | 15.11 GB | 19.18 GB | +//! | `0` | 123 | 1.60 GB | 4.14 GB | +//! +//! 9.4x off the linked artifacts, suite green both ways. + +// Panicking on setup failure is the idiomatic way for a test to fail loudly. +#![allow(clippy::unwrap_used, clippy::expect_used)] + +mod common; + +/// What the adopted arm sets. Spelled as an integer because that is how cargo +/// reads it; `debug = true` is `2` and `debug = false` is `0`, so a later edit +/// spelling it as a bool is still judged on the value rather than the syntax. +const ADOPTED_DEBUG: i64 = 0; + +fn dev_profile() -> toml::Value { + let manifest = std::fs::read_to_string(common::at_root("Cargo.toml")) + .expect("the workspace manifest is where the profiles are declared"); + let parsed: toml::Value = toml::from_str(&manifest).expect("Cargo.toml parses as TOML"); + parsed + .get("profile") + .and_then(|profile| profile.get("dev")) + .cloned() + .expect("[profile.dev] is declared") +} + +/// `debug` normalised across the two spellings cargo accepts. +fn declared_debug(profile: &toml::Value) -> i64 { + let value = profile + .get("debug") + .expect("[profile.dev] declares `debug` — an absent key is cargo's default of 2, which is the regression this asserts against"); + match value { + toml::Value::Integer(level) => *level, + toml::Value::Boolean(true) => 2, + toml::Value::Boolean(false) => 0, + other => panic!("[profile.dev] debug is neither an integer nor a bool: {other:?}"), + } +} + +#[test] +fn the_dev_profile_declares_the_adopted_debug_level() { + let debug = declared_debug(&dev_profile()); + assert_eq!( + debug, ADOPTED_DEBUG, + "[profile.dev] debug is {debug}, not the adopted {ADOPTED_DEBUG}. Measured \ + 2026-08-30, `debug = 1` put 15.11 GB into 122 linked test artifacts \ + against 1.60 GB at `debug = 0` — a 9.4x difference whose only symptom is \ + a full disk arriving as somebody else's rustc IO error (CLOUD-766, \ + CLOUD-1211). If this is a deliberate revert, move this constant and say \ + why in the same commit." + ); +} + +/// ANTI-VACUITY, and it is the case that would actually have caught the drift. +/// The assertion above passes over a manifest that declares `[profile.dev]` and +/// nothing else only because `declared_debug` panics on the absent key — this +/// pins that reading, so loosening it to a defaulting lookup fails here rather +/// than passing silently over cargo's `2`. +#[test] +fn an_absent_debug_key_is_not_read_as_the_adopted_value() { + let manifest: toml::Value = + toml::from_str("[profile.dev]\nincremental = true\n").expect("fixture parses"); + let profile = manifest + .get("profile") + .and_then(|profile| profile.get("dev")) + .expect("the fixture declares [profile.dev]"); + + assert!( + profile.get("debug").is_none(), + "the fixture is the absent-key case this asserts over" + ); + let caught = std::panic::catch_unwind(|| declared_debug(profile)); + assert!( + caught.is_err(), + "an absent `debug` is cargo's default of 2, not the adopted 0 — reading it \ + as satisfied is exactly the silent regression this file exists to refuse" + ); +} + +/// `[profile.dist]` and `[profile.release]` are out of CLOUD-1211's scope: they +/// build the shipped artifact, and a test-loop change must not reach them. This +/// pins that boundary rather than trusting the commit that drew it. +#[test] +fn the_shipped_profiles_are_untouched_by_the_test_loop_arm() { + let manifest = std::fs::read_to_string(common::at_root("Cargo.toml")) + .expect("the workspace manifest is where the profiles are declared"); + let parsed: toml::Value = toml::from_str(&manifest).expect("Cargo.toml parses as TOML"); + let profiles = parsed.get("profile").expect("[profile] is declared"); + + for shipped in ["release", "dist"] { + let profile = profiles + .get(shipped) + .unwrap_or_else(|| panic!("[profile.{shipped}] is declared")); + assert!( + profile.get("debug").is_none(), + "[profile.{shipped}] gained a `debug` key — CLOUD-1211 is a test-loop \ + change and the shipped artifact's profile is explicitly out of its scope" + ); + } +} From 23e1cc927341669e2b7a300a69c91cadfae4504f Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:11:24 +0000 Subject: [PATCH 08/13] fix(bench): the suite harness measured the wrong total and had an unusable null MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three defects, every one found by RUNNING the harness rather than by reading it — `.claude/rules/policy-modules.md`'s second-tier argument arriving on a bench program. The first shipped in c3771a24; the other two are what its first real readings exposed. ## It would have retired this row's own subject With `cargo nextest` as the total, the residue came out at **-1.0s and -0.1s** across two arms — a tidy zero, over the exact suite whose residue CLOUD-1208 measured at 97.7s and built this instrument to explain. Both readings are correct and they answer different questions. The row's 231s was `mise run test:filter`, so the unattributed cost is in the TASK — mise startup, the task graph, `step-receipt` — and never was inside nextest at all. A harness measuring nextest would have reported a residue-free suite and closed the row's subject as solved. That is the THIRD wrong attribution in this row's history and the first one the instrument produced itself, which is the argument for the instrument rather than against it: the two before it took an ad-hoc experiment nobody was obliged to run, and this one took one run of a committed program. So the total is `mise run test:cargo`, and `Summary` is parsed from that same invocation — taking `execute` from a separate run is what made the subtraction go negative, since two runs are not one run. `BATTEN_STEP_RECEIPT_BYPASS=1` rides along, which is the row's own "the per-step receipt makes even that unobservable on a hit" acted on rather than restated: a hit skips the step, so an arm measuring one would publish a cache lookup as the suite's cost. ## The null was 0.750, which is not a null arm=0 execute=123.6s total=124.6s arm=1 execute= 92.5s total= 93.4s ratio=null0 value=0.750 An instrument that cannot distinguish an effect below 25% cannot read any delta a sibling row would quote against it. The arms were not identical: the first warms the OS page cache over 124 test binaries and the second reads them back. `perf-pair`'s consecutive-arm null works because its arms are milliseconds over two committed fixtures; at this scale the first run IS the confound. One discarded warmup arm, three measured. ## And it parsed nothing at all The very first run failed with "nextest printed no Summary line" over a suite that had just printed `Summary [ 143.437s] 3194 tests run`: nextest colours that line, so every `\s*` in the pattern was looking at an SGR escape. `--color never` for the common path and a strip for whatever still arrives — losing the Summary silently would report the residue as the whole non-build cost, which is the mislabelling this row exists to prevent. Proven against the captured bytes rather than by a re-run: raw fails, stripped yields `143.437 / 3194 / 122`. Refs: CLOUD-1208 --- bench/rust/sweep.py | 69 +++++++++++++++++++++++++++++++++++++-------- 1 file changed, 58 insertions(+), 11 deletions(-) diff --git a/bench/rust/sweep.py b/bench/rust/sweep.py index c5ea0e3ae..1fcf8fa07 100755 --- a/bench/rust/sweep.py +++ b/bench/rust/sweep.py @@ -71,11 +71,29 @@ import time from pathlib import Path -# Two warm arms, so the null is a measured spread rather than a number in a -# comment. `perf-compare`'s 0.966–1.102 came from n=30 of a much cheaper arm; -# a suite arm is minutes, so the count is what is affordable and the spread is -# reported with its own `pairs=` so a reader knows how thin it is. -NULL_PAIRS = 2 +# Measured arms, after the discarded one below. Each is minutes, so the count is +# what is affordable, and the spread is reported with its own `pairs=` so a reader +# knows how thin it is rather than reading two numbers as a distribution. +ARMS = 3 + +# ONE DISCARDED ARM FIRST, AND IT IS NOT POLITENESS — the harness was unusable +# without it. Measured 2026-08-30, two consecutive arms and no warmup: +# +# arm=0 execute=123.6s total=124.6s +# arm=1 execute= 92.5s total= 93.4s +# ratio=null0 value=0.750 +# +# A null of 0.750 means the instrument cannot distinguish any effect smaller than +# 25%, which is larger than every delta any sibling row is trying to measure. The +# arms were not identical: the first one warms the OS page cache over 124 test +# binaries and the second reads them back. `perf-pair`'s consecutive-arm null +# works because its arms are milliseconds over two committed fixtures; at this +# scale the first run IS the confound. +# +# So the first arm is run and thrown away, and every reported arm starts equally +# warm. A null that stays wide after this is a real property of the metric and is +# reported as one. +WARMUP_ARMS = 1 RESULTS = Path("bench/rust/RESULTS.md") @@ -107,10 +125,10 @@ def fail(message: str, code: int = 2) -> None: sys.exit(code) -def run(argv: list[str]) -> tuple[float, str, int]: +def run(argv: list[str], env: dict[str, str] | None = None) -> tuple[float, str, int]: """Wall clock, combined and de-escaped output, and status of one command.""" started = time.monotonic() - result = subprocess.run(argv, capture_output=True, text=True, check=False) + result = subprocess.run(argv, capture_output=True, text=True, check=False, env=env) elapsed = time.monotonic() - started return elapsed, ANSI.sub("", result.stdout + result.stderr), result.returncode @@ -124,6 +142,20 @@ def arm(label: str) -> dict[str, float]: naming it "the build" and then quoting a cold number as a warm one is the first of the two defects above, so the arm records which it was by reporting the number rather than a word. + + THE TOTAL IS THE TASK, NOT `cargo nextest`, and getting that wrong once is + why this docstring says so. Measured 2026-08-30 with `cargo nextest` as the + total, the residue came out at **-1.0s and -0.1s** across two arms — a tidy + zero, over the exact suite whose residue CLOUD-1208 measured at 97.7s. Both + readings were correct and they answer different questions: the row's 231s was + `mise run test:filter`, so the unattributed cost is in the TASK — mise + startup, the task graph, `step-receipt` — and never was inside nextest at all. + + A harness measuring `cargo nextest` would therefore have reported a + residue-free suite and retired the row's own subject as solved. That is the + third wrong attribution in this row's history and the first one this + instrument produced itself, which is the argument for the instrument rather + than against it. """ build_wall, _build_out, build_rc = run( ["cargo", "nextest", "run", "--workspace", "--no-run", "--color", "never"] @@ -134,9 +166,19 @@ def arm(label: str) -> dict[str, float]: # published as a fast number. fail(f"arm {label}: the suite did not build, so nothing here is a measurement", 1) - total_wall, out, _ = run( - ["cargo", "nextest", "run", "--workspace", "--no-fail-fast", "--color", "never"] - ) + # The task a developer actually runs, so the wrapper's cost is inside the + # total rather than outside the instrument. Its `Summary` is parsed from this + # same invocation — taking `execute` from a separate run is what made the + # subtraction go negative, since the two runs are not the same run. + # + # THE RECEIPT IS BYPASSED, and that is the row's own observation acted on: + # "the per-step receipt makes even that unobservable on a hit". A hit skips + # the step entirely, so an arm measuring one would report a few hundred + # milliseconds of cache lookup as the suite's cost. `BATTEN_STEP_RECEIPT_BYPASS` + # is `step-receipt.sh`'s own declared lever for exactly this — the same one CI + # rides — so the arms measure the work rather than the cache. + environment = dict(os.environ, BATTEN_STEP_RECEIPT_BYPASS="1") + total_wall, out, _ = run(["mise", "run", "test:cargo"], env=environment) # A red suite is still a valid COST measurement — this is a sensor, and # refusing to report because a test failed would make the instrument # unavailable exactly when somebody is bisecting a slow failing suite. The @@ -219,8 +261,13 @@ def main() -> int: if shutil.which("cargo") is None: fail("cargo is not on PATH — run this through `mise run suite-bench-rust`") + # Discarded, for the reason WARMUP_ARMS states: without it the null is 0.750 + # and the instrument cannot see any delta a sibling row would quote. + for index in range(WARMUP_ARMS): + arm(f"warmup{index}") + arms = [] - for index in range(NULL_PAIRS): + for index in range(ARMS): terms = arm(str(index)) record(str(index), terms) arms.append(terms) From 11afe14ec6b354607d759ccf3dcf9f83325777db Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:18:29 +0000 Subject: [PATCH 09/13] test(bench): record the first sound four-term reading, and a null worth quoting MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit arm=0 build=1.1s execute=101.3s total=102.5s residue=0.1s arm=1 build=1.1s execute= 97.6s total= 98.8s residue=0.1s arm=2 build=1.1s execute= 98.6s total= 99.9s residue=0.2s null-spread low=0.963 high=1.012 pairs=2 The null is **0.963–1.012** where the un-warmed harness gave 0.750, so the instrument can now read a delta a sibling row would quote instead of swamping it. It brackets `perf-compare`'s own 0.966–1.102 closely, which is the first evidence that suite wall clock behaves like the invocation series once the page cache is not the independent variable. ## CLOUD-1208's 97.7s residue does not reproduce, and that is a result `total` is `mise run test:cargo` — the task, the same thing the row measured at 231s — and the residue is **0.1-0.2s across three arms**. Nothing is unattributed. The row measured 231s wall against a 127.0s `Summary` at `debug = 1`. This tree is `debug = 0`, where the same suite is ~99s against ~99s of `Summary`. The hypothesis that fits both readings is that the residue was the OS faulting in 122 binaries of ~124 MB each, and that at ~13 MB each it collapses — which would mean CLOUD-1211 removed CLOUD-1208's subject rather than merely sitting beside it. **Stated as a hypothesis, not a finding.** It is the fourth attribution attempt in this row's history and the first three were all confident and wrong, so it is not quoted until the paired `debug = 1` arm is measured with this same harness against this same null. That arm is CLOUD-1211's time half and is owed anyway. Refs: CLOUD-1208, CLOUD-1211 --- bench/rust/RESULTS.md | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) create mode 100644 bench/rust/RESULTS.md diff --git a/bench/rust/RESULTS.md b/bench/rust/RESULTS.md new file mode 100644 index 000000000..a54412408 --- /dev/null +++ b/bench/rust/RESULTS.md @@ -0,0 +1,23 @@ +# Four-term cost of the Rust suite + +Generated by `mise run suite-bench-rust`. Do not hand-edit. + +`total` is wall clock for the whole run. `build` is a `--no-run` call +taken first, so on a warm tree it is the freshness check rather than a +compile. `execute` is nextest's own `Summary`. **`residue` is the +subtraction and nothing more — this report does not name its cause.** + +Two attempts to name it were wrong by 4.5x and 56x (CLOUD-1208). It is +measured NOT to be nextest's per-binary list phase: a zero-match filter +run pays the freshness check and the full enumeration and totals 1.75s. + +- arms: 3 +- cases: 3200 across 124 binaries +- residue share of the first arm: 0.1% +- repeat-run null: 0.963–1.012 over 2 pairs + +| arm | build | execute | total | residue | +| ---: | ---: | ---: | ---: | ---: | +| 0 | 1.1s | 101.3s | 102.5s | 0.1s | +| 1 | 1.1s | 97.6s | 98.8s | 0.1s | +| 2 | 1.1s | 98.6s | 99.9s | 0.2s | From d26ffa03f8850d987c1f63d11789b9998601f2cf Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 01:33:01 +0000 Subject: [PATCH 10/13] =?UTF-8?q?fix(build):=20keep=20line=20tables=20for?= =?UTF-8?q?=20workspace=20code=20=E2=80=94=20`debug=20=3D=200`=20sold=20th?= =?UTF-8?q?e=20wrong=20thing?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `03fb6621` set `[profile.dev] debug = 0` across the whole dev profile. That was the wrong call and this reverts it to the arm CLOUD-1211 §3 actually asked for. Three arms, each a cold `mise run test:cargo` over a cleared `target/debug`, counting `target/debug/deps`' extension-less linked binaries: arm artifacts bytes mean cold wall debug = 1 (the baseline) 125 15.53 GB 124.3 MB 231s debug = 0 (the whole profile) 123 1.60 GB 13.0 MB 264s debug = 1 + package."*" debug = 0 125 6.82 GB 54.5 MB 217s ## Why the biggest number is the rejected one `debug = 0` is 9.7x and it buys that by dropping debuginfo from the whole dev profile, batten's own code included — so a panicking test reports a backtrace with no line numbers. That is the diagnostic a reader needs at exactly the moment it is gone, and no byte count is worth it. §3 said as much: scope it away from the test targets, "leaving `[profile.dev]`'s stated incremental reasoning intact for the code it was actually written about". Cargo cannot express per-target-kind scoping, and the previous commit recorded that constraint, named `[profile.dev.package."*"]` as the nearest expressible split — and then took the blunt instrument anyway. Measured, the split is where the bytes were: 124.3 MB to 54.5 MB per binary, 2.3x off the tree, with every `batten` frame keeping its file and line. ## The wall-clock column is withdrawn, not quoted `03fb6621` floated the residue-is-debuginfo-load hypothesis. It is unsupported and the numbers lean against it: `debug = 0` was the SLOWEST cold arm of the three. All three are single unpaired cold runs at different contention, disagreeing in both directions and sitting far outside CLOUD-1208's measured 0.963-1.012 null — which is what unpaired readings look like, not a finding. The paired warm arm that would decide it CANNOT BE TAKEN in this container: at `debug = 1` the tree leaves 6.3 GB against `target-prune`'s 9970 MB floor, so the instrument cannot run in the condition it needs to measure. That is CLOUD-766's exhaustion arriving inside the experiment, and it is recorded rather than worked around. So the byte column is the measured result and the time column is recorded only so nobody re-runs it expecting an answer. ## The gate `dev_profile.rs` now pins BOTH halves, because either alone is silently insufficient: workspace `debug = 1` is the half that must not be traded for bytes, and the `package."*"` override is the half the bytes come from. Dropping the override is invisible until a session runs out of disk. The anti-vacuity case is kept and re-aimed — it pins that `declared_debug` PANICS on an absent key, since a defaulting lookup would read a dropped setting as satisfied. Refs: CLOUD-1211, CLOUD-766, CLOUD-1208 --- Cargo.toml | 57 +++++++++---- crates/batten/tests/dev_profile.rs | 132 +++++++++++++++++++---------- 2 files changed, 127 insertions(+), 62 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 9f5fc66b3..7cfa2641b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -558,30 +558,55 @@ strip = true # targets nobody attaches a debugger to. Nothing counted the second group's bytes # until CLOUD-766 hit a full disk. # -# MEASURED on this container, 2026-08-30, over the same `mise run test:cargo` -# both ways — the artifact census is `target/debug/deps`' extension-less linked -# binaries, which is the population `crates/batten/src/prune.rs:262-269` reads: -# -# debug = 1 122 artifacts 15.11 GB mean 123.8 MB target/debug 19.18 GB -# debug = 0 123 artifacts 1.60 GB mean 13.0 MB target/debug 4.14 GB -# -# A 9.4x reduction in linked artifacts and 4.6x on the whole tree, with the suite -# green both ways. That is far past the "halves 14.1 GB" this row was refined -# against, and it is why the byte delta is a SEPARATE acceptance test from the -# time delta: an arm this large is worth adopting whatever its wall clock does. +# THREE ARMS MEASURED on this container, 2026-08-30, each a cold +# `mise run test:cargo` over a cleared `target/debug`. The census counts +# `target/debug/deps`' extension-less linked binaries — the population +# `crates/batten/src/prune.rs:262-269` reads: +# +# arm artifacts bytes mean cold wall +# debug = 1 (the baseline) 125 15.53 GB 124.3 MB 231s +# debug = 0 (the whole profile) 123 1.60 GB 13.0 MB 264s +# debug = 1 + package."*" debug = 0 125 6.82 GB 54.5 MB 217s +# +# THE MIDDLE ARM IS NOT ADOPTED, AND REJECTING IT IS THE POINT OF THIS COMMENT. +# It takes 9.7x off the bytes, which is the largest number here and the reason it +# was briefly committed. It buys that by dropping debuginfo from the WHOLE dev +# profile — batten's own code included — so a panicking test reports a backtrace +# with no line numbers. That is the diagnostic a reader wants most at exactly the +# moment they need it, and no byte count is worth it. +# +# The adopted arm keeps line tables for workspace code and strips the dependency +# closure, which is where the bytes actually were: 124.3 MB -> 54.5 MB per binary +# while every `batten` frame keeps its file and line. Nobody steps into gix or +# regorus while debugging this crate. +# +# THE WALL-CLOCK COLUMN IS NOT A FINDING and must not be quoted as one. Three +# single cold runs at different contention, unpaired and with no null — the 264s +# in particular was taken while other work shared the box. They disagree in both +# directions, which is what unpaired readings look like. The byte column is the +# measured result; the time column is recorded only so nobody re-runs it +# expecting an answer. The paired warm arm that WOULD decide it could not be +# taken: at `debug = 1` the tree leaves 6.3 GB against `target-prune`'s 9970 MB +# floor, so the instrument cannot run in the condition it needs to measure — +# CLOUD-766's exhaustion arriving inside the experiment. # # THE CARGO CONSTRAINT, recorded because the row's §3 asked for something cargo -# cannot express: profiles are per-PACKAGE, not per-target-kind, so there is no -# way to say "debug off for test targets only". `[profile.dev.package."*"]` is -# the nearest expressible split (dependencies only, workspace code keeps its -# debuginfo) and is the arm to reach for if a backtrace ever needs the symbols -# back. Scoping "away from targets nothing debugs" is not available. +# cannot express: profiles are per-PACKAGE, not per-target-kind, so "debug off +# for test targets only" is not sayable. The split below is the nearest thing +# that preserves this profile's stated reasoning for the code it was written +# about. # # The linker claim this row was FILED on is withdrawn and stays recorded so it is # not re-proposed: rust-lld has been the default on this host triple since Rust # 1.90, this repository pins 1.97.1, and `readelf -p .comment` over a built # artifact reports `Linker: LLD 22.1.6`. The build already links with lld. [profile.dev] +debug = 1 + +# The dependency closure carries no debuginfo. It is the bulk of every test +# binary and nothing in it is ever stepped into; workspace code above keeps its +# line tables, which is the half that has to survive. +[profile.dev.package."*"] debug = 0 # The profile the distributed single binary is built with: maximal optimization diff --git a/crates/batten/tests/dev_profile.rs b/crates/batten/tests/dev_profile.rs index cffe9cf34..5b9982ec7 100644 --- a/crates/batten/tests/dev_profile.rs +++ b/crates/batten/tests/dev_profile.rs @@ -7,84 +7,126 @@ //! to hold two authorities together — so a later edit that drops a setting is a //! finding rather than a silent regression." //! -//! The regression this catches is silent by construction. Restoring `debug = 1` -//! (or letting it fall back to cargo's dev default of `2`) costs nothing a test -//! run can observe: the suite still passes, every gate still exits 0, and the -//! only symptom is `target/debug` growing back by an order of magnitude until a -//! session runs out of disk — which arrives as an unrelated rustc IO error -//! inside somebody else's test run, the misattribution CLOUD-766 records. +//! The regression this catches is silent by construction. Dropping the +//! dependency override, or letting `debug` fall back to cargo's dev default of +//! `2`, costs nothing a test run can observe: the suite still passes, every gate +//! still exits 0, and the only symptom is `target/debug` growing back until a +//! session runs out of disk — which arrives as an unrelated rustc IO error inside +//! somebody else's test run, the misattribution CLOUD-766 records. //! -//! # The measurement this pins +//! # The three arms, and why the biggest number is the rejected one //! -//! Same `mise run test:cargo` both ways on one container, 2026-08-30, counting -//! `target/debug/deps`' extension-less linked binaries — the population -//! `crates/batten/src/prune.rs:262-269` reads: +//! Each a cold `mise run test:cargo` over a cleared `target/debug`, this +//! container, 2026-08-30, counting `target/debug/deps`' extension-less linked +//! binaries — the population `crates/batten/src/prune.rs:262-269` reads: //! -//! | `debug` | artifacts | linked bytes | `target/debug` | -//! | ------- | --------- | ------------ | -------------- | -//! | `1` | 122 | 15.11 GB | 19.18 GB | -//! | `0` | 123 | 1.60 GB | 4.14 GB | +//! | arm | artifacts | linked bytes | mean | +//! | -------------------------------- | --------- | ------------ | -------- | +//! | `debug = 1` (baseline) | 125 | 15.53 GB | 124.3 MB | +//! | `debug = 0` whole profile | 123 | 1.60 GB | 13.0 MB | +//! | `debug = 1` + deps `0` (adopted) | 125 | 6.82 GB | 54.5 MB | //! -//! 9.4x off the linked artifacts, suite green both ways. +//! **The middle arm is 9.7x and is refused anyway.** It drops debuginfo from the +//! entire dev profile, `batten`'s own code included, so a panicking test reports +//! a backtrace with no line numbers — the diagnostic a reader needs at exactly +//! the moment it is gone. It was briefly committed and reverted; this file is +//! what makes that reversal hold. +//! +//! The adopted arm takes 2.3x off the bytes by stripping the dependency closure, +//! which is where they were, while every `batten` frame keeps its file and line. // Panicking on setup failure is the idiomatic way for a test to fail loudly. #![allow(clippy::unwrap_used, clippy::expect_used)] mod common; -/// What the adopted arm sets. Spelled as an integer because that is how cargo -/// reads it; `debug = true` is `2` and `debug = false` is `0`, so a later edit -/// spelling it as a bool is still judged on the value rather than the syntax. -const ADOPTED_DEBUG: i64 = 0; +/// What the adopted arm sets for WORKSPACE code. Spelled as an integer because +/// that is how cargo reads it; `debug = true` is `2` and `debug = false` is `0`, +/// so a later edit spelling it as a bool is judged on the value, not the syntax. +const ADOPTED_DEBUG: i64 = 1; -fn dev_profile() -> toml::Value { - let manifest = std::fs::read_to_string(common::at_root("Cargo.toml")) +/// What the adopted arm sets for the DEPENDENCY closure, which is where the +/// bytes actually were — 124.3 MB to 54.5 MB per linked binary. +const ADOPTED_DEPENDENCY_DEBUG: i64 = 0; + +/// The glob cargo spells "every dependency, but not workspace members". +const DEPENDENCY_GLOB: &str = "*"; + +fn manifest() -> toml::Value { + let text = std::fs::read_to_string(common::at_root("Cargo.toml")) .expect("the workspace manifest is where the profiles are declared"); - let parsed: toml::Value = toml::from_str(&manifest).expect("Cargo.toml parses as TOML"); - parsed + toml::from_str(&text).expect("Cargo.toml parses as TOML") +} + +fn dev_profile() -> toml::Value { + manifest() .get("profile") .and_then(|profile| profile.get("dev")) .cloned() .expect("[profile.dev] is declared") } -/// `debug` normalised across the two spellings cargo accepts. +/// `debug` normalised across the two spellings cargo accepts. Panics on an +/// absent key rather than defaulting, which is the reading +/// `an_absent_debug_key_is_not_read_as_the_adopted_value` pins. fn declared_debug(profile: &toml::Value) -> i64 { - let value = profile - .get("debug") - .expect("[profile.dev] declares `debug` — an absent key is cargo's default of 2, which is the regression this asserts against"); + let value = profile.get("debug").expect( + "this profile declares `debug` — an absent key is cargo's own default, \ + which is the regression this asserts against", + ); match value { toml::Value::Integer(level) => *level, toml::Value::Boolean(true) => 2, toml::Value::Boolean(false) => 0, - other => panic!("[profile.dev] debug is neither an integer nor a bool: {other:?}"), + other => panic!("`debug` is neither an integer nor a bool: {other:?}"), } } #[test] -fn the_dev_profile_declares_the_adopted_debug_level() { +fn workspace_code_keeps_its_line_tables() { let debug = declared_debug(&dev_profile()); assert_eq!( debug, ADOPTED_DEBUG, - "[profile.dev] debug is {debug}, not the adopted {ADOPTED_DEBUG}. Measured \ - 2026-08-30, `debug = 1` put 15.11 GB into 122 linked test artifacts \ - against 1.60 GB at `debug = 0` — a 9.4x difference whose only symptom is \ - a full disk arriving as somebody else's rustc IO error (CLOUD-766, \ - CLOUD-1211). If this is a deliberate revert, move this constant and say \ - why in the same commit." + "[profile.dev] debug is {debug}, not the adopted {ADOPTED_DEBUG}. This is \ + the half that must NOT be traded for bytes: at `debug = 0` the whole dev \ + profile loses debuginfo and a panicking test reports a backtrace with no \ + line numbers. That arm was measured at 9.7x off the artifacts, committed, \ + and reverted for exactly this reason (CLOUD-1211). If this is a deliberate \ + change, move the constant and say why in the same commit." + ); +} + +#[test] +fn the_dependency_closure_carries_no_debuginfo() { + let debug = manifest() + .get("profile") + .and_then(|profile| profile.get("dev")) + .and_then(|dev| dev.get("package")) + .and_then(|package| package.get(DEPENDENCY_GLOB)) + .map(|glob| declared_debug(glob)) + .expect( + "[profile.dev.package.\"*\"] is declared — without it every dependency \ + carries debuginfo again and the linked binaries go back to ~124 MB", + ); + assert_eq!( + debug, ADOPTED_DEPENDENCY_DEBUG, + "[profile.dev.package.\"*\"] debug is {debug}, not the adopted \ + {ADOPTED_DEPENDENCY_DEBUG}. This override is where the byte saving comes \ + from — 15.53 GB to 6.82 GB across 125 linked artifacts — and dropping it \ + is silent until a session runs out of disk (CLOUD-766)." ); } /// ANTI-VACUITY, and it is the case that would actually have caught the drift. -/// The assertion above passes over a manifest that declares `[profile.dev]` and -/// nothing else only because `declared_debug` panics on the absent key — this -/// pins that reading, so loosening it to a defaulting lookup fails here rather -/// than passing silently over cargo's `2`. +/// Both assertions above pass over a profile that declares the key at the right +/// value; neither would notice a `declared_debug` loosened to a defaulting +/// lookup, which would read an ABSENT key as cargo's default and report it as +/// satisfied. This pins the panicking read. #[test] fn an_absent_debug_key_is_not_read_as_the_adopted_value() { - let manifest: toml::Value = + let fixture: toml::Value = toml::from_str("[profile.dev]\nincremental = true\n").expect("fixture parses"); - let profile = manifest + let profile = fixture .get("profile") .and_then(|profile| profile.get("dev")) .expect("the fixture declares [profile.dev]"); @@ -96,8 +138,8 @@ fn an_absent_debug_key_is_not_read_as_the_adopted_value() { let caught = std::panic::catch_unwind(|| declared_debug(profile)); assert!( caught.is_err(), - "an absent `debug` is cargo's default of 2, not the adopted 0 — reading it \ - as satisfied is exactly the silent regression this file exists to refuse" + "an absent `debug` is cargo's own default, not the adopted value — reading \ + it as satisfied is exactly the silent regression this file refuses" ); } @@ -106,9 +148,7 @@ fn an_absent_debug_key_is_not_read_as_the_adopted_value() { /// pins that boundary rather than trusting the commit that drew it. #[test] fn the_shipped_profiles_are_untouched_by_the_test_loop_arm() { - let manifest = std::fs::read_to_string(common::at_root("Cargo.toml")) - .expect("the workspace manifest is where the profiles are declared"); - let parsed: toml::Value = toml::from_str(&manifest).expect("Cargo.toml parses as TOML"); + let parsed = manifest(); let profiles = parsed.get("profile").expect("[profile] is declared"); for shipped in ["release", "dist"] { From 625f59a2788b0f0bcce2bbb56989c01e02974744 Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 02:05:34 +0000 Subject: [PATCH 11/13] =?UTF-8?q?perf(build):=20optimise=20the=20dependenc?= =?UTF-8?q?y=20closure=20=E2=80=94=20the=20Rust=20suite=20halves,=20100.2s?= =?UTF-8?q?=20to=2048.6s?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit mise run test:cargo, warm 100.189s -> 48.581s 3201 tests, all passing batten hook, real config 325ms -> 70ms (release is 48ms) **2.06x on the whole suite**, against CLOUD-1208's measured 0.963-1.012 null. One line: `[profile.dev.package."*"] opt-level = 2`. ## What the per-case census actually said, once it was taken cleanly CLOUD-1223 was filed against a ranking taken while the box was busy, and it was wrong about where the cost is. Re-measured idle, the four `cli.rs` cases it names are inflated 4.6-9.7x by contention alone, and the binaries that are NOT inflated — `board_receipts` 43.8s, `pipeline_shapes` 25.0s, `mediated_verbs` 20.1s, `connector_verbs` 3 cases at 2.3s each — are uniformly ~1-3s per case with no artifact in the number. What every one of them has in common is a fixture carrying a REAL config, and therefore a `batten hook` invocation that loads the committed ruleset and compiles ~20 Rego modules. Measured, that invocation is **325ms on the debug binary against 48ms on release** — so the suite was paying a 6.8x tax per policy evaluation, and `board_receipts` alone makes ~135 of them. The tax is not in this repository's code. It is dependency code — Rego compilation and evaluation — running unoptimised because `[profile.dev]` never said otherwise. Optimising the closure while workspace code stays unoptimised recovers most of it and costs the edit-test loop nothing, because the code under iteration is the half still built for fast rebuilds. ## Three mechanisms this replaces, each withdrawn on measurement Recorded so none is proposed again: **share one `enforce` run** across the four `cli.rs` cases — impossible, each writes different content into its own fixture, so they are different computations. **Stub the spawning rules' binaries** — impossible, `claim-not-raced` and both `sbom-ntia` rows glob `Cargo.lock` and `mise-tasks/claim-race-check.sh`, which no fixture contains, so they never spawn there at all. **Rewrite the 20s `process_group` case** — pointless, it is a wall-clock wait on a real drain deadline, so it occupies a worker without competing for CPU and fixing it buys nothing at four workers. All three were read off durations. This one was read off the binary. ## The cost, stated rather than buried A cold dependency build goes 217s -> 366s. Paid ONCE and then cached: dependencies recompile only when they change or this profile does, and CI already carries `Swatinem/rust-cache`. +149s once against -51.6s every run, and the warm loop pays none of it. Refs: CLOUD-1223, CLOUD-1211, CLOUD-1208, CLOUD-352 --- Cargo.toml | 30 +++++++++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 7cfa2641b..24fc9b3dd 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -603,11 +603,35 @@ strip = true [profile.dev] debug = 1 -# The dependency closure carries no debuginfo. It is the bulk of every test -# binary and nothing in it is ever stepped into; workspace code above keeps its -# line tables, which is the half that has to survive. +# The dependency closure carries no debuginfo and IS optimised. Workspace code +# above keeps its line tables and stays unoptimised, so rebuilds of the code under +# iteration are still fast and its backtraces still readable — the split is the +# whole point, and neither half is a compromise for the other. +# +# `opt-level` MEASURED 2026-08-31, and it is the largest single win in this +# campaign. `batten hook` against this repository's own config — the committed +# ruleset plus ~20 Rego modules — is dominated by dependency code compiling and +# evaluating Rego, and unoptimised that work is 6.8x what the shipped binary does: +# +# batten hook, real config debug 325ms release 48ms +# with deps at opt-level = 2 debug 70ms (4.6x, near release) +# +# mise run test:cargo, warm 100.189s -> 48.581s 3201 tests, all passing +# +# A 2.06x on the whole suite, against CLOUD-1208's measured 0.963-1.012 null. The +# tests drive the DEBUG binary (`CARGO_BIN_EXE_batten`), so every case that judges +# a real config paid that 6.8x tax — which is why the binaries the per-case census +# flags are exactly the policy-evaluating ones (`board_receipts`, `mediated_verbs`, +# `pipeline_shapes`, `connector_verbs`, and `cli`'s committed-config cases). +# +# THE COST, STATED: a cold dependency build goes 217s -> 366s. It is paid ONCE and +# then cached — dependencies recompile only when they change or this profile does, +# and CI already carries `Swatinem/rust-cache`. So it is +149s once against -51.6s +# on every suite run, and the warm edit-test loop a developer sits in pays none of +# it. [profile.dev.package."*"] debug = 0 +opt-level = 2 # The profile the distributed single binary is built with: maximal optimization # and the smallest artifact. Distinct from `release` (used for local/dev release From e9e11054ca208313c2d8cb31587cc4885b21ea4b Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 02:32:11 +0000 Subject: [PATCH 12/13] =?UTF-8?q?revert(bench):=20drop=20the=20four-term?= =?UTF-8?q?=20harness=20=E2=80=94=20its=20premise=20did=20not=20reproduce?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Removes `bench/rust/sweep.py`, `bench/rust/RESULTS.md`, `[tasks.suite-bench-rust]`, `crates/batten/tests/suite_metric.rs` and the `.prettierignore` entry, all added earlier on this branch. ## CLOUD-1208's subject does not exist The row was built on a 42% unattributed residue: 231s wall against a 127.0s `Summary` and a 5.9s freshness check, leaving 97.7s nothing could explain. Measured at task level with the step receipt bypassed, across three arms: arm=0 build=1.1s execute=101.3s total=102.5s residue=0.1s arm=1 build=1.1s execute= 97.6s total= 98.8s residue=0.1s arm=2 build=1.1s execute= 98.6s total= 99.9s residue=0.2s **The residue is 0.1-0.2s.** The 97.7s came from reading log-file mtimes at `debug = 1`, not from an instrument. So the row is answered by the measurement rather than by a harness, and that answer is on the row. ## The instrument found nothing, and that is the honest reason to remove it nextest already emits three of the four terms — `Summary` is the execute term and the total, `--no-run` is the build term, per-case durations come out of the same output. What the harness added was a subtraction that comes out zero and a null that is two runs and a division. Every result this branch actually rests on came from somewhere else: the per-case distribution from parsing nextest's log, the 325ms-vs-48ms hook cost from timing the binary directly, the 2.06x from comparing two `Summary` lines, the artifact deltas from walking `target/debug`. ## And it was a language this repository does not pin `python` is absent from `[tools]`, so `#!/usr/bin/env python3` ran under whatever the host happened to have — against the rule that CI, hk and a developer's shell run byte-identical commands. The scheduled workflow §3 asked for was never written (`.github/workflows/**` is protected and `V-PROTECTED-MUTATION` declares no override route), and its `install_args` named `rust cargo-nextest` and no python, so the harness would not have run on a runner at all. That hole is wider than this file and is CLOUD-1229's. `suite_metric.rs` goes with it: 119 lines whose whole subject was that the removed task set an environment variable. What survives from the row is what it was really for — the residue is measured and does not reproduce, recorded where the next reader will find it. Refs: CLOUD-1208, CLOUD-1229 --- .prettierignore | 5 - bench/rust/RESULTS.md | 23 --- bench/rust/sweep.py | 303 ---------------------------- crates/batten/tests/suite_metric.rs | 119 ----------- mise.toml | 34 ---- 5 files changed, 484 deletions(-) delete mode 100644 bench/rust/RESULTS.md delete mode 100755 bench/rust/sweep.py delete mode 100644 crates/batten/tests/suite_metric.rs diff --git a/.prettierignore b/.prettierignore index 254c38c3a..05b6dea57 100644 --- a/.prettierignore +++ b/.prettierignore @@ -14,8 +14,3 @@ bench/tokens/RESULTS.md # lands unformatted, gets rewritten by prettier, and has to be regenerated again # to stay byte-stable — churn in a file nobody hand-edits. bench/suites/RESULTS.md - -# `bench/rust/RESULTS.md` is the Rust suite's half of that pair, generated by -# `mise run suite-bench-rust` (CLOUD-1208). Same generator-owns-the-bytes reason -# as its shell sibling directly above. -bench/rust/RESULTS.md diff --git a/bench/rust/RESULTS.md b/bench/rust/RESULTS.md deleted file mode 100644 index a54412408..000000000 --- a/bench/rust/RESULTS.md +++ /dev/null @@ -1,23 +0,0 @@ -# Four-term cost of the Rust suite - -Generated by `mise run suite-bench-rust`. Do not hand-edit. - -`total` is wall clock for the whole run. `build` is a `--no-run` call -taken first, so on a warm tree it is the freshness check rather than a -compile. `execute` is nextest's own `Summary`. **`residue` is the -subtraction and nothing more — this report does not name its cause.** - -Two attempts to name it were wrong by 4.5x and 56x (CLOUD-1208). It is -measured NOT to be nextest's per-binary list phase: a zero-match filter -run pays the freshness check and the full enumeration and totals 1.75s. - -- arms: 3 -- cases: 3200 across 124 binaries -- residue share of the first arm: 0.1% -- repeat-run null: 0.963–1.012 over 2 pairs - -| arm | build | execute | total | residue | -| ---: | ---: | ---: | ---: | ---: | -| 0 | 1.1s | 101.3s | 102.5s | 0.1s | -| 1 | 1.1s | 97.6s | 98.8s | 0.1s | -| 2 | 1.1s | 98.6s | 99.9s | 0.2s | diff --git a/bench/rust/sweep.py b/bench/rust/sweep.py deleted file mode 100755 index 1fcf8fa07..000000000 --- a/bench/rust/sweep.py +++ /dev/null @@ -1,303 +0,0 @@ -#!/usr/bin/env python3 -"""Four-term cost of the Rust suite, with its own repeat-run null. - -CLOUD-1208. `mise run test:cargo` emits ONE duration for a step that is four -costs, and the per-step receipt makes even that unobservable on a hit. The shell -side has had `mise run suite-bench` and `bench/suites/RESULTS.md` since -CLOUD-386; the Rust side has had nothing, so every claim about what that suite -costs — including the ones in this row's siblings — is a hand measurement -somebody took once. - -## Why four terms, and why the fourth is the point - - total wall = build + execute + - -`perf`/`perf-pair` measure the BINARY's invocation latency, which is a different -question one layer down; conflating the two is the error `.claude/rules/rust.md` -records for `acquisition-wall-clock` vs `wall-clock`. A report emitting only -nextest's `Summary` would declare a 127s suite that takes 231s. - -**THE RESIDUE IS REPORTED AND NEVER LABELLED, and that is this harness's whole -reason to exist.** CLOUD-1208 has been wrong about it twice: - - 1. Filed quoting 1376s wall and "~90% is compile and link" — both from - guessing when the run started and ended. Wrong by 4.5x, corrected by `stat` - on a log file. - 2. Then quoting the 97.7s residue as nextest's per-binary list phase — - reasoned from how nextest works, never measured. Wrong by 56x: a zero-match - filter run pays the freshness check AND the full enumeration and then runs - nothing, and totals 1.75s. - -Two independent attributions, both confident, both wrong, both caught only by an -ad-hoc experiment nobody was obliged to run. A harness printing -`list phase: 97.7s` would have shipped the second as fact. So this prints the -residue as a residue, and prints what it is NOT. - -## Why a `bench/` helper driven by a one-line task - -`policy/shell-retirement.rego` refuses ADDING an authored shell rule at `deny` -(`V-SHELL-RULE-ADDED`) with no override, so a `mise-tasks/*.sh` program is -unavailable — the same constraint that forced `[tasks.semver]`, -`[tasks.prose-only-check]`, `[tasks.policy-test]` and `bench/acquisition/sweep.py` -into their shapes. Under `bench/` rather than `mise-tasks/` for a second reason -that one records: mise makes every executable in a task directory a file task -named by its basename AND its stem, so a helper there would publish a second -entry point that runs this with no `BENCH_METRIC` set — stamping the invocation -series' default into the suite series, which is the one thing the stamp exists to -prevent. - -## A SENSOR, NEVER A GATE - -A duration ceiling is met by deleting assertions, which is strictly worse than a -slow suite because the result also has to be maintained. That is -`[tasks.coverage]`'s recorded argument against a coverage threshold, and -non-negotiable rule 2's "a log without a gate is sensor only" anticipates exactly -this case. So this draws no conclusion, exits 0 on any measurement it completed, -and is deliberately absent from `verify` and from `final`'s `needs:`. - -## Output - -Pointer-only per non-negotiable rule 4: durations, counts and target names. No -test names, no command lines, no cargo chatter. -""" - -from __future__ import annotations - -import os -import re -import shutil -import subprocess -import sys -import time -from pathlib import Path - -# Measured arms, after the discarded one below. Each is minutes, so the count is -# what is affordable, and the spread is reported with its own `pairs=` so a reader -# knows how thin it is rather than reading two numbers as a distribution. -ARMS = 3 - -# ONE DISCARDED ARM FIRST, AND IT IS NOT POLITENESS — the harness was unusable -# without it. Measured 2026-08-30, two consecutive arms and no warmup: -# -# arm=0 execute=123.6s total=124.6s -# arm=1 execute= 92.5s total= 93.4s -# ratio=null0 value=0.750 -# -# A null of 0.750 means the instrument cannot distinguish any effect smaller than -# 25%, which is larger than every delta any sibling row is trying to measure. The -# arms were not identical: the first one warms the OS page cache over 124 test -# binaries and the second reads them back. `perf-pair`'s consecutive-arm null -# works because its arms are milliseconds over two committed fixtures; at this -# scale the first run IS the confound. -# -# So the first arm is run and thrown away, and every reported arm starts equally -# warm. A null that stays wide after this is a real property of the metric and is -# reported as one. -WARMUP_ARMS = 1 - -RESULTS = Path("bench/rust/RESULTS.md") - -# nextest's own execute term, e.g. `Summary [ 127.000s] 3167 tests run: ...`. -SUMMARY = re.compile(r"Summary\s*\[\s*([0-9.]+)s\]\s*(\d+)\s+tests?\s+run") -# `Starting 3167 tests across 119 binaries`, which is the target count the -# residue has repeatedly been blamed on. -STARTING = re.compile(r"Starting\s+(\d+)\s+tests?\s+across\s+(\d+)\s+binar") - -# SGR escapes, stripped before either pattern is applied. -# -# Measured rather than anticipated: the first real run of this harness failed with -# "nextest printed no Summary line" over a suite that had just reported -# `Summary [ 143.437s] 3194 tests run`. nextest colours that line, so the bytes are -# `\x1b[32;1m Summary\x1b[0m \x1b[1m3194\x1b[0m …` and every `\s*` in the -# patterns above is looking at an escape sequence. -# -# BOTH HALVES, because either alone is a single point of failure for the one term -# this harness exists to report: `--color never` is passed below so the common path -# produces clean bytes, and this strips whatever still arrives — a `CLICOLOR_FORCE` -# in the environment, or a future nextest that colours a stream it does not today. -# Losing the Summary silently would mean reporting the residue as the whole -# non-build cost, which is the mislabelling this row is about. -ANSI = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") - - -def fail(message: str, code: int = 2) -> None: - print(f"::error:: suite-bench-rust: {message}", file=sys.stderr) - sys.exit(code) - - -def run(argv: list[str], env: dict[str, str] | None = None) -> tuple[float, str, int]: - """Wall clock, combined and de-escaped output, and status of one command.""" - started = time.monotonic() - result = subprocess.run(argv, capture_output=True, text=True, check=False, env=env) - elapsed = time.monotonic() - started - return elapsed, ANSI.sub("", result.stdout + result.stderr), result.returncode - - -def arm(label: str) -> dict[str, float]: - """One reading of all four terms, taken back to back on one machine. - - The `--no-run` call goes FIRST and its wall clock is the build term. On a - warm tree that is the freshness check (CLOUD-1208 measured 5.9s); on a cold - or partial one it is build-and-link. Either way the term is what it is — - naming it "the build" and then quoting a cold number as a warm one is the - first of the two defects above, so the arm records which it was by reporting - the number rather than a word. - - THE TOTAL IS THE TASK, NOT `cargo nextest`, and getting that wrong once is - why this docstring says so. Measured 2026-08-30 with `cargo nextest` as the - total, the residue came out at **-1.0s and -0.1s** across two arms — a tidy - zero, over the exact suite whose residue CLOUD-1208 measured at 97.7s. Both - readings were correct and they answer different questions: the row's 231s was - `mise run test:filter`, so the unattributed cost is in the TASK — mise - startup, the task graph, `step-receipt` — and never was inside nextest at all. - - A harness measuring `cargo nextest` would therefore have reported a - residue-free suite and retired the row's own subject as solved. That is the - third wrong attribution in this row's history and the first one this - instrument produced itself, which is the argument for the instrument rather - than against it. - """ - build_wall, _build_out, build_rc = run( - ["cargo", "nextest", "run", "--workspace", "--no-run", "--color", "never"] - ) - if build_rc != 0: - # No `-i` equivalent and no tolerance: a suite that does not build is - # perfectly timeable, which is how a broken tree would otherwise be - # published as a fast number. - fail(f"arm {label}: the suite did not build, so nothing here is a measurement", 1) - - # The task a developer actually runs, so the wrapper's cost is inside the - # total rather than outside the instrument. Its `Summary` is parsed from this - # same invocation — taking `execute` from a separate run is what made the - # subtraction go negative, since the two runs are not the same run. - # - # THE RECEIPT IS BYPASSED, and that is the row's own observation acted on: - # "the per-step receipt makes even that unobservable on a hit". A hit skips - # the step entirely, so an arm measuring one would report a few hundred - # milliseconds of cache lookup as the suite's cost. `BATTEN_STEP_RECEIPT_BYPASS` - # is `step-receipt.sh`'s own declared lever for exactly this — the same one CI - # rides — so the arms measure the work rather than the cache. - environment = dict(os.environ, BATTEN_STEP_RECEIPT_BYPASS="1") - total_wall, out, _ = run(["mise", "run", "test:cargo"], env=environment) - # A red suite is still a valid COST measurement — this is a sensor, and - # refusing to report because a test failed would make the instrument - # unavailable exactly when somebody is bisecting a slow failing suite. The - # status is reported so the reading is not mistaken for a green one. - summary = SUMMARY.search(out) - if summary is None: - fail(f"arm {label}: nextest printed no Summary line, so the execute term is unknown", 1) - execute = float(summary.group(1)) - cases = int(summary.group(2)) - - starting = STARTING.search(out) - binaries = int(starting.group(2)) if starting else 0 - - return { - "build": build_wall, - "execute": execute, - "total": total_wall, - # NOT an explanation. Subtraction, and nothing else is claimed about it. - "residue": total_wall - build_wall - execute, - "cases": float(cases), - "binaries": float(binaries), - } - - -def record(label: str, terms: dict[str, float]) -> None: - print( - f"arm={label} build={terms['build']:.1f}s execute={terms['execute']:.1f}s " - f"total={terms['total']:.1f}s residue={terms['residue']:.1f}s " - f"cases={int(terms['cases'])} binaries={int(terms['binaries'])}" - ) - - -def write_results(arms: list[dict[str, float]], nulls: list[float]) -> None: - first = arms[0] - share = (first["residue"] / first["total"] * 100) if first["total"] > 0 else 0.0 - lines = [ - "# Four-term cost of the Rust suite", - "", - "Generated by `mise run suite-bench-rust`. Do not hand-edit.", - "", - "`total` is wall clock for the whole run. `build` is a `--no-run` call", - "taken first, so on a warm tree it is the freshness check rather than a", - "compile. `execute` is nextest's own `Summary`. **`residue` is the", - "subtraction and nothing more — this report does not name its cause.**", - "", - "Two attempts to name it were wrong by 4.5x and 56x (CLOUD-1208). It is", - "measured NOT to be nextest's per-binary list phase: a zero-match filter", - "run pays the freshness check and the full enumeration and totals 1.75s.", - "", - f"- arms: {len(arms)}", - f"- cases: {int(first['cases'])} across {int(first['binaries'])} binaries", - f"- residue share of the first arm: {share:.1f}%", - ] - if nulls: - lines.append( - f"- repeat-run null: {min(nulls):.3f}–{max(nulls):.3f} over {len(nulls)} pairs" - ) - lines += [ - "", - "| arm | build | execute | total | residue |", - "| ---: | ---: | ---: | ---: | ---: |", - ] - for index, terms in enumerate(arms): - lines.append( - f"| {index} | {terms['build']:.1f}s | {terms['execute']:.1f}s " - f"| {terms['total']:.1f}s | {terms['residue']:.1f}s |" - ) - RESULTS.parent.mkdir(parents=True, exist_ok=True) - RESULTS.write_text("\n".join(lines) + "\n", encoding="utf-8") - - -def main() -> int: - root = subprocess.run( - ["git", "rev-parse", "--show-toplevel"], capture_output=True, text=True, check=False - ) - if root.returncode != 0: - fail("not a git repository, so there is no suite to measure") - os.chdir(root.stdout.strip()) - - if shutil.which("cargo") is None: - fail("cargo is not on PATH — run this through `mise run suite-bench-rust`") - - # Discarded, for the reason WARMUP_ARMS states: without it the null is 0.750 - # and the instrument cannot see any delta a sibling row would quote. - for index in range(WARMUP_ARMS): - arm(f"warmup{index}") - - arms = [] - for index in range(ARMS): - terms = arm(str(index)) - record(str(index), terms) - arms.append(terms) - - # THE NULL IS A SPREAD, and it is over `total` because that is the term every - # sibling row quotes a delta against. Consecutive identical arms, so the - # ratio is 1.0 plus pure noise by construction — the same construction - # `perf-pair --null` uses, and the reason a sibling's number can be read at - # all. A delta inside this spread has measured "no effect", which is a result. - nulls = [ - arms[index + 1]["total"] / arms[index]["total"] - for index in range(len(arms) - 1) - if arms[index]["total"] > 0 - ] - for index, value in enumerate(nulls): - print(f"ratio=null{index} value={value:.3f}") - if nulls: - print(f"null-spread low={min(nulls):.3f} high={max(nulls):.3f} pairs={len(nulls)}") - - # WHAT THE RESIDUE IS NOT, printed every run rather than left in a comment. - # This is the line that stops the next reader doing what the last two did. - print( - "residue-is-unattributed note=not-the-list-phase " - "measured=1.75s-for-a-zero-match-filter-run" - ) - - write_results(arms, nulls) - print(f"wrote={RESULTS}") - return 0 - - -if __name__ == "__main__": - sys.exit(main()) diff --git a/crates/batten/tests/suite_metric.rs b/crates/batten/tests/suite_metric.rs deleted file mode 100644 index 681b34567..000000000 --- a/crates/batten/tests/suite_metric.rs +++ /dev/null @@ -1,119 +0,0 @@ -//! The suite series cannot be diffed against the invocation series (CLOUD-1208). -//! -//! # The hazard -//! -//! `mise-tasks/perf-record.sh` appends measurements to `refs/notes/perf` and -//! stamps each entry with `metric=`, read from `BENCH_METRIC` and defaulting to -//! `wall-clock`. That default is the INVOCATION series — `noop`, `hook`, -//! `wired`, measured over two committed fixtures in milliseconds. -//! -//! CLOUD-1208 measures the Rust SUITE: minutes of build and execute over the -//! whole workspace. The two share a unit and share nothing else. If both stamped -//! `wall-clock`, a reader plotting the series would put a 231-second suite arm -//! next to a `--help` invocation and read the gap as a regression — a step -//! change that never happened, in a series nobody re-derives. -//! -//! This is `acquisition_metric.rs`'s assertion for the third series, and the -//! third is what turns a pair into a rule: `.claude/rules/rust.md` records the -//! same hazard for a future instruction-count series, which is why `metric=` -//! exists at all. -//! -//! # Why over `mise.toml` rather than over the helper -//! -//! The stamp is set by the task, not by the Python. A test reading the helper -//! would pass while the task that invokes it lost the variable — and the task is -//! the only caller, so the task is where the claim lives. - -// Panicking on setup failure is the idiomatic way for a test to fail loudly. -#![allow(clippy::unwrap_used, clippy::expect_used)] - -mod common; - -/// The default `perf-record` falls back to, and one of the two values this task -/// must not carry. Spelled here rather than read out of the shell, because the -/// point is that they are DIFFERENT — deriving one from the other would make the -/// assertion vacuous the day somebody changed the default. -const INVOCATION_METRIC: &str = "wall-clock"; - -/// The sibling sweep's stamp. A suite arm sharing THIS one would be the same -/// defect one axis over — `acquisition-bench` measures a generated fixture -/// family in milliseconds, and this measures the committed workspace in minutes. -const ACQUISITION_METRIC: &str = "acquisition-wall-clock"; - -fn task_body(task: &str) -> String { - let manifest = std::fs::read_to_string(common::at_root("mise.toml")) - .expect("the manifest is where every task in this repository is declared"); - // `toml::from_str`, which is the idiom every reader in `config.rs` and - // `facts.rs` uses. `str::parse` resolves to a different impl here and reports - // "unexpected content, expected nothing" over a manifest that is valid. - let parsed: toml::Value = toml::from_str(&manifest).expect("mise.toml parses as TOML"); - parsed - .get("tasks") - .and_then(|tasks| tasks.get(task)) - .and_then(|task| task.get("run")) - .and_then(toml::Value::as_str) - .unwrap_or_else(|| panic!("[tasks.{task}] declares a run body")) - .to_owned() -} - -fn stamp(task: &str) -> String { - task_body(task) - .split_whitespace() - .find_map(|word| word.strip_prefix("BENCH_METRIC=").map(str::to_owned)) - .unwrap_or_else(|| { - panic!( - "[tasks.{task}] sets BENCH_METRIC — without it perf-record stamps \ - the invocation series' default and the two become diffable" - ) - }) -} - -#[test] -fn the_suite_series_is_stamped_with_its_own_metric() { - let suite = stamp("suite-bench-rust"); - - assert!( - !suite.is_empty(), - "an empty stamp is the default by another route" - ); - assert_ne!( - suite, INVOCATION_METRIC, - "the suite series must not share the invocation series' stamp: a reader \ - plotting `{INVOCATION_METRIC}` would put a whole-workspace suite arm \ - beside a `--help` invocation and read the gap as a regression" - ); -} - -/// The three series are pairwise distinct, which is the property the pair of -/// assertions above only gets halfway to. Asserted against the sibling's LIVE -/// stamp rather than a second literal, because the claim is about the two tasks -/// disagreeing rather than about either one's spelling. -#[test] -fn the_suite_and_acquisition_series_do_not_share_a_stamp() { - let suite = stamp("suite-bench-rust"); - let acquisition = stamp("acquisition-bench"); - - assert_eq!( - acquisition, ACQUISITION_METRIC, - "the sibling's stamp moved, so this comparison is no longer the one \ - `acquisition_metric.rs` pins — reconcile the two before loosening either" - ); - assert_ne!( - suite, acquisition, - "a minutes-long workspace suite arm and a milliseconds-long generated \ - fixture arm would be diffable under a shared stamp" - ); -} - -/// ANTI-VACUITY. The cases above pass over any string that is not one of two -/// literals — including one set by a task that does not run the harness at all. -/// This pins that the body carrying the stamp is the one invoking the -/// measurement, which is `acquisition_metric.rs`'s own second case. -#[test] -fn the_stamp_is_set_on_the_task_that_runs_the_harness() { - let body = task_body("suite-bench-rust"); - assert!( - body.contains("bench/rust/sweep.py"), - "the body carrying the stamp is the one invoking the measurement: {body}" - ); -} diff --git a/mise.toml b/mise.toml index 47805cfae..bdc25a7a7 100644 --- a/mise.toml +++ b/mise.toml @@ -1298,40 +1298,6 @@ description = "Measure tree-surface acquisition cost as declared-document count depends = ["build:release"] run = "BENCH_METRIC=acquisition-wall-clock ./bench/acquisition/sweep.py" -[tasks.suite-bench-rust] -description = "Report: the Rust suite's cost in four terms — build, execute, total, and the residue between them (CLOUD-1208)" -# CLOUD-1208. The shell suite has had an instrument since CLOUD-386 -# (`suite-bench`, `bench/suites/RESULTS.md`, 144 suites); the Rust suite has had -# none, so `test:cargo` emits ONE duration for four costs and the per-step -# receipt makes even that unobservable on a hit. -# -# A REPORT, NEVER A GATE, for `[tasks.coverage]`'s recorded reason one screen up: -# a duration ceiling is met by deleting assertions, which is strictly worse than -# a slow suite. Deliberately absent from `[tasks.verify]` and from `final`'s -# `needs:` in ci.yml, surfaced on a schedule instead — CLOUD-111's placement, and -# `report-only-check` is the sensor on it. -# -# THE FOURTH TERM IS WHY THIS EXISTS. Measured warm, the suite is 231s wall -# against a 127.0s `Summary` and a 5.9s freshness check, leaving ~98s — 42% of the -# loop — that nothing in this repository could attribute. Two attempts to name it -# were wrong by 4.5x and 56x, so the harness prints it as a residue and prints -# what it is NOT. A report emitting only the `Summary` would declare a 127s suite -# that takes 231s. -# -# ONE LINE, over `bench/rust/sweep.py`, for `acquisition-bench`'s two reasons -# above: `V-SHELL-RULE-ADDED` refuses adding a `mise-tasks/*.sh` program, and a -# helper under a task directory would publish a second entry point running the -# sweep with no `BENCH_METRIC` set. `inline-task-bodies-not-growing` counts -# `run = '''` bodies non-increasing, which a single-line body does not touch. -# -# BENCH_METRIC IS THE LOAD-BEARING WORD, for the reason `acquisition-bench` states: -# `perf-record.sh` stamps it into every series entry and defaults to `wall-clock`, -# the INVOCATION series. A suite arm and a `--help` invocation share a unit and -# nothing else, so a shared stamp would let a reader diff them and read a step -# change that never happened. `crates/batten/tests/suite_metric.rs` asserts this -# task sets it rather than trusting that it does. -run = "BENCH_METRIC=suite-wall-clock ./bench/rust/sweep.py" - [tasks."install:local"] description = "Put the built binary where the hook registrations resolve it — `install.sh`'s own destination" depends = ["build:release"] From 45601adccd48004639e21f1bf57e08c074e5842e Mon Sep 17 00:00:00 2001 From: Alec Wenzowski Date: Mon, 31 Aug 2026 03:21:19 +0000 Subject: [PATCH 13/13] =?UTF-8?q?refactor(bench):=20retire=20596=20lines?= =?UTF-8?q?=20of=20Python=20out=20of=20`bench/`=20=E2=80=94=20the=20ratche?= =?UTF-8?q?t's=20scope=20is=20shell,=20the=20rule=20is=20no=20spaghetti?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two `.py` helpers had grown under `bench/`, outside the retirement ratchet's glob, and the second cited the first. `[tasks.acquisition-bench]`'s own comment recorded that the shape was forced — `shell-retirement` refuses ADDING an authored shell rule at `deny`, one route, no `bypass_env` — so the measurement went to the one language the ratchet does not watch. A second author read that comment, followed the precedent for the identical stated reason, and added a third helper (reverted on CLOUD-1208). That is a growth path with a citation trail, and this closes it. A ratchet's subject is authored shell because that is what it was built to retire. That is a statement about its reach, never a licence for what sits beside it. bench/gates/classify.py 269 lines, invoked by nothing — deleted. bench/acquisition/sweep.py 327 lines, one caller — ported. `bench/gates/RESULTS.md` stays: three source comments cite it as landed measurement evidence, so the artifact is load-bearing where its generator was not. Its header stops claiming a live generator and says what it now is — a frozen census taken 2026-08-23, not refreshed. The sweep moves into `crates/batten/src/perf.rs`, which is where the paired measurement already lives and is the module `policy/spawn-adapters.rego` already places for exactly this class: a harness whose whole subject is what an EXTERNAL process costs, so the spawns are the thing rather than an implementation of it. Sharing that module is also what stops a second percentile convention, a second record shape and a second hyperfine invocation from existing. The unpinned interpreter goes with the files: `python` was never in `[tools]`, so every one ran under whatever the host happened to have while `lock-complete` held every declared tool to three platforms. AN EXAMPLE TARGET RATHER THAN A VERB, and that is a refusal honoured rather than a preference. It was written as `perf acquire` first, on `perf pair`'s precedent. `crates/batten/tests/pointer_only.rs` sweeps EVERY leaf verb over a bare fixture corpus and refuses one that exits 3 — "it failed internally, so what it did not emit proves nothing" — and a sweep with no benchmark runner and no built binary to time has could-not-look as its only honest answer there. `perf pair` survives that sweep because it has a real SKIP predicate; there is no analogue here, and inventing one to satisfy a census is the false green these gates exist to catch. So the harness is a target the command surface does not carry, and it spawns nothing. Tests, in the two tiers `.claude/rules/policy-modules.md` asks for: perf.rs's own module the sweep-point parse and its refusals, the rendered reading byte-for-byte, and an anti-vacuity case that an empty null set prints no spread — the fold's identities would otherwise publish `low=inf high=-inf` as a measured width. acquisition_sweep.rs over the compiled binary, that the GENERATED FIXTURE is a tree the engine accepts. The load-bearing case seeds the module's sentinel into one declared document and asserts the finding names both the row and that document, because a fixture whose `documents` array the engine never reads still draws a tidy curve — the defect `weaver` shipped in the field, exit 0 over a knowingly-broken registry. Two gates caught defects on the way, both real: `document_facts` refused prose naming a consumer artifact inside `crates/batten` (non-negotiable rule 1), and clippy found a `redundant_closure` in `dev_profile.rs` that had already been pushed. `mise-tasks/replay-pointers.py` is the last one and is not reachable from here: its caller is governed, so it can only leave by retiring the `replay` gate whole under the two-shapes rule. Filed as CLOUD-1232, Ready, with that shape spelled out. Refs: CLOUD-1229, CLOUD-935, CLOUD-1208, CLOUD-843, CLOUD-1132, CLOUD-1232 --- bench/acquisition/sweep.py | 327 ------------ bench/gates/RESULTS.md | 10 +- bench/gates/classify.py | 269 ---------- crates/batten/examples/acquisition-bench.rs | 72 +++ crates/batten/src/perf.rs | 521 +++++++++++++++++++- crates/batten/tests/acquisition_metric.rs | 16 +- crates/batten/tests/acquisition_sweep.rs | 168 +++++++ crates/batten/tests/dev_profile.rs | 2 +- mise.toml | 61 ++- 9 files changed, 824 insertions(+), 622 deletions(-) delete mode 100755 bench/acquisition/sweep.py delete mode 100644 bench/gates/classify.py create mode 100644 crates/batten/examples/acquisition-bench.rs create mode 100644 crates/batten/tests/acquisition_sweep.rs diff --git a/bench/acquisition/sweep.py b/bench/acquisition/sweep.py deleted file mode 100755 index 2b3877cd4..000000000 --- a/bench/acquisition/sweep.py +++ /dev/null @@ -1,327 +0,0 @@ -#!/usr/bin/env python3 -"""Tree-surface acquisition cost as a function of declared-document count. - -CLOUD-935. `.claude/rules/rust.md`'s concurrency table carries one row whose -verdict is conditional and unmet — tree-surface fact ACQUISITION "stays serial -until a number says otherwise" — and states the condition: *"To move it now, -bring a number showing resolution — not projection — is the cost."* CLOUD-834 -measured PROJECTION and disclaims this half. This is that number. - -## Why a second harness rather than an arm in `perf` - -`mise-tasks/perf.sh` measures fixed paths over fixed fixtures, and its arms -bracket INVOCATION cost. This sweeps a variable, which is a different experiment -with a different independent axis, and it needs to generate a fixture family per -run rather than materialise two committed ones. Adding a swept arm to `perf` -would also have meant editing an authored shell rule, which -`policy/shell-retirement.rego` refuses at `deny` with no override route -(`V-SHELL-RULE-EDITED`) — so the shape here is a Python helper driven by an -inline `mise.toml` task, the same inline-task shape `semver` and `policy-test` -were forced into for that identical reason. - -Under `bench/` beside `bench/gates/classify.py` rather than under `mise-tasks/`: -mise makes every executable in that directory a file task named by its basename -AND its stem, so a helper there would publish a second entry point that runs this -sweep with no `BENCH_METRIC` set — stamping the invocation series' default into -the acquisition series, which is the one thing §5 exists to prevent. - -## The experiment, and the confound it is built to avoid - -ONE rule, ONE bundle, ONE module — and the row's `documents` array is what -grows. A row PER document would have made every step of the sweep add a module -compile and an evaluation beside each read, so the curve would price four things -and get reported as one. Holding everything but the declared path count fixed is -what leaves acquisition as the only term that moves. -`crates/batten/tests/document_read_count.rs::one_row_declaring_n_paths_acquires_n_documents` -pins that the engine really does acquire once per declared path under exactly -this shape, because a sweep over a variable the engine ignores would still draw a -tidy curve. - -## Ratios, never absolutes - -Machine noise is common-mode across arms measured seconds apart on one machine, -so it divides out — the same reason `perf-compare` decides a ratio and -`.claude/rules/rust.md` records why wall clock is usable at all here. Every arm -is reported, and the verdict is read off `ratio=` lines against the N=0 floor. - -## The null is not optional - -Two IDENTICAL trees at the largest N, measured as a separate pair. Its ratio is -1.0 plus pure noise by construction, which is what makes the spread a measured -quantity rather than a number in a comment — exactly how `perf-pair --null` -derived the 0.966–1.102 spread `perf-compare`'s 1.30 threshold clears. A sweep -number that sits inside the null spread has measured "no effect", and that is a -result rather than a failure to deliver. - -## Output - -Pointer-only per non-negotiable rule 4: one `path=` record per arm in `perf.sh`'s -byte-stable shape, then one `ratio=` line per comparison. No fixture contents, no -command lines, no hyperfine chatter — the raw JSON stays under the output -directory for a human. - -Exit 0 measured / 1 a measurement failed / 2 could not look. -""" - -from __future__ import annotations - -import json -import os -import shutil -import subprocess -import sys -from pathlib import Path - -# `perf.sh`'s names and defaults, deliberately: a caller who already knows how to -# turn that task down should not have to learn a second vocabulary. -RUNS = int(os.environ.get("BENCH_RUNS", "100")) -WARMUP = int(os.environ.get("BENCH_WARMUP", "10")) -# ABSOLUTE, and that is load-bearing rather than tidy. Every arm runs hyperfine -# with the FIXTURE tree as its working directory, so a relative export path -# resolves against the fixture and hyperfine dies with "No such file or -# directory" before it times anything. `mise-tasks/perf.sh`'s header records the -# identical lesson for its own check arm; this is the same trap one harness over. -# `resolve()` is happy on a path that does not exist yet, which is why it can sit -# here rather than after the mkdir. -OUT_DIR = Path(os.environ.get("BENCH_OUT_DIR", "target/acquisition-bench")).resolve() -BIN = Path(os.environ.get("BENCH_BIN", "target/release/batten")) - -# The sweep, and its FIRST entry is the ratio base. -# -# ONE, NOT ZERO, and that correction is the difference between measuring -# acquisition and measuring "does this tree have a policy row at all". A zero arm -# carries no rule, so the step from it to any other arm bundles the fixed cost of -# registering a bundle, compiling a module and evaluating it in with the reads — -# measured, that step alone read 1.367 at N=16, which would have been published as -# a per-document cost it is mostly not. Basing the ratios on a tree that already -# has exactly one rule and one document holds every fixed term constant, so the -# only thing differing between arms is how many paths that one row declares. -# -# 256 is chosen to be past the point where a per-document term, if there is one, -# has to be visible above a ~5 ms process start: at 256 even a 10 µs read is -# 2.5 ms. `BENCH_NS=0,...` still works and gives the no-policy reference, which is -# a different question and is not what the verdict is read off. -NS = [int(n) for n in os.environ.get("BENCH_NS", "1,16,64,256").split(",") if n] - -# How many identical pairs the null is taken over. Five rather than one, because -# a single ratio is a point and the sweep has to be read against a WIDTH. -NULL_PAIRS = int(os.environ.get("BENCH_NULL_PAIRS", "5")) - -# One module, whose body reads whatever was declared. Iterating `documents` -# rather than naming a path keeps the module identical across every arm, so the -# only thing differing between arms is the row's declaration. -MODULE = """package batten.acquisition - -import rego.v1 - -rules contains "acquisition-bench" - -violation contains { -\t"rule": "acquisition-bench", -\t"verdict": "V-ACQUISITION-BENCH", -\t"subjects": [{"path": path}], -} if { -\tsome path, doc in input.tree.documents -\tdoc.stray -} -""" - -AUTHORITY_HEAD = """version = 1 - -[[verdict]] -id = "V-ACQUISITION-BENCH" -gloss = "the bench fixture declared a document carrying the sentinel key" -class = \"\"\" -A generated fixture for CLOUD-935's acquisition sweep. It is never raised: the -documents carry no sentinel, so the run is clean and the number is about reading -rather than about rendering findings. -\"\"\" - -[[verdict.route]] -id = "R-REGENERATE-THE-FIXTURE" -kind = "document" -target = "batten.toml" -""" - - -def fail(message: str, code: int = 2) -> None: - print(f"::error:: acquisition-bench: {message}", file=sys.stderr) - raise SystemExit(code) - - -def build_tree(root: Path, n: int) -> None: - """A repository with one policy row declaring `n` distinct documents.""" - if root.exists(): - shutil.rmtree(root) - (root / "policy-acquisition").mkdir(parents=True) - (root / "policy-acquisition" / "gate.rego").write_text(MODULE, encoding="utf-8") - - paths = [f"config{i}.toml" for i in range(n)] - for path in paths: - # Small and uniform. The cost being priced is the fixed per-document term - # — open, read, parse, cache — rather than a per-byte one, and a large - # file would measure the parser instead. Said out loud so the fixture does - # not grow by accretion, the way `perf.sh` says the same thing about its - # post-tool payload. - (root / path).write_text("quiet = true\n", encoding="utf-8") - - # THE FLOOR ARM CARRIES NO ROW AND NO VERDICT, which is what makes it the - # floor: config load, trust resolution and the walk, and not one acquisition. - # A row declaring zero documents would still compile a module and put that - # cost into the baseline every ratio is taken against. - # - # The verdict row goes with it, and that is the REGISTRY's requirement rather - # than a choice: `[[verdict]]` runs in both directions, so a declared class - # nothing raises fails the load outright ("a class no gate reaches reads as - # coverage"). With no rule there is no module, so the token is unraised and a - # floor arm carrying it would not run at all. The residual difference is a few - # lines of TOML the other arms also parse, which is orders below the noise the - # null measures. - if n: - declared = ", ".join(f'"{p}"' for p in paths) - authority = ( - AUTHORITY_HEAD - + "\n[[rule]]\n" - 'id = "acquisition-bench"\n' - 'kind = "policy"\n' - 'scope = "tree"\n' - 'bundle = "policy-acquisition/"\n' - f"documents = [{declared}]\n" - 'severity = "deny"\n' - ) - else: - authority = "version = 1\n" - (root / "batten.toml").write_text(authority, encoding="utf-8") - - # `git init` so the walk is a repository walk, matching every other fixture in - # this tree. No global or system config: a contributor's own git settings must - # not be able to change what is measured (CLOUD-282). - env = dict(os.environ, GIT_CONFIG_GLOBAL="/dev/null", GIT_CONFIG_SYSTEM="/dev/null") - subprocess.run( - ["git", "init", "-q", "-b", "main"], - cwd=root, - env=env, - check=True, - capture_output=True, - ) - - -def measure(arm: str, root: Path, binary: Path) -> dict[str, float]: - """One hyperfine run of `batten check` in `root`, as a record.""" - out = OUT_DIR / f"{arm}.json" - result = subprocess.run( - [ - "hyperfine", - "--warmup", - str(WARMUP), - "--runs", - str(RUNS), - "--shell=none", - "--export-json", - str(out), - "--style", - "none", - f"{binary} check", - ], - cwd=root, - capture_output=True, - text=True, - ) - if result.returncode != 0: - # NO `-i`. Every arm's fixture is clean, so a non-zero exit means the - # binary started failing rather than that the measurement is awkward — - # and a broken path is still perfectly timeable, which is how it would - # otherwise be published as a fast number. - (OUT_DIR / f"{arm}.err").write_text(result.stderr, encoding="utf-8") - fail(f"measuring arm {arm} failed — see {OUT_DIR / f'{arm}.err'}. No records.", 1) - - times = sorted(json.loads(out.read_text(encoding="utf-8"))["results"][0]["times"]) - count = len(times) - # p95 from the sorted per-run times rather than mean+2sd, for `perf.sh`'s - # reason: startup latency is right-skewed, so a normal assumption understates - # exactly the tail a budget would be about. - return { - "p50": times[int((count - 1) * 0.5)] * 1000, - "p95": times[-(-int((count - 1) * 95) // 100)] * 1000, - "mean": sum(times) / count * 1000, - "runs": count, - } - - -def record(arm: str, stats: dict[str, float]) -> None: - print( - f"path={arm} p50={stats['p50']:.2f} p95={stats['p95']:.2f} " - f"mean={stats['mean']:.2f} runs={int(stats['runs'])}" - ) - - -def main() -> int: - root = subprocess.run( - ["git", "rev-parse", "--show-toplevel"], - capture_output=True, - text=True, - check=False, - ) - if root.returncode != 0: - fail("not a git repository, so there is no tree to measure over") - os.chdir(root.stdout.strip()) - - if shutil.which("hyperfine") is None: - fail("hyperfine is not installed — run `mise install`; it is pinned in mise.toml") - binary = BIN.resolve() - if not binary.is_file() or not os.access(binary, os.X_OK): - fail(f"{BIN} is missing — run `mise run build:release`. Nothing measured.") - - if OUT_DIR.exists(): - shutil.rmtree(OUT_DIR) - OUT_DIR.mkdir(parents=True) - - # THE SWEEP, measured back to back on one machine so the noise the ratios - # divide out is the same noise. - stats: dict[int, dict[str, float]] = {} - for n in NS: - tree = OUT_DIR / f"tree-{n}" - build_tree(tree, n) - stats[n] = measure(f"acquire-{n}", tree, binary) - record(f"acquire-{n}", stats[n]) - - # THE NULL, AND IT IS A SPREAD RATHER THAN A NUMBER. Two identical trees at - # the largest N, built separately so each comparison is between two arms - # rather than an arm against itself — repeated, because ONE null ratio says - # nothing about how wide the noise is and a sweep ratio can only be read - # against a width. `perf-compare`'s 0.966–1.102 came from n=30 for exactly - # this reason; the pairs here are longer, so fewer of them bound it. - nulls: list[float] = [] - largest = max(NS) - for pair in range(NULL_PAIRS): - sides = {} - for side in ("a", "b"): - tree = OUT_DIR / f"null{pair}-{side}" - build_tree(tree, largest) - arm = f"null{pair}-{side}" - sides[side] = measure(arm, tree, binary) - record(arm, sides[side]) - nulls.append(sides["b"]["p50"] / sides["a"]["p50"]) - - base = stats[NS[0]]["p50"] - if base <= 0: - fail("the base arm measured zero, so no ratio can be taken", 1) - for n in NS[1:]: - print(f"ratio=acquire-{n}/acquire-{NS[0]} value={stats[n]['p50'] / base:.3f}") - for pair, value in enumerate(nulls): - print(f"ratio=null{pair} value={value:.3f}") - print(f"null-spread low={min(nulls):.3f} high={max(nulls):.3f} pairs={len(nulls)}") - - # THE PER-DOCUMENT TERM, which is the number the verdict is actually about. - # Reported rather than left to a reader with a calculator, and taken across - # the widest span in the sweep because that is where the fixed terms matter - # least. Microseconds, since milliseconds would round it to nothing. - span = max(NS) - NS[0] - if span > 0: - per_doc = (stats[max(NS)]["p50"] - base) * 1000 / span - print(f"per-document us={per_doc:.2f} over={span} documents") - return 0 - - -if __name__ == "__main__": - sys.exit(main()) diff --git a/bench/gates/RESULTS.md b/bench/gates/RESULTS.md index 0344eaf99..378c9602c 100644 --- a/bench/gates/RESULTS.md +++ b/bench/gates/RESULTS.md @@ -1,6 +1,14 @@ # What each gate-described `mise-tasks/` program invokes -Generated by `bench/gates/classify.py`. Do not hand-edit. +A FROZEN CENSUS, taken 2026-08-23. Its generator was 269 lines of Python that +nothing invoked, and it was retired under CLOUD-1229 rather than kept warm for a +re-run nobody had asked for in a week. So these numbers are a reading of the tree +on that date and are not refreshed: the corpus has since shrunk as CLOUD-1059's +migrations landed, and a reader wanting today's count should take it rather than +trust this. What the file is still cited for — by `facts.rs`, `rules.rs` and +`tests/git_facts.rs` — is the SHAPE it measured, which is the git-fact variant +split below, and that does not go stale with the count. + Classified by COMMAND-POSITION invocation over a tree-sitter-bash parse, so a token inside a comment or a string is not a hit (`.claude/rules/scanning.md` row two; CLOUD-843's two passes disagreed diff --git a/bench/gates/classify.py b/bench/gates/classify.py deleted file mode 100644 index 23949e29e..000000000 --- a/bench/gates/classify.py +++ /dev/null @@ -1,269 +0,0 @@ -"""Classify the gate-described `mise-tasks/` programs by what each INVOKES. - -CLOUD-907's first deliverable, and it gates the rest of that row: the bucket -sizes the bash-retirement campaign, and an estimate cannot schedule it. - -# Why this is not a `grep` - -`.claude/rules/scanning.md` row two. The question — "is this token in command -position, inside a comment, or inside a string" — is a SYNTAX question, and the -two instruments give different answers. CLOUD-843 ran both an hour apart: a -substring pass gave 11 tree / 24 git / 31 tracker / 16 forge, and a -command-position pass over the same files gave 22 / 50 / 3 / 7, because -`ci-local-parity` and `pipefail-grep-check` carried the token in a COMMENT. The -substring reading was nearly published as the campaign's scoping. - -So this walks tree-sitter-bash's parse and reads `command_name` nodes. A comment -is its own node kind and is never a command head, so "comments stripped" is a -property of the grammar rather than a preprocessing step that can be got wrong. - -# Why it is not wired into `hk` - -Deliberately an INTERACTIVE instrument, run with the language pinned, exactly as -`scanning.md` scopes row two. CLOUD-310's rejection of a matcher CLI *as a gate* -is measured and stands: the programs under `mise-tasks/` carry no extension, so a -run pointed at that directory scans nothing and still exits 0 — a gate that found -nothing looks exactly like a gate that passed. A standing gate over command -position needs the general fix, which is CLOUD-914's row, not a second copy of -this script behind a `#MISE description`. - -# Running it - - python3 -m venv .venv && .venv/bin/pip install tree_sitter tree_sitter_bash - .venv/bin/python bench/gates/classify.py > bench/gates/RESULTS.md - mise exec -- prettier --write bench/gates/RESULTS.md - -The `prettier` pass is part of generation, not a hand-edit: `hk` formats every -tracked markdown file, so a generator whose output it would rewrite produces a -file the tree cannot hold. Column alignment is the whole of what it changes. It -goes through `mise exec` because prettier IS a pinned tool here (`npm:prettier` -in `mise.toml`), so a bare call would format with whatever version happened to -be on PATH and could produce bytes the gate then rewrites. - -The two tree-sitter packages are NOT pinned, and the reason is a property of what -they are rather than of where the script sits (CLOUD-480, raised on review). -mise's backends install executables; these are import-only Python libraries with -no CLI, so there is nothing for it to put on PATH — and `python` itself is not a -`[tools]` entry, so adding one would download a toolchain into every clone for a -script nothing on the landing path runs. The venv is the narrowest thing that -works. If CLOUD-914 makes command-position scanning a standing gate, its inputs -become landing-path inputs and get pinned like any other. -""" - -import collections -import pathlib -import re -import sys - -import tree_sitter_bash -from tree_sitter import Language, Parser - -PARSER = Parser(Language(tree_sitter_bash.language())) - -TASKS = pathlib.Path(__file__).resolve().parents[2] / "mise-tasks" - -# A task is gate-described when its `#MISE description=` OPENS with Gate. -# -# `Gate\b` rather than `Gate:`, and the difference is exactly one row: -# `signing-posture` opens `"Gate (and, with --repair, the write): ..."`. A -# colon-anchored predicate counts 84 and silently drops the one task that -# describes a gate with a caveat — the off-by-one this file exists to not make. -GATE_DESCRIPTION = re.compile(r'^#MISE description="Gate\b') - -# Which external program puts a task in which bucket, in PRECEDENCE order: the -# first bucket a task's command heads touch wins. A task that shells out to the -# forge is a forge task even when it also reads git, because the forge read is -# what blocks its migration. -BUCKETS: list[tuple[str, frozenset[str]]] = [ - ("forge", frozenset({"gh"})), - ("git", frozenset({"git"})), - ("build", frozenset({"cargo", "rustc", "hyperfine", "cargo-nextest"})), -] - -# Which git fact variant an invocation needs, decided from the subcommand and -# its flags rather than from the subcommand alone. `rev-parse` is 65 of the -# invocations and is NOT one question: `--git-dir` and `--show-toplevel` locate -# the repository, `HEAD` reads the current commit, and `^{commit}` resolves -# a declared ref. Collapsing them would put the whole corpus in one variant and -# tell the fact model nothing. -LOCATION_FLAGS = ("--git-dir", "--show-toplevel", "--is-inside-work-tree", "--absolute-git-dir") -ANCESTRY_FLAGS = ("--is-ancestor", "--count", "--merge-base") - - -def described_as_gate(text: str) -> bool: - for line in text.splitlines(): - if line.startswith("#MISE description="): - return GATE_DESCRIPTION.match(line) is not None - return False - - -def commands(source: bytes): - """Every `command` node, as (head, [argument words]). - - Words are the literal text of each argument; one built from an expansion - (`"$ref"`) is kept verbatim rather than guessed at, so a variant is never - inferred from a value this pass cannot see. - """ - tree = PARSER.parse(source) - stack = [tree.root_node] - while stack: - node = stack.pop() - if node.type == "command": - head = None - args = [] - for child in node.children: - if child.type == "command_name": - head = child.text.decode("utf-8", "replace") - elif head is not None and child.type not in ("file_redirect", "herestring_redirect"): - args.append(child.text.decode("utf-8", "replace")) - if head is not None: - yield head, args - stack.extend(node.children) - - -# Global options git accepts BEFORE the subcommand that take their value as a -# SEPARATE word. Skipping the value is what keeps `git -C "$root" rev-parse` from -# reading `"$root"` as the subcommand (CLOUD-480, found on review of #660): it -# resolved to no variant at all, so the task silently understated the git surface -# — and that count is what the retirement campaign is scheduled against. -GLOBAL_OPTS_WITH_VALUE = ("-C", "-c", "--git-dir", "--work-tree", "--namespace", "--exec-path") - - -def subcommand(words: list[str]) -> str: - """The subcommand, past any leading global options and their values.""" - index = 0 - while index < len(words): - word = words[index] - if not word.startswith("-"): - return word - # `--git-dir=x` carries its value inline, so only the separate-word form - # consumes the next element. - if word in GLOBAL_OPTS_WITH_VALUE: - index += 2 - else: - index += 1 - return "" - - -def variant(args: list[str]) -> str | None: - """Which git fact variant one `git ...` invocation needs.""" - words = [a for a in args if a] - sub = subcommand(words) - flags = [w for w in words if w.startswith("-")] - - if sub in ("fetch", "remote", "ls-remote", "push"): - return "remote" - if sub == "config": - return "remote" if any("remote." in w or "branch." in w for w in words) else "head" - if sub in ("status", "diff", "diff-index", "diff-files", "stash"): - return "status" - if sub in ("log", "show", "cat-file", "hash-object", "tag", "describe", "shortlog"): - return "log" - if sub == "merge-base": - return "ancestry" - if sub == "rev-list": - return "ancestry" if any(f.startswith(ANCESTRY_FLAGS) for f in flags) else "log" - if sub == "ls-files": - return "status" if any(f in ("-m", "-o", "--others", "--modified") for f in flags) else "tracked" - if sub in ("rev-parse", "symbolic-ref", "show-ref", "branch", "for-each-ref"): - if any(f in LOCATION_FLAGS for f in flags): - return "location" - return "head" - if sub in ("submodule", "worktree"): - return "location" - return None - - -def main() -> int: - rows = [] - for path in sorted(TASKS.iterdir()): - if not path.is_file(): - continue - source = path.read_bytes() - if not described_as_gate(source.decode("utf-8", "replace")): - continue - - heads: set[str] = set() - variants: set[str] = set() - for head, args in commands(source): - heads.add(head) - if head == "git": - found = variant(args) - if found: - variants.add(found) - - bucket = "tree" - for name, programs in BUCKETS: - if heads & programs: - bucket = name - break - - rows.append( - { - "task": path.name, - "bucket": bucket, - "variants": sorted(variants), - } - ) - - counts = collections.Counter(row["bucket"] for row in rows) - variant_counts: collections.Counter[str] = collections.Counter() - for row in rows: - if row["bucket"] == "git": - variant_counts.update(row["variants"]) - - out = sys.stdout - out.write("# What each gate-described `mise-tasks/` program invokes\n\n") - out.write( - "Generated by `bench/gates/classify.py`. Do not hand-edit.\n" - "Classified by COMMAND-POSITION invocation over a tree-sitter-bash parse,\n" - "so a token inside a comment or a string is not a hit\n" - "(`.claude/rules/scanning.md` row two; CLOUD-843's two passes disagreed\n" - "11/24/31/16 against 22/50/3/7 for exactly that reason).\n\n" - ) - out.write(f"- gate-described tasks: {len(rows)}\n") - for name in ("tree", "git", "build", "forge"): - out.write(f"- {name}: {counts.get(name, 0)}\n") - out.write("\n## The git bucket, by the fact variant each task needs\n\n") - out.write( - "A task appears once per variant it reads. The variant is decided from the\n" - "subcommand AND its flags: `rev-parse` is most of the corpus and is not one\n" - "question — `--git-dir` locates the repository, `HEAD` reads the current\n" - "commit, and a named ref resolves a declared one.\n\n" - ) - out.write("| variant | tasks |\n| --- | ---: |\n") - for name, count in sorted(variant_counts.items()): - out.write(f"| `{name}` | {count} |\n") - # WHICH TASKS NEED A FACT THAT DOES NOT EXIST YET, which is the number the - # campaign is actually scheduled against. `location` is the repository's own - # git dir and toplevel — the engine already resolves both before any rule - # runs — and `tracked` is `Fact::Tracked`, landed by CLOUD-846. A task whose - # whole git usage is those two needs no new fact at all, and counting it in - # the git bucket overstates the surface the fact model owes. - already = frozenset({"location", "tracked"}) - git_rows = [row for row in rows if row["bucket"] == "git"] - served = [row for row in git_rows if set(row["variants"]) <= already] - out.write("\n## What the git bucket actually owes the fact model\n\n") - out.write(f"- git-bucket tasks: {len(git_rows)}\n") - out.write( - f"- of those, served by facts that already exist " - f"(`location` + `Fact::Tracked`): {len(served)}\n" - ) - out.write(f"- needing a variant the engine cannot emit today: {len(git_rows) - len(served)}\n\n") - out.write("| git usage | tasks |\n| --- | ---: |\n") - shapes = collections.Counter( - ", ".join(f"`{v}`" for v in row["variants"]) or "—" for row in git_rows - ) - for shape, count in shapes.most_common(): - out.write(f"| {shape} | {count} |\n") - - out.write("\n## Every task\n\n") - out.write("| task | bucket | git variants |\n| --- | --- | --- |\n") - for row in rows: - variants = ", ".join(f"`{v}`" for v in row["variants"]) or "—" - out.write(f"| `{row['task']}` | {row['bucket']} | {variants} |\n") - return 0 - - -if __name__ == "__main__": - raise SystemExit(main()) diff --git a/crates/batten/examples/acquisition-bench.rs b/crates/batten/examples/acquisition-bench.rs new file mode 100644 index 000000000..9ed526ee4 --- /dev/null +++ b/crates/batten/examples/acquisition-bench.rs @@ -0,0 +1,72 @@ +//! Tree-surface acquisition cost as declared-document count scales (CLOUD-935). +//! +//! Retired out of `bench/acquisition/sweep.py` under CLOUD-1229, where it was 327 +//! lines of Python run by a one-line task under an interpreter nothing pinned. +//! +//! # Why an example target and not a verb +//! +//! `perf pair` is a verb, and this was written as its sibling first. The command +//! surface refused it, correctly: `crates/batten/tests/pointer_only.rs` sweeps +//! EVERY leaf verb over a bare fixture corpus and refuses one that exits `3`, +//! because "it failed internally, so what it did not emit proves nothing". A +//! sweep cannot satisfy that. It needs a benchmark runner and a built binary to +//! time, and in a bare corpus it has neither — so its only honest answer there is +//! could-not-look. `perf pair` passes that sweep because it has a real SKIP +//! predicate (a commit that cannot change what gets invoked cannot have made the +//! invocation slower); there is no analogue here, and manufacturing one to get +//! past a census would be exactly the false green this repository exists to +//! refuse. +//! +//! So the measurement is a target the surface does not carry: no verb, no +//! completion, no man page, and nothing for that census to be wrong about. What +//! it is NOT is a way around the workspace lints — an example is built by +//! `--all-targets`, so it is held to the same clippy bar as everything else. +//! +//! # Why the work is still in `crates/batten/src/perf.rs` +//! +//! This file spawns nothing. `policy/spawn-adapters.rego` decides which modules +//! may spawn by NAME RESOLUTION, and it places `perf` with a rationale that reads +//! as though written for this case: a harness whose whole subject is what an +//! external process costs, so the spawns are the thing rather than an +//! implementation of it. A sweep with its own `Command`, its own hyperfine +//! invocation and its own percentile convention would be an unplaced spawning +//! module AND a second authority over a record shape `perf-compare` already +//! reads. Sharing the module is what makes both unwritable. +//! +//! # Reading the output +//! +//! One `arm=` record per measured arm, then a `ratio=` per comparison, then the +//! `null-spread` those ratios must be read against, then the per-document term in +//! microseconds. A sweep number inside the null spread has measured *no effect*, +//! and that is a result rather than a failure to deliver. +//! +//! Exit 0 measured / 1 could not look. + +// The one sanctioned place to write to a stream: this target IS a binary +// boundary, exactly as `main.rs` is, and its whole output is the report. +#![allow(clippy::print_stdout, clippy::print_stderr)] + +use std::path::Path; + +fn main() -> std::process::ExitCode { + // `.` rather than a resolved toplevel: the task layer runs a task from the + // repository root, and `acquire` canonicalises before it resolves anything + // against it. A second repository-root resolver is the defect CLOUD-824 + // records one layer over, where a launcher asking git for `--show-toplevel` + // disagreed with the engine asking for the common dir. + match batten::perf::acquire(Path::new(".")) { + Ok(sweep) => { + print!("{sweep}"); + std::process::ExitCode::SUCCESS + } + // COULD NOT LOOK, in the `::error::` shape the workflow annotates, and + // never an empty sweep that exits 0. A bench harness reporting "measured, + // and there was nothing" over a run that never happened is the failure + // CLOUD-1208 hit twice in one session — once publishing a residue-free + // suite, once a null of 0.750. + Err(reason) => { + eprintln!("::error:: {reason}"); + std::process::ExitCode::FAILURE + } + } +} diff --git a/crates/batten/src/perf.rs b/crates/batten/src/perf.rs index cda13d876..336feb187 100644 --- a/crates/batten/src/perf.rs +++ b/crates/batten/src/perf.rs @@ -432,7 +432,7 @@ fn run(dir: &Path, program: &str, args: &[String], env: &[(String, String)]) -> } let status = command .status() - .with_context(|| format!("perf-pair: could not run {program}"))?; + .with_context(|| format!("perf: could not run {program}"))?; Ok(status.success()) } @@ -824,7 +824,7 @@ fn state_prefixed(state: &str, argv: &[String]) -> Vec { } /// One arm's record, with `perf`'s own percentile convention. -fn record(arm: &str, id: &'static str, result: &serde_json::Value) -> Result { +fn record(arm: &'static str, id: &str, result: &serde_json::Value) -> Result { let mut times: Vec = result .get("times") .and_then(serde_json::Value::as_array) @@ -862,7 +862,7 @@ fn record(arm: &str, id: &'static str, result: &serde_json::Value) -> Result Result, + ratios: Vec<(String, f64)>, + nulls: Vec, + per_document: Option<(f64, usize)>, +} + +fn round3(value: f64) -> f64 { + (value * 1000.0).round() / 1000.0 +} + +impl std::fmt::Display for Sweep { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + for record in &self.arms { + writeln!(f, "{record}")?; + } + for (label, value) in &self.ratios { + writeln!(f, "ratio={label} value={:.3}", round3(*value))?; + } + for (pair, value) in self.nulls.iter().enumerate() { + writeln!(f, "ratio=null{pair} value={:.3}", round3(*value))?; + } + if !self.nulls.is_empty() { + let low = self.nulls.iter().copied().fold(f64::INFINITY, f64::min); + let high = self.nulls.iter().copied().fold(f64::NEG_INFINITY, f64::max); + writeln!( + f, + "null-spread low={:.3} high={:.3} pairs={}", + round3(low), + round3(high), + self.nulls.len() + )?; + } + // THE PER-DOCUMENT TERM, which is the number the verdict is actually + // about. Reported rather than left to a reader with a calculator, and + // taken across the widest span in the sweep because that is where the + // fixed terms matter least. Microseconds, since milliseconds would round + // it to nothing. + if let Some((per_document, span)) = self.per_document { + writeln!(f, "per-document us={per_document:.2} over={span} documents")?; + } + Ok(()) + } +} + +/// Measure tree-surface acquisition cost as the declared-document count scales. +/// +/// # The experiment, and the confound it is built to avoid +/// +/// ONE rule, ONE bundle, ONE module — and the row's `documents` array is what +/// grows. A row PER document would have made every step of the sweep add a module +/// compile and an evaluation beside each read, so the curve would price four +/// things and get reported as one. Holding everything but the declared path count +/// fixed is what leaves acquisition as the only term that moves. +/// `crates/batten/tests/document_read_count.rs::one_row_declaring_n_paths_acquires_n_documents` +/// pins that the engine really does acquire once per declared path under exactly +/// this shape, because a sweep over a variable the engine ignores would still +/// draw a tidy curve. +/// +/// # The null is not optional +/// +/// Two IDENTICAL trees at the largest N, measured as a separate pair. Its ratio +/// is 1.0 plus pure noise by construction, which is what makes the spread a +/// measured quantity rather than a number in a comment — exactly how +/// `perf pair --null` derived the 0.966–1.102 spread `perf-compare`'s 1.30 +/// threshold clears. A sweep number inside the null spread has measured "no +/// effect", and that is a result rather than a failure to deliver. +/// +/// # Errors +/// +/// Every failure here is a property of the CHECKOUT rather than a verdict about +/// acquisition — a missing instrument, a binary nobody built, a fixture that +/// would not initialise — and each is an error rather than an empty measurement, +/// for [`pair`]'s reason. +pub fn acquire(repo: &Path) -> Result { + // ABSOLUTE FROM HERE DOWN, for `pair`'s measured reason: every arm runs + // hyperfine with the FIXTURE tree as its working directory, so a relative + // binary path resolves against the fixture and hyperfine dies before it times + // anything. + let repo = &repo + .canonicalize() + .with_context(|| format!("perf-acquire: could not resolve {}", repo.display()))?; + + if which("hyperfine").is_none() { + bail!( + "perf-acquire: hyperfine is not installed — run `mise install`; it is pinned in the manifest. Nothing measured." + ); + } + let binary = repo.join(env_or(BIN_VAR, DEFAULT_BIN)); + if !binary.is_file() { + bail!( + "perf-acquire: {} is missing — run `mise run build:release`. Nothing measured.", + binary.display() + ); + } + + let ns = declared_ns()?; + let out = acquire_out_dir(repo)?; + let null_pairs: usize = env_or(NULL_PAIRS_VAR, DEFAULT_NULL_PAIRS) + .parse() + .with_context(|| format!("perf-acquire: {NULL_PAIRS_VAR} is not a count"))?; + + // THE SWEEP, measured back to back on one machine so the noise the ratios + // divide out is the same noise. + let mut arms = Vec::new(); + let mut p50s = Vec::new(); + for n in &ns { + let tree = out.join(format!("tree-{n}")); + sweep_fixture(&tree, *n)?; + let record = measure_one("acquire", &format!("acquire-{n}"), &tree, &out, &binary)?; + p50s.push(record.p50); + arms.push(record); + } + + // THE NULL, AND IT IS A SPREAD RATHER THAN A NUMBER. Two identical trees at + // the largest N, built separately so each comparison is between two arms + // rather than an arm against itself — repeated, because ONE null ratio says + // nothing about how wide the noise is and a sweep ratio can only be read + // against a width. + let largest = ns.iter().copied().max().unwrap_or_default(); + let mut nulls = Vec::new(); + for pair in 0..null_pairs { + let mut sides = Vec::new(); + for side in ["a", "b"] { + let id = format!("null{pair}-{side}"); + let tree = out.join(&id); + sweep_fixture(&tree, largest)?; + let record = measure_one("null", &id, &tree, &out, &binary)?; + sides.push(record.p50); + arms.push(record); + } + let (first, second) = (sides[0], sides[1]); + if first <= 0.0 { + bail!("perf-acquire: null pair {pair} measured zero, so no ratio can be taken."); + } + nulls.push(second / first); + } + + let base = *p50s.first().unwrap_or(&0.0); + if base <= 0.0 { + bail!("perf-acquire: the base arm measured zero, so no ratio can be taken."); + } + let ratios = ns + .iter() + .zip(&p50s) + .skip(1) + .map(|(n, p50)| (format!("acquire-{n}/acquire-{}", ns[0]), p50 / base)) + .collect(); + + let span = largest.saturating_sub(ns[0]); + let per_document = (span > 0).then(|| { + #[expect( + clippy::cast_precision_loss, + reason = "a declared-document count is a small integer and this is a divisor, not a measurement" + )] + let width = span as f64; + ((p50s[p50s.len() - 1] - base) * 1000.0 / width, span) + }); + + Ok(Sweep { + arms, + ratios, + nulls, + per_document, + }) +} + +/// The declared sweep points, in order, with the first as the ratio base. +/// +/// Split from its environment read so the parse stays exercisable without one, +/// which is [`select`]'s split one concern over: a case that had to export +/// `BENCH_NS` would be asserting over process-global state that every other case +/// in the file shares. +fn parse_ns(declared: &str) -> Result> { + let ns: Vec = declared + .split(',') + .map(str::trim) + .filter(|entry| !entry.is_empty()) + .map(|entry| { + entry + .parse::() + .with_context(|| format!("perf-acquire: {NS_VAR} carries a non-count `{entry}`")) + }) + .collect::>()?; + if ns.is_empty() { + bail!("perf-acquire: {NS_VAR} declared no sweep points. Nothing measured."); + } + Ok(ns) +} + +/// [`parse_ns`] over what the environment declares. +fn declared_ns() -> Result> { + parse_ns(&env_or(NS_VAR, DEFAULT_NS)) +} + +/// The out directory this sweep owns, emptied first so a previous run's fixtures +/// and JSON can never be read as this one's. +fn acquire_out_dir(repo: &Path) -> Result { + let dir = repo + .join(env_or(OUT_DIR_VAR, DEFAULT_OUT_DIR)) + .join("acquire"); + if dir.exists() { + std::fs::remove_dir_all(&dir) + .with_context(|| format!("perf-acquire: could not clear {}", dir.display()))?; + } + std::fs::create_dir_all(&dir) + .with_context(|| format!("perf-acquire: could not create {}", dir.display()))?; + dir.canonicalize() + .with_context(|| format!("perf-acquire: could not resolve {}", dir.display())) +} + +/// A repository with one policy row declaring `n` distinct documents. +/// +/// **Public for [`select`]'s reason, which is the same reason one axis over**: the +/// measurement needs a benchmark runner and the `windows` job installs none, so a +/// case that ran the sweep would pass on two hosts and fail on the third. What +/// can be asserted everywhere is that the fixture this times is one the ENGINE +/// accepts — a generated authority that fails to load, or a module that refuses, +/// makes every arm time a broken tree and still draws a tidy curve. Exposing the +/// builder is what lets `tests/perf_acquire.rs` put the compiled binary over one +/// of these trees without a second spelling of the fixture. +/// +/// # Errors +/// +/// Any write that fails, or a `git init` that does — a fixture that did not +/// materialise is a could-not-look, never an arm measured over whatever was +/// there. +pub fn sweep_fixture(root: &Path, n: usize) -> Result<()> { + if root.exists() { + std::fs::remove_dir_all(root) + .with_context(|| format!("perf-acquire: could not clear {}", root.display()))?; + } + let bundle = root.join("policy-acquisition"); + std::fs::create_dir_all(&bundle) + .with_context(|| format!("perf-acquire: could not create {}", bundle.display()))?; + std::fs::write(bundle.join("gate.rego"), SWEEP_MODULE) + .context("perf-acquire: could not write the sweep module")?; + + let paths: Vec = (0..n).map(|index| format!("config{index}.toml")).collect(); + for path in &paths { + // Small and uniform. The cost being priced is the fixed per-document term + // — open, read, parse, cache — rather than a per-byte one, and a large + // file would measure the parser instead. Said out loud so the fixture does + // not grow by accretion. + std::fs::write(root.join(path), "quiet = true\n") + .with_context(|| format!("perf-acquire: could not write {path}"))?; + } + + // THE FLOOR ARM CARRIES NO ROW AND NO VERDICT, which is what makes it the + // floor: config load, trust resolution and the walk, and not one acquisition. + // A row declaring zero documents would still compile a module and put that + // cost into every baseline the ratios are taken against. The verdict row goes + // with it, and that is the REGISTRY's requirement rather than a choice: with + // no rule there is no module, so the token is unraised and a floor arm + // carrying the row would not load at all. + let authority = if n == 0 { + String::from("version = 1\n") + } else { + let declared = paths + .iter() + .map(|path| format!("\"{path}\"")) + .collect::>() + .join(", "); + format!( + "{SWEEP_AUTHORITY_HEAD}\n[[rule]]\nid = \"acquisition-bench\"\nkind = \"policy\"\n\ + scope = \"tree\"\nbundle = \"policy-acquisition/\"\ndocuments = [{declared}]\n\ + severity = \"deny\"\n" + ) + }; + std::fs::write(root.join("batten.toml"), authority) + .context("perf-acquire: could not write the fixture authority")?; + + // `git init` so the walk is a repository walk, matching every other fixture + // in this tree. No global or system config: a contributor's own git settings + // must not be able to change what is measured (CLOUD-282). + let args: Vec = ["init", "-q", "-b", "main"] + .iter() + .map(|arg| (*arg).to_owned()) + .collect(); + let env = vec![ + (String::from("GIT_CONFIG_GLOBAL"), String::from("/dev/null")), + (String::from("GIT_CONFIG_SYSTEM"), String::from("/dev/null")), + ]; + if !run(root, "git", &args, &env)? { + bail!( + "perf-acquire: could not initialise the fixture at {}. Nothing measured.", + root.display() + ); + } + Ok(()) +} + +/// One hyperfine run of `batten check` in `tree`, as a record. +/// +/// NO `-i`. Every arm's fixture is clean, so a non-zero exit means the binary +/// started failing rather than that the measurement is awkward — and a broken +/// path is still perfectly timeable, which is how it would otherwise be published +/// as a fast number. +fn measure_one( + arm: &'static str, + id: &str, + tree: &Path, + out: &Path, + binary: &Path, +) -> Result { + let json = out.join(format!("{id}.json")); + let args: Vec = vec![ + String::from("--warmup"), + env_or(WARMUP_VAR, DEFAULT_WARMUP), + String::from("--runs"), + env_or(RUNS_VAR, DEFAULT_RUNS), + String::from("--shell=none"), + String::from("--export-json"), + json.to_string_lossy().into_owned(), + String::from("--style"), + String::from("none"), + format!("{} check", binary.display()), + ]; + if !run(tree, "hyperfine", &args, &[])? { + bail!("perf-acquire: measuring arm {id} failed. No records."); + } + + let text = std::fs::read_to_string(&json) + .with_context(|| format!("perf-acquire: could not read arm {id}. No measurement."))?; + let parsed: serde_json::Value = serde_json::from_str(&text) + .with_context(|| format!("perf-acquire: arm {id} did not parse. No measurement."))?; + let result = parsed + .get("results") + .and_then(serde_json::Value::as_array) + .and_then(|results| results.first()) + .ok_or_else(|| anyhow::anyhow!("perf-acquire: arm {id} carried no results."))?; + record(arm, id, result) +} + #[cfg(test)] mod tests { use super::*; @@ -1016,4 +1452,83 @@ mod tests { assert!(message.contains("crates/"), "{message}"); assert!(message.contains("Cargo.lock"), "{message}"); } + + // --- the acquisition sweep (CLOUD-935, ported under CLOUD-1229) ---------- + + #[test] + fn the_sweep_points_are_read_in_the_order_they_were_declared() { + // The FIRST entry is the ratio base, so order is load-bearing rather than + // cosmetic: a parse that sorted or deduplicated would silently re-base + // every ratio the sweep prints. + let (Ok(swept), Ok(reversed)) = (parse_ns("1,16,64,256"), parse_ns("256, 1")) else { + panic!("a well-formed declaration parses"); + }; + assert_eq!(swept, vec![1, 16, 64, 256]); + assert_eq!(reversed, vec![256, 1]); + } + + #[test] + fn a_declaration_that_names_no_sweep_point_is_refused() { + // COULD-NOT-LOOK RATHER THAN AN EMPTY SWEEP. An empty list would print no + // arms, no ratios and exit 0 — a measurement that did not happen wearing + // a clean run's clothes, which is the one shape a bench harness must not + // produce (CLOUD-1208 measured this class twice). + assert!(parse_ns("").is_err()); + assert!(parse_ns(",,").is_err()); + assert!(parse_ns("1,many").is_err()); + } + + /// The rendered reading, byte for byte. + /// + /// House-style §6 applies to a bench verb's output too, and the fields here + /// are `Record`'s own plus three lines this harness adds. Pinning the bytes is + /// what stops the ratio precision or the field order drifting under a reader + /// who is diffing two runs. + #[test] + fn the_reading_renders_arms_then_ratios_then_the_spread_then_the_term() { + let arm = |path: &str, p50: f64| Record { + arm: "acquire", + path: path.to_owned(), + p50, + p95: 6.0, + mean: 5.0, + runs: 100, + }; + let sweep = Sweep { + arms: vec![arm("acquire-1", 4.75), arm("acquire-256", 6.12)], + ratios: vec![(String::from("acquire-256/acquire-1"), 6.12 / 4.75)], + nulls: vec![0.958, 1.022], + per_document: Some((5.37, 255)), + }; + assert_eq!( + sweep.to_string(), + "arm=acquire path=acquire-1 p50=4.75 p95=6 mean=5 runs=100\n\ + arm=acquire path=acquire-256 p50=6.12 p95=6 mean=5 runs=100\n\ + ratio=acquire-256/acquire-1 value=1.288\n\ + ratio=null0 value=0.958\n\ + ratio=null1 value=1.022\n\ + null-spread low=0.958 high=1.022 pairs=2\n\ + per-document us=5.37 over=255 documents\n" + ); + } + + #[test] + fn a_sweep_with_no_null_pairs_prints_no_spread_it_cannot_have() { + // ANTI-VACUITY on the line above. `null-spread` over an empty set would + // render `low=inf high=-inf`, which reads as a measured width and is the + // opposite of one — the fold's identities leaking into a published number. + let sweep = Sweep { + arms: Vec::new(), + ratios: Vec::new(), + nulls: Vec::new(), + per_document: None, + }; + assert_eq!(sweep.to_string(), ""); + } + + // The two cases over what `sweep_fixture` WRITES live in + // `crates/batten/tests/perf_acquire.rs` rather than here, and the reason is + // the workspace lint rather than a preference: reading a file back is a + // `Result`, and no module under `src/` waives `unwrap_used`. That builder is + // public for exactly this, so the assertion loses nothing by moving. } diff --git a/crates/batten/tests/acquisition_metric.rs b/crates/batten/tests/acquisition_metric.rs index b08683d89..a187e19ad 100644 --- a/crates/batten/tests/acquisition_metric.rs +++ b/crates/batten/tests/acquisition_metric.rs @@ -20,13 +20,19 @@ //! CLOUD-935 says the distinct stamp must be **asserted rather than assumed**, //! and this is that assertion. //! -//! # Why over `mise.toml` rather than over the helper +//! # Why over `mise.toml` rather than over the harness //! -//! The stamp is set by the task, not by the Python. A test reading the helper -//! would pass while the task that invokes it lost the variable — and the task is -//! the only caller, so the task is where the claim lives. +//! The stamp is set by the task, not by the measurement. A test reading the +//! harness would pass while the task that invokes it lost the variable — and the +//! task is the only caller, so the task is where the claim lives. //! `policy/command-task-defined.rego` already establishes `mise.toml` as a parsed //! document this repository reasons over; this is the same read in Rust. +//! +//! The harness was `bench/acquisition/sweep.py` until CLOUD-1229 retired it into +//! `crates/batten/examples/acquisition-bench.rs`. The anti-vacuity case below +//! moved with it, and moving it is the whole of what kept the case honest: it +//! names the invocation that actually runs the sweep, so a stamp set on some +//! other task cannot satisfy it. // Panicking on setup failure is the idiomatic way for a test to fail loudly. #![allow(clippy::unwrap_used, clippy::expect_used)] @@ -86,7 +92,7 @@ fn the_acquisition_series_is_stamped_with_its_own_metric() { fn the_stamp_is_set_on_the_task_that_runs_the_harness() { let body = task_body(); assert!( - body.contains("bench/acquisition/sweep.py"), + body.contains("--example acquisition-bench"), "the body carrying the stamp is the one invoking the measurement: {body}" ); } diff --git a/crates/batten/tests/acquisition_sweep.rs b/crates/batten/tests/acquisition_sweep.rs new file mode 100644 index 000000000..b78e9a028 --- /dev/null +++ b/crates/batten/tests/acquisition_sweep.rs @@ -0,0 +1,168 @@ +//! The acquisition sweep's contract, over the compiled engine (CLOUD-935, +//! CLOUD-1229). +//! +//! # Why this tier +//! +//! `crates/batten/src/perf.rs` unit-tests the parse and the rendering directly, +//! which is the right home for both: each is pure, and keeping them exercisable +//! without a benchmark runner is what lets them be asserted at all. The cases over +//! what the fixture builder WRITES are here instead, and for a lint reason rather +//! than a design one — reading a file back is a `Result`, and no module under +//! `src/` waives `unwrap_used`. +//! +//! What those cases cannot establish is the thing the whole measurement rests on: +//! **that the generated fixture is a tree the ENGINE accepts.** A `[[verdict]]` +//! row nothing raises, a module publishing the wrong rule name, a `documents` +//! array the engine never reads — every one of those makes `batten check` refuse +//! or no-op, and every arm then times a broken tree and still draws a tidy curve. +//! `.claude/rules/policy-modules.md` names that class: a dead gate and a clean +//! tree are byte-identical on the decision surface, and only a case over the +//! compiled binary tells them apart. +//! +//! # What is deliberately not here, and why it is not a gap +//! +//! The sweep itself is not run. It needs hyperfine, and `crates/batten/src/perf.rs` +//! records the measurement behind that: **the `windows` job installs none**, so a +//! case that ran the sweep would pass on two hosts and fail on the third — which +//! is exactly how `a_skip_exits_zero_and_prints_no_record` was once broken. The +//! same fact is why the harness is `crates/batten/examples/acquisition-bench.rs` +//! rather than a `perf` sub-verb: `tests/pointer_only.rs` sweeps every leaf verb +//! over a bare corpus and refuses one that exits 3, and could-not-look is the only +//! honest answer a sweep has there. +//! +//! # What this replaced, and why there is no ledger arm for it +//! +//! `bench/acquisition/sweep.py` is retired here under CLOUD-1229. It was 327 lines +//! of Python driven by a one-line task, and its own header argued the shape was +//! forced by `shell-retirement` refusing an added shell rule. A second author read +//! that argument and added a third helper for the identical stated reason +//! (CLOUD-1208). The campaign's subject is authored SHELL because that is what it +//! was built to retire — a statement about its reach, never a licence for what +//! sits beside it. +//! +//! It carries **no** `// changed:` marker, and that absence is the point rather +//! than an omission. Those arms are `shell-retirement`'s and `[rule.conserves]`'s +//! ledger over a governed file's death, and the deleted path was governed by +//! neither — not under `mise-tasks/`, not a `.bats` suite, watched by nothing. +//! Writing an arm for it would put a row in a ledger whose subject it never was. +//! The helper also carried no test tier of its own; it was a script with a +//! docstring, and what moved is the reasoning in that docstring, into the doc +//! comments on `perf::acquire` and `perf::sweep_fixture` and into the cases here +//! and in `perf.rs`'s own module. + +// Panicking on setup failure is the idiomatic way for a test to fail loudly. +#![allow(clippy::unwrap_used, clippy::expect_used)] + +mod common; + +use common::{Fixture, run, stderr, stdout}; + +#[test] +fn the_generated_fixture_is_a_tree_the_engine_accepts() { + // THE LOAD-BEARING CASE, and the reason this file exists. Every arm of the + // sweep times `batten check` over one of these trees, so a fixture the engine + // refuses is a measurement of the refusal — and a fixture whose row the engine + // never reads is a measurement of nothing, reported at three decimal places. + // + // Built through the harness's OWN builder rather than re-spelled here: a + // second spelling of the fixture is a second authority, and the two can + // disagree about exactly the thing this asserts. + let root = Fixture::new("perf-acquire-fixture").git().build(); + let tree = root.join("swept"); + batten::perf::sweep_fixture(&tree, 4).expect("the sweep's own fixture builder"); + + let output = run(&tree, &["check"]); + assert!( + output.status.success(), + "the swept fixture must be a tree `check` accepts, or every arm times a \ + refusal: {}", + stderr(&output) + ); +} + +/// ANTI-VACUITY for the case above, and it is the half that discriminates. +/// +/// `check` exits 0 over a tree with no rules at all, so the success above proves +/// nothing on its own — a builder that wrote an empty `batten.toml` would satisfy +/// it, and so would one whose `documents` array the engine never read. That +/// second one is the defect `.claude/rules/policy-modules.md` records from the +/// field: OpenTelemetry's `weaver` printed `✔ No policy violation`, exit 0, over a +/// knowingly-broken registry, because its module read a key the schema never +/// built. +/// +/// So this drives the predicate from the other side. The module fires on a +/// declared document carrying a `stray` key; the generated documents carry none, +/// which is why every arm is clean. Put the key into ONE of them and the finding +/// has to appear — which can only happen if the row loaded, the declared path was +/// acquired, and the module read the acquired node. +#[test] +fn the_swept_row_reads_the_documents_it_declares() { + let root = Fixture::new("perf-acquire-registered").git().build(); + let tree = root.join("swept"); + batten::perf::sweep_fixture(&tree, 4).expect("the sweep's own fixture builder"); + std::fs::write(tree.join("config2.toml"), "quiet = true\nstray = true\n") + .expect("seed the sentinel the module fires on"); + + let output = run(&tree, &["check"]); + assert_eq!( + output.status.code(), + Some(2), + "a seeded sentinel is a policy verdict: {}", + stderr(&output) + ); + let said = stdout(&output) + &stderr(&output); + assert!( + said.contains("acquisition-bench"), + "the swept row must be the one that fired — anything else means the sweep \ + is timing a rule that never reads its documents: {said}" + ); + assert!( + said.contains("config2.toml"), + "and it must point at the seeded document, not at the row: {said}" + ); +} + +#[test] +fn the_fixture_declares_exactly_the_documents_it_was_asked_for() { + // The confound the experiment is built to avoid, asserted rather than trusted: + // ONE rule, ONE bundle, ONE module, and only the `documents` array grows. A + // builder that added a row per document would still draw a tidy curve while + // pricing a module compile and an evaluation at every step. + let root = Fixture::new("perf-acquire-shape").git().build(); + let tree = root.join("swept"); + batten::perf::sweep_fixture(&tree, 3).expect("the sweep's own fixture builder"); + + let authority = + std::fs::read_to_string(tree.join("batten.toml")).expect("the fixture authority"); + assert_eq!(authority.matches("[[rule]]").count(), 1, "{authority}"); + assert!( + authority.contains(r#"documents = ["config0.toml", "config1.toml", "config2.toml"]"#), + "{authority}" + ); + assert!(tree.join("policy-acquisition/gate.rego").is_file()); + assert!(tree.join("config2.toml").is_file()); + assert!(!tree.join("config3.toml").exists()); +} + +#[test] +fn the_floor_arm_carries_neither_a_rule_nor_the_verdict_it_would_raise() { + // Both halves in one case, because they are one requirement: `[[verdict]]` runs + // in BOTH directions, so a floor arm declaring the class with no rule to raise + // it would fail the load outright and time nothing at all. + let root = Fixture::new("perf-acquire-floor").git().build(); + let tree = root.join("swept"); + batten::perf::sweep_fixture(&tree, 0).expect("the sweep's own fixture builder"); + + let authority = + std::fs::read_to_string(tree.join("batten.toml")).expect("the fixture authority"); + assert!(!authority.contains("[[rule]]"), "{authority}"); + assert!(!authority.contains("V-ACQUISITION-BENCH"), "{authority}"); + + let output = run(&tree, &["check"]); + assert!( + output.status.success(), + "the floor arm must load and run, or the baseline every ratio is taken \ + against is a refusal: {}", + stderr(&output) + ); +} diff --git a/crates/batten/tests/dev_profile.rs b/crates/batten/tests/dev_profile.rs index 5b9982ec7..912596bf4 100644 --- a/crates/batten/tests/dev_profile.rs +++ b/crates/batten/tests/dev_profile.rs @@ -103,7 +103,7 @@ fn the_dependency_closure_carries_no_debuginfo() { .and_then(|profile| profile.get("dev")) .and_then(|dev| dev.get("package")) .and_then(|package| package.get(DEPENDENCY_GLOB)) - .map(|glob| declared_debug(glob)) + .map(declared_debug) .expect( "[profile.dev.package.\"*\"] is declared — without it every dependency \ carries debuginfo again and the linked binaries go back to ~124 MB", diff --git a/mise.toml b/mise.toml index bdc25a7a7..0854bf9a5 100644 --- a/mise.toml +++ b/mise.toml @@ -1267,21 +1267,46 @@ description = "Measure tree-surface acquisition cost as declared-document count # until a number says otherwise" — and names the condition: bring a number about # RESOLUTION rather than projection. This is the harness that brings it. # -# AN INLINE BODY OVER A `mise-tasks/*.sh` PROGRAM, and that is forced rather than -# stylistic: `policy/shell-retirement.rego` refuses ADDING an authored shell rule -# at `deny` (`V-SHELL-RULE-ADDED`) with one `document` route and no override and -# no `bypass_env`. `[tasks.semver]`, `[tasks.prose-only-check]` and -# `[tasks.policy-test]` are inline for that same reason. The measurement itself -# lives in `bench/acquisition/sweep.py`, beside `bench/gates/classify.py` — the -# standing example of a Python bench helper in this tree. -# -# UNDER `bench/`, NOT `mise-tasks/`, and that is a correction rather than a -# preference. mise makes every executable under `mise-tasks/` a file task named -# by its basename AND its stem, so a helper there would have published a SECOND -# entry point — `mise run acquisition-bench` resolving to the bare script, with no -# `BENCH_METRIC` set and therefore stamping the invocation series' default. The -# assertion below would still have passed, over a task nobody ran. `bench/` is not -# a task directory, so there is exactly one way in. +# THE MEASUREMENT IS `batten perf acquire`, AND IT USED TO BE PYTHON (CLOUD-1229). +# This comment used to argue that `bench/acquisition/sweep.py` was forced: an +# authored shell rule cannot be ADDED (`V-SHELL-RULE-ADDED`, one `document` route, +# no override, no `bypass_env`), so the measurement went to the one language the +# retirement campaign does not watch. That reading was wrong in a way this line +# then propagated — a second author read it, followed the precedent for the +# identical stated reason, and added a third helper (CLOUD-1208). The campaign's +# subject is authored SHELL because that is what it was built to retire; that is a +# statement about its reach, never a licence for what sits beside it. +# +# So the sweep moved into `crates/batten/src/perf.rs`, which is where the paired +# measurement already lives and is the module `policy/spawn-adapters.rego` already +# places for exactly this class — a harness whose whole subject is what an +# EXTERNAL process costs, so the spawns are the thing rather than an +# implementation of it. It also takes the unpinned interpreter with it: `python` +# was never in `[tools]`, so every helper ran under whatever the host happened to +# have while `lock-complete` held every declared tool to three platforms. +# +# AN EXAMPLE TARGET RATHER THAN A VERB, and that is a refusal honoured rather than +# a preference. It was written as `perf acquire` first; +# `crates/batten/tests/pointer_only.rs` sweeps EVERY leaf verb over a bare fixture +# corpus and refuses one that exits 3, because "it failed internally, so what it +# did not emit proves nothing" — and a sweep with no benchmark runner and no built +# binary to time has could-not-look as its only honest answer there. `perf pair` +# survives that sweep because it has a real SKIP predicate; there is no analogue +# here, and inventing one to satisfy a census is the false green these gates exist +# to catch. `crates/batten/examples/acquisition-bench.rs` is the entry point, it +# spawns nothing, and `--all-targets` holds it to the same clippy bar as the rest. +# +# THE TASK BODY STAYS INLINE AND STAYS ONE LINE, which is the half of the old +# argument that survives: `inline-task-bodies-not-growing` holds the count of +# multi-line task bodies non-increasing, so the alternative was never a bigger +# body here. +# +# AND THIS COMMENT DELIBERATELY DOES NOT SPELL THAT ROW'S PATTERN. An earlier +# revision quoted the literal opener the ratchet counts, and the ratchet counted +# the comment — 31 to 32, refused, over a change that added no body at all. It is +# a substring pass, so a token inside a comment is a hit, which is the class +# `.claude/rules/scanning.md` records from CLOUD-843's two disagreeing passes. +# Describe the row here; do not write its needle. # # BENCH_METRIC IS THE LOAD-BEARING LINE. `mise-tasks/perf-record.sh` reads it from # the environment and stamps it into every series entry, defaulting to @@ -1295,8 +1320,12 @@ description = "Measure tree-surface acquisition cost as declared-document count # OFF THE LANDING PATH, like `perf` itself: it builds a release binary and spends # minutes in hyperfine, and it answers a question about a measurement rather than # about a commit. Nothing in `verify` or the hk gate calls it. +# `build:release` stays a dependency even though `cargo run --example` builds the +# example itself: what the sweep TIMES is the release `batten` binary, and an +# example target does not build it. Dropping this line makes every arm answer +# could-not-look on a clean tree. depends = ["build:release"] -run = "BENCH_METRIC=acquisition-wall-clock ./bench/acquisition/sweep.py" +run = "BENCH_METRIC=acquisition-wall-clock cargo run --quiet --release -p batten --example acquisition-bench" [tasks."install:local"] description = "Put the built binary where the hook registrations resolve it — `install.sh`'s own destination"