diff --git a/.github/release-notes/v2.3.1.md b/.github/release-notes/v2.3.1.md new file mode 100644 index 00000000..d3d1d42f --- /dev/null +++ b/.github/release-notes/v2.3.1.md @@ -0,0 +1,87 @@ +RustyNES **v2.3.1 "Plumb Line"** is a measurement release. It makes the +performance apparatus trustworthy and then uses it — and what it found is that +**none of the ten hot-path candidates it measured yielded a shippable +improvement.** That is a claim about those ten, not about the core as a whole: +two core leads the campaign surfaced (the APU at 18.7% of frame, and `range.rs` +inlined inside `Ppu::tick` at 1.52%) remain **unmeasured** and are carried +forward. + +**No emulation-core changes.** AccuracyCoin holds at **exactly 141/141** and +nestest is 0-diff, verified after every experimental probe was reverted rather +than merely asserted by construction: this release did land and remove real +edits. + +## Why a measurement release + +Two failures in the preceding release motivated it. + +- **v2.3.0's adopted PPU optimization measured `+2%` on a contended host and + `−5.13%` re-measured quiet** — the same commit, opposite sign. The project's + adopt/reject bar is only as good as the host it runs on, and nothing noticed + the host. +- **The profile the campaign was scoped from does not contain the APU.** + `perf report` shows zero `rustynes_apu::` symbols at any percent limit, because + fat LTO inlines the APU wholesale into `cpu_clock`. The working split + "PPU ~53%, CPU+bus ~39%" had folded roughly a fifth of the frame into the wrong + bucket. + +## New measurement tooling + +| tool | what it revealed | +| --- | --- | +| `frame_probe` — harness-free frame cost | criterion's own rayon / `exp` / sort work was **~17% of every profile** | +| `frame_breakdown.sh` — attribution by source file | the **APU is 18.7% of frame time**; `perf report --inline` does *not* recover it | +| `ab_check.sh` — adoption A/B with an A/B/A order-bias control | the reference drifts up to **−1.17% from run position alone** | + +Corrected subsystem split: **PPU 52.1% · APU 18.7% · CPU 10.1% · bus/scheduler +coupling 9.9% · std inlined at call sites 6.7% · mappers 2.5%.** The CPU proper +is about a third of what the symbol profile implied. + +`bench_relative_check.sh` additionally declines to emit a verdict when the host +was too noisy to resolve the effect under test, keyed on a robust MAD-based +coefficient of variation. + +## Ten candidates measured, ten rejected + +| mechanism | items | +| --- | --- | +| LLVM already performs the transformation | sink dead per-dot derivations | +| the premise is factually false | `repr(Rust)` ignores source order; the named functions were already inlined | +| real work, absorbed off the critical path | the `index_framebuffer` store; the open-bus decay loop; the ALE/read recompute | +| the elision is real but buys nothing | typed-index bounds elision | +| the target is too small to matter | the `bg_split_state` capability gate (0.09% of frame) | +| forbidden by the ownership model | hoisting `PpuBusAdapter` (borrow checker, with no `unsafe` permitted) | + +Six distinct mechanisms, which is what makes this a finding rather than one bad +assumption repeated: **the per-dot loop has no incidental overhead left to +reclaim.** Its ~3.78 ms is work the accuracy model requires. That corroborates +the existing record, where bounds-check elision and a SIMD blitter both measured +*slower*. + +## Two near-misses + +Worth recording, because each would have shipped on a single reading: + +- One candidate produced a textbook **−1.84% … −2.75% at p = 0.00 on all four + workloads** — entirely an order-bias artifact. It measured as exactly zero on + re-run. This is what prompted the A/B/A control. +- Another measured **−0.51% at p = 0.00 on a shipped configuration** with a clean + control, then **+0.01% (p = 0.96)** on re-run. + +Both were caught only by requiring an independent second run. + +## Also in this release + +- The PGO workflow's BOLT probe no longer reports success without BOLT. It ran + `apt-get install bolt` and trusted the exit status — but on Ubuntu that package + is the **Thunderbolt 3 device manager**, so the stage failed on the tool it had + just "confirmed" instead of skipping as its best-effort contract intends. +- Every rejected experiment is recorded in `docs/performance.md` with its + numbers, its order-bias control, and the mechanism behind the null result. + +## Verification + +- `cargo test --workspace --features test-roms` green — AccuracyCoin **141/141**, + `visual_regression` 9/9, nestest 0-diff. +- Workspace clippy clean at `-D warnings`; `cargo fmt --all --check` clean. +- `shellcheck` clean on every touched script. diff --git a/.github/workflows/pgo.yml b/.github/workflows/pgo.yml index d9972fbd..05bc5ecc 100644 --- a/.github/workflows/pgo.yml +++ b/.github/workflows/pgo.yml @@ -266,13 +266,91 @@ jobs: - name: Install cargo-pgo run: cargo install cargo-pgo --locked + # Probe for llvm-bolt by LOCATING THE BINARY, never by trusting a package + # manager's exit code. + # + # The previous form did `apt-get install -y bolt` and set have_bolt=true if + # that succeeded. On Ubuntu the package named `bolt` is the **Thunderbolt 3 + # device manager** — an unrelated project that happens to own the name. apt + # installed it, exited 0, the probe reported success, and the stage then + # died on `Cannot find llvm-bolt: cannot find binary path` (run + # 31006334399). A "best-effort" job that is supposed to SKIP when the tool + # is missing instead failed the whole run. + # + # LLVM ships the binary as `llvm-bolt` (apt.llvm.org's `bolt-` packages) + # or versioned under /usr/lib/llvm-/bin, so search all of those and + # export the directory on PATH for `cargo pgo`, which resolves `llvm-bolt` + # by name. Verifying the binary exists is what makes the skip honest. - name: Probe for llvm-bolt id: bolt_probe run: | - if command -v llvm-bolt >/dev/null 2>&1; then - echo "have_bolt=true" >> "$GITHUB_OUTPUT" - elif sudo apt-get update && sudo apt-get install -y --no-install-recommends bolt; then + # NOT `set -e`: this step probes for things that are allowed to be + # absent. A missing tool must SKIP the stage, not fail the run. + set -uo pipefail + # PURE discovery: echoes the path of an llvm-bolt binary, or nothing. + # It does not install, symlink, or otherwise touch the host — a probe + # that mutates state as a side effect of looking is hard to reason + # about and hard to re-run. Linking is a separate, explicit step below. + # + # ENUMERATE the versioned installs rather than probing a fixed version + # window: a hard-coded `for v in 21 .. 16` reports "not found" on any + # image shipping a version outside it, indistinguishable from "BOLT is + # not installed" — the failure mode this whole probe exists to + # eliminate. Globs that match nothing expand to the literal pattern, + # which the `-x` test rejects. + find_bolt_bin() { + if command -v llvm-bolt >/dev/null 2>&1; then + command -v llvm-bolt; return 0 + fi + for cand in /usr/bin/llvm-bolt-* /usr/local/bin/llvm-bolt-* \ + /usr/lib/llvm-*/bin/llvm-bolt; do + [ -x "${cand}" ] || continue + printf '%s\n' "${cand}"; return 0 + done + return 1 + } + + # cargo-pgo resolves the UNVERSIONED name, so a versioned hit needs a + # symlink. Kept separate from discovery, and reporting failure rather + # than assuming success: without the `|| return 1` and the + # executability re-check, a FAILED link still yielded a directory and + # a success status — the same "assume it worked" bug, one level down. + link_bolt() { + _bin="$1" + case "${_bin}" in + */llvm-bolt) dirname "${_bin}"; return 0 ;; # already unversioned + esac + sudo ln -sf "${_bin}" /usr/local/bin/llvm-bolt || return 1 + [ -x /usr/local/bin/llvm-bolt ] || return 1 + echo /usr/local/bin + } + + find_bolt() { + _found="$(find_bolt_bin)" || return 1 + link_bolt "${_found}" + } + + bolt_dir="$(find_bolt || true)" + if [ -z "${bolt_dir}" ]; then + # Try to install it, then LOOK AGAIN — an install succeeding proves + # nothing about which project's `bolt` landed on disk. + sudo apt-get update >/dev/null 2>&1 || true + # Candidate package names only — the loop re-probes after EACH one + # and stops at the first that actually yields a binary, so an + # unlisted name costs a skip, never a false positive. + for pkg in llvm-bolt bolt-21 bolt-20 bolt-19 bolt-18 bolt-17 \ + llvm-21-tools llvm-20-tools llvm-19-tools llvm-18-tools; do + sudo apt-get install -y --no-install-recommends "$pkg" >/dev/null 2>&1 || continue + bolt_dir="$(find_bolt || true)" + [ -n "${bolt_dir}" ] && break + done + fi + + if [ -n "${bolt_dir}" ]; then + echo "${bolt_dir}" >> "$GITHUB_PATH" echo "have_bolt=true" >> "$GITHUB_OUTPUT" + echo "llvm-bolt found: $(command -v llvm-bolt || echo "${bolt_dir}/llvm-bolt")" \ + >> "$GITHUB_STEP_SUMMARY" else echo "have_bolt=false" >> "$GITHUB_OUTPUT" echo "llvm-bolt unavailable on this runner — skipping BOLT stage." >> "$GITHUB_STEP_SUMMARY" @@ -303,33 +381,61 @@ jobs: scripts/pgo/run.sh "$PGO_FRAMES" cargo pgo bolt optimize -- -p rustynes-frontend + # DISABLED (v2.3.1) — these two steps cannot measure what they claim, and + # one of them silently reported a fabricated number. Run 31067782333 is the + # evidence: the probe and runtime fixes above made BOLT genuinely work + # (instrument + optimize both succeeded for the first time), which finally + # exposed what the gate downstream was doing. + # + # 1. `cargo pgo bolt optimize` takes NO cargo subcommand. Its usage is + # `cargo pgo bolt optimize [OPTIONS] [-- ...]`, unlike + # `cargo pgo optimize` (the PGO side) which does accept `bench`/`test`. + # Both steps were written by analogy with the PGO stage and both are + # rejected: `unexpected argument 'bench' found` / `'test' found`. + # + # 2. The bench step swallowed that with `|| cargo bench ...`, so it fell + # back to a PLAIN (non-BOLT) build, computed a speedup against the plain + # baseline, and wrote it to the summary as "BOLT speedup vs plain + # release". It compared plain against plain. The step reported SUCCESS. + # Had that ratio landed above the 3% bar, the gate would have promoted a + # BOLT binary on a measurement containing no BOLT. + # + # 3. Even with the CLI corrected, the design does not hold: BOLT optimizes + # the `rustynes` FRONTEND binary, while the gate benches + # `rustynes-core`'s `full_frame` criterion bench — a different binary + # BOLT never touched. Measuring BOLT honestly needs a harness that runs + # inside the optimized artifact (`frame_probe` built as part of it), not + # a core bench built separately. + # + # Left disabled rather than patched: a gate that cannot measure its subject + # is worse than no gate, and #2 shows this one could actively mislead. The + # instrument/optimize steps above still prove BOLT runs end to end, and the + # artifact is still produced. Re-enable behind a harness that benches the + # BOLT-optimized binary itself. - name: BOLT full_frame bench + gate - if: steps.bolt_probe.outputs.have_bolt == 'true' + if: false run: | - cargo pgo bolt optimize bench -- -p rustynes-core --bench full_frame -- \ - --warm-up-time 1 --measurement-time 5 --save-baseline bolt || \ - cargo bench -p rustynes-core --bench full_frame -- \ - --warm-up-time 1 --measurement-time 5 --save-baseline bolt - bolt_est="target/criterion/nes_run_frame_nestest/bolt/estimates.json" - bolt_ns="$(python3 -c "import json,sys;print(int(json.load(open(sys.argv[1]))['mean']['point_estimate']))" "$bolt_est")" - speedup="$(python3 -c "print(f'{(1 - ${bolt_ns}/${BASE_NS})*100:.2f}')")" - { - echo "### BOLT post-link gate" - echo "BOLT speedup vs plain release: ${speedup}% (threshold > ${PGO_MIN_SPEEDUP_PCT}%)" - } >> "$GITHUB_STEP_SUMMARY" - python3 -c "import sys; sys.exit(0 if ${speedup} > ${PGO_MIN_SPEEDUP_PCT} else 1)" || { - echo "BOLT did not beat the > ${PGO_MIN_SPEEDUP_PCT}% bar — not promoting." >> "$GITHUB_STEP_SUMMARY" - exit 0 - } + echo "disabled — see the comment above (run 31067782333)" - name: Determinism oracle (BOLT codegen) - if: steps.bolt_probe.outputs.have_bolt == 'true' - run: cargo pgo bolt optimize test -- --workspace --release --features test-roms + if: false + run: | + echo "disabled — see the comment above (run 31067782333)" + # The artifact must be the BOLT output, not whatever `rustynes` happens to + # be sitting in target/. `path: target/**/release/rustynes` matched the + # PGO binary that `scripts/pgo/run.sh` had already written, so an artifact + # named `rustynes-pgo-bolt` contained NO BOLT — the same mislabelling as + # the bench gate above, which reported a plain build as a BOLT speedup. + # + # `cargo pgo bolt optimize` writes `rustynes-bolt-optimized` alongside the + # plain binary. `if-no-files-found: error` rather than `warn`: if the file + # is absent the correct outcome is a visible failure, not a quietly empty + # artifact that looks like a successful BOLT build. - name: Upload BOLT binary if: steps.bolt_probe.outputs.have_bolt == 'true' uses: actions/upload-artifact@v7 with: - name: rustynes-pgo-bolt - path: target/**/release/rustynes - if-no-files-found: warn + name: rustynes-bolt-optimized + path: target/**/release/rustynes-bolt-optimized + if-no-files-found: error diff --git a/CHANGELOG.md b/CHANGELOG.md index 1edca775..dcbd9bc4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,50 @@ cycle-accurate core later replaced. ## [Unreleased] +## [2.3.1] - 2026-08-06 - "Plumb Line" (measurement apparatus + ten measured rejections) + +### Performance + +- **No emulation-core changes. Ten hot-path optimization candidates were + measured and all ten rejected**, through six distinct mechanisms: LLVM already + performed the transformation; the item's premise was factually false; the work + was real but absorbed off the critical path; the elision was real but bought + nothing; the target was too small to matter; the ownership model forbids it. + Full numbers, controls and reasoning are in `docs/performance.md` + (entries G1–G10). **AccuracyCoin remains at exactly 141/141 and nestest + 0-diff**, verified after every experimental probe was reverted. +- New measurement tooling, all of which found something the previous apparatus + could not: + - `crates/rustynes-test-harness/src/bin/frame_probe.rs` — harness-free + steady-state frame cost, with no criterion in the process image (criterion's + own rayon/`exp`/sort work had been ~17% of every profile). + - `scripts/perf/frame_breakdown.sh` — per-subsystem attribution by **source + file**, which recovers work the symbol profile hides. It shows the **APU at + 18.7% of frame time**, invisible under `perf report` because fat LTO inlines + it wholesale into `cpu_clock` (`perf report --inline` does not recover it). + - `scripts/perf/ab_check.sh` — adoption A/B with an **A/B/A order-bias + control**: the reference is benched a third time, last, against its own first + run, so drift from position-in-the-run is reported rather than mistaken for a + result. +- `scripts/bench_relative_check.sh` now declines to emit a verdict when the host + was too noisy to resolve the effect it tests for, keyed on a robust + MAD-based coefficient of variation. + +### Fixed + +- **The PGO workflow's BOLT probe reported success without BOLT present.** It ran + `apt-get install bolt` and trusted the exit status — but on Ubuntu that package + is the *Thunderbolt 3 device manager*, an unrelated project that owns the name. + The stage then failed on the tool it had just "confirmed", instead of skipping + as its best-effort contract intends. The probe now locates the actual + `llvm-bolt` binary and reports honestly when it is absent. + +### Documentation + +- `docs/performance.md` records every rejected experiment with its numbers, its + order-bias control, and the mechanism behind the null result — including two + near-misses that a single measurement would have adopted. + ## [2.3.0] - 2026-08-05 - "Datum II" (PPU-accuracy capstone + true multi-viewport tool windows) Closes the **v2.2.6 → v2.3.0 NESdev-remediation line**. Both remaining diff --git a/Cargo.lock b/Cargo.lock index 3fa79858..dc4113d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4290,7 +4290,7 @@ dependencies = [ [[package]] name = "rustynes-android" -version = "2.3.0" +version = "2.3.1" dependencies = [ "android-activity", "android_logger", @@ -4308,7 +4308,7 @@ dependencies = [ [[package]] name = "rustynes-apu" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bitflags 2.13.1", "criterion", @@ -4321,7 +4321,7 @@ dependencies = [ [[package]] name = "rustynes-cheevos" -version = "2.3.0" +version = "2.3.1" dependencies = [ "cc", "ureq", @@ -4329,7 +4329,7 @@ dependencies = [ [[package]] name = "rustynes-core" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bitflags 2.13.1", "criterion", @@ -4346,7 +4346,7 @@ dependencies = [ [[package]] name = "rustynes-cpu" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bitflags 2.13.1", "criterion", @@ -4357,7 +4357,7 @@ dependencies = [ [[package]] name = "rustynes-frontend" -version = "2.3.0" +version = "2.3.1" dependencies = [ "anstyle", "arboard", @@ -4411,11 +4411,11 @@ dependencies = [ [[package]] name = "rustynes-gfx-shaders" -version = "2.3.0" +version = "2.3.1" [[package]] name = "rustynes-hdpack" -version = "2.3.0" +version = "2.3.1" dependencies = [ "lewton", "png", @@ -4426,7 +4426,7 @@ dependencies = [ [[package]] name = "rustynes-ios" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bytemuck", "cpal", @@ -4440,7 +4440,7 @@ dependencies = [ [[package]] name = "rustynes-libretro" -version = "2.3.0" +version = "2.3.1" dependencies = [ "libc", "rust-libretro", @@ -4449,7 +4449,7 @@ dependencies = [ [[package]] name = "rustynes-mappers" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bitflags 2.13.1", "criterion", @@ -4461,7 +4461,7 @@ dependencies = [ [[package]] name = "rustynes-mobile" -version = "2.3.0" +version = "2.3.1" dependencies = [ "rustynes-core", "rustynes-hdpack", @@ -4476,7 +4476,7 @@ dependencies = [ [[package]] name = "rustynes-netplay" -version = "2.3.0" +version = "2.3.1" dependencies = [ "futures-util", "js-sys", @@ -4492,7 +4492,7 @@ dependencies = [ [[package]] name = "rustynes-ppu" -version = "2.3.0" +version = "2.3.1" dependencies = [ "bitflags 2.13.1", "criterion", @@ -4504,14 +4504,14 @@ dependencies = [ [[package]] name = "rustynes-ra" -version = "2.3.0" +version = "2.3.1" dependencies = [ "rustynes-cheevos", ] [[package]] name = "rustynes-script" -version = "2.3.0" +version = "2.3.1" dependencies = [ "mlua", "piccolo", @@ -4522,7 +4522,7 @@ dependencies = [ [[package]] name = "rustynes-test-harness" -version = "2.3.0" +version = "2.3.1" dependencies = [ "insta", "png", diff --git a/Cargo.toml b/Cargo.toml index d895755c..2667f94c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -32,7 +32,7 @@ members = [ default-members = ["crates/rustynes-libretro"] [workspace.package] -version = "2.3.0" +version = "2.3.1" edition = "2024" rust-version = "1.96" license = "GPL-3.0-or-later" diff --git a/VERSION-PLAN.md b/VERSION-PLAN.md index 9baa9b15..02a727cf 100644 --- a/VERSION-PLAN.md +++ b/VERSION-PLAN.md @@ -1,6 +1,6 @@ # RustyNES Version Plan -**Current release: v2.3.0 "Datum II"** — the capstone that **closes** the v2.2.6 → v2.3.0 line (true multi-viewport OS-window detach, the emulator-lock frame-pacing fix, a −5.1% byte-identical PPU optimization, and both forum-reported accuracy items verified already-correct) — all on the **v2.0.0 "Timebase"** MAJOR base (the one-clock / every-cycle-bus-access scheduler rewrite). **v1.0.0** was the first stable, production cut. As of **v2.2.9**, RustyNES is **GPL-3.0-or-later** — a derivative work of GPL-licensed emulators (ADR 0036); a licensing correction, **not** a SemVer break (no public-API or save-state change). `docs/STATUS.md` is the authoritative current-state record; `CHANGELOG.md` carries the full per-release history. +**Current release: v2.3.1 "Plumb Line"** — the measurement release: the apparatus made trustworthy and then used, producing **ten measured rejections and no emulation-core changes** (AccuracyCoin exactly 141/141). Built on **v2.3.0 "Datum II"**, the capstone that **closed** the v2.2.6 → v2.3.0 line (true multi-viewport OS-window detach, the emulator-lock frame-pacing fix, a −5.1% byte-identical PPU optimization, and both forum-reported accuracy items verified already-correct) — all on the **v2.0.0 "Timebase"** MAJOR base (the one-clock / every-cycle-bus-access scheduler rewrite). **v1.0.0** was the first stable, production cut. As of **v2.2.9**, RustyNES is **GPL-3.0-or-later** — a derivative work of GPL-licensed emulators (ADR 0036); a licensing correction, **not** a SemVer break (no public-API or save-state change). `docs/STATUS.md` is the authoritative current-state record; `CHANGELOG.md` carries the full per-release history. RustyNES follows [Semantic Versioning 2.0.0](https://semver.org/). @@ -55,7 +55,7 @@ The cycle-accurate engine was integrated as the core in a sequence of documentar | **v0.9.7** | Performance pass (display-sync pacing, dedicated emu thread, audio DRC, run-ahead) | | **v1.0.0** | Production cut — engine + ported desktop UX shell + documentation synthesis | -> **Engine lineage note.** The deep technical history under `docs/` (the `v2.0` master-clock refactor, ADRs, audit logs, the long accuracy program) describes the **upstream engine lineage**. Those old "v1.x"/"v2.x" anchors are engineering history, **not** RustyNES release versions. RustyNES's own release line is v0.1.0 → v0.8.6 → (documentary v0.9.0–v0.9.7) → **v1.0.0** → the v1.1.0–v1.10.0 additive feature line → **v2.0.0 "Timebase"** (the designated MAJOR break) → the v2.0.x "Harbor" line → the v2.1.x "Fathom" accuracy line → the v2.2.x line → **v2.3.0 "Datum II"** (current). +> **Engine lineage note.** The deep technical history under `docs/` (the `v2.0` master-clock refactor, ADRs, audit logs, the long accuracy program) describes the **upstream engine lineage**. Those old "v1.x"/"v2.x" anchors are engineering history, **not** RustyNES release versions. RustyNES's own release line is v0.1.0 → v0.8.6 → (documentary v0.9.0–v0.9.7) → **v1.0.0** → the v1.1.0–v1.10.0 additive feature line → **v2.0.0 "Timebase"** (the designated MAJOR break) → the v2.0.x "Harbor" line → the v2.1.x "Fathom" accuracy line → the v2.2.x line → v2.3.0 "Datum II" → **v2.3.1 "Plumb Line"** (current). ### Post-1.0 release line (v1.1.0 → current) @@ -76,9 +76,10 @@ The 1.x line was **additive / off-by-default** — every release stayed byte-ide | **v2.2.1 – v2.2.5** | Housekeeping (v2.2.1); build / distribution / CI-integrity — libretro buildbot + supply-chain hardening (v2.2.2 "Conduit"); performance + accuracy-closure (v2.2.3 "Datum"); libretro/RetroArch distribution (v2.2.4 "Cartridge"); provenance / licensing / documentation integrity (v2.2.5 "Colophon") | | **v2.2.6 – v2.2.9** | The **de-monetization + NESdev-remediation** line — RustyNES made permanently open-source and income-free (v2.2.6 "Almanac", ADR 0035); expansion-audio fidelity (v2.2.7 "Timbre II"); gamma-correct presentation (v2.2.8 "Aperture II"); TAS/movie wiring + detachable tool windows + the **relicense to GPL-3.0-or-later** (v2.2.9 "Studio II", ADR 0036) | | **v2.2.9 "Studio II"** | TAS/movie wiring + the GPL-3.0-or-later relicense — see `CHANGELOG.md` `[2.2.9]` | -| **v2.3.0 "Datum II"** (current) | Head of the v2.x line; **closes** the v2.2.6 → v2.3.0 remediation line. PPU-accuracy capstone — SMB left-edge + hybrid-address (Rad Racer) verified already-correct against the AccuracyCoin oracle and locked with an exact-141/141 regression gate; hybrid-address provenance finalized (doc/oracle-derived); true multi-viewport OS-window detach; the emulator-lock frame-pacing fix; a −5.1% byte-identical PPU optimization — see `CHANGELOG.md` `[2.3.0]` | +| **v2.3.0 "Datum II"** | Head of the v2.x line; **closes** the v2.2.6 → v2.3.0 remediation line. PPU-accuracy capstone — SMB left-edge + hybrid-address (Rad Racer) verified already-correct against the AccuracyCoin oracle and locked with an exact-141/141 regression gate; hybrid-address provenance finalized (doc/oracle-derived); true multi-viewport OS-window detach; the emulator-lock frame-pacing fix; a −5.1% byte-identical PPU optimization — see `CHANGELOG.md` `[2.3.0]` | +| **v2.3.1 "Plumb Line"** (current) | Measurement apparatus made trustworthy, then used: a harness-free frame probe, per-source-file subsystem attribution (which recovers the **APU at 18.7% of frame**, invisible in the symbol profile), an adoption A/B with an A/B/A order-bias control, and a contention-aware relative gate. **Ten core hot-path candidates measured, all ten rejected** via six distinct mechanisms — **no emulation-core changes**, AccuracyCoin exactly 141/141 — see `CHANGELOG.md` `[2.3.1]` | -> **Forward path.** The v2.0.x "Harbor", v2.1.x "Fathom", and v2.2.x lines have all shipped; the v2.2.6 → v2.3.0 line has now **closed** with v2.3.0 "Datum II"; no successor line is locked (the v2.3.1 → v2.3.4 performance campaign is planned, not committed). RustyNES is **permanently open-source and income-free** (ADR 0035): the earlier "joint Google Play + App Store + AltStore + F-Droid launch" is **withdrawn** — any store listing is a **free** app with **no monetization** (no ads, tracking, or paid unlock), an unversioned later step. `to-dos/ROADMAP.md` is the authoritative forward roadmap. +> **Forward path.** The v2.0.x "Harbor", v2.1.x "Fathom", and v2.2.x lines have all shipped; the v2.2.6 → v2.3.0 line has now **closed** with v2.3.0 "Datum II"; the v2.3.x performance campaign is under way as **three releases, not four**: **v2.3.1 "Plumb Line"** (current) absorbs both the measurement apparatus and the core hot-path campaign, whose ten items were all measured and all rejected and so had no shippable content of their own; **v2.3.2 "Grain"** is the frontend / coupling / display work formerly called "Conduit II"; **v2.3.3 "Lucid"** the novel features. RustyNES is **permanently open-source and income-free** (ADR 0035): the earlier "joint Google Play + App Store + AltStore + F-Droid launch" is **withdrawn** — any store listing is a **free** app with **no monetization** (no ads, tracking, or paid unlock), an unversioned later step. `to-dos/ROADMAP.md` is the authoritative forward roadmap. ## Versioning guidelines diff --git a/crates/rustynes-ppu/src/ppu.rs b/crates/rustynes-ppu/src/ppu.rs index 634cfb91..e97919e8 100644 --- a/crates/rustynes-ppu/src/ppu.rs +++ b/crates/rustynes-ppu/src/ppu.rs @@ -598,6 +598,12 @@ pub struct Ppu { /// after a rollback/restore rebased that counter. Storing `now - timestamp` /// (and reconstructing `now - age` on load, relative to the live counter) keeps /// a run-ahead / netplay `snapshot`→`restore` byte-identical to the forward run. + /// + /// Field POSITION here is not performance-relevant, and this was measured + /// rather than assumed (v2.3.1 G2, `docs/performance.md`): neither adding + /// `#[repr(C)]` nor moving this 256-byte cold array to the end of the struct + /// produced a reproducible change on any workload. `Ppu` is ~2.8 KB and stays + /// L1-resident across a frame, so layout has little left to buy. pub(crate) oam_decay_cycles: [u64; 32], /// Master enable for the OAM-decay model. **`false` by default** — a frontend / /// config knob (re-applied on load like `region` / `active_palette`), NOT part @@ -1929,6 +1935,13 @@ impl Ppu { // (≈ 1,073,447 CPU cycles at NTSC, rounded to one million). This is // conservative but well within the window the `ppu_open_bus` test // cares about. + // NOTE (v2.3.1 G5): reformulating this as a deadline comparison instead + // of a per-cycle decrement was measured by DELETING the loop outright — + // the ceiling any reformulation could reach — and the ceiling is ZERO. + // ~29,780 calls/frame sounds expensive; it is three predictable + // compare-and-decrement steps on data already in L1, which an + // out-of-order core absorbs entirely. Do not re-attempt; see + // `docs/performance.md`. let mut i = 0; while i < 3 { if self.open_bus_decay[i] > 0 { @@ -3984,6 +3997,15 @@ impl Ppu { // Parallel palette-index output for the `NES_NTSC` composite filter // (T-110-A1). Same `(emphasis << 6) | colour` value, in index space; // `off` is the RGBA byte offset, so `off >> 2` is the pixel index. + // NOTE (v2.3.1 G4): making this store conditional on a consumer wanting + // it was measured by deleting it outright — the ceiling any opt-in gate + // could reach — and the ceiling is ZERO on the shipped configuration. + // `perf` attributes ~0.78% to this line, but a line's sample share is not + // its marginal cost: this is a sequential `u16` store the store buffer + // absorbs off the critical path, so removing it frees nothing and the + // samples simply redistribute. Not worth the correctness hazard of + // gating a buffer the NTSC filter, the mobile API, `fast_dotloop_diff` + // and a unit test all read. See `docs/performance.md`. self.index_framebuffer[off >> 2] = lut_idx as u16; // v1.2.0 C3 (hd-pack): record the CHR tile that produced this pixel, @@ -4181,6 +4203,11 @@ impl Ppu { if cycle == 0 { return; } + // NOTE (v2.3.1 G3): pushing these two below the `cycle < 65` early-out + // as well — they are dead across the dots 1..=64 clear window — was + // measured and produced NO change on any workload across two runs. LLVM + // already sinks pure computations past branches that do not use them. + // Do not re-attempt as a performance change; see `docs/performance.md`. let sprite_height: i16 = if self.ctrl.contains(PpuCtrl::SPRITE_SIZE_16) { 16 } else { @@ -4333,6 +4360,12 @@ impl Ppu { // this by using -1 as the y-test reference, which makes // `-1 - y < 0` for all OAM y values, so the y-test always // fails at pre-render and scanline 0 sees no sprites. + // + // NOTE (v2.3.1 G3): sinking these two to their single use site in the + // `65..=256` arm — they are dead on 149 of 341 dots — was measured and + // produced NO change on any workload across two runs. LLVM already sinks + // pure computations past branches that do not use them. Do not re-attempt + // as a performance change; see `docs/performance.md`. let next_line: i16 = if self.scanline == self.region.prerender_line() { -1 } else { diff --git a/crates/rustynes-test-harness/Cargo.toml b/crates/rustynes-test-harness/Cargo.toml index 9907ba83..b7fbea23 100644 --- a/crates/rustynes-test-harness/Cargo.toml +++ b/crates/rustynes-test-harness/Cargo.toml @@ -119,6 +119,16 @@ name = "dump_battery_ram" path = "src/bin/dump_battery_ram.rs" required-features = ["test-roms"] +# v2.3.1 "Plumb Line" — harness-free steady-state frame-cost probe. Profile THIS +# instead of the criterion bench: a `perf record` of the bench binary attributes +# ~17% of samples to criterion itself (rayon plumbing, libm exp, its sorts), +# which skews every per-function percentage. Reports median/p99/CV plus an +# explicit host-quiet verdict, because a number measured on a contended machine +# is worse than no number — it looks like data. +[[bin]] +name = "frame_probe" +path = "src/bin/frame_probe.rs" + # v2.0.0 beta.2 (A2 scoping) — burn-loop histogram probe: prints the # per-opcode busless-cycle counts (`Cpu::burn_histogram`) that the # every-cycle-bus-access conversion must turn into dummy reads. See diff --git a/crates/rustynes-test-harness/src/bin/frame_probe.rs b/crates/rustynes-test-harness/src/bin/frame_probe.rs new file mode 100644 index 00000000..a7716d53 --- /dev/null +++ b/crates/rustynes-test-harness/src/bin/frame_probe.rs @@ -0,0 +1,312 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +//! v2.3.1 "Plumb Line" — a harness-free frame-cost probe. +//! +//! ## Why this exists +//! +//! The criterion `full_frame` bench is the project's headline number and the +//! input to both CI gates and the PGO promotion gate — but it is a poor thing to +//! *profile*. A `perf record` of the bench binary attributes roughly **17% of +//! samples to criterion itself**: `rayon` plumbing for its parallel analysis, +//! `libm`'s `exp` from the distribution fitting, and its sorts. That noise sits +//! on top of every per-function percentage and silently skews attribution when +//! deciding which hot path to attack next. +//! +//! This probe runs the same workload with **no criterion in the process image**: +//! load a ROM, run frames in a tight steady-state loop, report wall-clock cost. +//! Profile *this* binary and every sample belongs to the emulator. +//! +//! It is deliberately NOT a replacement for the criterion suite. Criterion still +//! owns adopt/reject verdicts because it does the statistics properly; this owns +//! profiling and quick iteration. +//! +//! ## Host-quiet reporting +//! +//! A performance verdict measured on a contended machine is worse than no +//! verdict, because it looks like data. The v2.3.0 P1 campaign hit exactly this: +//! its first profile ran at **39% criterion outliers** and the second, on a quiet +//! host, at 2% — same code, same binary. So this probe reports spread +//! (median / p99 / a robust MAD-based coefficient of variation) alongside the +//! headline number and prints an explicit verdict on whether the host looked +//! quiet enough to trust. It never hides a noisy measurement behind a mean. +//! +//! ## Usage +//! +//! ```text +//! frame_probe # default corpus, 600 frames each +//! frame_probe --frames 1800 # longer steady state +//! frame_probe --rom path/to.nes # explicit ROM (repeatable) +//! frame_probe --warmup 120 # frames discarded before timing +//! ``` +//! +//! Typical profiling use: +//! +//! ```text +//! cargo build --release -p rustynes-test-harness --bin frame_probe --features test-roms +//! perf record -F 1200 --call-graph=dwarf -- \ +//! target/release/frame_probe --rom tests/roms/nestest/nestest.nes --frames 3000 +//! perf report --no-children +//! ``` + +use std::path::PathBuf; +use std::time::Instant; + +use rustynes_core::Nes; + +/// Default corpus: the two ROMs the criterion `full_frame` bench and both CI +/// gates use, so the probe's numbers are directly comparable to the gate's. +/// `nestest` is the CPU/bus-leaning workload; `flowing_palette` is the +/// render-heavy one. +const DEFAULT_CORPUS: &[&str] = &[ + "tests/roms/nestest/nestest.nes", + "tests/roms/assorted/flowing_palette.nes", +]; + +/// Frames discarded before timing starts, so the measurement covers steady +/// state rather than boot, first-frame allocation, and cold caches. +const DEFAULT_WARMUP: u32 = 120; + +/// Timed frames per ROM. +const DEFAULT_FRAMES: u32 = 600; + +/// One NTSC frame at 60.0988 Hz, milliseconds — the deadline every reported +/// figure is measured against. +const NTSC_FRAME_MS: f64 = 16.639; + +/// Above this robust coefficient of variation the host is too noisy for the +/// numbers to support an adopt/reject decision. Chosen against the measured +/// back-to-back noise floor of ~0.7% on a quiet host (see +/// `scripts/bench_relative_check.sh`), with headroom so ordinary desktop jitter +/// does not cry wolf. +const QUIET_CV_PCT: f64 = 2.5; + +/// Per-ROM timing summary. All values are nanoseconds per emulated frame. +struct Summary { + label: String, + median: f64, + p99: f64, + min: f64, + /// Robust coefficient of variation: `1.4826 * MAD / median`, as a percent. + /// Median-absolute-deviation rather than stddev because a handful of + /// scheduler preemptions should not dominate the spread estimate. + cv_pct: f64, + frames: u32, +} + +/// Nearest-rank percentile of an already-sorted slice. +/// +/// Integer arithmetic rather than a float `ceil`, so there is no cast in either +/// direction: `rank = ceil(q_num * len / q_den)` computed exactly. `q_num/q_den` +/// is the quantile as a rational (e.g. 99/100 for p99), which is all this probe +/// ever needs and avoids the truncation/precision lints entirely. +fn percentile(sorted: &[f64], q_num: usize, q_den: usize) -> f64 { + if sorted.is_empty() { + return 0.0; + } + let rank = (q_num * sorted.len()).div_ceil(q_den); + sorted[rank.saturating_sub(1).min(sorted.len() - 1)] +} + +fn summarize(label: String, mut samples: Vec) -> Summary { + samples.sort_by(f64::total_cmp); + let median = percentile(&samples, 1, 2); + let mut dev: Vec = samples.iter().map(|s| (s - median).abs()).collect(); + dev.sort_by(f64::total_cmp); + let mad = percentile(&dev, 1, 2); + let cv_pct = if median > 0.0 { + 1.4826 * mad / median * 100.0 + } else { + 0.0 + }; + Summary { + label, + median, + p99: percentile(&samples, 99, 100), + min: samples.first().copied().unwrap_or(0.0), + cv_pct, + frames: u32::try_from(samples.len()).unwrap_or(u32::MAX), + } +} + +/// Time `frames` steady-state frames of one ROM, returning per-frame ns. +fn probe(bytes: &[u8], warmup: u32, frames: u32) -> Result, String> { + let mut nes = Nes::from_rom(bytes).map_err(|e| format!("{e:?}"))?; + for _ in 0..warmup { + nes.run_frame(); + } + let mut samples = Vec::with_capacity(frames as usize); + for _ in 0..frames { + let t0 = Instant::now(); + let fb = nes.run_frame(); + // Keep the frame observably used so the optimizer cannot elide the work. + // `Nes::framebuffer()` is a borrow, so this costs a length read. + std::hint::black_box(fb.len()); + // `as_secs_f64() * 1e9` rather than `as_nanos() as f64`: a frame is far + // below the f64-exact integer range either way, but this keeps the cast + // lints satisfied without an allow. + samples.push(t0.elapsed().as_secs_f64() * 1.0e9); + } + Ok(samples) +} + +/// Parse a `u32` CLI count, exiting with a usage error rather than falling back +/// to a default. `require_positive` additionally rejects zero. +/// +/// A measurement tool must not quietly substitute a different input than the one +/// it was asked for — the number it prints would then describe a run the caller +/// never requested. Concretely, `--frames 0` previously parsed, produced an +/// empty sample set, and reported a 0.00% CV ("host: QUIET"), a 0 ms median and +/// an infinite realtime multiplier: a confident-looking measurement of nothing. +/// Exit code 2 marks a usage error, distinct from a probe that ran. +fn parse_count(value: Option<&str>, flag: &str, require_positive: bool) -> u32 { + let Some(raw) = value else { + eprintln!("frame_probe: {flag} requires a value"); + std::process::exit(2); + }; + let Ok(n) = raw.parse::() else { + eprintln!("frame_probe: {flag} expects a non-negative integer, got {raw:?}"); + std::process::exit(2); + }; + if require_positive && n == 0 { + eprintln!("frame_probe: {flag} must be greater than zero"); + std::process::exit(2); + } + n +} + +/// Workspace root, resolved from the **compile-time** manifest directory. +/// +/// This is only used to locate the DEFAULT ROM corpus. `CARGO_MANIFEST_DIR` is +/// baked in at build time, so a binary copied away from its build tree resolves +/// to a path that no longer exists — which is why the default-corpus loop below +/// reports each missing ROM by path and then exits non-zero with +/// `no ROMs measured`, rather than silently measuring an empty set. Pass +/// `--rom ` explicitly when running a relocated binary. +fn workspace_root() -> PathBuf { + PathBuf::from(env!("CARGO_MANIFEST_DIR")) + .parent() + .and_then(|p| p.parent()) + .expect("workspace root is two levels above the crate manifest") + .to_path_buf() +} + +fn main() { + let mut frames = DEFAULT_FRAMES; + let mut warmup = DEFAULT_WARMUP; + let mut roms: Vec = Vec::new(); + + let mut args = std::env::args().skip(1); + while let Some(arg) = args.next() { + match arg.as_str() { + // Reject rather than silently fall back to the default. `--frames 0` + // used to be accepted and produced an empty sample set, which then + // reported a 0.00% CV ("host: QUIET"), a 0 ms median, and an + // infinite realtime multiplier — a confident-looking measurement of + // nothing, which is the exact failure mode this probe exists to + // avoid. A typo'd `--frames 60O` deserves the same treatment. + "--frames" => frames = parse_count(args.next().as_deref(), "--frames", true), + // Warmup MAY legitimately be zero, so only the parse is enforced. + "--warmup" => warmup = parse_count(args.next().as_deref(), "--warmup", false), + // Same contract as the count flags: a flag with no value is a usage + // error, not a silent no-op. `--rom` with a missing path used to + // drop the flag and fall back to the DEFAULT corpus, so the probe + // measured something other than what was asked for and said nothing. + "--rom" => { + let Some(p) = args.next() else { + eprintln!("frame_probe: --rom requires a path"); + std::process::exit(2); + }; + roms.push(PathBuf::from(p)); + } + "--help" | "-h" => { + println!( + "frame_probe [--frames N] [--warmup N] [--rom PATH]...\n\n\ + Harness-free steady-state frame cost. Profile this binary\n\ + instead of the criterion bench so samples are not diluted by\n\ + criterion's own rayon/exp/sort work (~17% of the bench profile)." + ); + return; + } + // A typo'd flag must NOT fall through to a default run. `--frmaes + // 400` previously printed a warning and then measured the default + // 600-frame corpus, reporting a number for a run nobody asked for — + // the same "measured something else and said nothing" failure the + // count-flag validation above exists to prevent. + other => { + eprintln!("frame_probe: unknown argument {other:?}"); + eprintln!("frame_probe: see --help for accepted flags"); + std::process::exit(2); + } + } + } + + let root = workspace_root(); + if roms.is_empty() { + roms = DEFAULT_CORPUS.iter().map(|r| root.join(r)).collect(); + } + + println!("frame_probe — {frames} timed frames/ROM after {warmup} warmup frames\n"); + + let mut summaries = Vec::new(); + for rom in &roms { + let label = rom + .file_stem() + .map_or_else(|| rom.display().to_string(), |s| s.to_string_lossy().into()); + let bytes = match std::fs::read(rom) { + Ok(b) => b, + Err(e) => { + eprintln!("skip {}: {e}", rom.display()); + continue; + } + }; + match probe(&bytes, warmup, frames) { + Ok(samples) => summaries.push(summarize(label, samples)), + Err(e) => eprintln!("skip {}: {e}", rom.display()), + } + } + + if summaries.is_empty() { + eprintln!("frame_probe: no ROMs measured"); + std::process::exit(1); + } + + println!( + "{:<24} {:>11} {:>11} {:>11} {:>8}", + "workload", "median ms", "p99 ms", "min ms", "CV %" + ); + for s in &summaries { + println!( + "{:<24} {:>11.4} {:>11.4} {:>11.4} {:>8.2}", + s.label, + s.median / 1.0e6, + s.p99 / 1.0e6, + s.min / 1.0e6, + s.cv_pct + ); + } + + // Host-quiet verdict. Reported, never silently folded into the numbers. + let worst = summaries.iter().fold(0.0_f64, |a, s| a.max(s.cv_pct)); + println!(); + if worst <= QUIET_CV_PCT { + println!( + "host: QUIET (worst CV {worst:.2}% <= {QUIET_CV_PCT:.2}%) — numbers are usable for an A/B" + ); + } else { + println!( + "host: NOISY (worst CV {worst:.2}% > {QUIET_CV_PCT:.2}%) — do NOT base an adopt/reject \ + decision on this run; close other work and re-measure" + ); + } + + // NTSC frame budget context, so the number always carries its meaning. + for s in &summaries { + let ms = s.median / 1.0e6; + println!( + " {:<22} {:>6.2}x realtime, {:>5.1}% of the {NTSC_FRAME_MS} ms NTSC budget ({} frames)", + s.label, + NTSC_FRAME_MS / ms, + ms / NTSC_FRAME_MS * 100.0, + s.frames + ); + } +} diff --git a/docs/STATUS.md b/docs/STATUS.md index cbf5e7d2..c76809d9 100644 --- a/docs/STATUS.md +++ b/docs/STATUS.md @@ -1,6 +1,18 @@ # RustyNES — Project Status Matrix -> **Current release: v2.3.0** (2026-08-05) — **"Datum II"**, the capstone closing +> **Current release: v2.3.1** (2026-08-06) — **"Plumb Line"**, the measurement +> release. The performance apparatus was made trustworthy and then used: a +> harness-free frame probe, per-source-file subsystem attribution (which recovers +> the **APU at 18.7% of frame time**, invisible in the symbol profile because fat +> LTO inlines it into `cpu_clock`), an adoption A/B with an **A/B/A order-bias +> control**, and a relative gate that declines to conclude on a contended host. +> **Ten core hot-path optimization candidates were measured and all ten +> rejected** through six distinct mechanisms — none of the ten yielded a +> shippable improvement. (Two leads the campaign surfaced remain **unmeasured**: +> the APU at 18.7% of frame, and `range.rs` inlined inside `Ppu::tick` at 1.52%.) +> **No emulation-core changes: AccuracyCoin holds at +> exactly 141/141 and nestest is 0-diff.** Built on **v2.3.0** (2026-08-05) — +> **"Datum II"**, the capstone closing > the v2.2.6 → v2.3.0 NESdev-remediation line. Tool panels now open as **real OS > windows** (v2.2.9's affordance only *embedded* them, so the Windows-10 > trapped-window report is now genuinely fixed) and every tool window is diff --git a/docs/performance.md b/docs/performance.md index 90ab4721..da5ea7e2 100644 --- a/docs/performance.md +++ b/docs/performance.md @@ -178,6 +178,48 @@ release), not per-PR-push. runner**, in one job sharing one target dir, and fails if HEAD is more than `BENCH_MAX_REGRESSION_PCT` (default 10%) slower. +### v2.3.1 — where a frame actually goes (and why the symbol profile lies) + +`scripts/perf/frame_breakdown.sh` profiles `frame_probe` and buckets samples by +**source file**, which follows inlined code back to the crate that wrote it. +Measured on nestest, 1500 frames at 1500 Hz, quiet host: + +| subsystem | % of frame | top source files | +| --- | ---: | --- | +| PPU (`rustynes-ppu`) | **52.1%** | `ppu.rs` 51.7% | +| APU (`rustynes-apu`) | **18.7%** | `apu.rs` 8.4%, `frame_counter.rs` 2.1%, `blip.rs` 2.1% | +| CPU (`rustynes-cpu`) | 10.1% | `cpu.rs` 9.4%, `status.rs` 0.7% | +| Bus / scheduler coupling | 9.9% | `bus.rs` 9.9% | +| std inlined at emulator call sites | 6.7% | `range.rs` 1.9%, `uint_macros.rs` 1.6% | +| Mappers | 2.5% | `m000_nrom.rs` 1.4%, `mapper.rs` 0.8% | + +**The symbol-level profile does not contain the APU at all.** Under +`lto = "fat"` + `codegen-units = 1` the APU is inlined wholesale into +`::cpu_clock`, so `perf report --no-children` shows +`Ppu::tick` 31%, `cpu_clock` 18%, `emit_pixel` 10% — and **zero** +`rustynes_apu::` symbols at any percent limit. Roughly **a fifth of the frame is +attributed to the wrong subsystem** by the naive view. `perf report --inline` +does not help: measured, it produces output byte-identical to the non-inline +report, because those frames are not recoverable as call frames. + +This corrects the working figure used when the v2.3.x campaign was scoped +("PPU ~53%, CPU+bus ~39%"): the PPU share holds, but the CPU+bus share is really +CPU 10% + APU 19% + coupling 10%, and the CPU proper is a third of what it +appeared to be. Note this does *not* reopen §P4 — that experiment measured the +one remaining APU lever at a **≤1.9% ceiling** and its conclusion stands. The APU +being large and the APU being *reducible* are different claims; only the first is +established here. + +`std inlined at emulator call sites` is real emulator work whose source path +belongs to the standard library. It is reported as its own line rather than +redistributed proportionally, which would invent precision the data does not +contain. + +Source attribution needs DWARF, which `[profile.release]` does not emit, so the +script rebuilds the probe with `CARGO_PROFILE_RELEASE_DEBUG=2`. Debuginfo does +not change codegen, and the script prints the probe's own frame cost so that +assumption is checkable against a stock release build rather than asserted. + **Why gate 2 exists.** The ceiling answers "is the emulator still real-time?", not "did this change make it worse". On the ~4 ms/frame the core actually runs at, a change could get **2.5x slower and still pass** — the gate would sleep @@ -205,6 +247,54 @@ resolvable: a shallow clone, a root commit, a brand-new branch whose all. The job checks out with `fetch-depth: 0` precisely so the normal case does *not* skip. +#### v2.3.1 — the gate declines to conclude on a contended host + +The common-mode cancellation above holds only while the two back-to-back runs +see a comparable machine. On a contended host they do not, and the delta stops +measuring the code. **v2.3.0 P1 is the worked example: profiled on a busy +machine it read +2%; re-measured quiet, the same commit was −5.13%.** The number +was not merely imprecise — it had the wrong sign. + +The gate therefore reads criterion's own artifacts (`sample.json` + +`tukey.json`) for both runs and reports two figures per bench: + +- **robust CV** — `1.4826 × MAD / median`. This is the **trigger**. Unlike + stddev it is not itself dragged around by the outliers being measured, so it + stays a usable yardstick on exactly the contended runs that matter. +- **outlier %** — criterion's own "Found N outliers among M measurements", + recovered as a number. Reported as evidence only, deliberately **not** the + trigger. + +**Outlier % looks like the obvious signal and is a trap.** Criterion's fences +are IQR-derived, so a benchmark whose bulk is unusually *tight* flags a large +outlier fraction from tiny absolute excursions. Measured against this repo's own +saved baselines while building the gate: + +| bench | outliers | robust CV | +| --- | --- | --- | +| `nes_run_frame_flowing_palette_fast` | **30.0%** | **0.19%** | +| `nes_run_frame_nestest` | 20.0% | 0.58% | +| `nes_run_frame_flowing_palette` | 6.0% | 1.18% | +| `nes_run_frame_nestest_fast` | **0.0%** | **2.79%** | + +The two signals do not merely disagree, they invert: the run with the most +outliers is the quietest in the set, and the run with none is the noisiest. +Gating on outlier % would have refused a verdict on the best measurement here. + +The CV threshold is derived, not picked: a gate cannot adjudicate an effect it +cannot resolve, so the host counts as contended once `3 × CV` exceeds +`BENCH_MAX_REGRESSION_PCT` — once the noise band is wide enough to swallow the +very regression being tested for. At the default 10% limit that is a **3.33%** +CV, overridable via `BENCH_MAX_NOISE_CV_PCT`. + +When contended the gate emits **NO VERDICT** (exit 0, loudly) rather than a pass +or a fail. A clean delta on a noisy host is not evidence that nothing regressed, +any more than a dirty one is evidence that something did — reporting either +would be manufacturing a conclusion from data that cannot support one. The one +exception: a delta beyond **3× the measured CV** still FAILs, because contention +inflates a measurement but does not invent a 40% one. Gate 1's absolute ceiling +applies throughout, so declining never leaves a branch ungated. + For an ad-hoc local comparison, criterion baselines directly: ```bash @@ -571,6 +661,314 @@ for a byte-identical escape hatch is not justified. had zero callers outside the core and its tests, so no shipped configuration of any frontend could enable it. +### v2.3.1 G7/G8/G9/G10 — inline hints, typed indices, capability gate, adapter hoist (decision: all REJECTED) + +The last four campaign items. With G1–G6 the score is **ten measured, ten +rejected**, which is itself the release's finding — see the summary below. + +**G7 (plan item 1) — `#[inline]` on `bus.rs`.** The plan called this "the highest +expected value in the plan" because `bus.rs` carries **zero** `#[inline]` hints +across 5,349 lines. True, but only **three** of its functions survive codegen as +symbols: `cpu_clock` (18.32%), `raw_cpu_read` (2.45%), `apply_genie` (0.12%). The +specifically-named `run_ppu_to`, `apu_advance_one`, and the twelve +`PpuBusAdapter` forwarders emit **no symbol at all** — fat LTO already inlines +every one, so hinting them instructs the compiler to do what it has done. + +Hinting the two that genuinely are not inlined, measured separately because they +are opposite bets: + +| candidate | `nestest` | control | verdict | +| --- | ---: | ---: | --- | +| `#[inline]` on both | **+0.60%** (p = 0.02) | −0.10% (p = 0.72) | **regression** | +| `#[inline]` on `raw_cpu_read` only | −0.98% (p = 0.00) | −0.76% (p = 0.01) | drift | + +Hinting the large function *hurts* — `cpu_clock` contains the entire inlined APU, +and duplicating it at every call site costs more in I-cache than the call saved, +the same mechanism that made v2.2.3 P3 slower. Hinting the small one does +nothing. All non-`nestest` workloads flat throughout. + +**This weakens, without disproving, G3's hypothesis** that v2.3.0 P1's −5.13% +came from its `#[inline]` rather than its code motion. P1's hint was on a small +per-dot *PPU* function, structurally unlike either function here, so the +hypothesis is untested rather than refuted — but two attempts to find an +inline-hint win on this core have now failed, and it should not be repeated as +though it were established. + +**G8 (plan item 10) — `oam` / `ciram` as fixed arrays.** Both are `Box<[u8]>` +indexed with `& 0xFF` / `& 0x07FF`, so the bounds check is provably dead but the +type does not say so; `[u8; 0x100]` / `[u8; 0x800]` encode the length statically +and elide it with no `unsafe`. The swap is four lines — surrounding code coerces +arrays to slices transparently. Result: `nestest` −0.61% (p = 0.05) against a +control of **−0.78% (p = 0.01)**, everything else flat. The checks really were +removed; removing them bought nothing. Matches v2.2.3 P3 on the same shape. + +**G9 (plan item 3) — capability-gate `bg_split_state`.** Ceiling probe skipped the +per-fetch mapper dispatch outright. Three workloads flat; +`flowing_palette_fast` moved +0.54% (p = 0.03) with a **control of +0.81% +(p = 0.00)** on that same workload. Ceiling zero, consistent with the 0.09% the +symbol carries in the profile. + +**G10 (plan item 4) — hoist `PpuBusAdapter` out of the dot loop. Not implementable +under this campaign's constraints, and pointless if it were.** The plan reads the +per-dot construction as an oversight defeating vtable hoisting. It is forced: the +adapter holds `mapper: self.mapper.as_mut()`, and `self.sample_nmi_edge()` runs +in the same loop taking `&mut self`. Hoisting would hold a mutable borrow of +`self.mapper` across a call needing all of `self` — rejected by the borrow +checker. With **no `unsafe` in the chip stack** (the standing constraint), it +cannot be done without restructuring `sample_nmi_edge` onto disjoint fields. And +the profile says there is nothing to win: no `PpuBusAdapter` symbol survives +codegen, its three field moves already inlined into callers measured at zero. + +--- + +#### Core-hot-path campaign summary: why ten of ten were rejected + +Ten items, ten rejections, via **six distinct mechanisms** — the diversity is the +point, because it means this is not one bad assumption repeated: + +| mechanism | items | +| --- | --- | +| LLVM already performs the transformation | G3 (sink dead derivations) | +| the premise is factually false | G2 (`repr(Rust)` ignores source order), G7 (already inlined) | +| the work is real but free — absorbed off the critical path | G4 (store buffer), G5 (predicted branches), G6 (recompute) | +| the elision is real but buys nothing | G8 (bounds checks) | +| the target is too small to matter | G9 (0.09%) | +| forbidden by the ownership model | G10 (borrow checker) | + +The unifying finding: **the per-dot loop has no incidental overhead left to +reclaim.** Its ~3.78 ms is spent on work the accuracy model requires, and the +core is issue-limited on that work rather than on the bookkeeping the campaign +targeted. This corroborates the existing record rather than contradicting it — +`emit_pixel` bounds-check elision measured *slower* (P3), the SIMD blitter +measured *slower* (v2.1.8 A2), and the APU mixer lever capped at ≤1.9% (P4). + +Two methodological results outlast the items themselves: + +1. **The A/B/A order-bias control** (added in G2) fired on essentially every + subsequent run and is the only reason G6 was not adopted on a −0.51% + (p = 0.00) reading of a *shipped* configuration that measured +0.01% + (p = 0.96) on re-run. +2. **Ceiling probes** — delete the work, knowingly breaking correctness, and + measure the upper bound before building anything. G4, G5, G6 and G9 were each + settled by one benchmark run instead of a day of engineering; G4 alone would + have meant threading an opt-in flag through four consumers for a zero gain. + +The remaining levers are structural, not micro-architectural: v2.3.3's frontend +copy chain (three full 720 KiB memcpys per displayed frame) and snapshot slimming +(~250 KB per run-ahead frame) are whole-buffer costs, not instruction-level ones. + +### v2.3.1 G4/G5/G6 — three "obvious waste" items, all ceiling-zero (decision: REJECTED) + +Measured by **ceiling probe**: rather than engineer each optimization and then +discover it was worthless, delete the work outright — knowingly breaking +correctness — and measure the upper bound any real implementation could reach. +Where the ceiling is zero, the engineering is moot and no correctness hazard is +ever introduced. This turned three multi-hour items into three benchmark runs. + +| item | what the ceiling probe deleted | per-frame volume | ceiling | +| --- | --- | ---: | ---: | +| **G4** (plan item 8) | the `index_framebuffer` store in `emit_pixel` | 61,440 `u16` stores | **zero** | +| **G5** (plan item 6) | the whole open-bus decay loop in `on_cpu_cycle` | ~29,780 calls | **zero** | +| **G6** (plan item 2) | the ALE/read fetch-address recomputation | ~30,720 recomputes | **zero** | + +In every case the shipped `_fast` workloads were flat and the apparent movement +on `nestest` was matched or exceeded by the run's own A/B/A control: + +| item | candidate `nestest` | control `nestest` | +| --- | ---: | ---: | +| G4 | −0.82% (p = 0.01) | −0.88% (p = 0.01) | +| G5 | −0.49% (p = 0.06) | −0.51% (p = 0.05) | +| G6 run 1 | −0.89% (p = 0.00) | −0.16% (p = 0.37) | +| G6 run 2 | −0.96% (p = 0.00) | **−1.17% (p = 0.00)** | + +G6 is the instructive one. Run 1 looked like the campaign's first genuine win — +**−0.51% at p = 0.00 on `nestest_fast`, a shipped configuration, with a clean +control on that workload**. Run 2 measured the same probe at **+0.01% +(p = 0.96)**, and its `nestest` control drifted −1.17%, larger than the +candidate's own −0.96%. Under the relaxed sub-3% adoption bar, run 1 alone would +have been adopted. The mandatory second run is what stopped it. + +Note also that `nestest` is the FIRST workload criterion benches, so it absorbs +the most warm-up, and it is where drift shows up most consistently across every +run in this campaign. Treat a `nestest`-only result with particular suspicion. + +**Why there is nothing to reclaim.** Three different mechanisms, one conclusion: + +- **G4** — a line's profile share is not its marginal cost. `perf` attributes + ~0.78% to that store, but it is a sequential `u16` write the store buffer + absorbs off the critical path; deleting it frees nothing and the samples simply + redistribute onto neighbours. +- **G5** — ~29,780 calls/frame sounds expensive but is three perfectly predicted + compare-and-decrement steps on L1-resident data, which an out-of-order core + hides entirely under other latency. +- **G6** — the recomputation is real, but it is not on the critical path either. + +**G6 was also not adoptable at any speed**, which the ceiling result makes moot +but is worth recording. The read half re-derives the fetch address for +`observe_a12_addr`; `ale_splice` takes the read address's high bits from +`address_bus` (latched at the ALE dot) and its low bits from `octal_latch`, so +the recomputed value exists *specifically* to drive A12. On hardware only A7–A0 +pass through the 74LS373, so the PPU drives the current full address during the +read cycle and A12 follows it. Caching would freeze A12 to the ALE dot, shifting +MMC3 IRQ timing whenever a `$2000`/`$2005`/`$2006` write lands between the two +dots. The plan item read two identical-looking expressions and inferred +redundancy; they are identical only in the common case and are *meant* to be able +to differ. + +### v2.3.1 G3 — sink dead per-dot derivations to their use site (decision: REJECTED, reverted) + +The campaign's highest-ranked *code* item, and the same transformation shape as +the adopted v2.3.0 P1. Two sites compute values they then discard: + +- `tick_sprite_eval_per_dot` derives `next_line` and `sprite_height` on entry, + but the `match self.dot` consumes them only in the `65..=256` arm — dead on + dots 0, 1..=64 and 257..=340, i.e. **149 of 341 dots**. +- `tick_oam_bus` derives `sprite_height` and `scan` above the `cycle < 65` + secondary-OAM-clear path that discards both — dead across a quarter of every + visible line. (v2.3.0 P1 had already moved the `cycle == 0` return above them.) + +Both were sunk to their single point of use — in the sprite-eval case, inside the +`if !self.sprite_eval_done` guard, tighter than the match arm. All inputs are +pure reads of `scanline` / `region` / `ctrl`, so byte-identical by construction. + +**Correctness verified before measuring:** AccuracyCoin **100.00% over 141 +assigned tests**, `visual_regression` 9/9 (golden framebuffers — the direct +byte-identity evidence), full `--features test-roms` workspace suite green, +clippy clean at `-D warnings`. + +**Two independent A/B runs, and the order-bias control is the story:** + +| workload | run 1 candidate | run 2 candidate | +| --- | ---: | ---: | +| `nestest` | −0.56% (p = 0.00) | −0.05% (p = 0.84) | +| `flowing_palette` | +0.20% (p = 0.33) | −0.17% (p = 0.17) | +| `nestest_fast` *(shipped)* | −0.03% (p = 0.91) | −0.14% (p = 0.48) | +| `flowing_palette_fast` *(shipped)* | −0.01% (p = 0.95) | +0.01% (p = 0.96) | + +Run 1's `nestest` −0.56% at p = 0.00 looks like a small real win. It is not, and +the A/B/A control proves it directly rather than by argument: **run 2's control — +the reference benched against itself, with no code difference whatsoever — +reported `nestest` at −0.59%, p = 0.00.** The drift and the "effect" are the same +size, on the same workload, at the same significance. Run 1's control had already +flagged a −0.39% (p = 0.03) drift on `nestest_fast`. + +**Rejected and reverted.** Both shipped `_fast` variants are flat across both +runs (p ≥ 0.48, intervals straddling zero). + +**Why it does nothing — the generalizable finding.** LLVM already sinks pure, +side-effect-free computations past branches that do not use them. At +`opt-level = 3` with fat LTO, writing the sink by hand tells codegen nothing it +had not already worked out. The source change made explicit what the optimizer +was doing anyway. + +This reframes **v2.3.0 P1**, which bundled an `#[inline]` with a hoist of exactly +this shape and measured −5.13%. The two were never separated. G3 is evidence that +the hoist half contributes ~nothing, which points at the `#[inline]` — a change +to the *inliner's cost model*, something LLVM cannot infer — as the actual source +of that win. Recorded as a hypothesis, not a conclusion: it was not re-measured +in isolation. + +Both sites keep a comment marking the attempt so it is not re-tried. + +### v2.3.1 G2 — `Ppu` field layout (decision: REJECTED — and it exposed a harness bug) + +The campaign item asked to reorder `Ppu`'s 114 fields by access frequency, +noting the ~15 hot ones are "scattered, with a 2 KiB `rgba_lut` sitting between +the palette state and the framebuffer pointer", and called it "pure reordering — +byte-identical by construction". + +**The premise is void.** `Ppu` is `#[repr(Rust)]`, so declaration order does not +determine memory layout; rustc is free to reorder and does. Probed offsets: + +```text + 488 rgba_lut (2048 B) … ends 2536 +2570 v 2574 dot 2576 scanline 2578 bg_shift_lo +2580 bg_shift_hi 2582 at_shift_lo 2584 at_shift_hi +2586 flags_cached_scanline <- 17 bytes, one cache line +2828 x +``` + +rustc sorts by alignment, which packs every hot `u16`/`i16` scalar contiguously +into a single cache line and puts the 2 KiB LUT *before* the whole hot cluster — +the opposite of what the item describes. Source reordering cannot move any of it. + +Measured anyway, in the only form that can change layout — `#[repr(C)]`, which +forces declaration order — plus a variant moving the 256-byte `oam_decay_cycles` +(dead unless OAM decay is enabled, default-off) out from between the scroll +registers and the per-dot render state: + +| run | candidate | result | +| --- | --- | --- | +| 1 | `repr(C)` | −1.84% … −2.75%, **p = 0.00 on all four** | +| 2 | `repr(C)` + cold field moved to end | no change on 3 of 4 (p ≥ 0.31) | +| 3 | `repr(C)` again | **no change on all four** (p ≥ 0.11) | + +**Run 1 was wrong, and run 3 is why.** The same candidate that produced a +textbook −2% at p = 0.00 on every workload produced nothing on re-measurement. +Nothing about the code changed between them. + +**Root cause — a systematic bias in `ab_check.sh`, now fixed.** The reference was +always benched FIRST and the candidate SECOND. Anything that makes the host +monotonically faster over the life of a run — page-cache warming, governor +ramping, a background job finishing, boost/thermal settling — is therefore +indistinguishable from "the candidate is faster". Run 1 followed a period of +heavy local activity (test runs, `perf record`, worktree builds); the machine was +still settling while the reference was measured and had settled by the candidate. + +The fix is an **A/B/A order-bias control**: the reference is now re-benched a +third time, last, against its own first run. Whatever that reports is pure +position-in-the-run drift and is the noise floor the candidate must be read +against. The script also now states that a single run is not a result and that +anything under ~5% needs an independent second run — with this experiment as the +cautionary example. + +**Item rejected.** No reproducible effect from any layout change tried. That is +also the physically sensible answer: `Ppu` is ~2,856 bytes and stays L1-resident +across a frame, so field layout has little left to buy. Layout is not where this +emulator's remaining time is. + +### v2.3.1 G1 — idle-line fast path, re-measured (decision: REJECTED again, stays default-OFF) + +The v2.3.x campaign predicted the default-OFF `ppu-idle-line-fast` path +(§P2, max −1.55%, below the bar) "becomes worthwhile if per-dot dispatch gets +cheaper", and v2.3.0 P1 made per-dot dispatch cheaper by −5.13%. Re-measured on +that basis. Criterion change analysis, host CPU-pinned (`taskset -c 2-5`), +2 s warm-up / 10 s measurement, feature-OFF baseline vs feature-ON: + +| bench | change | p | verdict | +| --- | ---: | ---: | --- | +| `nes_run_frame_nestest` | −0.94% | 0.00 | small win | +| `nes_run_frame_flowing_palette` | **+0.98%** | 0.02 | small **regression** | +| `nes_run_frame_nestest_fast` | −0.36% | 0.29 | no change | +| `nes_run_frame_flowing_palette_fast` | +0.84% | 0.06 | no change | + +**Rejected.** Nothing approaches the >3% bar, the two workloads disagree in +sign, and — decisively — **both `_fast` variants report no change, and those are +the shipped configuration** (`fast_dotloop` became the default in v2.2.3). The +feature stays implemented and default-OFF on exactly the terms §P2 set. + +Worth recording that this re-measurement **disagrees in sign with §P2** on +`flowing_palette` (−1.31% then, +0.98% now). Neither is wrong so much as both are +inside the noise for an effect this size. The consistent finding across two +independent sessions is that the idle-line path moves the shipped configuration +by less than ±1.5%, with an unstable sign — which is what "does not clear the +bar" means in practice. + +**Method note, which cost a wrong intermediate conclusion.** The first pass +adjudicated this from point-estimate ratios plus the v2.3.1 contention heuristic +(host contended when `3 × robustCV` exceeds the effect being tested). That +heuristic is correct for the CI *regression* gate, where the question is whether +one delta could be noise — but it is the wrong statistic for an adoption +decision taken from 100-sample means, where the relevant quantity is the +confidence interval and the standard error falls as `CV / √n` (≈0.2% here, not +2%). Applied to an adoption decision it demanded a quiet host that no desktop +provides and would have refused every verdict in this campaign. + +**Adoption decisions are adjudicated by criterion's `--baseline` change analysis +(change interval + p-value), as §P2/§P3/§P4 already did.** The v2.3.1 gate keeps +its 3×CV rule for the job it was built for. Two different questions, two +different statistics; conflating them is what produced the wrong first read. + ### v2.3.0 P1 — per-dot sprite-eval / OAM-bus call cost (decision: ADOPTED) The v2.3.0 frontend-stutter investigation re-profiled the core on a quiet machine diff --git a/scripts/bench_relative_check.sh b/scripts/bench_relative_check.sh index fe0e198d..43f9dae0 100755 --- a/scripts/bench_relative_check.sh +++ b/scripts/bench_relative_check.sh @@ -37,9 +37,54 @@ # with a clear message and exit 0 — a gate that cannot establish a baseline must # not manufacture a verdict. # +# ## Host contention: the gate refuses to guess (v2.3.1) +# +# The cancellation argument above holds only while the two back-to-back runs see +# a comparable machine. On a contended host they do not: whichever run happens to +# land next to the noisy neighbour is inflated, the "common-mode" assumption +# breaks, and the delta stops measuring the code. v2.3.0 P1 is the worked example +# — profiled on a busy machine it read +2%; re-measured quiet, the same commit +# was -5.13%. The number was not merely imprecise, it had the wrong sign. +# +# So this gate now reads criterion's own contention evidence and declines to +# conclude when the host was too noisy to support a conclusion: +# +# * **robust CV** — `1.4826 * MAD / median`. This is the trigger. Unlike +# stddev it is not itself dragged around by the outliers being measured, so +# it stays a usable yardstick on exactly the contended runs that matter. +# * **outlier %** — computed the way criterion computes it: each sample's +# per-iteration average against the Tukey fences criterion already wrote to +# `tukey.json`. Reported as evidence only; deliberately NOT the trigger. +# +# Outlier % looks like the obvious signal and is a trap here. Criterion's fences +# are IQR-derived, so a benchmark whose bulk is unusually *tight* flags a large +# outlier fraction from tiny absolute excursions. Measured on this repo's own +# saved baselines: `nes_run_frame_flowing_palette_fast` reports **30% outliers +# at 0.19% robust CV** (a superbly quiet run), while `nes_run_frame_nestest_fast` +# reports **0% outliers at 2.79% CV**. The two signals not only disagree, they +# invert. Gating on outlier % would have refused a verdict on the quietest run +# in the set. +# +# The CV threshold is not a magic constant either: it is derived from the effect +# size the gate exists to detect. A gate cannot adjudicate an effect it cannot +# resolve, so the host counts as contended once `3 * CV` exceeds +# `BENCH_MAX_REGRESSION_PCT` — i.e. once the noise band is wide enough to +# swallow the very regression being tested for. At the default 10% limit that is +# a 3.33% CV. +# +# When contended the gate emits **NO VERDICT** (exit 0, loudly) rather than a +# pass or a fail — a clean delta on a noisy host is not evidence of no regression +# any more than a dirty one is evidence of a regression. The one exception is a +# delta that dwarfs even the inflated noise (more than 3x the measured CV): +# contention inflates a measurement, it does not invent a 40% one, so that still +# FAILs. The absolute ceiling in `bench_regression_check.sh` applies either way, +# so declining here never leaves the branch ungated. +# # Env knobs: # BENCH_BASE_REF base commit-ish (default HEAD~1) # BENCH_MAX_REGRESSION_PCT fail above this % slower (default 10) +# BENCH_MAX_NOISE_CV_PCT above this robust CV %, emit NO VERDICT instead of +# pass/fail (default BENCH_MAX_REGRESSION_PCT / 3) # BENCH_MEASUREMENT_TIME criterion measurement seconds (default 3) set -euo pipefail @@ -48,6 +93,32 @@ repo_root="$(pwd)" BASE_REF="${1:-${BENCH_BASE_REF:-HEAD~1}}" MAX_REGRESSION_PCT="${BENCH_MAX_REGRESSION_PCT:-10}" +# Default derived from the regression limit rather than picked: the gate declines +# once the noise band (3x CV) is wide enough to swallow the effect it is testing +# for. Overridable, but the derivation is the point. +# Derived with awk, which treats the value as DATA. The obvious form +# interpolates ${MAX_REGRESSION_PCT} into inline Python source, so a non-numeric +# BENCH_MAX_REGRESSION_PCT would either break parsing or execute as code. +MAX_NOISE_CV_PCT="${BENCH_MAX_NOISE_CV_PCT:-$(awk -v r="${MAX_REGRESSION_PCT}" \ + 'BEGIN { if (r + 0 <= 0) { print "3.33" } else { printf "%.2f", (r + 0) / 3 } }')}" +# An OVERRIDE is copied verbatim, so validate it here rather than letting a value +# like `3oops` reach the python comparison below and die mid-run with a traceback +# after both benches have already been paid for — the most expensive possible +# moment to discover a bad argument. +# +# Both a character check AND a digit check are needed. Rejecting only +# `*[!0-9.]*` / `*.*.*` still admits a bare `.` (one dot, no other characters), +# which `float()` cannot parse; requiring at least one digit closes that. +require_number() { + case "$2" in + ''|*[!0-9.]*|*.*.*) ;; # empty / non-numeric char / more than one dot + *[0-9]*) return 0 ;; # has a digit and survived the above: valid + esac + echo "bench_relative_check: $1 must be a number, got '$2'" >&2 + exit 2 +} +require_number BENCH_MAX_NOISE_CV_PCT "${MAX_NOISE_CV_PCT}" +require_number BENCH_MAX_REGRESSION_PCT "${MAX_REGRESSION_PCT}" MEASUREMENT_TIME="${BENCH_MEASUREMENT_TIME:-3}" BENCH_IDS=(nes_run_frame_nestest nes_run_frame_flowing_palette) @@ -68,6 +139,15 @@ echo "==> Relative frame-time gate" echo " base: ${base_sha:0:12} (${BASE_REF})" echo " head: ${head_sha:0:12}" echo " fail if HEAD is more than ${MAX_REGRESSION_PCT}% slower" +echo " no verdict above ${MAX_NOISE_CV_PCT}% robust CV (host too noisy to resolve it)" + +# Recorded purely as evidence in the log: a reader diagnosing a NO VERDICT wants +# to know what the machine was doing. Nothing branches on this — load average is +# a lagging 1-minute figure and the runner may not be Linux, so the actual +# contention decision is made from criterion's own per-sample data below. +if [[ -r /proc/loadavg ]]; then + echo " host: load avg $(cut -d' ' -f1-3 /proc/loadavg) across $(nproc 2>/dev/null || echo '?') cpus" +fi # ---- Bench the BASE commit in a throwaway worktree ------------------------ # A worktree, never `git checkout`: this script must not touch the working tree @@ -111,9 +191,48 @@ mean_ns() { python3 -c "import json,sys; print(int(json.load(open(sys.argv[1]))['mean']['point_estimate']))" "${est}" } +# Contention evidence for one saved baseline, straight from criterion's own +# artifacts: `sample.json` (per-sample iteration counts + elapsed times) and +# `tukey.json` (the four Tukey fences criterion already computed). Emits +# " ", or "MISSING" when either artifact is absent. +noise_of() { + local id="$1" which="$2" + local dir="${CARGO_TARGET_DIR}/criterion/${id}/${which}" + [[ -f "${dir}/sample.json" && -f "${dir}/tukey.json" ]] || { echo "MISSING"; return; } + python3 - "${dir}" <<'PY' +import json, statistics, sys + +d = sys.argv[1] +sample = json.load(open(f"{d}/sample.json")) +# Criterion classifies on the per-sample AVERAGE (elapsed / iterations), which is +# also the scale its Tukey fences are expressed in. Guard against a zero iters +# entry rather than trusting the file. +avgs = [t / i for t, i in zip(sample["times"], sample["iters"]) if i] +if not avgs: + print("MISSING") + raise SystemExit + +# tukey.json is [lo_severe, lo_mild, hi_mild, hi_severe]; anything outside the +# mild fences is an outlier, matching criterion's "Found N outliers" tally. +_, lo_mild, hi_mild, _ = json.load(open(f"{d}/tukey.json")) +outliers = sum(1 for a in avgs if a < lo_mild or a > hi_mild) + +# Robust spread: MAD scaled to a normal-consistent sigma. Unlike stddev this is +# not itself inflated by the very outliers being measured, so it stays a usable +# yardstick on exactly the contended runs this gate cares about. +med = statistics.median(avgs) +mad = statistics.median([abs(a - med) for a in avgs]) +cv = (1.4826 * mad / med * 100) if med else 0.0 +print(f"{outliers / len(avgs) * 100:.1f} {cv:.2f}") +PY +} + rc=0 -printf '\n%-32s %12s %12s %10s\n' "bench" "base (ms)" "head (ms)" "delta" -printf '%-32s %12s %12s %10s\n' "-----" "---------" "---------" "-----" +contended=0 +printf '\n%-32s %11s %11s %9s %9s %8s\n' \ + "bench" "base (ms)" "head (ms)" "delta" "outliers" "noise" +printf '%-32s %11s %11s %9s %9s %8s\n' \ + "-----" "---------" "---------" "-----" "--------" "-----" for id in "${BENCH_IDS[@]}"; do base_ns="$(mean_ns "${id}" relgate_base)" head_ns="$(mean_ns "${id}" relgate_head)" @@ -122,18 +241,63 @@ for id in "${BENCH_IDS[@]}"; do rc=1 continue fi + + base_noise="$(noise_of "${id}" relgate_base)" + head_noise="$(noise_of "${id}" relgate_head)" + if [[ "${base_noise}" == "MISSING" || "${head_noise}" == "MISSING" ]]; then + # Fall back to the pre-v2.3.1 behaviour rather than skipping: without + # sample data we cannot show the host was quiet, but we also cannot show + # it was noisy, and the delta itself is still a real measurement. + out_pct="n/a" + noise_pct="n/a" + bench_contended=0 + else + read -r base_out base_cv <<<"${base_noise}" + read -r head_out head_cv <<<"${head_noise}" + read -r out_pct noise_pct bench_contended <<<"$(python3 - \ + "$base_out" "$head_out" "$base_cv" "$head_cv" "$MAX_NOISE_CV_PCT" <<'PY' +import sys +bo, ho, bc, hc, limit = (float(x) for x in sys.argv[1:6]) +# Worst case of the two runs on each axis: if EITHER commit was measured on a +# noisy machine, the comparison between them is compromised. +out, cv = max(bo, ho), max(bc, hc) +print(f"{out:.1f} {cv:.2f} {1 if cv > limit else 0}") +PY +)" + (( bench_contended )) && contended=1 + fi + read -r base_ms head_ms delta_pct <<<"$(python3 - "$base_ns" "$head_ns" <<'PY' import sys b, h = int(sys.argv[1]), int(sys.argv[2]) print(f"{b/1e6:.3f} {h/1e6:.3f} {(h - b) / b * 100:+.2f}") PY )" - printf '%-32s %12s %12s %9s%%\n' "${id}" "${base_ms}" "${head_ms}" "${delta_pct}" + printf '%-32s %11s %11s %8s%% %8s%% %7s%%\n' \ + "${id}" "${base_ms}" "${head_ms}" "${delta_pct}" "${out_pct}" "${noise_pct}" + over="$(python3 -c "print('1' if ${delta_pct} > ${MAX_REGRESSION_PCT} else '0')")" - if [[ "${over}" == "1" ]]; then - echo "FAIL: ${id} regressed ${delta_pct}% (limit ${MAX_REGRESSION_PCT}%)" + [[ "${over}" == "1" ]] || continue + + # Over the limit on a QUIET host is a regression. Over the limit on a noisy + # one is only a regression if it is too large for that noise to explain — + # 3x the measured robust CV. Contention inflates a measurement; it does not + # invent a 40% one. + if (( bench_contended )); then + dwarfs="$(python3 -c "print('1' if ${delta_pct} > 3 * ${noise_pct} else '0')")" + if [[ "${dwarfs}" != "1" ]]; then + echo "NOTE: ${id} is ${delta_pct}% slower, but the host was contended" + echo " (${out_pct}% outliers, ${noise_pct}% robust CV) and the delta is" + echo " within 3x that noise — not attributable to the code change." + continue + fi + echo "FAIL: ${id} regressed ${delta_pct}% — beyond 3x the ${noise_pct}% measured" + echo " noise, so host contention cannot account for it." rc=1 + continue fi + echo "FAIL: ${id} regressed ${delta_pct}% (limit ${MAX_REGRESSION_PCT}%)" + rc=1 done echo @@ -154,4 +318,27 @@ well as ones that did) and raise BENCH_MAX_REGRESSION_PCT for this run. EOF exit 1 fi -echo "==> Relative frame-time gate passed (no bench regressed beyond ${MAX_REGRESSION_PCT}%)." + +if (( contended )); then + cat < Relative frame-time gate: NO VERDICT (host too noisy to resolve the effect). + +Measured sample spread exceeded ${MAX_NOISE_CV_PCT}% robust CV, so the noise band +(3x CV) is wide enough to swallow the ${MAX_REGRESSION_PCT}% regression this gate +tests for. The two back-to-back runs did not see a comparable machine, and the +common-mode cancellation the gate depends on does not hold. This is reported as +neither a pass nor a fail on purpose: a clean delta measured on a noisy host is +not evidence that nothing regressed. (v2.3.0 P1 read +2% contended and -5.13% +quiet — the same commit, opposite signs.) + +No regression large enough to outrun the measured noise was found, so this does +not block. The absolute ceiling in bench_regression_check.sh still applies. + +To get a real verdict, re-run on a quiet machine — or locally: + + scripts/bench_relative_check.sh ${BASE_REF} +EOF + exit 0 +fi +echo "==> Relative frame-time gate passed (no bench regressed beyond ${MAX_REGRESSION_PCT}%," +echo " on a host quiet enough for the comparison to mean something)." diff --git a/scripts/perf/ab_check.sh b/scripts/perf/ab_check.sh new file mode 100755 index 00000000..c2f75f7c --- /dev/null +++ b/scripts/perf/ab_check.sh @@ -0,0 +1,207 @@ +#!/usr/bin/env bash +# ab_check.sh — adjudicate ONE optimization against the >3% adoption bar. +# +# Companion to `bench_relative_check.sh`, and deliberately a different tool +# answering a different question: +# +# bench_relative_check.sh CI gate. "Did this commit regress by more than +# BENCH_MAX_REGRESSION_PCT (10%)?" Point estimates +# plus the 3x-robust-CV contention rule are the right +# statistics for that: the question is whether ONE +# delta could be noise. +# +# ab_check.sh (this) Adoption decision. "Is this change worth keeping at +# the >3% bar?" That is a question about the MEAN of +# ~100 samples, where the confidence interval governs +# and the standard error falls as CV/sqrt(n). Applying +# the 3xCV rule here demands a quiet host no desktop +# provides and refuses every verdict -- a mistake made +# once, in v2.3.1 G1, and recorded in +# docs/performance.md so it is not repeated. +# +# So this script defers to criterion's own `--baseline` change analysis, which +# reports a change interval and a p-value. That is what P2/P3/P4 and G1 used. +# +# ## What it compares +# +# The WORKING TREE against a reference (default HEAD), back to back on the same +# host, sharing one target dir. The reference is built in a throwaway git +# worktree -- never a `git checkout`, so uncommitted work is never touched even +# if the run dies. Optionally applies extra cargo features to the candidate side +# only, which is how a default-OFF feature flag is adjudicated (G1 used exactly +# that shape). +# +# ## Usage +# +# scripts/perf/ab_check.sh # working tree vs HEAD +# scripts/perf/ab_check.sh --base HEAD~1 +# scripts/perf/ab_check.sh --features ppu-idle-line-fast # flag A/B, same tree +# scripts/perf/ab_check.sh --bench nes_run_frame_nestest # one workload +# AB_MEASUREMENT_TIME=20 scripts/perf/ab_check.sh # tighter intervals +# +# CPU pinning (`taskset`) is applied when available: measured on this project's +# host it took robust CV from 2.73% to 1.95%, which narrows every confidence +# interval for free. +# +# ## Reading the result +# +# criterion prints, per workload, `change: [lo mid hi] (p = ...)`, and the run +# ends with an A/B/A order-bias control plus the full adoption rule. +# +# The bar is EVIDENCE QUALITY, not effect size (maintainer decision, v2.3.1): a +# consistent, reproduced, statistically clean gain is adoptable even below 3%. +# What is NOT negotiable is the second independent run -- a single run has +# already produced a p=0.00 result on all four workloads that was pure artifact. +# A mixed-sign result across workloads is a rejection, not an average. +# +# Record the outcome in docs/performance.md either way -- including rejections +# with their numbers. That convention is why this campaign could skip so many +# already-settled dead ends. +set -euo pipefail + +cd "$(dirname "${BASH_SOURCE[0]}")/../.." +repo_root="$(pwd)" + +BASE_REF="HEAD" +FEATURES="" +BENCH_FILTER="" +MEASUREMENT_TIME="${AB_MEASUREMENT_TIME:-10}" +WARMUP="${AB_WARMUP_TIME:-2}" + +while [[ $# -gt 0 ]]; do + case "$1" in + --base) BASE_REF="$2"; shift 2 ;; + --features) FEATURES="$2"; shift 2 ;; + --bench) BENCH_FILTER="$2"; shift 2 ;; + -h|--help) sed -n '2,60p' "${BASH_SOURCE[0]}"; exit 0 ;; + *) echo "unknown argument: $1" >&2; exit 2 ;; + esac +done + +if ! base_sha="$(git rev-parse --verify --quiet "${BASE_REF}^{commit}")"; then + echo "SKIP: cannot resolve base ref '${BASE_REF}'." >&2 + exit 0 +fi + +# Pin to a fixed CPU set when possible. Frequency scaling and scheduler +# migration are the dominant noise sources on a desktop; pinning removes the +# second and stabilises the first. +PIN=() +if command -v taskset >/dev/null 2>&1; then + ncpu="$(nproc 2>/dev/null || echo 1)" + if [[ "${ncpu}" -ge 6 ]]; then + PIN=(taskset -c 2-5) + fi +fi + +work="$(mktemp -d)" +cleanup() { + git worktree remove --force "${work}/base" >/dev/null 2>&1 || true + rm -rf "${work}" +} +trap cleanup EXIT + +export CARGO_TARGET_DIR="${repo_root}/target" + +bench_args=() +[[ -n "${BENCH_FILTER}" ]] && bench_args+=("${BENCH_FILTER}") +bench_args+=(--warm-up-time "${WARMUP}" --measurement-time "${MEASUREMENT_TIME}") + +echo "==> Adoption A/B (bar: >3% faster, whole interval, p < 0.05)" +echo " reference : ${base_sha:0:12} (${BASE_REF})" +if [[ -n "${FEATURES}" ]]; then + echo " candidate : same tree + features '${FEATURES}'" +else + echo " candidate : working tree" +fi +[[ ${#PIN[@]} -gt 0 ]] && echo " pinned : ${PIN[*]}" +echo " timing : ${WARMUP}s warm-up, ${MEASUREMENT_TIME}s measurement" +echo + +# ---- Reference side ------------------------------------------------------- +# A feature-flag A/B compares the SAME tree with and without the flag, so the +# reference is the working tree too; only a code A/B needs the worktree. +if [[ -n "${FEATURES}" ]]; then + echo "==> Benching reference (flag off)" + "${PIN[@]}" cargo bench -p rustynes-core --bench full_frame -- \ + "${bench_args[@]}" --save-baseline ab_ref >/dev/null +else + echo "==> Benching reference (${base_sha:0:12}) in a throwaway worktree" + git worktree add --detach "${work}/base" "${base_sha}" >/dev/null + ( + cd "${work}/base" + "${PIN[@]}" cargo bench -p rustynes-core --bench full_frame -- \ + "${bench_args[@]}" --save-baseline ab_ref + ) >/dev/null +fi + +# ---- Candidate side, compared against it ---------------------------------- +echo "==> Benching candidate, compared against the reference" +echo +feat_args=() +[[ -n "${FEATURES}" ]] && feat_args+=(--features "${FEATURES}") +"${PIN[@]}" cargo bench -p rustynes-core "${feat_args[@]}" --bench full_frame -- \ + "${bench_args[@]}" --baseline ab_ref 2>&1 \ + | grep -E "^nes_run_frame|time:|change:|Performance has|No change" \ + | sed 's/^/ /' + +# ---- ORDER-BIAS CONTROL (A/B/A) ------------------------------------------- +# The reference is always benched FIRST, so anything that makes the machine +# monotonically faster over the life of the run — page cache warming, CPU +# governor ramping, a background job finishing, thermal/boost settling — is +# indistinguishable from "the candidate is faster". This is not hypothetical: +# v2.3.1 G2's first run reported a clean −1.84%..−2.75% (p=0.00 on all four +# workloads) for a `#[repr(C)]` layout change that, re-measured, showed no +# effect at all. The candidate had not improved; the machine had. +# +# So bench the REFERENCE a second time, last, against its own first run. Any +# change reported below is pure position-in-the-run bias and is the noise floor +# the candidate's numbers must be read against. Ideally it is "No change" on +# every workload; if it is not, the candidate result above is worth exactly as +# much as this drift is small. +echo +echo "==> Order-bias control: re-benching the REFERENCE against itself, last" +echo +if [[ -n "${FEATURES}" ]]; then + "${PIN[@]}" cargo bench -p rustynes-core --bench full_frame -- \ + "${bench_args[@]}" --baseline ab_ref 2>&1 \ + | grep -E "^nes_run_frame|change:|Performance has|No change" \ + | sed 's/^/ /' +else + ( + cd "${work}/base" + "${PIN[@]}" cargo bench -p rustynes-core --bench full_frame -- \ + "${bench_args[@]}" --baseline ab_ref + ) 2>&1 \ + | grep -E "^nes_run_frame|change:|Performance has|No change" \ + | sed 's/^/ /' +fi + +cat <<'EOF' + +READ THE ORDER-BIAS CONTROL FIRST. It re-benches the reference against itself, +so whatever it reports is drift from position-in-the-run alone. If it is not +"No change" on every workload, the candidate numbers above carry at least that +much systematic error and a small result is not interpretable. + +ADOPTION RULE (maintainer decision, v2.3.1): a consistent, well-established gain +is adoptable even below 3%. The old flat ">3%" bar existed to stop noise-chasing, +not because 2% is worthless -- so the burden moved from EFFECT SIZE to EVIDENCE +QUALITY. Adopt when ALL of: + + * reproduced by a SECOND INDEPENDENT RUN (not a re-read of the same run); + * p < 0.05 on the workloads that moved; + * the order-bias control reports no drift; + * the sign is consistent across workloads -- mixed signs is a rejection, never + something to average; + * the shipped `_fast` variants move (fast_dotloop is default-on since v2.2.3, + so a change that only moves the non-fast variants moves nothing a user runs). + +The second run is not optional ceremony. v2.3.1 G2 produced a textbook -1.84%.. +-2.75% at p=0.00 on ALL FOUR workloads, from an order-bias artifact; it measured +as exactly zero on re-run. Under a size-only bar that would have been rejected +for being under 3%. Under an evidence-based bar it is rejected for the right +reason -- it was never real. + +Record the outcome in docs/performance.md either way, rejections included. +EOF diff --git a/scripts/perf/frame_breakdown.sh b/scripts/perf/frame_breakdown.sh new file mode 100755 index 00000000..3ecd7355 --- /dev/null +++ b/scripts/perf/frame_breakdown.sh @@ -0,0 +1,255 @@ +#!/usr/bin/env bash +# frame_breakdown.sh — v2.3.1 "Plumb Line" per-subsystem frame-cost breakdown. +# +# Answers "where does a frame actually go?" for the COMPOSED emulator, by +# profiling `frame_probe` (the harness-free probe, so no criterion plumbing +# dilutes the samples) and bucketing them into PPU / CPU / APU / mappers / +# scheduler-coupling. +# +# ## Why this is not just `perf report` +# +# The obvious command — `perf report --no-children -g none` — gives a symbol +# profile that is actively misleading about this codebase, and the correction is +# the whole reason this script exists. +# +# Under `lto = "fat"` + `codegen-units = 1`, the APU is inlined wholesale into +# `::cpu_clock`. The symbol view therefore reports: +# +# 31.0% rustynes_ppu::ppu::Ppu::tick +# 18.3% ::cpu_clock +# 10.0% rustynes_ppu::ppu::Ppu::emit_pixel +# ... (rustynes_apu:: does not appear ANYWHERE, at any percent limit) +# +# Read naively that says the APU is free. It is not: bucketing the same profile +# by source file surfaces `apu.rs`, `blip.rs`, `pulse.rs`, `frame_counter.rs`, +# `dmc.rs`, `noise.rs`, `mixer.rs`, `length.rs` totalling **~19%** of frame cost, +# all of it hidden inside that one `cpu_clock` line. Any optimization plan built +# on the symbol view will mis-target by roughly a fifth of the frame. +# +# `perf report --inline` does NOT fix this — measured, it produces byte-identical +# output to the non-inline report, because the inlined APU frames are not +# recoverable as call frames at all. Source-file attribution is. +# +# ## Method and its one real limit +# +# Samples are bucketed by SOURCE FILE (`perf report --sort srcfile`), which +# follows inlined code back to the crate that wrote it. perf reports basenames +# only, so the map from basename to subsystem is built from the tree at run time +# rather than hardcoded (it cannot rot). Four basenames exist in more than one +# emulation crate — `bus.rs`, `scheduler.rs`, `lib.rs`, `snapshot.rs`: +# +# * `bus.rs` and `scheduler.rs` are bucketed as COUPLING regardless of crate. +# That is not a fudge: every one of them is the bus/scheduler abstraction, +# so the semantic bucket is the same whichever crate the samples came from +# (verified — `bus.rs` samples resolve to `LockstepBus::raw_cpu_read`, +# `Cpu::read1`, `cpu_clock`, and `Ppu::tick`, i.e. all three crates' bus +# files, all of them bus work). +# * `lib.rs` and `snapshot.rs` genuinely cannot be attributed from a basename, +# so they land in UNATTRIBUTED and are printed rather than guessed at. +# +# Anything whose basename is not owned by a workspace emulation crate lands in +# **NONWORKSPACE-INLINED** — reported as "std + deps inlined at call sites". In +# practice that is dominated by the standard library (`range.rs`, `option.rs`, +# `cmp.rs`, `uint_macros.rs`, …), but it also catches inlined third-party crates +# (`bitflags`, `bytemuck`, `smallvec`, …), so the label deliberately does not say +# "std" alone. All of it is emulator work performed at emulator call sites that +# carries someone else's source path and cannot be assigned to a subsystem. +# +# It is reported on its own line and NOT redistributed proportionally across the +# buckets — that would invent precision the data does not contain. +# +# ## Debuginfo +# +# Source attribution needs DWARF, which `[profile.release]` does not emit, so the +# probe is rebuilt with `CARGO_PROFILE_RELEASE_DEBUG=2`. Debuginfo adds DWARF +# sections without changing codegen — inlining, layout and instruction selection +# are identical — so the profile is faithful to the shipped binary. +# +# The script PRINTS the debuginfo probe's frame cost, but that is CONTEXT, not a +# verification of the claim above: it never builds a stock probe, so it has +# nothing to compare against. To check the claim, run `frame_probe` from a plain +# `cargo build --release` and compare medians yourself. +# +# ## Usage +# +# scripts/perf/frame_breakdown.sh # default nestest, 1500 frames +# scripts/perf/frame_breakdown.sh --rom path/to.nes +# scripts/perf/frame_breakdown.sh --frames 4000 --freq 3000 +# scripts/perf/frame_breakdown.sh --keep # keep perf.data for hotspot +# +# Requires `perf` and a host where `perf_event_paranoid <= 2` (user-space +# sampling of your own process). Skips with exit 0 if perf is unavailable, so +# this never becomes a hard CI dependency. +set -euo pipefail + +cd "$(dirname "${BASH_SOURCE[0]}")/../.." +ROOT="$(pwd)" + +ROM="tests/roms/nestest/nestest.nes" +FRAMES=1500 +FREQ=1500 +KEEP=0 + +while [[ $# -gt 0 ]]; do + case "$1" in + --rom) ROM="$2"; shift 2 ;; + --frames) FRAMES="$2"; shift 2 ;; + --freq) FREQ="$2"; shift 2 ;; + --keep) KEEP=1; shift ;; + -h|--help) sed -n '2,80p' "${BASH_SOURCE[0]}"; exit 0 ;; + *) echo "unknown argument: $1" >&2; exit 2 ;; + esac +done + +if ! command -v perf >/dev/null 2>&1; then + echo "SKIP: perf not installed — the breakdown needs sampling support." + exit 0 +fi +if [[ ! -f "${ROM}" ]]; then + echo "SKIP: ROM not found: ${ROM}" + exit 0 +fi + +paranoid="$(cat /proc/sys/kernel/perf_event_paranoid 2>/dev/null || echo 99)" +if [[ "${paranoid}" -gt 2 ]]; then + echo "SKIP: perf_event_paranoid=${paranoid} (>2) — cannot sample without elevated" + echo " privileges. Lower it with:" + echo " sudo sysctl kernel.perf_event_paranoid=2" + exit 0 +fi + +work="$(mktemp -d)" +trap '[[ "${KEEP}" == "1" ]] || rm -rf "${work}"' EXIT + +echo "==> Building frame_probe with debuginfo (codegen unchanged)" +CARGO_PROFILE_RELEASE_DEBUG=2 \ + cargo build --release -p rustynes-test-harness --bin frame_probe >/dev/null + +probe="${ROOT}/target/release/frame_probe" + +# Report the probe's own cost first, as context for the percentages below. It is +# NOT a check that debuginfo left the measurement undisturbed — no stock build is +# made here, so there is nothing to compare it against. See the header. +echo "==> Frame cost of the DEBUGINFO probe (context only — no stock build is" +echo " made here to compare against; see the header note)" +"${probe}" --rom "${ROM}" --frames 400 | sed 's/^/ /' + +echo +echo "==> Sampling ${FRAMES} frames at ${FREQ} Hz" +perf record -q -F "${FREQ}" -e cycles:u -o "${work}/perf.data" -- \ + "${probe}" --rom "${ROM}" --frames "${FRAMES}" >/dev/null 2>&1 + +# Build the basename -> subsystem map from the tree, so adding a source file +# never silently falls into UNATTRIBUTED and the map cannot drift from reality. +: > "${work}/map.txt" +# `test-harness` is included so the probe's OWN driver loop (frame_probe.rs) +# is reported as HARNESS rather than falling through to the non-workspace +# bucket, where it would be indistinguishable from inlined std/dependency code. +for crate in cpu ppu apu mappers core test-harness; do + case "${crate}" in + cpu) bucket=CPU ;; + ppu) bucket=PPU ;; + apu) bucket=APU ;; + mappers) bucket=MAPPERS ;; + core) bucket=COUPLING ;; + test-harness) bucket=HARNESS ;; + *) bucket=UNATTRIBUTED ;; + esac + find "crates/rustynes-${crate}/src" -name '*.rs' -printf '%f\n' 2>/dev/null \ + | sed "s|\$| ${bucket}|" >> "${work}/map.txt" +done + +perf report -i "${work}/perf.data" --no-children -g none --sort srcfile --stdio \ + 2>/dev/null | grep -E '^\s+[0-9]' > "${work}/by_file.txt" || true + +if [[ ! -s "${work}/by_file.txt" ]]; then + echo "SKIP: perf produced no source-attributed samples (missing DWARF?)." + exit 0 +fi + +python3 - "${work}/map.txt" "${work}/by_file.txt" <<'PY' +import collections, re, sys + +map_path, report_path = sys.argv[1], sys.argv[2] + +# basename -> set of buckets claimed by the tree scan. +owners = collections.defaultdict(set) +for line in open(map_path): + parts = line.split() + if len(parts) == 2: + owners[parts[0]].add(parts[1]) + +# Semantic overrides for the basenames owned by more than one emulation crate. +# bus.rs / scheduler.rs are the bus + scheduler abstraction in every crate that +# defines them, so the subsystem is the same whichever one a sample came from. +# lib.rs / snapshot.rs carry no such invariant and stay unattributed. +OVERRIDE = {"bus.rs": "COUPLING", "scheduler.rs": "COUPLING", + "nes.rs": "COUPLING", "lib.rs": None, "snapshot.rs": None} + +def bucket_for(fname): + if fname in OVERRIDE: + return OVERRIDE[fname] or "UNATTRIBUTED" + claims = owners.get(fname) + if not claims: + # Not one of ours: inlined std/core, or a dependency. + return "NONWORKSPACE-INLINED" + if len(claims) == 1: + return next(iter(claims)) + return "UNATTRIBUTED" + +totals = collections.Counter() +detail = collections.defaultdict(list) +grand = 0.0 +for line in open(report_path): + m = re.match(r'\s+([0-9.]+)%\s+(\S+)', line) + if not m: + continue + pct, fname = float(m.group(1)), m.group(2) + b = bucket_for(fname) + totals[b] += pct + grand += pct + detail[b].append((pct, fname)) + +ORDER = ["PPU", "CPU", "APU", "COUPLING", "MAPPERS", "HARNESS", + "NONWORKSPACE-INLINED", "UNATTRIBUTED"] +LABEL = { + "PPU": "PPU (rustynes-ppu)", + "CPU": "CPU (rustynes-cpu)", + "APU": "APU (rustynes-apu)", + "COUPLING": "Bus / scheduler coupling", + "MAPPERS": "Mappers", + "HARNESS": "probe driver (not emulator work)", + "NONWORKSPACE-INLINED": "std + deps inlined at call sites", + "UNATTRIBUTED": "unattributed (ambiguous basename)", +} + +print() +print(f"{'subsystem':<38} {'% of frame':>11} top source files") +print(f"{'-'*38} {'-'*11} {'-'*40}") +for b in ORDER: + if b not in totals: + continue + top = ", ".join(f"{f} {p:.1f}%" for p, f in sorted(detail[b], reverse=True)[:3]) + print(f"{LABEL[b]:<38} {totals[b]:>10.1f}% {top}") +print(f"{'-'*38} {'-'*11}") +print(f"{'accounted for':<38} {grand:>10.1f}%") + +print() +print("Notes:") +print(" * Percentages are of sampled cycles, bucketed by SOURCE FILE, so code") +print(" inlined across crate boundaries is credited to the crate that wrote") +print(" it. A symbol-level profile of this binary shows NO rustynes_apu at") +print(" all — the APU is inlined into cpu_clock and only source attribution") +print(" recovers it.") +print(" * 'std + deps inlined at call sites' is real emulator work whose source") +print(" path belongs to the standard library OR to a third-party crate. It is") +print(" reported rather than redistributed, which would invent precision.") +print(" * The residual below 100% is perf's own per-file percent rounding.") +PY + +if [[ "${KEEP}" == "1" ]]; then + echo + echo "perf.data kept at ${work}/perf.data" + echo " hotspot ${work}/perf.data" + echo " perf report -i ${work}/perf.data --no-children -g none --sort srcfile" +fi diff --git a/to-dos/plans/v2.3.1-plumb-line-plan.md b/to-dos/plans/v2.3.1-plumb-line-plan.md new file mode 100644 index 00000000..5d05d0fc --- /dev/null +++ b/to-dos/plans/v2.3.1-plumb-line-plan.md @@ -0,0 +1,305 @@ +# v2.3.1 "Plumb Line" — Measurement First, and What It Measured + +**Status:** COMPLETE · cut as **v2.3.1 "Plumb Line"** (2026-08-06) · branch `feat/v2.3.1-plumb-line` · base `be4fbef0` (v2.3.0 "Datum II") + +## Goal + +Make the measurement apparatus trustworthy before spending releases acting on +what it reports — then use it. Nothing downstream is worth doing on top of +numbers that cannot distinguish a real effect from a busy machine, or that +attribute a fifth of the frame to the wrong subsystem. + +**Scope note (maintainer decision).** This release originally covered only the +tooling, with the core hot-path campaign planned as a separate v2.3.2 "Grain". +The campaign ran, measured **ten items and rejected all ten**, and therefore had +no shippable content of its own. Its results are **folded into this release** — +they are the answer this measurement work existed to produce. The **"Grain" name +moves to the frontend / coupling / display work** (formerly "Conduit II"), where +the campaign's own evidence says the remaining wins actually are. Revised line: + +| release | theme | +| --- | --- | +| **v2.3.1 "Plumb Line"** | measurement apparatus **+ the core hot-path campaign's ten negative results** | +| **v2.3.2 "Grain"** | frontend, coupling, display (was "Conduit II") | +| **v2.3.3 "Lucid"** | the three novel features (was v2.3.4) | + +**No emulator source changes.** AccuracyCoin stays at exactly 141/141 and nestest +0-diff — verified after every probe was reverted, not merely by construction, +since this release did land (and remove) real experimental edits. + +## Why this release exists at all + +Two concrete failures in the immediately preceding work motivated it: + +1. **v2.3.0 P1 measured `+2%` on a contended host and `−5.13%` re-measured quiet + — the same commit, opposite sign.** The adopt/reject bar (>3%, same-runner, + byte-identical) is only as good as the host it runs on, and nothing in the + tooling noticed the host. +2. **The symbol profile the campaign was scoped from does not contain the APU.** + `perf report --no-children` on the release binary shows zero `rustynes_apu::` + symbols at any percent limit, because fat LTO inlines the APU wholesale into + `::cpu_clock`. The working split "PPU ~53%, CPU+bus ~39%" + silently folded ~19% of the frame into the wrong bucket. + +## Work items + +### 1. Harness-free frame-cost probe — DONE (`f468e76a`) + +`crates/rustynes-test-harness/src/bin/frame_probe.rs`. Runs the criterion +`full_frame` workload with **no criterion in the process image**, which had been +contributing ~17% of profile samples (rayon plumbing, `libm exp` from +distribution fitting, its sorts) on top of every per-function percentage. + +Reports median / p99 / min plus a robust MAD-based CV, and prints an explicit +**host-quiet verdict** rather than hiding spread behind a mean. Integer +nearest-rank percentiles, so there is no float `ceil` and no cast lint to +suppress. + +Deliberately *not* a criterion replacement: criterion still owns adopt/reject +verdicts because it does the statistics properly. This owns profiling and quick +iteration. + +### 2. Per-subsystem cost breakdown — DONE (`32fc0075`) + +`scripts/perf/frame_breakdown.sh`. Profiles the probe and buckets samples by +**source file**, which follows inlined code back to the crate that wrote it. + +Measured (nestest, 1500 frames, 1500 Hz, quiet host): + +| subsystem | % of frame | +| --- | ---: | +| PPU (`rustynes-ppu`) | 52.1% | +| **APU (`rustynes-apu`)** | **18.7%** | +| CPU (`rustynes-cpu`) | 10.1% | +| Bus / scheduler coupling | 9.9% | +| std inlined at emulator call sites | 6.7% | +| Mappers | 2.5% | + +`perf report --inline` does **not** recover the APU — measured, it produces +output byte-identical to the non-inline report, because those frames are not +recoverable as call frames. Source attribution is the only method tried that +works. + +Consequence for v2.3.2: the PPU share holds, but **the CPU proper is about a +third of what it appeared to be**, and the APU is the second-largest consumer. +This does *not* reopen §P4 — that measured the one remaining APU lever at a +**≤1.9% ceiling**, and "large" is not "reducible". It does mean any future APU +work should be scoped against 19%, not against the ~0% the symbol view implies. + +Known limits, recorded in the script header rather than left implicit: perf emits +basenames, so the basename → subsystem map is built by scanning the tree at run +time; `bus.rs` / `scheduler.rs` bucket to coupling regardless of owning crate +(verified against a joint `sym,srcfile` view — all three crates' `bus.rs` samples +are bus work); `lib.rs` / `snapshot.rs` go to an explicit unattributed bucket +rather than being guessed at; inlined std code is reported on its own line and +**not** redistributed proportionally. + +### 3. Contention-aware A/B gate — DONE (`52cedcb8`) + +`scripts/bench_relative_check.sh` now reads criterion's own `sample.json` + +`tukey.json` for both runs and **declines to emit a verdict** when the host was +too noisy to resolve the effect being tested for. + +The first design gated on criterion's **outlier %** — the obvious signal — and +real data falsified it before it shipped: + +| bench | outliers | robust CV | +| --- | ---: | ---: | +| `nes_run_frame_flowing_palette_fast` | **30.0%** | **0.19%** | +| `nes_run_frame_nestest` | 20.0% | 0.58% | +| `nes_run_frame_flowing_palette` | 6.0% | 1.18% | +| `nes_run_frame_nestest_fast` | **0.0%** | **2.79%** | + +The two axes invert: criterion's fences are IQR-derived, so a benchmark whose +bulk is unusually *tight* flags a huge outlier fraction from tiny excursions. +Gating on outlier % would have refused a verdict on the quietest run in the set. +Robust CV (`1.4826 × MAD / median`) is the trigger; outlier % is reported as +evidence only. + +The threshold is derived, not chosen: contended once `3 × CV` exceeds +`BENCH_MAX_REGRESSION_PCT`, i.e. once the noise band can swallow the regression +being tested for. Verdicts: + +| host | delta | verdict | +| --- | --- | --- | +| quiet | within limit | PASS | +| quiet | over limit | FAIL | +| contended | beyond 3× CV | FAIL (contention inflates; it does not invent) | +| contended | within 3× CV | **NO VERDICT**, exit 0, loudly | + +All four paths exercised against synthetic baselines built from on-disk criterion +data, so the logic is verifiable without a bench run. + +### 4. BOLT — measurement dispatched, verdict pending + +BOLT already exists (`.github/workflows/pgo.yml`) but runs only on an explicit +`workflow_dispatch` with `run_bolt: true`, and its number was never recorded. +Measurement run [31006334399](https://github.com/doublegate/RustyNES/actions/runs/31006334399) +dispatched against `main` at 3600 training frames. + +Decision rule, unchanged from the rest of the project: promote to a standard step +of the Linux release path only on **>3% and byte-identical**. Document the number +either way, including a rejection. + +### 5. PGO corpus study — assessed, not run + +The corpus is 7 committed ROMs (`pgo_trainer.rs`), covering NROM static + +render-heavy, MMC1, MMC3, APU/DMC, sprite-eval stress, and the AccuracyCoin +gauntlet. + +**Method note that constrains the study.** A corpus A/B cannot be done as two +absolute measurements across two dispatches — that is exactly the cross-run +comparison the gate in item 3 refuses. It *can* be done by comparing each run's +own PGO-vs-plain **ratio**, which is the runner-invariant quantity. But the noise +on each ratio is on the order of a percent or two on a shared runner, so the +study can only resolve a corpus effect of roughly that size or larger. + +**Prior expectation is that the effect is below that floor:** per item 2 the +profile is dominated by PPU (52%) and APU (19%), both already represented in the +corpus by `flowing_palette` / `oam_stress` and `db_apu`, while mappers — where +widening would add the most *variety* — are 2.5% of frame cost. Running two more +40-minute jobs to produce an underpowered inconclusive result is not a good +trade; recorded here so the reasoning is visible rather than the item silently +dropped. + +### 6. `cargo-nextest` — assessed, deferred to maintainer + +Would shorten the verify loop (~1.3–1.5× test wall-clock). Not adopted here +because nextest **does not run doctests**, and this workspace has doc examples in +the core chip crates that `cargo test --workspace` currently covers. Adopting it +means adding a separate `cargo test --doc` step to the local gate and CI — a +workflow change that belongs to the maintainer, not a drive-by. + +## Verification bar + +- No emulator source touched → AccuracyCoin **exactly 141/141**, nestest 0-diff + by construction. +- `bash -n` + `shellcheck` clean on both scripts. +- `pre-commit run --files ` clean (never `--all-files` — it rewrites + vendored trees). +- Every campaign entry recorded in `docs/performance.md`, **including the + rejections and their numbers** — the convention that let this plan skip so many + already-settled dead ends. + +## The core hot-path campaign (folded in) — ten measured, ten rejected + +Every item below was measured with the apparatus above and **all ten were +rejected**. Full numbers, controls and mechanisms are in `docs/performance.md` +(entries G1–G10); this section keeps the ranking history that led into them, +because the gap between the predicted ranking and the measured outcome is itself +the result. + +**Outcome by item:** + +| item | predicted | measured | +| --- | --- | --- | +| 9b idle-line fast path | worth re-testing | REJECTED — mixed signs, shipped configs flat | +| 7 field layout | promote (cheap) | REJECTED — premise false; `repr(Rust)` ignores source order | +| 5 sink dead derivations | keep high (P1 shape) | REJECTED — LLVM already sinks pure computations | +| 8 skip index framebuffer | keep, modest | REJECTED — ceiling zero (store absorbed off critical path) | +| 6 open-bus decay deadline | keep | REJECTED — ceiling zero | +| 2 hoist ALE recompute | keep, modest | REJECTED — ceiling zero; also unadoptable (freezes A12) | +| 1 inline audit | downgrade | REJECTED — large fn regressed +0.60%, small fn nil | +| 10 typed-index elision | expect reject | REJECTED — checks removed, bought nothing | +| 3 gate `bg_split_state` | drop (0.09%) | REJECTED — ceiling zero, as predicted | +| 4 hoist `PpuBusAdapter` | drop (no symbol) | REJECTED — **not implementable** without `unsafe` | + +The two downgraded-on-evidence items (3, 4) were measured anyway at the +maintainer's instruction — "you never know until we measure it" — and both +confirmed. The promoted items did not. + +### The ranking that produced them + +Scoped against the symbol profile ("PPU ~53%, CPU+bus ~39%"), then re-ranked +against source attribution with a measured ceiling for each rather than a call +count. Call counts describe how *often* code runs; only the profile says whether +that costs anything — and, as the campaign then showed, not even the profile says +whether removing it *saves* anything. + +**The single most consequential finding:** `cpu_clock` is **86% inlined APU**. +Its 18.3% symbol time decomposes to `apu.rs` 6.19 + `frame_counter.rs` 2.38 + +`blip.rs` 2.14 + `pulse.rs` 2.01 + `length.rs` 1.10 + `noise.rs` 0.93 + +`mixer.rs` 0.74 + `triangle.rs` 0.34 = **15.83%**, against **1.79%** of actual +`bus.rs` code. `Cpu::end_cycle` is the same story (2.53% of its 9.02% is +`apu.rs`). Item 1 was ranked "highest expected value" on the strength of +`cpu_clock` being ~16% of *bus* code. It is not. + +| # | item | measured ceiling | **pre-campaign** recommendation | +| --- | --- | ---: | --- | +| 9 | widen fast-dot coverage (HBlank window) | `Ppu::tick` 27.7%; its prologue line alone 1.84% | **promote to first** | +| 5 | stop recomputing discarded per-dot values | `tick_oam_bus` 5.53%; hot line 0.95% | **keep high** (v2.3.0 P1 precedent) | +| 7 | `Ppu` field layout by access frequency | `ppu.rs` 51.7%, concentrated in `tick`/`emit_pixel` | **promote** — cheap, byte-identical by construction | +| 2 | hoist duplicated ALE/fetch address computation | `ale_drive_*` 1.55% combined | keep, modest | +| 6 | open-bus decay → deadline | same shape as `ppudata_sm_countdown` line at 0.81% | keep, and see the new sibling below | +| 8 | skip the unused index framebuffer | write line 0.78%, plus untallied cache pressure from touching 61,440 `u16` entries (122,880 B)/frame | keep, modest; bundle with 7 | +| 1 | inline audit of `core/bus.rs` | premise true (0 hints in 5,349 lines) but only 1.79% of the frame is `bus.rs` inside `cpu_clock`; `run_ppu_to` / `apu_advance_one` / `PpuBusAdapter` emit **no symbols at all**, i.e. LTO already inlined them | **downgrade** — cheap to try, but the ranking rested on an inflated figure | +| 10 | typed-index bounds elision (`oam` / `ciram`) | — | keep as measure-and-expect-reject (P3 precedent) | +| 3 | capability-gate `bg_split_state` | **0.09%** — it is in the profile, at nine hundredths of a percent | **drop as a perf item** (cannot clear a 3% bar by 30×) | +| 4 | hoist `PpuBusAdapter` out of the per-dot loop | no adapter symbol survives codegen | **drop** — already optimized away | + +### Gaps the correction exposes + +- **The APU is 18.7% of the frame and Grain contains zero APU items.** That is a + direct consequence of scoping from a profile in which the APU was invisible. + This does **not** contradict §P4, which measured *mixed-sample caching* at a + ≤1.9% ceiling; the per-APU-cycle channel tick path is a different target + (`frame_counter.rs` 2.38%, `pulse.rs` 2.01%, `length.rs` 1.10%, + `noise.rs` 0.93%). Worth one measured item; not worth assuming it is free + either way. +- **`range.rs` costs 1.52% *inside* `Ppu::tick`** — range/iterator machinery in + the hottest loop in the emulator. Investigate what it is before assuming it is + addressable, but it is a larger single line item than four of the ten items + above. +- **A per-dot countdown decrement sibling to item 6**: `ppudata_sm_countdown` + (0.81%) has exactly the shape item 6 targets for open-bus decay. If the + deadline rewrite works for one, it applies to both. + +Every figure above is nestest at 1500 Hz on a quiet host and is a *ceiling*, not +a prediction: removing 100% of a line's cost is the best case. + +**Of the three gaps above, only the first two remain open.** The +`ppudata_sm_countdown` sibling is closed by G5: the open-bus decay it mirrors has +a ceiling of zero, so the same rewrite applied to the same shape would too. The +APU (18.7%) and `range.rs`-inside-`Ppu::tick` (1.52%) were never measured and are +the only core leads this campaign leaves behind — both should be ceiling-probed +before any implementation, on the evidence of all ten items above. + +## What this campaign changed about how the project measures + +Three practices, each earned by a specific near-miss, all now encoded in tooling +rather than in habit: + +1. **A/B/A order-bias control** (`scripts/perf/ab_check.sh`). The reference is + benched a third time, last, against its own first run; whatever it reports is + drift from position alone. Added after G2 produced a −1.84%…−2.75% result at + p = 0.00 on all four workloads that was pure artifact. +2. **Ceiling probes.** Delete the work — knowingly breaking correctness — and + measure the bound before engineering anything. Settled G4, G5, G6 and G9 in + one run each. G4 alone would otherwise have meant threading an opt-in flag + through four consumers for a zero gain. +3. **Mandatory second run.** The adoption bar moved from effect *size* to + evidence *quality* (below-3% gains are adoptable) — which only works if a + single run is never sufficient. G6 measured −0.51% at p = 0.00 on a shipped + configuration and +0.01% (p = 0.96) on re-run. + +Also recorded: `nestest` is the first workload criterion benches, absorbs the +most warm-up, and is where drift appeared most often across every run here. Treat +a `nestest`-only result with suspicion. + +## Carried forward + +- **BOLT verdict** → `docs/performance.md`. Run 31006334399 failed before + producing a number (`apt-get install bolt` installs Ubuntu's *Thunderbolt 3 + device manager*, not LLVM BOLT); the probe now locates the binary instead of + trusting the package manager, but that fix is **committed and unexercised**. +- **PGO corpus study** — assessed, not run; see item 5 above for the method + constraint that bounds what it could resolve. +- **`cargo-nextest`** — assessed, deferred to the maintainer (it does not run + doctests, which this workspace has). +- **Remaining core leads**: the APU at 18.7% and `range.rs` at 1.52% inside + `Ppu::tick`. Ceiling-probe both before implementing anything. +- **Grain (v2.3.2) is now the frontend / coupling / display work.** The core + campaign's own evidence points there: its targets are whole-buffer costs — + three full 720 KiB framebuffer memcpys per displayed frame, a ~250 KB snapshot + per run-ahead frame, a per-frame `format!` storm under the emulator lock — not + the instruction-level bookkeeping that came back empty ten times.