diff --git a/crates/benilla-app/src/pipe_warm/mod.rs b/crates/benilla-app/src/pipe_warm/mod.rs index 4c1fd38a..e543b59b 100644 --- a/crates/benilla-app/src/pipe_warm/mod.rs +++ b/crates/benilla-app/src/pipe_warm/mod.rs @@ -13,6 +13,7 @@ use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; use std::sync::Arc; +use std::time::Instant; use bevy::prelude::*; use bevy::render::render_resource::{CachedPipelineState, PipelineCache, PipelineDescriptor}; @@ -106,12 +107,14 @@ fn publish_cover( } /// Count the cache's pipelines after it queues this frame's builds, and warn on any new one -/// compiled uncovered. `seen` is the previous frame's count. +/// compiled uncovered. `seen` is the previous frame's count, `warmed` every variant that compiled +/// behind a cover, so a live compile can name which warm variant it is a near miss of. fn watch_pipelines( cache: Res, watch: Res, mut seen: Local, mut settled_seen: Local, + mut warmed: Local>, ) { let covered = watch.0.covered.load(Ordering::Relaxed); // Early-out when nothing is new and everything had settled; queued pipelines settle later @@ -131,12 +134,26 @@ fn watch_pipelines( settled += 1; } if id >= *seen { - let line = describe(&pipe.descriptor); + let variant = Variant::of(&pipe.descriptor); + let line = variant.line(); if covered { debug!("pipeline compiled (covered) [{id}] {line}"); } else { // The tripwire: a live compile is a visible stall, and a warm pass coverage hole. - warn!("pipeline compiled LIVE [{id}] {line}"); + // Naming the nearest warm variant turns the hole into one editable difference, + // which is the whole distance between "8 pipelines compiled LIVE" and a fix. + match variant.nearest(&warmed) { + Some(warm) => warn!( + "pipeline compiled LIVE [{id}] {line} — nearest warm variant differs in: \ + {}", + variant.diff(warm).join(", "), + ), + None => warn!( + "pipeline compiled LIVE [{id}] {line} — no warm variant carries the label \ + {}, so the menagerie has no arm for this lane at all", + variant.label, + ), + } } if let Ok(path) = std::env::var("WOW_PIPE_TRACE") { use std::io::Write; @@ -149,6 +166,9 @@ fn watch_pipelines( let _ = writeln!(f, "[{id}] {cov} {line}"); } } + if covered { + warmed.push(variant); + } } } *seen = total; @@ -157,82 +177,280 @@ fn watch_pipelines( watch.0.settled.store(settled, Ordering::Relaxed); } -/// One greppable line of a pipeline's variant identity. -fn describe(desc: &PipelineDescriptor) -> String { - fn defs(d: &[bevy::shader::ShaderDefVal]) -> String { - let mut v: Vec = d - .iter() - .map(|d| match d { - bevy::shader::ShaderDefVal::Bool(k, true) => k.clone(), - bevy::shader::ShaderDefVal::Bool(k, false) => format!("!{k}"), - bevy::shader::ShaderDefVal::Int(k, i) => format!("{k}={i}"), - bevy::shader::ShaderDefVal::UInt(k, u) => format!("{k}={u}"), - }) - .collect(); - v.sort(); - v.join("+") - } - match desc { - PipelineDescriptor::RenderPipelineDescriptor(d) => { - let label = d.label.as_deref().unwrap_or("?"); - let vs = d - .vertex - .shader - .path() - .map_or_else(|| format!("{:?}", d.vertex.shader.id()), |p| p.to_string()); - let vbufs: Vec = d - .vertex - .buffers - .iter() - .map(|b| { - let locs: Vec = b - .attributes +/// Shader defs, sorted and `+`-joined, as both the log line and the diff read them. +fn defs(d: &[bevy::shader::ShaderDefVal]) -> String { + let mut v: Vec = d + .iter() + .map(|d| match d { + bevy::shader::ShaderDefVal::Bool(k, true) => k.clone(), + bevy::shader::ShaderDefVal::Bool(k, false) => format!("!{k}"), + bevy::shader::ShaderDefVal::Int(k, i) => format!("{k}={i}"), + bevy::shader::ShaderDefVal::UInt(k, u) => format!("{k}={u}"), + }) + .collect(); + v.sort(); + v.join("+") +} + +/// A pipeline's variant identity, field by field. Kept for every variant that compiled behind a +/// cover, so a later live compile can be read against the set that did warm; one string per field +/// rather than one per pipeline, so the whole table is about a megabyte. +struct Variant { + label: String, + /// The vertex shader, or the compute shader when [`Self::compute`]. + shader: String, + shader_defs: String, + bufs: String, + cull: String, + bias: i32, + depth_write: bool, + cmp: String, + /// `None` is a depth-only pipeline, which prints `frag=none`. + fs: Option, + fs_defs: String, + target: String, + samples: u32, + compute: bool, +} + +impl Variant { + fn of(desc: &PipelineDescriptor) -> Self { + match desc { + PipelineDescriptor::RenderPipelineDescriptor(d) => { + let (bias, depth_write, cmp) = d.depth_stencil.as_ref().map_or_else( + || (0, false, String::from("none")), + |ds| { + ( + ds.bias.constant, + ds.depth_write_enabled, + format!("{:?}", ds.depth_compare), + ) + }, + ); + let fragment = d.fragment.as_ref(); + Self { + label: d.label.as_deref().unwrap_or("?").to_string(), + shader: shader_name(&d.vertex.shader), + shader_defs: defs(&d.vertex.shader_defs), + bufs: d + .vertex + .buffers .iter() - .map(|a| a.shader_location.to_string()) - .collect(); - format!("stride{}@[{}]", b.array_stride, locs.join(",")) - }) - .collect(); - let (bias, dw, cmp) = d.depth_stencil.as_ref().map_or_else( - || (0, false, String::from("none")), - |ds| { - ( - ds.bias.constant, - ds.depth_write_enabled, - format!("{:?}", ds.depth_compare), - ) - }, - ); - let frag = d.fragment.as_ref().map_or_else( - || String::from("frag=none"), - |f| { - let fs = f - .shader - .path() - .map_or_else(|| format!("{:?}", f.shader.id()), |p| p.to_string()); - let tgt = f.targets.iter().flatten().next().map_or_else( - || String::from("none"), - |t| format!("blend={:?} mask={:?}", t.blend, t.write_mask), - ); - format!("fs={fs} fs_defs=[{}] {tgt}", defs(&f.shader_defs)) - }, - ); - format!( - "label={label} vs={vs} vs_defs=[{}] bufs=[{}] cull={:?} bias={bias} depth_write={dw} cmp={cmp} {frag} samples={}", - defs(&d.vertex.shader_defs), - vbufs.join(";"), - d.primitive.cull_mode, - d.multisample.count, - ) + .map(|b| { + let locs: Vec = b + .attributes + .iter() + .map(|a| a.shader_location.to_string()) + .collect(); + format!("stride{}@[{}]", b.array_stride, locs.join(",")) + }) + .collect::>() + .join(";"), + cull: format!("{:?}", d.primitive.cull_mode), + bias, + depth_write, + cmp, + fs: fragment.map(|f| shader_name(&f.shader)), + fs_defs: fragment.map_or_else(String::new, |f| defs(&f.shader_defs)), + target: fragment.map_or_else(String::new, |f| { + f.targets.iter().flatten().next().map_or_else( + || String::from("none"), + |t| format!("blend={:?} mask={:?}", t.blend, t.write_mask), + ) + }), + samples: d.multisample.count, + compute: false, + } + } + PipelineDescriptor::ComputePipelineDescriptor(d) => Self { + label: d.label.as_deref().unwrap_or("?").to_string(), + shader: shader_name(&d.shader), + shader_defs: defs(&d.shader_defs), + bufs: String::new(), + cull: String::new(), + bias: 0, + depth_write: false, + cmp: String::new(), + fs: None, + fs_defs: String::new(), + target: String::new(), + samples: 0, + compute: true, + }, } - PipelineDescriptor::ComputePipelineDescriptor(d) => { - let label = d.label.as_deref().unwrap_or("?"); - let cs = d - .shader - .path() - .map_or_else(|| format!("{:?}", d.shader.id()), |p| p.to_string()); - format!("label={label} compute={cs} defs=[{}]", defs(&d.shader_defs)) + } + + /// One greppable line of the whole identity. + fn line(&self) -> String { + if self.compute { + return format!( + "label={} compute={} defs=[{}]", + self.label, self.shader, self.shader_defs + ); } + let frag = self.fs.as_ref().map_or_else( + || String::from("frag=none"), + |fs| format!("fs={fs} fs_defs=[{}] {}", self.fs_defs, self.target), + ); + format!( + "label={} vs={} vs_defs=[{}] bufs=[{}] cull={} bias={} depth_write={} cmp={} {frag} \ + samples={}", + self.label, + self.shader, + self.shader_defs, + self.bufs, + self.cull, + self.bias, + self.depth_write, + self.cmp, + self.samples, + ) + } + + /// The warm variant this one is closest to, among those sharing its label: a different label + /// is a different lane, and reading one against the other would mislead rather than point. + fn nearest<'a>(&self, warmed: &'a [Variant]) -> Option<&'a Variant> { + warmed + .iter() + .filter(|w| w.label == self.label) + .min_by_key(|w| self.diff(w).len()) + } + + /// Every field that differs, as `field=mine (warm theirs)`; a def set reports the defs + /// themselves, `+` carried here and `-` carried only there. + fn diff(&self, warm: &Self) -> Vec { + let mut out = Vec::new(); + let mut field = |name: &str, mine: &str, theirs: &str| { + if mine != theirs { + out.push(format!("{name}={mine} (warm {theirs})")); + } + }; + field("shader", &self.shader, &warm.shader); + field("bufs", &self.bufs, &warm.bufs); + field("cull", &self.cull, &warm.cull); + field("bias", &self.bias.to_string(), &warm.bias.to_string()); + field( + "depth_write", + &self.depth_write.to_string(), + &warm.depth_write.to_string(), + ); + field("cmp", &self.cmp, &warm.cmp); + field( + "fs", + self.fs.as_deref().unwrap_or("none"), + warm.fs.as_deref().unwrap_or("none"), + ); + field("target", &self.target, &warm.target); + field( + "samples", + &self.samples.to_string(), + &warm.samples.to_string(), + ); + for (name, mine, theirs) in [ + ("vs_defs", &self.shader_defs, &warm.shader_defs), + ("fs_defs", &self.fs_defs, &warm.fs_defs), + ] { + let d = def_diff(mine, theirs); + if !d.is_empty() { + out.push(format!("{name} {}", d.join(" "))); + } + } + out + } +} + +/// A shader's path, or its id when it is embedded without one. +fn shader_name(h: &Handle) -> String { + h.path() + .map_or_else(|| format!("{:?}", h.id()), |p| p.to_string()) +} + +/// `+DEF` for a def only the live variant carries, `-DEF` for one only the warm variant did. +fn def_diff(mine: &str, theirs: &str) -> Vec { + let split = |s: &str| -> Vec { + if s.is_empty() { + Vec::new() + } else { + s.split('+').map(str::to_string).collect() + } + }; + let (mine, theirs) = (split(mine), split(theirs)); + let mut out: Vec = mine + .iter() + .filter(|d| !theirs.contains(d)) + .map(|d| format!("+{d}")) + .collect(); + out.extend( + theirs + .iter() + .filter(|d| !mine.contains(d)) + .map(|d| format!("-{d}")), + ); + out +} + +#[cfg(test)] +mod tests { + use super::{def_diff, Variant}; + + fn variant(label: &str, cull: &str, defs: &str) -> Variant { + Variant { + label: label.to_string(), + shader: String::from("wow_model.wgsl"), + shader_defs: defs.to_string(), + bufs: String::from("stride32@[0,1,2]"), + cull: cull.to_string(), + bias: 0, + depth_write: true, + cmp: String::from("GreaterEqual"), + fs: Some(String::from("wow_model.wgsl")), + fs_defs: defs.to_string(), + target: String::from("blend=None"), + samples: 1, + compute: false, + } + } + + #[test] + fn a_live_pipeline_reads_against_the_warm_variant_it_is_a_near_miss_of() { + let warm = vec![ + variant("pbr_opaque_mesh_pipeline", "Some(Back)", "VERTEX_UVS"), + variant("other_pipeline", "None", "VERTEX_UVS+WOW_RIG_SKIN"), + ]; + let live = variant( + "pbr_opaque_mesh_pipeline", + "None", + "VERTEX_UVS+WOW_RIG_SKIN", + ); + + // The label picks the lane: the nearer-looking row in another lane is not an answer. + let nearest = live.nearest(&warm).expect("the same-label variant"); + assert_eq!(nearest.label, "pbr_opaque_mesh_pipeline"); + let diff = live.diff(nearest); + assert_eq!( + diff, + vec![ + "cull=None (warm Some(Back))", + "vs_defs +WOW_RIG_SKIN", + "fs_defs +WOW_RIG_SKIN", + ] + ); + + // A lane the menagerie has no arm for at all says so rather than pointing at a stranger. + assert!(variant("shafts_pipeline", "None", "") + .nearest(&warm) + .is_none()); + } + + #[test] + fn a_def_set_difference_names_the_defs_and_which_side_carries_each() { + assert_eq!(def_diff("A+B", "A+B"), Vec::::new()); + assert_eq!(def_diff("A+B", "A"), vec!["+B"]); + assert_eq!(def_diff("A", "A+B"), vec!["-B"]); + assert_eq!(def_diff("A+C", "A+B"), vec!["+C", "-B"]); + // An empty set is no defs, not one def named "". + assert_eq!(def_diff("", "A"), vec!["-A"]); + assert_eq!(def_diff("", ""), Vec::::new()); } } @@ -248,9 +466,13 @@ struct WarmBoothCam; /// Warm-pass state; the loading screen holds its cover on [`Self::satisfied`]. #[derive(Resource, Default)] pub(crate) struct WarmPass { - /// `Time` when the menagerie spawned under this cover, `None` when idle. Real, because - /// `Time` clamps its delta at 250 ms and would shrink the stalls being timed. - spawned_at: Option, + /// When the menagerie finished spawning under this cover, `None` when idle. + /// + /// An [`Instant`] read inside the system, not a frame clock: **every** frame clock is sampled + /// at the top of the frame, and the frame this pass spawns in is the one that just loaded the + /// in-game UI — 4.8 s of his login — so a frame-clock stamp hands the budget below a debt it + /// never incurred and the reveal is cut off part-done. + spawned_at: Option, /// This cover's warm work is done (drained, timed out, or not applicable). done: bool, /// The 1x1 stand-in texture [`warm_effect_lane`] binds, held strong for the pass's life. @@ -266,7 +488,9 @@ pub(crate) struct WarmPass { /// Pacing state: rigs warmed so far, when the last slice went out, frames the reveal spanned, /// and the slice on screen now (hidden again next frame). revealed: usize, - last_reveal: f32, + /// Rigs the menagerie spawned under this cover, so a timeout can say how far it got. + total: usize, + last_reveal: Option, reveal_frames: u32, showing: Vec, } @@ -325,7 +549,6 @@ fn run_warm_pass( mut warm: ResMut, watch: Res, cover: Res, - time: Res>, camera: Query>, rigs: Query<(Entity, Option<&ChildOf>), With>, mut rig_vis: WarmRigVis, @@ -353,7 +576,7 @@ fn run_warm_pass( warm.done = true; return; } - let now = time.elapsed_secs(); + let now = Instant::now(); // Already warmed in this process: nothing to compile. if warm.warmed_once { warm.done = true; @@ -373,10 +596,6 @@ fn run_warm_pass( if !cover.presented() { return; } - warm.spawned_at = Some(now); - warm.last_reveal = now; - warm.revealed = 0; - warm.reveal_frames = 0; // The twin booth warms the custom-projection view key real bakes install; the real // booths warm the Perspective one. let warm_booth = crate::portrait::spawn_warm_booth(&mut commands, &mut lanes.images); @@ -405,7 +624,19 @@ fn run_warm_pass( &light.0, &torch, ); - info!("pipeline warm: menagerie up ({count} variants, {WARM_REVEAL_PER_FRAME}/frame)"); + // The budget starts once the rigs exist. Spawning them is this frame's own cost, which + // no timeout can cut short, and charging it to the reveal only shortens the reveal. + let built = now.elapsed(); + warm.spawned_at = Some(Instant::now()); + warm.last_reveal = warm.spawned_at; + warm.total = count; + warm.revealed = 0; + warm.reveal_frames = 0; + info!( + "pipeline warm: menagerie up ({count} variants, {WARM_REVEAL_PER_FRAME}/frame, built \ + in {} ms)", + built.as_millis(), + ); return; }; if warm.done { @@ -441,32 +672,38 @@ fn run_warm_pass( let revealed_now = warm.showing.len(); if revealed_now > 0 { warm.revealed += revealed_now; - warm.last_reveal = now; + warm.last_reveal = Some(now); warm.reveal_frames += 1; } let all_revealed = revealed_now == 0; - let last_reveal = warm.last_reveal; + let last_reveal = warm.last_reveal.unwrap_or(spawned); let pending = watch .0 .created .load(Ordering::Relaxed) .saturating_sub(watch.0.settled.load(Ordering::Relaxed)); - if all_revealed && pending == 0 && now - last_reveal >= WARM_SETTLE_SECS { + let waited = now.saturating_duration_since(spawned).as_secs_f32(); + if all_revealed + && pending == 0 + && now.saturating_duration_since(last_reveal).as_secs_f32() >= WARM_SETTLE_SECS + { warm.done = true; warm.warmed_once = true; warm.effect_tex = None; despawn_rigs(&mut commands, &rigs); info!( - "pipeline warm: {} rigs drained in {:.2}s over {} paced frames", - warm.revealed, - now - spawned, - warm.reveal_frames, + "pipeline warm: {} rigs drained in {waited:.2}s over {} paced frames", + warm.revealed, warm.reveal_frames, ); - } else if now - spawned >= WARM_TIMEOUT_SECS { + } else if waited >= WARM_TIMEOUT_SECS { warm.done = true; warm.effect_tex = None; despawn_rigs(&mut commands, &rigs); - warn!("pipeline warm: TIMED OUT with {pending} pipelines pending — cover released"); + warn!( + "pipeline warm: TIMED OUT after {waited:.2}s with {pending} pipeline(s) pending and \ + {} of {} rigs revealed over {} frames — cover released, the rest compiles live", + warm.revealed, warm.total, warm.reveal_frames, + ); } }