Export: stage wall times in perf.stats (export.stages)

filmcraft_export::Stage, stage_times(), note_stage() and timed(): the wall
time of setup, loudness, render, encode (and its RGB->YUV convert part),
audio, mux and finish, summed per process like export.hardware. Converters
in the H.264 / ProRes / NVENC / VideoToolbox encoders are timed as Convert.
Two clock reads per stage per batch; the exported file does not change
(determinism tests). Test: an export grows every stage counter.

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

crates/engine/src/perf.rs

@@ -48,10 +48,14 @@ pub fn decode_json() -> Value {
     })
 }
 
-/// Export counters: pictures encoded by hardware encoders, sessions, declined requests.
+/// Export counters: pictures encoded by hardware encoders, sessions, declined requests; and the wall
+/// time of each export stage in milliseconds (`stages`: setup, loudness, render, encode with its
+/// `convert` part, audio, mux, finish), summed over the exports of this process (diff two readings).
 pub fn export_json() -> Value {
     let hw = filmcraft_export::hw_encode_stats();
-    json!({"hardware": {"frames": hw.frames, "sessions": hw.sessions, "declined": hw.declined}})
+    let stages: serde_json::Map<String, Value> =
+        filmcraft_export::stage_times().into_iter().map(|(s, ns)| (format!("{}Ms", s.name()), json!(ns as f64 / 1e6))).collect();
+    json!({"hardware": {"frames": hw.frames, "sessions": hw.sessions, "declined": hw.declined}, "stages": stages})
 }
 
 /// The engine's `perf.stats`.
@@ -105,6 +109,9 @@ mod tests {
         for k in ["frames", "sessions", "declined"] {
             assert!(v["export"]["hardware"][k].is_number(), "export.hardware.{k} in {v}");
         }
+        for k in ["setupMs", "loudnessMs", "renderMs", "encodeMs", "convertMs", "audioMs", "muxMs", "finishMs"] {
+            assert!(v["export"]["stages"][k].is_number(), "export.stages.{k} in {v}");
+        }
         assert!(v["media"]["openSources"].is_number());
         assert_eq!(v["jobs"]["running"], json!(0));
         assert_eq!(s.history.undo.len(), undo, "a query adds no undo step");

crates/export/src/determinism_tests.rs

@@ -46,6 +46,24 @@ fn same_file_whatever_the_core_count() {
     }
 }
 
+#[test]
+fn an_export_adds_up_the_wall_time_of_its_stages() {
+    let before: Vec<(Stage, u64)> = stage_times();
+    let s = ExportSettings { format: Format::H264, path: tmp("stages.mp4"), ..Default::default() };
+    let (p, seq, m) = project();
+    export(&p, seq, &s, &m, &Progress::default()).unwrap();
+    let after = stage_times();
+    let grew = |stage: Stage| {
+        let at = |v: &[(Stage, u64)]| v.iter().find(|(s, _)| *s == stage).map_or(0, |(_, ns)| *ns);
+        at(&after) > at(&before)
+    };
+    // other tests export in parallel, so the counters can only be checked for growth
+    for stage in [Stage::Setup, Stage::Render, Stage::Encode, Stage::Convert, Stage::Audio, Stage::Mux, Stage::Finish] {
+        assert!(grew(stage), "{} did not grow", stage.name());
+    }
+    assert_eq!(Stage::ALL.len(), after.len(), "one counter per stage");
+}
+
 /// Slice NAL units (types 1 and 5) in a length-prefixed (4-byte) H.264 sample.
 fn slices_in(sample: &[u8]) -> usize {
     let (mut n, mut i) = (0, 0);

crates/export/src/job.rs

@@ -30,8 +30,8 @@ use crate::mxf_out::{MxfMux, MxfSetup};
 use crate::pipeline::Pipeline;
 use crate::settings::{AudioCodec, BitrateMode, Multiplexer};
 use crate::{
-    AudioEncoder, ColorSignal, EncodedPacket, EncoderFrame, ExportError, ExportSettings, Format, H264Pass, Out, Progress, Report, Result, VideoEncoder,
-    audio_factories, export_range, frame_span, video_factories,
+    AudioEncoder, ColorSignal, EncodedPacket, EncoderFrame, ExportError, ExportSettings, Format, H264Pass, Out, Progress, Report, Result, Stage, VideoEncoder,
+    audio_factories, export_range, frame_span, note_stage, timed, video_factories,
 };
 
 /// Output frames per interleaved group: the video packets of these frames, then the audio up to
@@ -97,6 +97,10 @@ fn make_venc(settings: &ExportSettings, w: u32, h: u32, rate: FrameRate) -> Resu
 impl Exporter {
     /// Set up an export (encoder, output size, colour signalling); sets `progress.total`.
     pub fn new(project: Arc<Project>, seq: ItemId, settings: &ExportSettings, progress: &Progress) -> Result<Self> {
+        timed(Stage::Setup, || Self::set_up(project, seq, settings, progress))
+    }
+
+    fn set_up(project: Arc<Project>, seq: ItemId, settings: &ExportSettings, progress: &Progress) -> Result<Self> {
         if !stepped(settings.format) {
             return Err(ExportError::Unsupported(format!("{} is not a stepped export", settings.format.label())));
         }
@@ -283,7 +287,8 @@ impl Exporter {
                 progress.set_status("Measuring loudness");
             }
             let a = self.audio.as_mut().ok_or_else(|| ExportError::Encode("internal: the audio pipeline was not created".into()))?;
-            a.measure(&self.settings, sources, &|| progress.cancel.load(Ordering::Relaxed))?;
+            let settings = &self.settings;
+            timed(Stage::Loudness, || a.measure(settings, sources, &|| progress.cancel.load(Ordering::Relaxed)))?;
             if filmcraft_media::pending::take() {
                 return Ok(Step::Pending);
             }
@@ -297,12 +302,12 @@ impl Exporter {
         if self.next < self.f1 {
             let (f, end) = (self.next, (self.next + self.batch).min(self.f1));
             let pipe = &self.pipe;
-            let frames: Vec<(Vec<u8>, Vec<f32>)> = (f..end).into_par_iter().map(|fi| pipe.frame(fi, sources)).collect();
+            let frames: Vec<(Vec<u8>, Vec<f32>)> = timed(Stage::Render, || (f..end).into_par_iter().map(|fi| pipe.frame(fi, sources)).collect());
             if self.first_pass {
                 if filmcraft_media::pending::take() {
                     return Ok(Step::Pending);
                 }
-                self.encode(&frames, f)?;
+                timed(Stage::Encode, || self.encode(&frames, f))?;
                 progress.done.fetch_add((end - f) as u64, Ordering::Relaxed);
                 self.next = end;
                 return Ok(Step::Progress);
@@ -312,10 +317,12 @@ impl Exporter {
             let cuts: Vec<i64> = (f + 1..=end).filter(|&g| (g - self.f0) % INTERLEAVE == 0).collect();
             let mut mixed = Vec::with_capacity(cuts.len());
             if let Some(sr) = self.audio.as_ref().map(|a| a.sr) {
+                let t = web_time::Instant::now();
                 for &g in &cuts {
                     let until = self.sample_at_frame(g, sr);
                     mixed.push(self.audio.as_mut().and_then(|a| a.pull(until, sources)));
                 }
+                note_stage(Stage::Audio, t.elapsed());
             }
             if filmcraft_media::pending::take() {
                 return Ok(Step::Pending);
@@ -323,15 +330,18 @@ impl Exporter {
             let mut mixed = mixed.into_iter();
             for (k, frame) in frames.iter().enumerate() {
                 let fi = f + k as i64;
-                let packets = self.encode(std::slice::from_ref(frame), fi)?;
+                let packets = timed(Stage::Encode, || self.encode(std::slice::from_ref(frame), fi))?;
                 self.queued.extend(packets);
                 if cuts.contains(&(fi + 1)) {
-                    if self.mux.is_none() && self.mxf.is_none() {
-                        self.open_mux()?;
-                    }
-                    let packets = std::mem::take(&mut self.queued);
-                    self.write_video(packets)?;
-                    self.write_audio(mixed.next().flatten())?;
+                    timed(Stage::Mux, || -> Result<()> {
+                        if self.mux.is_none() && self.mxf.is_none() {
+                            self.open_mux()?;
+                        }
+                        let packets = std::mem::take(&mut self.queued);
+                        self.write_video(packets)
+                    })?;
+                    let pcm = mixed.next().flatten();
+                    timed(Stage::Audio, || self.write_audio(pcm))?;
                 }
             }
             progress.done.fetch_add((end - f) as u64, Ordering::Relaxed);
@@ -348,6 +358,7 @@ impl Exporter {
             self.next = self.f0;
             return Ok(Step::Progress);
         }
+        let finishing = web_time::Instant::now();
         let mixed = self.audio.as_mut().and_then(|a| a.rest(sources));
         if filmcraft_media::pending::take() {
             return Ok(Step::Pending);
@@ -379,6 +390,7 @@ impl Exporter {
                 (w.finish(&self.settings)?, Vec::new())
             }
         };
+        note_stage(Stage::Finish, finishing.elapsed());
         let secs = self.t0.elapsed().as_secs_f64();
         let nframes = self.frames();
         if !self.settings.part_of_batch {

crates/export/src/lib.rs

@@ -658,6 +658,71 @@ pub fn note_hw_encode_declined() {
     HW_DECLINED.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
 }
 
+/// The stages of an export whose wall time [`stage_times`] adds up (`perf.stats` `export.stages`).
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+pub enum Stage {
+    /// [`Exporter::new`]: settings, pipeline, encoder and audio set-up.
+    Setup,
+    /// The loudness pass before the first frame (normalised audio only).
+    Loudness,
+    /// Rendering a batch of frames (parallel; includes decoding the sources, effects, colour).
+    Render,
+    /// Encoding the rendered frames, colour conversion included (serial).
+    Encode,
+    /// The part of [`Stage::Encode`] spent converting RGB to the encoder's YUV.
+    Convert,
+    /// Mixing and encoding audio and writing it to the container.
+    Audio,
+    /// Writing video samples to the container (and creating it).
+    Mux,
+    /// Flushing the encoders and finishing the file.
+    Finish,
+}
+
+const STAGES: usize = 8;
+
+impl Stage {
+    pub const ALL: [Stage; STAGES] = [Stage::Setup, Stage::Loudness, Stage::Render, Stage::Encode, Stage::Convert, Stage::Audio, Stage::Mux, Stage::Finish];
+
+    /// The name in `perf.stats`.
+    pub fn name(self) -> &'static str {
+        match self {
+            Stage::Setup => "setup",
+            Stage::Loudness => "loudness",
+            Stage::Render => "render",
+            Stage::Encode => "encode",
+            Stage::Convert => "convert",
+            Stage::Audio => "audio",
+            Stage::Mux => "mux",
+            Stage::Finish => "finish",
+        }
+    }
+}
+
+static STAGE_NS: [std::sync::atomic::AtomicU64; STAGES] = [const { std::sync::atomic::AtomicU64::new(0) }; STAGES];
+
+/// Wall time each export stage has taken so far in this process, in nanoseconds, summed over every
+/// stepped export (they only grow: diff two readings to measure one export). Measuring costs two
+/// clock reads per stage per batch; nothing an export does depends on it.
+pub fn stage_times() -> Vec<(Stage, u64)> {
+    Stage::ALL.iter().map(|s| (*s, STAGE_NS.get(*s as usize).map_or(0, |a| a.load(std::sync::atomic::Ordering::Relaxed)))).collect()
+}
+
+/// Add `d` to a stage's wall time (also for encoders outside this crate: [`Stage::Convert`]).
+pub fn note_stage(stage: Stage, d: std::time::Duration) {
+    if let Some(a) = STAGE_NS.get(stage as usize) {
+        a.fetch_add(u64::try_from(d.as_nanos()).unwrap_or(u64::MAX), std::sync::atomic::Ordering::Relaxed);
+    }
+}
+
+/// Run `f`, adding its wall time to `stage`.
+pub fn timed<T>(stage: Stage, f: impl FnOnce() -> T) -> T {
+    let t = web_time::Instant::now();
+    let r = f();
+    note_stage(stage, t.elapsed());
+    r
+}
+
 /// Register a video encoder factory (tried before the built-in ones and those registered earlier).
 /// Registering the same factory twice is harmless.
 pub fn register_encoder(f: EncoderFactory) {
@@ -795,13 +860,13 @@ impl VideoEncoder for ProResEncoder {
     }
     fn encode(&mut self, f: &EncoderFrame) -> Result<Vec<EncodedPacket>> {
         let mut fr = filmcraft_prores::Frame::new(f.width, f.height, filmcraft_prores::ChromaFormat::Yuv422, 10, false);
-        match f.hdr {
+        timed(Stage::Convert, || match f.hdr {
             Some(rgb) => {
                 let (kr, kb) = self.signal.kr_kb();
                 rgbf_to_yuv422_10(rgb, f.width as usize, f.height as usize, kr, kb, &mut fr.y, &mut fr.cb, &mut fr.cr)
             }
             None => rgba_to_yuv422_10(f.rgba, f.width as usize, f.height as usize, &mut fr.y, &mut fr.cb, &mut fr.cr),
-        }
+        });
         let data = self.enc.encode(&fr).map_err(|e| ExportError::Encode(e.to_string()))?;
         Ok(vec![EncodedPacket { data, key: true, duration: self.rate.den as u32, composition_offset: 0 }])
     }
@@ -1072,13 +1137,13 @@ impl VideoEncoder for H264Encoder {
         self.rate.num as u32
     }
     fn encode(&mut self, f: &EncoderFrame) -> Result<Vec<EncodedPacket>> {
-        match f.hdr {
+        timed(Stage::Convert, || match f.hdr {
             Some(rgb) => {
                 let (kr, kb) = self.signal.kr_kb();
                 rgbf_to_yuv420_8(rgb, f.width as usize, f.height as usize, kr, kb, &mut self.y, &mut self.u, &mut self.v)
             }
             None => rgba_to_yuv420_8(f.rgba, f.width as usize, f.height as usize, &mut self.y, &mut self.u, &mut self.v),
-        }
+        });
         let cw = (f.width as usize).div_ceil(2);
         let frame = filmcraft_h264enc::YuvFrame { y: &self.y, u: &self.u, v: &self.v, y_stride: f.width as usize, uv_stride: cw };
         let ps = self.enc.try_encode(&frame, f.index as i64 * self.rate.den).map_err(|e| ExportError::Encode(e.to_string()))?;

crates/platform/src/hardware_encode.rs

@@ -194,7 +194,7 @@ impl VideoEncoder for HardwareEncoder {
         if f.rgba.len() < w.saturating_mul(h).saturating_mul(4) {
             return Err(ExportError::Encode("the RGBA picture is smaller than its size".into()));
         }
-        filmcraft_export::rgba_to_yuv420_8(f.rgba, w, h, &mut self.y, &mut self.u, &mut self.v);
+        filmcraft_export::timed(filmcraft_export::Stage::Convert, || filmcraft_export::rgba_to_yuv420_8(f.rgba, w, h, &mut self.y, &mut self.u, &mut self.v));
         let packets = self.vt.encode(f.index, &self.y, &self.u, &self.v).map_err(ExportError::Encode)?;
         // the muxer needs the parameter sets after the first group of pictures
         if f.index == 0 {

crates/platform/src/nvenc/export.rs

@@ -57,7 +57,9 @@ impl VideoEncoder for NvencEncoder {
         if f.width != self.w || f.height != self.h {
             return Err(ExportError::Encode(format!("NVENC: a {}x{} picture for a {}x{} encoder", f.width, f.height, self.w, self.h)));
         }
-        filmcraft_export::rgba_to_yuv420_8(f.rgba, self.w as usize, self.h as usize, &mut self.y, &mut self.u, &mut self.v);
+        filmcraft_export::timed(filmcraft_export::Stage::Convert, || {
+            filmcraft_export::rgba_to_yuv420_8(f.rgba, self.w as usize, self.h as usize, &mut self.y, &mut self.u, &mut self.v)
+        });
         let ps = self
             .enc
             .encode(&self.y, &self.u, &self.v, f.index)