From c13c85615c05aea8956ba99971a3285a0171e296 Mon Sep 17 00:00:00 2001 From: grom Date: Mon, 19 Oct 2026 07:59:28 -0600 Subject: [PATCH] pipes: a warm budget is not charged the frame it starts in MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pipeline warm pass held a 10 s budget and timed out 5.2 s in, leaving pipelines to compile live — a visible stall each. `Time` is sampled at the top of the frame, and the frame the menagerie spawns in is the frame that loads the in-game UI: his login's 3.9 s (4.8 s the day before) came out of the budget before the first rig was ever revealed. His own log says so without a bisect: "2069 rigs drained in 9.75s" printed 5.84 s after "menagerie up", and 9.75 - 5.84 = 3.91 s, exactly that session's `in-game UI up in 3907 ms`. It cleared the timeout by a quarter of a second. The stamp is now an `Instant` read in the system, taken *after* `spawn_menagerie`: building the rigs is the frame's own cost, which no timeout can cut short, so charging it to the reveal only shortens the reveal. The spawn line prints that build cost and the timeout line prints how far it got, so the next failure reads as "too slow" or "budget stolen" with no further instrumenting. And a live compile now names the near miss instead of just its own identity: every variant that compiled behind a cover is kept as a `Variant`, and an uncovered one logs the warm variant it is closest to and the single field that differs — `cull=None (warm Some(Back))`, `vs_defs +WOW_RIG_SKIN` — or says no warm variant carries its label at all, which is a missing menagerie arm rather than a missing variant. One field is an edit; a 900-character pipeline identity is a research project. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/pipe_warm/mod.rs | 429 ++++++++++++++++++------ 1 file changed, 333 insertions(+), 96 deletions(-) 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, + ); } }