Skip to main content

max / audiofiles

Measure per-stage analysis timing at vault scale Section 1 times the analysis stages per file, against the corpus and no vault, so its numbers say nothing about whether they still hold once a library is large. AF_BENCH_STAGES runs the same breakdown mid-import at each batch boundary and reports the curve. persist is the column the section exists for. The DSP stages work on one decoded buffer and cannot see the vault, so a flat line from them is the expected result and the useful one: it says the per-file numbers keep their meaning at scale. Persistence writes into a growing database, and section 1 never touches the DB at all. Off by default. The probe competes with the import it interrupts, so a run with it on is not comparable with the ingest baselines already saved under benchmarks/. It also probes after the batch timer stops, so its own work never lands inside a files/s figure. Two corrections to the reporting, both found by reading output that was already wrong. The first probe is discarded as warmup: an earlier version compared first to last and reported "DSP total -84.7%" on a run where nothing had degraded, because at 15 files per probe the first checkpoint is dominated by cold cache and first decode. The import curve above can compare endpoints since its batches are 500 files; a probe this small cannot, so the summary reports a range across steady-state checkpoints and says so when the spread is wide enough to be noise. And a stage under the display resolution prints <0.01 rather than 0.00: a one-shot corpus drives detect_bpm_key and is_loop to microseconds through their early returns, and 0.00 in a column being scanned for a bottleneck reads as free work.
Co-Authored-By
Claude Opus 5 (1M context) <noreply@anthropic.com>
Author: Max Johnson <me@maxj.phd> · 2026-08-05 16:26 UTC
Signed with PGP, not checked
Commit: 89ad3b6aa621008f93e937c964d53aea9c695f40
Parent: 46717b0
3 files changed, +384 insertions, -21 deletions
M Cargo.lock +8 -8
@@ -7297,14 +7297,6 @@
7297 7297 "winnow 1.0.4",
7298 7298 ]
7299 7299
7300 - [[patch.unused]]
7301 - name = "docengine"
7302 - version = "0.4.0"
7303 -
7304 - [[patch.unused]]
7305 - name = "supernote-push"
7306 - version = "0.1.0"
7307 -
7308 7300 [[patch.unused]]
7309 7301 name = "kberg"
7310 7302 version = "0.1.0"
@@ -7312,3 +7304,11 @@
7312 7304 [[patch.unused]]
7313 7305 name = "painhours"
7314 7306 version = "0.1.0"
7307 +
7308 + [[patch.unused]]
7309 + name = "supernote-push"
7310 + version = "0.1.0"
7311 +
7312 + [[patch.unused]]
7313 + name = "docengine"
7314 + version = "0.4.0"
M crates/audiofiles-bench/src/ingest.rs +355
@@ -48,6 +48,261 @@
48 48 .unwrap_or(2000)
49 49 }
50 50
51 + /// How many files to run the per-stage probe over at each checkpoint, or 0 for
52 + /// no probe.
53 + ///
54 + /// Off by default, and that is deliberate rather than timid. The probe analyses
55 + /// files in the middle of an import, so it competes for the drive and the page
56 + /// cache with the thing being measured. Every ingest baseline saved before this
57 + /// existed was recorded without it, and turning it on by default would make new
58 + /// runs quietly incomparable with `benchmarks/ingest-2026-07-29-*.json`. Opt in
59 + /// when the per-stage curve is the question; leave it off when the ingest curve
60 + /// is.
61 + fn stage_probe_size() -> usize {
62 + std::env::var("AF_BENCH_STAGES")
63 + .ok()
64 + .and_then(|v| v.parse().ok())
65 + .unwrap_or(0)
66 + }
67 +
68 + /// One per-stage probe: the DSP breakdown plus persistence, at a known vault size.
69 + ///
70 + /// `persist_ms` is the reason this exists. The DSP stages are pure CPU over one
71 + /// decoded buffer and have no way to know how large the vault is, so a flat line
72 + /// from them is the expected result and the useful one: it says the per-file
73 + /// numbers in section 1 keep their meaning at scale. Persistence is the stage
74 + /// that can degrade, because it writes into a growing database, and section 1
75 + /// never touches the DB at all.
76 + struct StageProbe {
77 + samples: i64,
78 + decode_ms: f64,
79 + loudness_ms: f64,
80 + spectral_ms: f64,
81 + mfcc_ms: f64,
82 + vector_ms: f64,
83 + bpm_key_ms: f64,
84 + loop_ms: f64,
85 + fingerprint_ms: f64,
86 + total_ms: f64,
87 + persist_ms: f64,
88 + files: usize,
89 + }
90 +
91 + /// Run the per-stage probe over `files` against a vault currently holding
92 + /// `samples` rows.
93 + ///
94 + /// Medians, not means: one file that happens to be long drags a mean far enough
95 + /// to invent a trend across checkpoints that is not there.
96 + fn stage_probe(
97 + db: &Database,
98 + samples: i64,
99 + files: &[(String, PathBuf)],
100 + config: &AnalysisConfig,
101 + ) -> Option<StageProbe> {
102 + if files.is_empty() {
103 + return None;
104 + }
105 + let mut decode = Vec::new();
106 + let mut loud = Vec::new();
107 + let mut spec = Vec::new();
108 + let mut mfcc = Vec::new();
109 + let mut vector = Vec::new();
110 + let mut bpm_key = Vec::new();
111 + let mut loops = Vec::new();
112 + let mut fp = Vec::new();
113 + let mut total = Vec::new();
114 +
115 + for (_, path) in files {
116 + let Some((t, _, _)) = crate::time_stages(path) else {
117 + continue;
118 + };
119 + decode.push(t.decode_ms);
120 + loud.push(t.loudness_ms);
121 + spec.push(t.spectral_ms);
122 + mfcc.push(t.mfcc_ms);
123 + vector.push(t.vector_ms);
124 + bpm_key.push(t.bpm_key_ms);
125 + loops.push(t.loop_ms);
126 + fp.push(t.fingerprint_ms);
127 + total.push(t.total_ms);
128 + }
129 + if total.is_empty() {
130 + return None;
131 + }
132 +
133 + // Persistence is measured on a real analysis of the same files, written into
134 + // the live vault. Timing a fabricated row would measure the wrong statement.
135 + let results: Vec<_> = files
136 + .iter()
137 + .filter_map(|(hash, path)| analysis::analyze_sample(hash, path, config).ok())
138 + .collect();
139 + let persist_start = Instant::now();
140 + let persisted = analysis::save_analysis_batch(db, &results).is_ok();
141 + let persist_total_ms = persist_start.elapsed().as_secs_f64() * 1000.0;
142 + let persist_ms = if persisted && !results.is_empty() {
143 + persist_total_ms / results.len() as f64
144 + } else {
145 + f64::NAN
146 + };
147 +
148 + let files_probed = total.len();
149 + Some(StageProbe {
150 + samples,
151 + decode_ms: crate::percentile(&mut decode, 50.0),
152 + loudness_ms: crate::percentile(&mut loud, 50.0),
153 + spectral_ms: crate::percentile(&mut spec, 50.0),
154 + mfcc_ms: crate::percentile(&mut mfcc, 50.0),
155 + vector_ms: crate::percentile(&mut vector, 50.0),
156 + bpm_key_ms: crate::percentile(&mut bpm_key, 50.0),
157 + loop_ms: crate::percentile(&mut loops, 50.0),
158 + fingerprint_ms: crate::percentile(&mut fp, 50.0),
159 + total_ms: crate::percentile(&mut total, 50.0),
160 + persist_ms,
161 + files: files_probed,
162 + })
163 + }
164 +
165 + /// The per-stage curve as a JSON array, one object per checkpoint.
166 + fn stage_series(probes: &[StageProbe]) -> serde_json::Value {
167 + serde_json::Value::Array(
168 + probes
169 + .iter()
170 + .map(|p| {
171 + let round = |v: f64| (v * 1000.0).round() / 1000.0;
172 + serde_json::json!({
173 + "samples": p.samples,
174 + "files_probed": p.files,
175 + "decode_ms": round(p.decode_ms),
176 + "loudness_ms": round(p.loudness_ms),
177 + "spectral_ms": round(p.spectral_ms),
178 + "mfcc_ms": round(p.mfcc_ms),
179 + "vector_ms": round(p.vector_ms),
180 + "bpm_key_ms": round(p.bpm_key_ms),
181 + "loop_ms": round(p.loop_ms),
182 + "fingerprint_ms": round(p.fingerprint_ms),
183 + "total_ms": round(p.total_ms),
184 + // NaN is not representable in JSON, so a failed persist
185 + // reads as null rather than as a plausible number.
186 + "persist_ms": if p.persist_ms.is_finite() {
187 + serde_json::json!(round(p.persist_ms))
188 + } else {
189 + serde_json::Value::Null
190 + },
191 + })
192 + })
193 + .collect(),
194 + )
195 + }
196 +
197 + /// Print the per-stage curve, and say whether anything actually drifted.
198 + fn report_stage_series(probes: &[StageProbe]) {
199 + if probes.is_empty() {
200 + return;
201 + }
202 + println!();
203 + println!("━━━ PER-STAGE TIMING AT VAULT SCALE ━━━");
204 + println!();
205 + println!(" Medians in ms per file, probed mid-import at each vault size.");
206 + println!(" DSP stages should be flat: they cannot see the vault. persist");
207 + println!(" writes into the growing DB and is the one that can drift.");
208 + println!();
209 + println!(
210 + " {:>8} {:>7} {:>7} {:>7} {:>7} {:>7} {:>7} {:>8}",
211 + "samples", "decode", "spectral", "mfcc", "bpm/key", "loop", "total", "persist"
212 + );
213 + println!(" {}", "-".repeat(70));
214 + // Anything under the display resolution prints as `<0.01`, never as `0.00`.
215 + // The corpus is what makes this matter: `detect_bpm_key` and `is_loop` bail
216 + // out early on a file too short to hold a beat, so a one-shot corpus drives
217 + // both to microseconds. Those are real early returns, not free work, and
218 + // `0.00` in a column somebody is scanning for a bottleneck reads as "this
219 + // stage costs nothing" rather than "this stage declined to run here".
220 + let cell = |v: f64| {
221 + if v.abs() < 0.005 {
222 + "<0.01".to_string()
223 + } else {
224 + format!("{v:.2}")
225 + }
226 + };
227 + for p in probes {
228 + let persist = if p.persist_ms.is_finite() {
229 + format!("{:.3}", p.persist_ms)
230 + } else {
231 + "FAILED".to_string()
232 + };
233 + println!(
234 + " {:>8} {:>7} {:>7} {:>7} {:>7} {:>7} {:>7} {:>8}",
235 + p.samples,
236 + cell(p.decode_ms),
237 + cell(p.spectral_ms),
238 + cell(p.mfcc_ms),
239 + cell(p.bpm_key_ms),
240 + cell(p.loop_ms),
241 + cell(p.total_ms),
242 + persist
243 + );
244 + }
245 +
246 + println!();
247 + if probes.len() < 3 {
248 + // Deliberately no trend line here. The first probe carries the warmup
249 + // this whole section has to exclude, so with fewer than three
250 + // checkpoints there is nothing left to compare after dropping it.
251 + println!(" fewer than 3 checkpoints, so no trend is reported: the first");
252 + println!(" probe carries cold-cache warmup and there is nothing left to");
253 + println!(" compare against once it is dropped. Raise the file count or");
254 + println!(" lower AF_BENCH_BATCH.");
255 + return;
256 + }
257 +
258 + // THE FIRST PROBE IS DISCARDED, and this is the correction that makes the
259 + // section honest. An early version compared first to last and reported
260 + // "DSP total -84.7%" on a run where nothing had degraded at all: at 15 files
261 + // per probe, the first checkpoint is dominated by cold page cache and first
262 + // decode, so it is 3-5x the steady-state cost. The import curve above can
263 + // compare first to last because its batches are 500 files and amortise that
264 + // away; a probe this small cannot. Reporting a warmup artifact as a scaling
265 + // trend is precisely the failure mode the measurement-traps list exists for.
266 + let steady = &probes[1..];
267 + let spread = |mut v: Vec<f64>| {
268 + let hi = crate::percentile(&mut v.clone(), 100.0);
269 + let lo = crate::percentile(&mut v, 0.0);
270 + (lo, hi)
271 + };
272 + let (dsp_lo, dsp_hi) = spread(steady.iter().map(|p| p.total_ms).collect());
273 + println!(
274 + " Steady state ({} checkpoints, first dropped as warmup):",
275 + steady.len()
276 + );
277 + println!(
278 + " DSP total {dsp_lo:.2} to {dsp_hi:.2} ms{}",
279 + if dsp_lo > 1e-9 && dsp_hi / dsp_lo > 2.0 {
280 + " <- spread over 2x, treat as noise not trend"
281 + } else {
282 + ""
283 + }
284 + );
285 + let persists: Vec<f64> = steady
286 + .iter()
287 + .map(|p| p.persist_ms)
288 + .filter(|v| v.is_finite())
289 + .collect();
290 + if persists.is_empty() {
291 + println!(" persist not measured");
292 + } else {
293 + let (p_lo, p_hi) = spread(persists);
294 + println!(" persist {p_lo:.3} to {p_hi:.3} ms");
295 + if p_lo > 1e-9 && p_hi / p_lo > 2.0 {
296 + println!(" ^ persistence moved more than 2x across the fill: the stage");
297 + println!(" that writes into the growing DB is the one to look at.");
298 + }
299 + }
300 + println!();
301 + println!(" A range, not a delta: two endpoints cannot tell a trend from");
302 + println!(" noise. The machine has to be idle for any of this to mean");
303 + println!(" anything (wiki af-benchmarks, \"Measurement traps\").");
304 + }
305 +
51 306 /// Deterministic reorder of the file list.
52 307 ///
53 308 /// Without this the list arrives sorted by path, which groups files by class,
@@ -340,6 +595,14 @@
340 595 // measurement and this avoids an extension lookup per sample.
341 596 let mut imported: Vec<(String, PathBuf)> = Vec::with_capacity(files.len());
342 597
598 + let probe_size = stage_probe_size();
599 + let mut probes: Vec<StageProbe> = Vec::new();
600 + let probe_config = AnalysisConfig::default();
601 + if probe_size > 0 {
602 + println!(" (per-stage probe on, {probe_size} file(s) per batch: import numbers below");
603 + println!(" are NOT comparable with baselines recorded without it)");
604 + }
605 +
343 606 for chunk in files.chunks(batch) {
344 607 let mut bytes = 0u64;
345 608 let start = Instant::now();
@@ -394,6 +657,21 @@
394 657 report.set("import_files", stats.iter().map(|s| s.files).sum::<usize>());
395 658 report.set("import_bytes", stats.iter().map(|s| s.bytes).sum::<u64>());
396 659 report.set("import_complete", false);
660 +
661 + // Probe AFTER the batch timer has stopped, so the probe's own decode and
662 + // DB work never lands inside a files/s figure. It still perturbs the
663 + // drive and the page cache for the batches that follow, which is why the
664 + // whole thing is opt-in.
665 + if probe_size > 0 {
666 + let sample_rows = count_samples(&db);
667 + let recent: Vec<(String, PathBuf)> =
668 + imported.iter().rev().take(probe_size).cloned().collect();
669 + if let Some(p) = stage_probe(&db, sample_rows, &recent, &probe_config) {
670 + probes.push(p);
671 + report.set("stage_series", stage_series(&probes));
672 + }
673 + }
674 +
397 675 report.checkpoint();
398 676 }
399 677
@@ -454,6 +732,8 @@
454 732 report.set("import_throughput_drift_pct", (delta * 10.0).round() / 10.0);
455 733 }
456 734
735 + report_stage_series(&probes);
736 +
457 737 // Dedup: re-importing the same files must hit the content-addressed store
458 738 // and skip the copy. If this is not dramatically faster, dedup is not
459 739 // working and every duplicate costs a full hash-and-copy.
@@ -560,3 +840,78 @@
560 840 );
561 841 report.write();
562 842 }
843 +
844 + #[cfg(test)]
845 + mod tests {
846 + use super::*;
847 +
848 + fn probe(samples: i64, total_ms: f64, persist_ms: f64) -> StageProbe {
849 + StageProbe {
850 + samples,
851 + decode_ms: 1.0,
852 + loudness_ms: 1.0,
853 + spectral_ms: 1.0,
854 + mfcc_ms: 1.0,
855 + vector_ms: 1.0,
856 + bpm_key_ms: 1.0,
857 + loop_ms: 1.0,
858 + fingerprint_ms: 1.0,
859 + total_ms,
860 + persist_ms,
861 + files: 25,
862 + }
863 + }
864 +
865 + #[test]
866 + fn stage_probe_is_off_unless_asked_for() {
867 + // Guards the default. Turning the probe on silently would make every
868 + // new ingest run incomparable with the saved baselines.
869 + // SAFETY: single-threaded test, no other thread reads the environment.
870 + unsafe { std::env::remove_var("AF_BENCH_STAGES") };
871 + assert_eq!(stage_probe_size(), 0);
872 + }
873 +
874 + #[test]
875 + fn stage_series_carries_one_object_per_checkpoint() {
876 + let series = stage_series(&[probe(500, 12.0, 0.4), probe(1000, 12.5, 0.6)]);
877 + let rows = series.as_array().unwrap();
878 + assert_eq!(rows.len(), 2);
879 + assert_eq!(rows[0]["samples"], 500);
880 + assert_eq!(rows[1]["samples"], 1000);
881 + assert_eq!(rows[0]["files_probed"], 25);
882 + assert!((rows[1]["persist_ms"].as_f64().unwrap() - 0.6).abs() < 1e-9);
883 + }
884 +
885 + #[test]
886 + fn a_failed_persist_serialises_as_null_not_as_a_number() {
887 + // NaN has no JSON spelling. Emitting it as 0.0 would read downstream as
888 + // "persistence was free", which is the opposite of what happened.
889 + let series = stage_series(&[probe(500, 12.0, f64::NAN)]);
890 + assert!(series[0]["persist_ms"].is_null());
891 + }
892 +
893 + #[test]
894 + fn a_trend_needs_more_than_two_checkpoints() {
895 + // Regression guard on a real mistake: an early version compared the
896 + // first probe to the last and reported "DSP total -84.7%" on a run
897 + // where nothing degraded. The first probe is warmup, so it is dropped,
898 + // and with fewer than three checkpoints nothing survives to compare.
899 + // These call the printer for absence of panic; the contract they pin is
900 + // that `steady` is `probes[1..]` and is only read when len >= 3.
901 + report_stage_series(&[]);
902 + report_stage_series(&[probe(100, 40.0, 0.05)]);
903 + report_stage_series(&[probe(100, 40.0, 0.05), probe(200, 12.0, 0.05)]);
904 + report_stage_series(&[
905 + probe(100, 40.0, 0.05),
906 + probe(200, 12.0, 0.05),
907 + probe(300, 12.5, 0.06),
908 + ]);
909 + }
910 +
911 + #[test]
912 + fn stage_probe_returns_nothing_for_an_empty_file_set() {
913 + let db = Database::open_in_memory().unwrap();
914 + let config = AnalysisConfig::default();
915 + assert!(stage_probe(&db, 0, &[], &config).is_none());
916 + }
917 + }
M crates/audiofiles-bench/src/main.rs +21 -13
@@ -22,7 +22,15 @@
22 22 //! `AF_BENCH_VAULT` (scratch vault for ingest and layout), `AF_BENCH_FSL10K`
23 23 //! (FSL10K root for accuracy), `AF_BENCH_BATCH`, `AF_BENCH_LIMIT`,
24 24 //! `AF_BENCH_ANALYZE`, `AF_BENCH_LAYOUT_N`, `AF_BENCH_JSON` (machine-readable
25 - //! output path), `AF_AFCL_OUT` (where `afcl` writes the layer).
25 + //! output path), `AF_AFCL_OUT` (where `afcl` writes the layer),
26 + //! `AF_BENCH_STAGES` (files per per-stage probe during `ingest`, 0 = off).
27 + //!
28 + //! Section 1 times the analysis stages per file, against the corpus and no
29 + //! vault. `AF_BENCH_STAGES` runs the same breakdown mid-import at each batch
30 + //! boundary, which is what says whether those per-file numbers still hold as a
31 + //! vault fills. It is off by default because the probe competes with the import
32 + //! it interrupts, so a run with it on is not comparable with the saved ingest
33 + //! baselines.
26 34 //!
27 35 //! Every mode opens with a conditions block naming the drive behind each path.
28 36 //! These numbers are I/O bound, so they belong to a drive as much as to the
@@ -52,19 +60,19 @@
52 60 // The `_ms` suffix is the unit, not redundant naming. Dropping it would leave
53 61 // bare `decode`/`loudness` fields whose scale a reader has to guess.
54 62 #[allow(clippy::struct_field_names)]
55 - struct StageTiming {
56 - decode_ms: f64,
57 - loudness_ms: f64,
58 - spectral_ms: f64,
59 - mfcc_ms: f64,
60 - vector_ms: f64,
61 - bpm_key_ms: f64,
62 - loop_ms: f64,
63 - fingerprint_ms: f64,
64 - total_ms: f64,
63 + pub(crate) struct StageTiming {
64 + pub(crate) decode_ms: f64,
65 + pub(crate) loudness_ms: f64,
66 + pub(crate) spectral_ms: f64,
67 + pub(crate) mfcc_ms: f64,
68 + pub(crate) vector_ms: f64,
69 + pub(crate) bpm_key_ms: f64,
70 + pub(crate) loop_ms: f64,
71 + pub(crate) fingerprint_ms: f64,
72 + pub(crate) total_ms: f64,
65 73 }
66 74
67 - fn time_stages(path: &Path) -> Option<(StageTiming, f64, u32)> {
75 + pub(crate) fn time_stages(path: &Path) -> Option<(StageTiming, f64, u32)> {
68 76 let total_start = Instant::now();
69 77
70 78 // Decode
@@ -215,7 +223,7 @@
215 223
216 224 // Report Formatting
217 225
218 - fn percentile(values: &mut [f64], p: f64) -> f64 {
226 + pub(crate) fn percentile(values: &mut [f64], p: f64) -> f64 {
219 227 if values.is_empty() {
220 228 return 0.0;
221 229 }