diff --git a/crates/compositor/src/compositor_macos.rs b/crates/compositor/src/compositor_macos.rs index 8ea220ec1..3d6aa9727 100644 --- a/crates/compositor/src/compositor_macos.rs +++ b/crates/compositor/src/compositor_macos.rs @@ -2358,22 +2358,30 @@ impl Compositor { let y = cache.make_texture_from_pixel_buffer(out_tex, 0, metal::MTLPixelFormat::R8Unorm)?; let uv = cache.make_texture_from_pixel_buffer(out_tex, 1, metal::MTLPixelFormat::RG8Unorm)?; - let cmd_buf = self.gpu.context.new_command_buffer(); - for (target, pipeline) in [(&y, &self.pipeline_fs_y), (&uv, &self.pipeline_fs_uv)] { - let enc = self.begin_pass( - cmd_buf, - target, - Some(metal::MTLClearColor::new(0.0, 0.0, 0.0, 1.0)), - pipeline, - )?; - enc.set_fragment_texture(0, Some(&self.rt)); - enc.draw_primitives(metal::MTLPrimitiveType::Triangle, 0, 3); - enc.end_encoding(); + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::Nv12Passes); + let cmd_buf = self.gpu.context.new_command_buffer(); + for (target, pipeline) in [(&y, &self.pipeline_fs_y), (&uv, &self.pipeline_fs_uv)] { + let enc = self.begin_pass( + cmd_buf, + target, + Some(metal::MTLClearColor::new(0.0, 0.0, 0.0, 1.0)), + pipeline, + )?; + enc.set_fragment_texture(0, Some(&self.rt)); + enc.draw_primitives(metal::MTLPrimitiveType::Triangle, 0, 3); + enc.end_encoding(); + } + self.submit(cmd_buf); } // Pas de miroir `Shared`, pas de `getBytes` : c'est tout l'intérêt. On attend // quand même, parce que `avcodec_send_frame` va lire ce buffer juste après. - self.submit(cmd_buf); - self.sync(); + // L'attente porte sur TOUT le travail GPU de la frame, composition comprise : + // `compose_frame` n'a fait que soumettre. + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::GpuWait); + self.sync(); + } Ok(()) } diff --git a/crates/compositor/src/export_probe.rs b/crates/compositor/src/export_probe.rs new file mode 100644 index 000000000..667138042 --- /dev/null +++ b/crates/compositor/src/export_probe.rs @@ -0,0 +1,144 @@ +//! Sondes de temps par étage pour l'export, activées par `OPENSCREEN_EXPORT_PROFILE=1`. +//! +//! Le but est de répondre à UNE question — où part le temps d'un export — sans avoir à +//! croire une intuition. Chaque étage accumule des nanosecondes et un compte d'appels ; +//! `report` imprime le tableau sur stderr à la fin de la marche. +//! +//! # Coût quand c'est éteint +//! +//! `scope()` lit un `OnceLock` et, si la sonde est éteinte, ne prend AUCUNE horloge : +//! le `Scope` rendu porte `None` et son `Drop` ne fait rien. Allumée, elle coûte deux +//! `Instant::now()` (un `mach_absolute_time` chacun, ~20 ns sur Apple Silicon) et un +//! `fetch_add` relaxé par étage et par frame. +//! +//! # Ce que les nombres veulent dire, et ne veulent pas dire +//! +//! Les étages sont mesurés là où le CPU les appelle, pas là où le GPU les exécute. Metal +//! est asynchrone : `compose_frame` ne fait que soumettre, et l'attente de TOUT le travail +//! GPU de la frame tombe dans `gpu_wait`. Lire `compose` comme « le coût de la composition » +//! est donc faux — c'est le coût de la CONSTRUIRE, pas de la rendre. + +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::OnceLock; +use std::time::Instant; + +#[derive(Clone, Copy)] +pub enum Stage { + DecodeScreen = 0, + DecodeWebcam = 1, + Compose = 2, + VtGetBuffer = 3, + Nv12Passes = 4, + GpuWait = 5, + SendFrame = 6, + DrainMux = 7, + Progress = 8, + Finalize = 9, +} + +const N: usize = 10; + +const NAMES: [&str; N] = [ + "decode.screen", + "decode.webcam", + "compose.submit", + "vt.get_buffer", + "nv12.passes", + "gpu.wait", + "enc.send_frame", + "mux.drain", + "progress.cb", + "finalize", +]; + +static NANOS: [AtomicU64; N] = [ + AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), + AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), +]; +static COUNT: [AtomicU64; N] = [ + AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), + AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), AtomicU64::new(0), +]; + +static ENABLED: OnceLock = OnceLock::new(); + +pub fn enabled() -> bool { + *ENABLED.get_or_init(|| { + matches!( + std::env::var("OPENSCREEN_EXPORT_PROFILE").ok().as_deref(), + Some("1") | Some("true") + ) + }) +} + +pub struct Scope { + stage: usize, + t0: Option, +} + +impl Drop for Scope { + fn drop(&mut self) { + if let Some(t0) = self.t0 { + NANOS[self.stage].fetch_add(t0.elapsed().as_nanos() as u64, Ordering::Relaxed); + COUNT[self.stage].fetch_add(1, Ordering::Relaxed); + } + } +} + +/// Ouvre une sonde sur `stage`. Le temps est compté jusqu'au `Drop` du `Scope` rendu. +pub fn scope(stage: Stage) -> Scope { + Scope { + stage: stage as usize, + t0: if enabled() { Some(Instant::now()) } else { None }, + } +} + +/// Imprime le tableau sur stderr. `wall_s` est le mur total de la fonction d'export, ce qui +/// permet de voir ce que les étages NE couvrent pas. +pub fn report(wall_s: f64, frames: u64) { + if !enabled() { + return; + } + let total_ns: u64 = (0..N).map(|i| NANOS[i].load(Ordering::Relaxed)).sum(); + eprintln!("[profile] {frames} frames en {wall_s:.3} s ({:.1} fps)", frames as f64 / wall_s.max(1e-9)); + eprintln!("[profile] {:<16} {:>10} {:>9} {:>8} {:>7}", "étage", "total (s)", "µs/frame", "% mur", "appels"); + let mut rows: Vec = (0..N).collect(); + rows.sort_by_key(|&i| std::cmp::Reverse(NANOS[i].load(Ordering::Relaxed))); + for i in rows { + let ns = NANOS[i].load(Ordering::Relaxed); + let c = COUNT[i].load(Ordering::Relaxed); + if c == 0 { + continue; + } + eprintln!( + "[profile] {:<16} {:>10.3} {:>9.1} {:>7.1}% {:>7}", + NAMES[i], + ns as f64 / 1e9, + ns as f64 / 1e3 / c as f64, + 100.0 * (ns as f64 / 1e9) / wall_s.max(1e-9), + c + ); + } + eprintln!( + "[profile] {:<16} {:>10.3} {:>9} {:>7.1}%", + "SOMME sondes", + total_ns as f64 / 1e9, + "", + 100.0 * (total_ns as f64 / 1e9) / wall_s.max(1e-9) + ); + eprintln!( + "[profile] {:<16} {:>10.3} {:>9} {:>7.1}% <- ce que les sondes ne couvrent pas", + "non sondé", + wall_s - total_ns as f64 / 1e9, + "", + 100.0 * (wall_s - total_ns as f64 / 1e9) / wall_s.max(1e-9) + ); +} + +/// Remet tous les compteurs à zéro. Un même process peut enchaîner deux exports. +pub fn reset() { + for i in 0..N { + NANOS[i].store(0, Ordering::Relaxed); + COUNT[i].store(0, Ordering::Relaxed); + } +} diff --git a/crates/compositor/src/gif_export.rs b/crates/compositor/src/gif_export.rs index a30a43007..c74adb090 100644 --- a/crates/compositor/src/gif_export.rs +++ b/crates/compositor/src/gif_export.rs @@ -254,7 +254,7 @@ fn export_gif_inner( let mut screen_decs: HashMap = HashMap::new(); let mut webcam_decs: HashMap = HashMap::new(); screen_decs.insert(clips[0].screen.clone(), unsafe { - Decoder::open(&clips[0].screen, gpu)? + Decoder::open_for_export(&clips[0].screen, gpu)? }); let frames = unsafe { diff --git a/crates/compositor/src/lib.rs b/crates/compositor/src/lib.rs index 64a9c44af..ac9c93bab 100644 --- a/crates/compositor/src/lib.rs +++ b/crates/compositor/src/lib.rs @@ -31,6 +31,7 @@ pub mod audio; pub mod audio_jobs; pub mod config; pub mod cursor; +pub mod export_probe; pub mod ffi; pub mod frame_geometry; pub mod gif_export; diff --git a/crates/compositor/src/pipeline_linux.rs b/crates/compositor/src/pipeline_linux.rs index bbc29f4ed..03a8a5e52 100644 --- a/crates/compositor/src/pipeline_linux.rs +++ b/crates/compositor/src/pipeline_linux.rs @@ -100,6 +100,12 @@ pub struct Decoder { unsafe impl Send for Decoder {} impl Decoder { + /// Même point d'entrée que sur macOS, pour que `timeline_walk` reste portable. Le backend + /// Linux décode déjà en logiciel (`SwDecoder`) : l'intention n'a rien à trancher. + pub fn open_for_export(path: &str, gpu: &Gpu) -> Result { + Self::open(path, gpu) + } + pub fn open(path: &str, gpu: &Gpu) -> Result { let sw = SwDecoder::open(path)?; let fps = sw.fps(); diff --git a/crates/compositor/src/pipeline_macos.rs b/crates/compositor/src/pipeline_macos.rs index c7cf571bc..ba6034d0f 100644 --- a/crates/compositor/src/pipeline_macos.rs +++ b/crates/compositor/src/pipeline_macos.rs @@ -64,6 +64,20 @@ impl Drop for FrameGuard { /// seuil dépend du GOP des captures, pas du backend de décodage. const SEEK_FORWARD_MAX_SEC: f64 = 0.5; +/// Pourquoi ce décodeur est ouvert. La preview et l'export ne demandent pas la même chose +/// au décodeur, et sur macOS ils ne prennent donc pas le même backend. +/// +/// La preview lit au temps réel : il lui suffit de tenir la cadence, et elle scrube, donc la +/// latence d'un seek pèse plus que le débit. Une marche d'export déroule aussi vite que la +/// machine le permet — c'est du débit pur, et l'arbitrage n'est pas le même. +#[derive(Clone, Copy, PartialEq, Eq, Debug)] +pub enum DecodeIntent { + /// Lecture temps réel (`live.rs`). Arbitrage historique, inchangé. + Preview, + /// Marche d'export (`timeline_walk`, `gif_export`). + Export, +} + /// Décodeur ffmpeg — câblage VideoToolbox (et repli logiciel pour les codecs hors-session). /// Cf. `pipeline_windows::Decoder` pour la version D3D11VA. Mêmes champs publics pour /// que `live.rs::Player` reste portable ; les détails internes (hw_device_ctx, format @@ -98,7 +112,19 @@ pub struct Decoder { } impl Decoder { + /// Ouvre pour la PREVIEW. Signature conservée pour tous les appelants existants. pub fn open(path: &str, gpu: &Gpu) -> Result { + Self::open_with(path, gpu, DecodeIntent::Preview) + } + + /// Ouvre pour une marche d'EXPORT, où seul le débit compte. Windows et Linux exposent le + /// même point d'entrée sans rien en faire de particulier ; c'est ici qu'il change quelque + /// chose. + pub fn open_for_export(path: &str, gpu: &Gpu) -> Result { + Self::open_with(path, gpu, DecodeIntent::Export) + } + + pub fn open_with(path: &str, gpu: &Gpu, intent: DecodeIntent) -> Result { unsafe { let mut fmt: *mut crate::ffi::AVFormatContext = ptr::null_mut(); let cpath = CString::new(path)?; @@ -163,11 +189,58 @@ impl Decoder { const FF_PROFILE_H264_CONSTRAINED_BASELINE: i32 = 578; let is_baseline = profile == FF_PROFILE_H264_BASELINE || profile == FF_PROFILE_H264_CONSTRAINED_BASELINE; + // H.264 8 bits 4:2:0 : ce que produit toute capture d'écran, et le SEUL cas sur + // lequel l'arbitrage ci-dessous a été mesuré. `format` vient de `codecpar`, donc + // rempli par `avformat_find_stream_info` ; un flux dont le format reste inconnu + // n'est pas éligible et garde le comportement d'avant. + let is_h264_8bit = (*codecpar).codec_id == crate::ffi::AVCodecID::AV_CODEC_ID_H264 + && (*codecpar).format == crate::ffi::AVPixelFormat::AV_PIX_FMT_YUV420P as i32; let forced = std::env::var("OPENSCREEN_MAC_DECODE").ok(); let want_hw = match forced.as_deref() { Some("software") => false, Some("videotoolbox") => true, - _ => !is_baseline, + // Baseline : arbitrage historique, inchangé (cf. la note ci-dessus). + _ if is_baseline => false, + // MESURÉ, et contraire à ce que la note ci-dessus annonçait. Sur une marche + // d'export, un flux H.264 8 bits se décode plus vite en logiciel que par + // VideoToolbox — y compris en profil High, que cette note donnait à VT. + // + // Mac mini M1 8 Go / macOS 26.5. Source 1920x1080@60, 60 s, profil High. + // Scénario S4 du benchmark, sortie 1080p60 H.264. Trois cycles, un floor + // ffmpeg intercalé par cycle, dérive de fermeture 1,0002, machine à 86 % idle : + // + // VideoToolbox 32 079 ms 1,819x floor (MAD 34 ms) + // logiciel 22 863 ms 1,296x floor (MAD 16 ms) -28,7 % + // + // Par étage : décodage écran 13,13 s -> 1,02 s, webcam 4,20 s -> 0,29 s. + // L'image ne bouge pas — bitstream H.264 (NAL SEI retirés), pixels décodés et + // audio ont le même md5 sur les six sorties des deux variantes. + // + // La raison est celle que la note Baseline donne déjà, et elle ne dépend pas + // du profil : VideoToolbox a une latence FIXE par frame et alloue un + // CVPixelBuffer à chacune, là où le décodeur logiciel étale le travail sur des + // cœurs qui sont multiples. Ce qui compte est que la frame soit assez bon + // marché à décoder — ce que du 1080p 8 bits est. + // + // LA 4K AUSSI, mesurée depuis. Décodage seul, 1200 frames, meilleur de trois + // passes, même machine — avec le cas 1080p en témoin pour valider la méthode + // contre le résultat bout-en-bout ci-dessus : + // + // 1080p logiciel 2586 fps VideoToolbox 212 fps x12,2 + // 4K logiciel 849 fps VideoToolbox 71 fps x11,9 + // + // Le rapport ne bouge quasiment pas avec la résolution : la latence fixe par + // frame de VideoToolbox domine des deux côtés. Il n'y a donc pas de seuil de + // résolution à poser, et en poser un « par prudence » écarterait le chemin + // rapide du cas qui en profite le plus — 71 fps, c'est en dessous du temps + // réel pour une timeline 4K60. + // + // RESTE NON MESURÉ : 10 bits et HEVC. Ils gardent VideoToolbox, et la + // condition les écarte par construction (`format == YUV420P` et + // `codec_id == H264`). La preview aussi n'a pas été mesurée, et la changer + // sans la mesurer serait exactement l'erreur que ce commit corrige. + _ if intent == DecodeIntent::Export && is_h264_8bit => false, + _ => true, }; let r = if want_hw { crate::ffi::av_hwdevice_ctx_create( @@ -180,6 +253,18 @@ impl Decoder { } else { -1 // repli logiciel délibéré, pas un échec }; + // Dire lequel a été pris. Sans cette ligne, « l'export est lent » et « l'export a + // pris VideoToolbox » ne se distinguent pas dans un rapport de bug, et un + // changement d'arbitrage ne se vérifie qu'au chronomètre. + eprintln!( + "[pipeline] décodage {} : {} (codec={} profil={} format={} intention={:?})", + path.rsplit('/').next().unwrap_or(path), + if r == 0 { "videotoolbox" } else { "logiciel" }, + (*codecpar).codec_id, + profile, + (*codecpar).format, + intent, + ); let cpu = if r != 0 { // Pas de VideoToolbox sur ce codec : fallback software. `get_format` est // laissé à NULL (libavcodec choisit son format de sortie, ici NV12 via @@ -853,14 +938,18 @@ impl VideoEncoder { if self.sw.is_null() { // Chemin zero-copy : une frame du pool VideoToolbox, dont `data[3]` porte le // `CVPixelBuffer` dans lequel le compositeur va rendre directement. - let frame = crate::ffi::av_frame_alloc(); - if frame.is_null() { - bail!("av_frame_alloc (frame VT)"); - } - let mut frame = frame; - if crate::ffi::av_hwframe_get_buffer((*self.ctx).hw_frames_ctx, frame, 0) < 0 { - crate::ffi::av_frame_free(&mut frame); - bail!("av_hwframe_get_buffer (pool VT épuisé)"); + let mut frame; + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::VtGetBuffer); + let f = crate::ffi::av_frame_alloc(); + if f.is_null() { + bail!("av_frame_alloc (frame VT)"); + } + frame = f; + if crate::ffi::av_hwframe_get_buffer((*self.ctx).hw_frames_ctx, frame, 0) < 0 { + crate::ffi::av_frame_free(&mut frame); + bail!("av_hwframe_get_buffer (pool VT épuisé)"); + } } let pb = (*frame).data[3] as *mut std::ffi::c_void; if pb.is_null() { @@ -873,10 +962,13 @@ impl VideoEncoder { return Err(e); } (*frame).pts = pts; - let sent = crate::ffi::averr( - crate::ffi::avcodec_send_frame(self.ctx, frame), - "send_frame_composited_vt", - ); + let sent = { + let _p = crate::export_probe::scope(crate::export_probe::Stage::SendFrame); + crate::ffi::averr( + crate::ffi::avcodec_send_frame(self.ctx, frame), + "send_frame_composited_vt", + ) + }; crate::ffi::av_frame_free(&mut frame); return sent; } @@ -898,6 +990,7 @@ impl VideoEncoder { (*self.sw).linesize[1] as usize, )?; (*self.sw).pts = pts; + let _p = crate::export_probe::scope(crate::export_probe::Stage::SendFrame); crate::ffi::averr( crate::ffi::avcodec_send_frame(self.ctx, self.sw), "send_frame_composited", @@ -999,6 +1092,7 @@ pub fn run_composited_multi( bail!("run_composited_multi: aucun clip à exporter"); } let (out_w, out_h) = (params.width, params.height); + crate::export_probe::reset(); let t0 = std::time::Instant::now(); let mut frames: u64 = 0; @@ -1090,8 +1184,14 @@ pub fn run_composited_multi( &mut webcam_decs, &mut |n| { enc.send_composited(comp, out_w, out_h, n as i64)?; - drain_encoder(ectx, octx, ostream, opkt)?; - progress(n + 1); + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::DrainMux); + drain_encoder(ectx, octx, ostream, opkt)?; + } + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::Progress); + progress(n + 1); + } Ok(()) }, &mut |clip_index, source_end_sec, frames_in_clip, speed_segments| { @@ -1123,6 +1223,7 @@ pub fn run_composited_multi( }; // Flush : un null frame à l'encodeur finalise son bitstream. + let _finalize = crate::export_probe::scope(crate::export_probe::Stage::Finalize); unsafe { crate::ffi::averr( crate::ffi::avcodec_send_frame(ectx, ptr::null_mut()), @@ -1160,6 +1261,8 @@ pub fn run_composited_multi( } let wall_s = t0.elapsed().as_secs_f64(); + drop(_finalize); + crate::export_probe::report(wall_s, frames); Ok(Stats { frames, wall_s, diff --git a/crates/compositor/src/pipeline_windows.rs b/crates/compositor/src/pipeline_windows.rs index 5fff82056..f51e9e656 100644 --- a/crates/compositor/src/pipeline_windows.rs +++ b/crates/compositor/src/pipeline_windows.rs @@ -502,6 +502,13 @@ pub(crate) struct Decoder { unsafe impl Send for Decoder {} impl Decoder { + /// Même point d'entrée que sur macOS, pour que `timeline_walk` reste portable. Ici le + /// choix D3D11VA/logiciel dépend du feature level du device, pas de l'usage : l'intention + /// n'a rien à trancher. + pub(crate) unsafe fn open_for_export(path: &str, gpu: &Gpu) -> Result { + Self::open(path, gpu) + } + pub(crate) unsafe fn open(path: &str, gpu: &Gpu) -> Result { let mut fmt: *mut AVFormatContext = ptr::null_mut(); let cpath = CString::new(path)?; diff --git a/crates/compositor/src/timeline_walk.rs b/crates/compositor/src/timeline_walk.rs index 5d95a81db..e5a2eec68 100644 --- a/crates/compositor/src/timeline_walk.rs +++ b/crates/compositor/src/timeline_walk.rs @@ -202,10 +202,10 @@ pub(crate) unsafe fn walk_composited_timeline( comp.set_has_webcam(has_camera); let webcam_key = if has_camera { &clip.webcam } else { &clip.screen }; if !screen_decs.contains_key(&clip.screen) { - screen_decs.insert(clip.screen.clone(), Decoder::open(&clip.screen, gpu)?); + screen_decs.insert(clip.screen.clone(), Decoder::open_for_export(&clip.screen, gpu)?); } if !webcam_decs.contains_key(webcam_key) { - webcam_decs.insert(webcam_key.clone(), Decoder::open(webcam_key, gpu)?); + webcam_decs.insert(webcam_key.clone(), Decoder::open_for_export(webcam_key, gpu)?); } let sdec = screen_decs.get_mut(&clip.screen).unwrap(); let wdec = webcam_decs.get_mut(webcam_key).unwrap(); @@ -305,11 +305,17 @@ pub(crate) unsafe fn walk_composited_timeline( for segment_frame in 0..segment.frame_count { let target_source_time = segment.start_sec + segment_frame as f64 * segment.speed / out_fps as f64; - if !advance_decoder_to(sdec, target_source_time, 0.0)? { - break 'clip_frames; + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::DecodeScreen); + if !advance_decoder_to(sdec, target_source_time, 0.0)? { + break 'clip_frames; + } } - if !advance_decoder_to(wdec, target_source_time, clip.webcam_offset_sec)? { - break 'clip_frames; + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::DecodeWebcam); + if !advance_decoder_to(wdec, target_source_time, clip.webcam_offset_sec)? { + break 'clip_frames; + } } let sf = sdec.cur_frame(); let wf = wdec.cur_frame(); @@ -321,7 +327,10 @@ pub(crate) unsafe fn walk_composited_timeline( if cursor_enabled && cursor_active_path.is_some() { comp.set_cursor_time(Some(target_source_time as f32)); } - comp.compose_frame(sf, wf, frames as f32, cfg)?; + { + let _p = crate::export_probe::scope(crate::export_probe::Stage::Compose); + comp.compose_frame(sf, wf, frames as f32, cfg)?; + } on_frame(frames)?; frames += 1;