M9.7: AV1 decode statistics (per-stage busy time) and perf test with stage breakdown

Decoder::stats() reports frames, tiles and the busy time of setup, tile decoding,
deblocking, CDEF, superres, loop restoration and output. The ignored perf test
measures single-threaded throughput with the thread CPU clock (robust to machine
load), prints ms/frame per stage, and the all-cores wall-clock rate next to the
load average. Adds high-quality and 4x2-tile 1080p fixtures. Decoder::with_threads
and flush() are added as the API the threaded decoder will use.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Cargo.lock

@@ -1362,6 +1362,7 @@ dependencies = [
  "filmcraft-bitstream",
  "filmcraft-testkit",
  "rayon",
+ "rustix 1.1.5",
  "thiserror 2.0.21",
 ]
 

crates/av1/Cargo.toml

@@ -20,3 +20,7 @@ rayon = { workspace = true, optional = true }
 
 [dev-dependencies]
 filmcraft-testkit = { workspace = true }
+
+# Thread CPU clock for load-robust performance tests.
+[target.'cfg(unix)'.dev-dependencies]
+rustix = { version = "1", default-features = false, features = ["std", "time"] }

crates/av1/src/decoder.rs

@@ -9,6 +9,7 @@ use crate::frame::FrameBuf;
 use crate::header::{FrameHeader, HeaderState, LoopFilterDeltas, RefInfo, SegmentationFeatures, SequenceHeader, default_gm_params};
 use crate::spec_tables::*;
 use crate::state::FrameState;
+use crate::stats::{DecodeStats, Stage, Timer};
 use crate::tile::TileDecoder;
 use crate::{Error, Picture, Result};
 
@@ -53,6 +54,8 @@ pub struct Decoder {
     seen_frame_header: bool,
     /// Apply film grain synthesis to output frames (default true).
     pub apply_film_grain: bool,
+    stats: DecodeStats,
+    threads: usize,
 }
 
 struct CurFrame {
@@ -61,6 +64,17 @@ struct CurFrame {
     saved_cdfs: Option<Box<Cdfs>>,
 }
 
+fn default_threads() -> usize {
+    #[cfg(all(feature = "threads", not(target_arch = "wasm32")))]
+    {
+        std::thread::available_parallelism().map(|n| n.get()).unwrap_or(1).min(16)
+    }
+    #[cfg(not(all(feature = "threads", not(target_arch = "wasm32"))))]
+    {
+        1
+    }
+}
+
 impl Default for Decoder {
     fn default() -> Self {
         Self::new()
@@ -68,7 +82,13 @@ impl Default for Decoder {
 }
 
 impl Decoder {
+    /// A decoder using all available cores (with the `threads` feature).
     pub fn new() -> Decoder {
+        Decoder::with_threads(default_threads())
+    }
+
+    /// A decoder using up to `threads` worker threads (1 = decode on the calling thread).
+    pub fn with_threads(threads: usize) -> Decoder {
         Decoder {
             seq: None,
             refs: Default::default(),
@@ -80,9 +100,21 @@ impl Decoder {
             cur: None,
             seen_frame_header: false,
             apply_film_grain: true,
+            stats: DecodeStats::default(),
+            threads: threads.max(1),
         }
     }
 
+    /// Output every picture still held by the decoder (end of stream / before a seek).
+    pub fn flush(&mut self) -> Vec<Picture> {
+        Vec::new()
+    }
+
+    /// Frame / tile counts and per-stage busy time accumulated so far.
+    pub fn stats(&self) -> DecodeStats {
+        self.stats
+    }
+
     /// The active sequence header, once one has been decoded.
     pub fn sequence_header(&self) -> Option<&SequenceHeader> {
         self.seq.as_ref()
@@ -219,6 +251,7 @@ impl Decoder {
             let idx = fh.frame_to_show_map_idx;
             let rf = self.ref_frames[idx].clone().ok_or(Error::Invalid("show_existing_frame of an empty slot"))?;
             let info = self.refs[idx].clone();
+            let t = Timer::start();
             let pic = self.output_picture(&seq, &rf, info.upscaled_width as usize, info.frame_height as usize, &fh.film_grain);
             if fh.frame_type == KEY_FRAME as u8 {
                 // reference frame loading process (7.21) then refresh every slot (7.20)
@@ -229,6 +262,7 @@ impl Decoder {
                     self.ref_frames[i] = Some(rf.clone());
                 }
             }
+            self.stats.add(Stage::Output, t.secs());
             return Ok(Some(pic));
         }
         // Encoders exist that code frames slightly larger than the sequence maximum (e.g. a
@@ -236,6 +270,7 @@ impl Decoder {
         if fh.upscaled_width > 65536 || fh.frame_height > 65536 {
             return Err(Error::Invalid("frame size"));
         }
+        let t = Timer::start();
         let mut fs = FrameState::new(&seq, &fh);
         fs.refs = self.ref_frames.clone();
         fs.ref_info = self.refs.clone();
@@ -269,6 +304,7 @@ impl Decoder {
             c
         };
         self.cur = Some(Box::new(CurFrame { fs, cdfs, saved_cdfs: None }));
+        self.stats.add(Stage::Setup, t.secs());
         Ok(None)
     }
 
@@ -309,6 +345,7 @@ impl Decoder {
             let end = pos.checked_add(size).filter(|&e| e <= data.len()).ok_or(Error::Truncated)?;
             let tile_data = &data[pos..end];
             pos = end;
+            let t = Timer::start();
             let cdfs = cur.cdfs.clone();
             cur.fs.intra_frame_y_mode_cdf = DEFAULT_INTRA_FRAME_Y_MODE_CDF;
             let mut td = TileDecoder::new(&mut cur.fs, tile_data, cdfs, tile_row, tile_col);
@@ -316,6 +353,8 @@ impl Decoder {
             if !td.fs.fh.disable_frame_end_update_cdf && tile_num == ctx_tile {
                 cur.saved_cdfs = Some(td.cdf);
             }
+            self.stats.tiles += 1;
+            self.stats.add(Stage::Tiles, t.secs());
         }
         if tg_end != num_tiles - 1 {
             self.cur = Some(cur);
@@ -333,7 +372,9 @@ impl Decoder {
 
     fn decode_frame_wrapup(&mut self, cur: CurFrame) -> Result<Option<Picture>> {
         let CurFrame { mut fs, cdfs, .. } = cur;
-        crate::postfilter::apply(&mut fs);
+        crate::postfilter::apply(&mut fs, &mut self.stats);
+        let t = Timer::start();
+        self.stats.frames += 1;
         let seq = fs.seq.clone();
         let fh = fs.fh.clone();
         if fh.seg.enabled && !fh.seg.update_map {
@@ -378,7 +419,9 @@ impl Decoder {
                 self.ref_frames[i] = Some(rf.clone());
             }
         }
-        if fh.show_frame { Ok(Some(self.output_picture(&seq, &rf, fh.upscaled_width as usize, fh.frame_height as usize, &fh.film_grain))) } else { Ok(None) }
+        let pic = if fh.show_frame { Some(self.output_picture(&seq, &rf, fh.upscaled_width as usize, fh.frame_height as usize, &fh.film_grain)) } else { None };
+        self.stats.add(Stage::Output, t.secs());
+        Ok(pic)
     }
 
     fn output_picture(&self, seq: &SequenceHeader, rf: &RefFrame, w: usize, h: usize, grain: &crate::header::FilmGrainParams) -> Picture {

crates/av1/src/lib.rs

@@ -21,12 +21,14 @@ mod postfilter;
 mod restoration;
 mod spec_tables;
 mod state;
+mod stats;
 mod symbol;
 mod tile;
 mod transform;
 
 pub use decoder::Decoder;
 pub use header::{ColorConfig, FrameHeader, SequenceHeader};
+pub use stats::{DecodeStats, Stage};
 
 /// Decoder errors.
 #[derive(Debug, Clone, PartialEq, Eq, thiserror::Error)]

crates/av1/src/postfilter.rs

@@ -4,13 +4,17 @@
 use crate::frame::Plane;
 use crate::spec_tables::*;
 use crate::state::FrameState;
+use crate::stats::{DecodeStats, Stage, Timer};
 
-pub(crate) fn apply(fs: &mut FrameState) {
+pub(crate) fn apply(fs: &mut FrameState, stats: &mut DecodeStats) {
+    let mut t = Timer::start();
     let lvl = fs.fh.lf.level;
     if lvl[0] != 0 || lvl[1] != 0 {
         loop_filter(fs);
     }
+    stats.add(Stage::LoopFilter, t.lap());
     let cdef = crate::cdef::apply(fs);
+    stats.add(Stage::Cdef, t.lap());
     let (up_cur, up_cdef) = if fs.fh.use_superres {
         let c = crate::restoration::upscale(fs, &fs.cur);
         let d = cdef.as_ref().map(|f| crate::restoration::upscale(fs, f));
@@ -18,7 +22,9 @@ pub(crate) fn apply(fs: &mut FrameState) {
     } else {
         (std::mem::take(&mut fs.cur), cdef)
     };
+    stats.add(Stage::Superres, t.lap());
     fs.cur = if fs.fh.lr.uses_lr { crate::restoration::loop_restoration(fs, &up_cur, up_cdef.as_ref().unwrap_or(&up_cur)) } else { up_cdef.unwrap_or(up_cur) };
+    stats.add(Stage::Restoration, t.lap());
 }
 
 // ---------------------------------------------------------------------------------------------

crates/av1/src/stats.rs

@@ -0,0 +1,110 @@
+//! Decode statistics: frame / tile counts and the busy time of every decoding stage.
+
+/// A decoding stage (see [`DecodeStats::stage_secs`]).
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+pub enum Stage {
+    /// Frame header follow-up: reference setup, motion field estimation, CDF initialisation.
+    Setup,
+    /// Tile decoding: mode info, coefficients, prediction and reconstruction.
+    Tiles,
+    /// Deblocking loop filter (7.14).
+    LoopFilter,
+    /// CDEF (7.15).
+    Cdef,
+    /// Super-resolution upscaling (7.16).
+    Superres,
+    /// Loop restoration (7.17).
+    Restoration,
+    /// Reference update, motion vector storage, output copy and film grain synthesis.
+    Output,
+}
+
+impl Stage {
+    pub const COUNT: usize = 7;
+    pub const ALL: [Stage; Stage::COUNT] = [Stage::Setup, Stage::Tiles, Stage::LoopFilter, Stage::Cdef, Stage::Superres, Stage::Restoration, Stage::Output];
+
+    pub fn name(self) -> &'static str {
+        match self {
+            Stage::Setup => "setup",
+            Stage::Tiles => "tiles",
+            Stage::LoopFilter => "deblock",
+            Stage::Cdef => "cdef",
+            Stage::Superres => "superres",
+            Stage::Restoration => "restoration",
+            Stage::Output => "output",
+        }
+    }
+}
+
+/// Counters accumulated by a [`crate::Decoder`]. Stage times are busy time summed over every
+/// thread that worked on the stage (wall-clock per piece of work), so with threads they can add
+/// up to more than the elapsed time.
+#[derive(Clone, Copy, Debug, Default, PartialEq)]
+pub struct DecodeStats {
+    /// Frames decoded (excluding show_existing_frame repeats).
+    pub frames: u64,
+    /// Tiles decoded.
+    pub tiles: u64,
+    /// Busy seconds per [`Stage`] (index with `stage as usize`).
+    pub stage_secs: [f64; Stage::COUNT],
+}
+
+impl DecodeStats {
+    pub fn secs(&self, stage: Stage) -> f64 {
+        self.stage_secs[stage as usize]
+    }
+
+    pub(crate) fn add(&mut self, stage: Stage, secs: f64) {
+        self.stage_secs[stage as usize] += secs;
+    }
+
+    pub(crate) fn merge(&mut self, o: &DecodeStats) {
+        self.frames += o.frames;
+        self.tiles += o.tiles;
+        for (a, b) in self.stage_secs.iter_mut().zip(o.stage_secs.iter()) {
+            *a += b;
+        }
+    }
+
+    /// Sum of all stage times.
+    pub fn total_secs(&self) -> f64 {
+        self.stage_secs.iter().sum()
+    }
+}
+
+/// A wall-clock stopwatch (a no-op on wasm32, which has no clock in std).
+pub(crate) struct Timer {
+    #[cfg(not(target_arch = "wasm32"))]
+    start: std::time::Instant,
+}
+
+impl Timer {
+    #[inline]
+    pub fn start() -> Timer {
+        Timer {
+            #[cfg(not(target_arch = "wasm32"))]
+            start: std::time::Instant::now(),
+        }
+    }
+
+    /// Seconds since `start` (0 on wasm32).
+    #[inline]
+    pub fn secs(&self) -> f64 {
+        #[cfg(not(target_arch = "wasm32"))]
+        {
+            self.start.elapsed().as_secs_f64()
+        }
+        #[cfg(target_arch = "wasm32")]
+        {
+            0.0
+        }
+    }
+
+    /// Seconds since `start`, restarting the stopwatch.
+    #[inline]
+    pub fn lap(&mut self) -> f64 {
+        let s = self.secs();
+        *self = Timer::start();
+        s
+    }
+}

crates/av1/tests/perf.rs

@@ -1,33 +1,109 @@
-//! Decode throughput (ignored; run with `cargo test --release -p filmcraft-av1 --test perf --
-//! --ignored --nocapture`).
+//! Decode throughput and per-stage breakdown (ignored; run with
+//! `cargo test --release -p filmcraft-av1 --test perf -- --ignored --nocapture`).
+//!
+//! The machine may be busy (other builds), so single-threaded work is also measured with the
+//! thread CPU clock, which is robust to load; wall-clock figures are printed next to the load
+//! average.
 
 mod common;
 use common::*;
+use filmcraft_av1::{DecodeStats, Decoder, Stage};
 use std::time::Instant;
 
+fn thread_cpu_secs() -> Option<f64> {
+    #[cfg(unix)]
+    {
+        let t = rustix::time::clock_gettime(rustix::time::ClockId::ThreadCPUTime);
+        Some(t.tv_sec as f64 + t.tv_nsec as f64 * 1e-9)
+    }
+    #[cfg(not(unix))]
+    {
+        None
+    }
+}
+
+fn load_average() -> String {
+    let out = std::process::Command::new("sysctl").args(["-n", "vm.loadavg"]).output().ok();
+    if let Some(o) = out.filter(|o| o.status.success()) {
+        return String::from_utf8_lossy(&o.stdout).trim().trim_matches(|c| c == '{' || c == '}').trim().to_string();
+    }
+    std::fs::read_to_string("/proc/loadavg").map(|s| s.split_whitespace().take(3).collect::<Vec<_>>().join(" ")).unwrap_or_else(|_| "?".into())
+}
+
+struct Run {
+    wall: f64,
+    cpu: Option<f64>,
+    shown: usize,
+    stats: DecodeStats,
+}
+
+fn run(frames: &[Vec<u8>], threads: usize) -> Run {
+    let mut dec = Decoder::with_threads(threads);
+    let t = Instant::now();
+    let c0 = thread_cpu_secs();
+    let mut shown = 0;
+    for f in frames {
+        shown += dec.decode(f).unwrap().len();
+    }
+    shown += dec.flush().len();
+    let cpu = c0.and_then(|c0| thread_cpu_secs().map(|c1| c1 - c0));
+    Run { wall: t.elapsed().as_secs_f64(), cpu, shown, stats: dec.stats() }
+}
+
 fn bench(spec: &Spec) {
     let Some(ff) = ffmpeg() else { return };
     let path = make(&ff, spec);
     let frames = ivf_frames(&path);
-    let mut best = f64::INFINITY;
-    let mut shown = 0;
+    // Single-threaded: best of 3 by thread CPU time (falls back to wall time).
+    let mut best: Option<Run> = None;
     for _ in 0..3 {
-        let mut dec = filmcraft_av1::Decoder::new();
-        let t = Instant::now();
-        shown = 0;
-        for f in &frames {
-            shown += dec.decode(f).unwrap().len();
+        let r = run(&frames, 1);
+        let key = |r: &Run| r.cpu.unwrap_or(r.wall);
+        if best.as_ref().is_none_or(|b| key(&r) < key(b)) {
+            best = Some(r);
         }
-        best = best.min(t.elapsed().as_secs_f64());
     }
-    println!("{:<28} {:>3} frames  {:>6.1} fps", spec.name, shown, shown as f64 / best);
+    let b = best.unwrap();
+    let n = b.stats.frames.max(1) as f64;
+    let cpu_fps = b.cpu.map(|c| format!("{:6.1}", b.shown as f64 / c)).unwrap_or_else(|| "     ?".into());
+    println!(
+        "{:<26} {:>3} shown {:>3} decoded {:>3} tiles/frame | 1 thread: {} fps (thread CPU) {:6.1} fps (wall)",
+        spec.name,
+        b.shown,
+        b.stats.frames,
+        b.stats.tiles / b.stats.frames.max(1),
+        cpu_fps,
+        b.shown as f64 / b.wall
+    );
+    let total = b.stats.total_secs();
+    let mut line = String::from("    ms/frame:");
+    for s in Stage::ALL {
+        let v = b.stats.secs(s);
+        if v > 0.0005 {
+            line += &format!(" {} {:.2} ({:.0}%)", s.name(), 1e3 * v / n, 100.0 * v / total);
+        }
+    }
+    println!("{line}");
+    // All cores: best of 3 by wall time.
+    let threads = std::thread::available_parallelism().map(|n| n.get()).unwrap_or(1);
+    let mut best_wall = f64::INFINITY;
+    for _ in 0..3 {
+        let r = run(&frames, threads);
+        assert_eq!(r.shown, b.shown);
+        best_wall = best_wall.min(r.wall);
+    }
+    println!("    {threads} threads: {:6.1} fps (wall, load average {})", b.shown as f64 / best_wall, load_average());
 }
 
 #[test]
 #[ignore]
 fn decode_throughput() {
     let p = |crf: &'static str, params: &'static str| -> Vec<&'static str> { vec!["-preset", "8", "-crf", crf, "-svtav1-params", params] };
-    bench(&Spec::new("perf_1080p_intra", "testsrc2=s=1920x1080:r=25,noise=alls=6:allf=t", 10, "yuv420p", &p("30", "keyint=1")));
-    bench(&Spec::new("perf_1080p_gop", "testsrc2=s=1920x1080:r=25,noise=alls=6:allf=t", 60, "yuv420p", &p("30", "keyint=60")));
-    bench(&Spec::new("perf_1080p_gop_10bit", "testsrc2=s=1920x1080:r=25,noise=alls=6:allf=t", 60, "yuv420p10le", &p("30", "keyint=60")));
+    let src = "testsrc2=s=1920x1080:r=25,noise=alls=6:allf=t";
+    bench(&Spec::new("perf_1080p_intra", src, 10, "yuv420p", &p("30", "keyint=1")));
+    bench(&Spec::new("perf_1080p_gop", src, 60, "yuv420p", &p("30", "keyint=60")));
+    bench(&Spec::new("perf_1080p_gop_10bit", src, 60, "yuv420p10le", &p("30", "keyint=60")));
+    // Higher quality (more coefficients, finer partitions) and a multi-tile stream (4x2 tiles).
+    bench(&Spec::new("perf_1080p_gop_hq", src, 60, "yuv420p", &p("18", "keyint=60")));
+    bench(&Spec::new("perf_1080p_gop_tiles", src, 60, "yuv420p", &p("30", "keyint=60:tile-columns=2:tile-rows=1")));
 }