diff --git a/TODO.md b/TODO.md index 42c30c3..f31cf8b 100644 --- a/TODO.md +++ b/TODO.md @@ -300,6 +300,23 @@ The long pole, and the reason `helm-core` does no I/O. Tracked as that never had any - and an ejected MekWarrior is written as another entity in the same file, so a force has to tell people from machines. +- [x] **A ratchet for speed, not just for answers.** `performance.txt` records + what each operation costs and the test fails anything a fifth worse. + `conformance.txt` catches a wrong answer; nothing caught a dependency + swapped for a slower one, a lookup that became a scan, or a parser that + started allocating per line. + + Two things make the figures steady enough to assert on. Every task is + timed in each round rather than one task to completion, so a busy minute + costs all of them a round instead of making one look slow. And each keeps + its fastest round, because a shared machine has a floor and no ceiling. + Run-to-run drift is then under a tenth, against a gate of a fifth. + + Held only in release: an unoptimised build is several times slower and + the two sets of figures are not comparable, so a debug run prints them + and checks nothing. `HELM_PERF_BLESS=1` re-records, and a commit that + moves a figure should say why. + - [ ] **Zero unregistered disagreements.** Whatever is left after the above is either our bug or theirs, and theirs gets written down by name the way the Alpha Strike specials deviation is. diff --git a/crates/helm-bv/performance.txt b/crates/helm-bv/performance.txt new file mode 100644 index 0000000..9f440b5 --- /dev/null +++ b/crates/helm-bv/performance.txt @@ -0,0 +1,13 @@ +# What each operation costs, in nanoseconds, fastest of several rounds of a +# release build. +# +# A figure more than a fifth worse than these fails the performance test. +# Re-record with HELM_PERF_BLESS=1, and say in the commit why it moved. +# +# These are one machine's numbers. Another machine needs its own. + +parse a .mul 1909 +write a .mul 3001 +read a design 122784 +score a design 197382 +score a damaged design 198490 diff --git a/crates/helm-bv/tests/performance.rs b/crates/helm-bv/tests/performance.rs new file mode 100644 index 0000000..fb73170 --- /dev/null +++ b/crates/helm-bv/tests/performance.rs @@ -0,0 +1,231 @@ +//! What the work costs, held to what it cost yesterday. +//! +//! Not a benchmark suite - it answers one question: has something got +//! materially slower? A dependency swapped for a "better" one, a lookup that +//! became a scan, a parse that started allocating per line. All of those are +//! invisible in a conformance report, which only asks whether the answers are +//! right. +//! +//! `performance.txt` beside this file is the ratchet, the way `conformance.txt` +//! is for the answers. A figure more than a fifth worse than the recorded one +//! fails; `HELM_PERF_BLESS=1` writes the current figures down. +//! +//! Two things make the numbers steady enough to assert on. Each measurement is +//! the *fastest* of several runs rather than the average, because a machine +//! shared with other work has a floor and no ceiling - the fastest run is the +//! one that was least interrupted. And each run repeats the operation enough +//! times that a clock tick is noise. +//! +//! The figures are still this machine's, and a release build's - an +//! unoptimised one is several times slower and is printed rather than checked. +//! Moving to another machine means blessing them again. + +use std::path::PathBuf; +use std::time::{Duration, Instant}; + +/// How much worse than the recorded figure is a failure. +const TOLERANCE: f64 = 1.20; +/// How many rounds every measurement is taken over; each keeps its fastest. +const RUNS: u32 = 7; + +struct Inputs { + library: helm_unitfile::Library, + catalogue: helm_core::Catalogue, +} + +fn inputs() -> Option { + let mm = PathBuf::from(std::env::var("HELM_MEGAMEK").ok()?); + let bridge = PathBuf::from(std::env::var("HELM_BRIDGE").ok()?); + let file = std::fs::File::open(mm.join("data/mekfiles/unit_files.zip")).ok()?; + Some(Inputs { + library: helm_unitfile::read_zip(file).ok()?, + catalogue: helm_bridge::read_catalogue(&bridge.join("equipment.jsonl")).ok()?, + }) +} + +fn report_path() -> PathBuf { + PathBuf::from(env!("CARGO_MANIFEST_DIR")).join("performance.txt") +} + +/// One thing being timed. +struct Task<'a> { + what: &'static str, + /// How many times to repeat it per round, so a clock tick is noise. + iterations: u32, + work: Box, +} + +/// Time every task, keeping each one's fastest round. +/// +/// Round robin rather than one task at a time: this machine is shared, and a +/// busy minute that lands entirely inside one measurement makes that operation +/// look slow and the others look fine. Timing all of them in each round means +/// a busy minute costs every task a round, and each still has its own best one +/// to be judged on. +fn measure(tasks: &mut [Task<'_>]) -> Vec<(&'static str, Duration)> { + let mut best: Vec = vec![Duration::MAX; tasks.len()]; + // A warm-up round, thrown away: the first touches cold caches. + for round in 0..=RUNS { + for (i, task) in tasks.iter_mut().enumerate() { + let start = Instant::now(); + for _ in 0..task.iterations { + (task.work)(); + } + let each = start.elapsed() / task.iterations; + if round > 0 { + best[i] = best[i].min(each); + } + } + } + tasks.iter().map(|t| t.what).zip(best).collect() +} + +#[test] +#[ignore = "needs a MegaMek install and a bridge dump; set HELM_MEGAMEK and HELM_BRIDGE"] +fn nothing_has_got_materially_slower() { + let Some(inputs) = inputs() else { + panic!("set HELM_MEGAMEK to a MegaMek install and HELM_BRIDGE to a bridge dump"); + }; + + let atlas = inputs + .library + .units + .iter() + .find(|u| u.display_name() == "Atlas AS7-D") + .expect("the library has an Atlas AS7-D"); + let mul = helm_unitfile::write_mul(&helm_unitfile::Mul { + units: vec![helm_unitfile::MulUnit { + chassis: "Atlas".into(), + model: "AS7-D".into(), + gunnery: 4, + piloting: 5, + armor: [("CT".to_string(), 3)].into_iter().collect(), + ..Default::default() + }], + }); + let damaged = helm_bv::Condition { + armor: [("CT".to_string(), 3)].into_iter().collect(), + ..helm_bv::Condition::undamaged() + }; + + let measured = measure(&mut [ + Task { + what: "parse a .mul", + iterations: 2000, + work: Box::new(|| { + std::hint::black_box(helm_unitfile::parse_mul(&mul).ok()); + }), + }, + Task { + what: "write a .mul", + iterations: 2000, + work: Box::new(|| { + let parsed = helm_unitfile::parse_mul(&mul).unwrap(); + std::hint::black_box(helm_unitfile::write_mul(&parsed)); + }), + }, + Task { + what: "read a design", + iterations: 500, + work: Box::new(|| { + std::hint::black_box(helm_bv::Mek::read(atlas, &inputs.catalogue).ok()); + }), + }, + Task { + what: "score a design", + iterations: 500, + work: Box::new(|| { + std::hint::black_box(helm_bv::battle_value(atlas, &inputs.catalogue).ok()); + }), + }, + Task { + what: "score a damaged design", + iterations: 500, + work: Box::new(|| { + std::hint::black_box( + helm_bv::battle_value_in(atlas, &inputs.catalogue, &damaged).ok(), + ); + }), + }, + ]); + + // Debug is several times slower than release and the two sets of figures + // are not comparable: blessing in one profile and checking in the other + // would fail everything for no reason. Only release is held to the mark. + if cfg!(debug_assertions) { + println!("{}", render(&measured)); + println!( + "unoptimised build, so these are not compared. \ + Run with --release to hold them to performance.txt." + ); + return; + } + + let report = render(&measured); + if std::env::var("HELM_PERF_BLESS").is_ok() { + std::fs::write(report_path(), &report).expect("write performance.txt"); + println!("blessed:\n{report}"); + return; + } + + let Ok(recorded) = std::fs::read_to_string(report_path()) else { + panic!("no performance.txt; run once with HELM_PERF_BLESS=1 to record one"); + }; + let recorded = parse_recorded(&recorded); + + let mut slower = Vec::new(); + println!( + "{:<26} {:>10} {:>10} {:>8}", + "", "recorded", "now", "change" + ); + for (what, took) in &measured { + let now = took.as_secs_f64() * 1e9; + let Some(before) = recorded.get(*what) else { + println!("{what:<26} {:>10} {now:>10.0} {:>8}", "-", "new"); + continue; + }; + let change = now / before; + println!( + "{what:<26} {before:>10.0} {now:>10.0} {:>7.0}%", + (change - 1.0) * 100.0 + ); + if change > TOLERANCE { + slower.push(format!( + "{what} takes {now:.0}ns against {before:.0}ns recorded, {:.0}% worse", + (change - 1.0) * 100.0 + )); + } + } + assert!( + slower.is_empty(), + "slower than recorded by more than a fifth:\n {}\n\ + If the change is wanted, re-record with HELM_PERF_BLESS=1 and say why in the commit.", + slower.join("\n ") + ); +} + +fn render(measured: &[(&str, Duration)]) -> String { + let mut out = String::from( + "# What each operation costs, in nanoseconds, fastest of several rounds of a\n\ + # release build.\n\ + #\n\ + # A figure more than a fifth worse than these fails the performance test.\n\ + # Re-record with HELM_PERF_BLESS=1, and say in the commit why it moved.\n\ + #\n\ + # These are one machine's numbers. Another machine needs its own.\n\n", + ); + for (what, took) in measured { + out.push_str(&format!("{what:<26} {:.0}\n", took.as_secs_f64() * 1e9)); + } + out +} + +fn parse_recorded(text: &str) -> std::collections::BTreeMap { + text.lines() + .filter(|l| !l.trim_start().starts_with('#') && !l.trim().is_empty()) + .filter_map(|l| { + let at = l.rfind(char::is_whitespace)?; + Some((l[..at].trim().to_string(), l[at..].trim().parse().ok()?)) + }) + .collect() +}