diff --git a/Cargo.lock b/Cargo.lock index 6f39573a..ca1c5c7f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1435,6 +1435,7 @@ dependencies = [ "bevy_platform", "bevy_utils", "tracing", + "tracing-chrome", "tracing-error", "tracing-log", "tracing-oslog", @@ -6818,6 +6819,17 @@ dependencies = [ "syn", ] +[[package]] +name = "tracing-chrome" +version = "0.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bf0a738ed5d6450a9fb96e86a23ad808de2b727fd1394585da5cdd6788ffe724" +dependencies = [ + "serde_json", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.36" diff --git a/crates/benilla-formats/src/bin/benilla-extract/main.rs b/crates/benilla-formats/src/bin/benilla-extract/main.rs index 3d2b0212..65459661 100644 --- a/crates/benilla-formats/src/bin/benilla-extract/main.rs +++ b/crates/benilla-formats/src/bin/benilla-extract/main.rs @@ -294,11 +294,12 @@ enum Command { prefix: Option, }, /// Sweep every WMO ROOT and cross-tab the two halves of the skybox mechanism: the root's - /// **MOSB** skybox model against its groups' `0x40000` flag. `0x40000` is undocumented, so - /// this is what *identifies* it — the bit turning out to be set on a group iff its root names - /// a skybox is the whole argument that it means "draw this root's skybox here". Also the - /// population instrument: which 1.12 buildings replace the `Light.dbc` gradient dome with an - /// authored sky (Stratholme's burning city is the headline), and how much of each does it + /// **MOSB** skybox model against its groups' `0x40000` flag. `0x40000` is undocumented, so this + /// is what *identifies* it — across all 815 roots the bit never appears without a MOSB. Note + /// what that does and does NOT buy: it establishes `flag => MOSB`, never which group the + /// renderer tests (the carved law is the flood-VISITED group, decision 0773 correcting 0767). + /// Also the population instrument: which 1.12 buildings replace the `Light.dbc` gradient dome + /// with an authored sky (Stratholme's burning city is the only one reachable), and how much Skyboxscan, /// Dump all 18 `LightIntBand` rows of the `Light.dbc` entry covering a world position at a /// time of day — the band-semantics instrument (which row holds which colour at which hour; diff --git a/crates/benilla-formats/src/bin/benilla-extract/scan.rs b/crates/benilla-formats/src/bin/benilla-extract/scan.rs index 3c52bd5e..70f0a977 100644 --- a/crates/benilla-formats/src/bin/benilla-extract/scan.rs +++ b/crates/benilla-formats/src/bin/benilla-extract/scan.rs @@ -2771,16 +2771,22 @@ pub fn texmodescan(chain: &mut Chain, prefix: Option<&str>) -> Result<()> { /// roots author a **MOSB** skybox model, and which carry groups flagged `0x40000` /// ([`benilla_formats::WmoGroupInfo::show_skybox`]). /// -/// This is the instrument that *identifies* the flag. `0x40000` is not documented anywhere we can -/// cite, so its meaning is established by correlation: if the bit is set on a group **iff** that -/// group's root names a skybox, the bit is the per-group "draw the root's skybox here" gate and -/// nothing else. The summary prints that cross-tab, so the claim is re-checkable in one command -/// against the shipped files rather than trusted from a decision record. +/// This is the instrument that *identifies* the flag — and **exactly how far that identification +/// reaches is the point**. `0x40000` is undocumented, so the cross-tab is what establishes it means +/// anything at all: the bit never appears on a group whose root names no skybox, across all 815 +/// roots. That is a one-way implication, `flag ⇒ MOSB`, and the summary prints it so the claim is +/// re-checkable in one command rather than trusted from a decision record. +/// +/// **It does not, and cannot, say which group the RENDERER tests** — and reading it as if it did is +/// the mistake decision 0767 made (superseded by 0773). The carved law is that `0x40000` is tested +/// inside the portal flood (`0x6b42e0` in `0x6b41c0`) on the group being *visited*, so the predicate +/// is "any flood-reached group carries the bit". A census over static asset bytes has no way to see +/// that distinction; only the binary did. /// /// It is also the population instrument for the mechanism: which buildings in 1.12 replace the -/// `Light.dbc` gradient dome with an authored sky, and how much of each one does it (Stratholme's -/// city shell sets the bit on its open streets — which are authored as INTERIOR groups — but not on -/// its enclosed rooms). +/// `Light.dbc` gradient dome with an authored sky, and how much of each one does it. Stratholme's +/// city shell sets the bit on 61 of its 83 groups; the only other roots that set it at all are the +/// four Caverns of Time shells, which ship in the 5875 data with no 1.12 instance to enter. pub fn skyboxscan(chain: &mut Chain) -> Result<()> { // Roots only: a group file is `_NNN.wmo`, and only the root carries MOSB/MOGI. let names: Vec = chain @@ -2848,17 +2854,22 @@ pub fn skyboxscan(chain: &mut Chain) -> Result<()> { if flag_only == 0 { println!( "\n=> 0x40000 NEVER appears without a MOSB ({flag_only} counter-examples in {scanned} \ - roots): the bit is the per-group 'draw this root's MOSB skybox' gate." + roots), and {mosb_only} root(s) name a skybox no group asks for. So the bit is real and \ + both halves matter — but this census establishes only 'flag implies MOSB'." ); println!( - " The converse does NOT hold ({mosb_only} root(s) name a skybox no group asks for), \ - so the GATE IS THE FLAG, not the chunk — a renderer keyed off MOSB alone would show \ - skies the reference never shows." + " It does NOT say WHICH group the renderer tests, and reading it as if it did is the \ + mistake decision 0767 made (superseded by 0773). The carved law: 0x40000 is tested \ + inside the portal flood (0x6b42e0 in 0x6b41c0) on the group being VISITED, never on the \ + group the camera stands in — so the predicate is 'any FLOOD-REACHED group carries the \ + bit, and the root names a MOSB'. Stratholme's King's Square is the counter-example that \ + settles it: the camera's own group (39) is EXTERIOR and unflagged, and the reference \ + paints the sky there anyway." ); } else { println!( - "\n=> {flag_only} group(s) set 0x40000 with no MOSB to draw — the flag is NOT the \ - skybox gate; re-derive it before building on it." + "\n=> {flag_only} group(s) set 0x40000 with no MOSB to draw — that would break even the \ + weak 'flag implies MOSB' reading this census rests on; re-derive before building on it." ); } Ok(()) diff --git a/crates/benilla-ui/src/script/layout.rs b/crates/benilla-ui/src/script/layout.rs index 1c955cda..59662ed5 100644 --- a/crates/benilla-ui/src/script/layout.rs +++ b/crates/benilla-ui/src/script/layout.rs @@ -109,6 +109,13 @@ impl InputFingerprint { /// driven through real FrameXML + Lua) is a standing probe for a missed input or a missed touch; /// set the env to extend that to a live run or another crate's suite. Read once; when off it /// costs a relaxed atomic load per resolve. +/// `WOW_LAYOUT_PROF=1` — per-solve shape reporting (see the read site in [`UiScript::resolve_layout`]). +/// Read once; off, it costs one relaxed atomic load per resolve and no clock reads at all. +fn layout_prof_enabled() -> bool { + static ON: std::sync::OnceLock = std::sync::OnceLock::new(); + *ON.get_or_init(|| std::env::var("WOW_LAYOUT_PROF").as_deref() == Ok("1")) +} + fn layout_verify_enabled() -> bool { static ON: std::sync::OnceLock = std::sync::OnceLock::new(); *ON.get_or_init(|| cfg!(test) || std::env::var("WOW_LAYOUT_VERIFY").as_deref() == Ok("1")) @@ -158,6 +165,7 @@ impl UiScript { layout_fingerprint, layout_epoch_resolved, layout_solves, + layout_rounds, .. } = model; @@ -377,7 +385,16 @@ impl UiScript { } let round_cap = plan.len() + region_data.len() + 2; + // `WOW_LAYOUT_PROF=1` — the per-solve shape: rounds, the graph's size, and the split + // between the frame solve and the region sweep. The numbers that say whether a solve is + // expensive because it runs too often or because each pass walks the whole UI. + let prof = layout_prof_enabled(); + let mut t_frames = std::time::Duration::ZERO; + let mut t_regions = std::time::Duration::ZERO; + let mut n_regions_swept = 0u64; for round in 0..round_cap { + *layout_rounds += 1; + let t_round = prof.then(std::time::Instant::now); let mut changed = false; // Seed the solver: the screen root, then every region rect settled so far (regions are @@ -425,8 +442,15 @@ impl UiScript { // // `scratch` is hoisted out of the loop so the per-region `LayoutInput` refills its // anchors `Vec` in place instead of allocating one per region per round. + if let Some(t) = t_round { + t_frames += t.elapsed(); + } + let t_reg = prof.then(std::time::Instant::now); let mut scratch = LayoutInput::default(); for (&rh, data) in region_data.iter() { + if prof { + n_regions_swept += 1; + } if data.anchors.is_empty() { continue; } @@ -499,7 +523,22 @@ impl UiScript { } } + if let Some(t) = t_reg { + t_regions += t.elapsed(); + } if !changed { + if prof { + eprintln!( + "[layout-prof] rounds={} frames={} regions_total={} regions_swept={} \ + frame_us={} region_us={}", + round + 1, + plan.len(), + region_data.len(), + n_regions_swept, + t_frames.as_micros(), + t_regions.as_micros() + ); + } if let Some((frames_before, regions_before)) = &verify_against { assert!( frames_before == resolved && regions_before == region_resolved, diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index fee5809d..68d5d1e9 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -588,6 +588,13 @@ impl UiScript { self.model_ref().layout_solves } + /// Total fixpoint ROUNDS across every solve ([`Model::layout_rounds`]) — a solve costs + /// rounds × the whole graph, so the ratio against [`Self::layout_solves`] is the per-pass + /// depth. + pub fn layout_rounds(&self) -> u64 { + self.model_ref().layout_rounds + } + /// A snapshot of the script errors collected so far (from `pcall`'d handlers). pub fn errors(&self) -> Vec { self.model_ref().errors.clone() diff --git a/crates/benilla-ui/src/script/model.rs b/crates/benilla-ui/src/script/model.rs index c3b4b79c..ca5fa33f 100644 --- a/crates/benilla-ui/src/script/model.rs +++ b/crates/benilla-ui/src/script/model.rs @@ -57,6 +57,10 @@ pub(crate) struct Model { /// merely producing the same rects. Counts the gate's decision, so it reads the same with the /// `WOW_LAYOUT_VERIFY` self-check on (which re-runs skipped resolves) as with it off. pub(crate) layout_solves: u64, + /// How many fixpoint ROUNDS those solves ran in total. A solve's cost is rounds × the whole + /// graph, so this is what separates "the gate let too much through" from "each pass is doing + /// too much" — the two have different fixes. + pub(crate) layout_rounds: u64, /// Hyperlink spans per frame — `(rect, link payload, full |H…|h markup)`, rects in the /// engine's y-up screen space. Fed by the app each frame after it rasterizes message lines /// ([`super::UiScript::set_link_spans`]); consumed by the pointer's release dispatch @@ -644,6 +648,7 @@ impl Model { layout_epoch: 0, layout_epoch_resolved: None, layout_solves: 0, + layout_rounds: 0, resolved: HashMap::new(), link_spans: HashMap::new(), chat_tab: false, diff --git a/crates/benilla/Cargo.toml b/crates/benilla/Cargo.toml index 6c077f8f..c5e90863 100644 --- a/crates/benilla/Cargo.toml +++ b/crates/benilla/Cargo.toml @@ -10,6 +10,11 @@ description = "The Bevy app: terrain viewer -> integrated debug client" # hot systems) + render-pass CPU timings to a Tracy capture (decision 0026 — the dev/player seam; # a `docs/howto/running.md` this once cited never landed). tracy = ["bevy/trace_tracy"] +# Opt-in Chrome-trace profiling: `cargo run --features trace_chrome` writes a `trace-.json` of +# every system's per-run span next to the working dir. Tracy's offline twin — it needs no GUI and no +# live capture, so a per-system cost question is answerable from a terminal (and from a run someone +# else recorded). Aggregate it with `scripts/tracesum.py`. +trace_chrome = ["bevy/trace_chrome"] [dependencies] anyhow.workspace = true diff --git a/crates/benilla/assets/shaders/wmo_skybox.wgsl b/crates/benilla/assets/shaders/wmo_skybox.wgsl index 5ecd7bdd..3808c674 100644 --- a/crates/benilla/assets/shaders/wmo_skybox.wgsl +++ b/crates/benilla/assets/shaders/wmo_skybox.wgsl @@ -3,10 +3,15 @@ // the one place 1.12 content reaches this: `StratholmeSkybox.m2`, a static emissive cube whose three // texture pairs are the painted red sky. // -// GAMMA LANE (decision 0161): the model's batches are authored `emissive` + `two-sided` + opaque, so -// the faithful output is the texel's own gamma bytes, unlit and unmodulated — the same treatment the -// gradient dome's stops get. No fog: this IS the backdrop the world's fog converges toward, and the -// reference's sky pass runs before (and outside) the fog stage. +// GAMMA LANE (decision 0161): the batches are authored material flags `0x05` = UNLIT (`0x01`) | +// TWO_SIDED (`0x04`), blend 0 (`benilla-extract m2batch`), so the texel's own gamma bytes, unlit and +// unmodulated, is what the *material* asks for. +// +// UNVERIFIED, and flagged as such: we draw it **unfogged** — and the M2 does not set the UNFOGGED bit +// (`0x02`), so by its own authoring this model IS fogged. The no-fog treatment was an analogy with the +// gradient dome, not a byte law: wow-re has `CMapObj+0x12c` (the MOSB pointer) carved with no renderer +// behind it, so nothing yet says which pass this draws in or under what state. An RE dispatch is open +// on exactly that. Do not harden this into a claim before it lands. // // SKY-PASS DEPTH (see `sky_order.rs`, "The depth law"): the box is drawn camera-anchored at model // scale, so its geometry sits *inside* the world — the shell radius must not decide occlusion. diff --git a/crates/benilla/src/asset_churn.rs b/crates/benilla/src/asset_churn.rs new file mode 100644 index 00000000..ab06280f --- /dev/null +++ b/crates/benilla/src/asset_churn.rs @@ -0,0 +1,154 @@ +//! `WOW_ASSET_CHURN=1` — what the app rewrites in `Assets` every frame, and how big it is. +//! +//! The question this answers: Bevy's `prepare_assets` re-uploads any image that was +//! **modified** since last frame, and `extract_render_asset` re-extracts it. Both showed up as a +//! flat multi-millisecond per-frame cost on the login screen — a static background image — where +//! nothing should be modified at all. A trace can name the *system* that pays; only the asset +//! events name the *asset* that made it pay. +//! +//! Prints one line per second: for each watched asset type, the per-frame Added/Modified counts, +//! and for images the megabytes those modifications ask the render world to re-upload, plus the +//! top offenders by how many frames they were touched in. + +use std::collections::HashMap; + +use bevy::asset::AssetEvent; +use bevy::prelude::*; +use bevy::time::Real; + +pub(crate) struct AssetChurnPlugin; + +/// Off unless `WOW_ASSET_CHURN=1`, read once (the plugin is skipped entirely, so an ordinary run +/// carries no systems at all — not even a disabled one). +pub(crate) fn enabled() -> bool { + static ON: std::sync::OnceLock = std::sync::OnceLock::new(); + *ON.get_or_init(|| std::env::var("WOW_ASSET_CHURN").as_deref() == Ok("1")) +} + +impl Plugin for AssetChurnPlugin { + fn build(&self, app: &mut App) { + if !enabled() { + return; + } + app.init_resource::() + .add_systems(Update, (watch_images, watch_meshes, report).chain()); + } +} + +#[derive(Resource, Default)] +struct Churn { + frames: u32, + /// asset type -> (added, modified) event totals this window. + counts: HashMap<&'static str, (u64, u64)>, + /// Image id -> how many DISTINCT frames it was modified in, the last frame index that counted + /// (so several Modified events in one frame count once), and its byte size when last seen. + /// Counting events instead printed "touched in 77/9 frames" — a ratio above 1.0 is the + /// instrument telling you it is measuring something other than what its label says. + images: HashMap, ImageChurn>, + /// Bytes of image data modification asks the render world to re-upload, this window. + image_bytes: u64, + last_report: f32, +} + +/// One image's churn within the reporting window. +#[derive(Clone, Copy, Default)] +struct ImageChurn { + /// Distinct frames this image was modified in. + frames: u64, + /// The last frame index already counted, so N events in one frame count once. + last_frame: Option, + /// Its data size when last seen (what a modification asks to be re-uploaded). + bytes: usize, +} + +fn watch_images( + mut events: MessageReader>, + images: Res>, + mut churn: ResMut, +) { + let churn = churn.as_mut(); + for e in events.read() { + match *e { + AssetEvent::Added { .. } => churn.counts.entry("Image").or_default().0 += 1, + AssetEvent::Modified { id } => { + churn.counts.entry("Image").or_default().1 += 1; + let bytes = images + .get(id) + .map_or(0, |i| i.data.as_ref().map_or(0, Vec::len)); + churn.image_bytes += bytes as u64; + let frame = churn.frames; + let slot = churn.images.entry(id).or_default(); + if slot.last_frame != Some(frame) { + slot.last_frame = Some(frame); + slot.frames += 1; + } + slot.bytes = bytes; + } + _ => {} + } + } +} + +fn watch_meshes(mut events: MessageReader>, mut churn: ResMut) { + for e in events.read() { + match *e { + AssetEvent::Added { .. } => churn.counts.entry("Mesh").or_default().0 += 1, + AssetEvent::Modified { .. } => churn.counts.entry("Mesh").or_default().1 += 1, + _ => {} + } + } +} + +fn report(mut churn: ResMut, time: Res>, images: Res>) { + churn.frames += 1; + if time.elapsed_secs() - churn.last_report < 1.0 { + return; + } + let churn = churn.as_mut(); + churn.last_report = time.elapsed_secs(); + let frames = f64::from(churn.frames.max(1)); + let mut line = format!("[asset-churn] over {} frames:", churn.frames); + let mut kinds: Vec<_> = churn.counts.iter().collect(); + kinds.sort_by_key(|(k, _)| *k); + for (kind, (added, modified)) in kinds { + line.push_str(&format!( + " {kind}: +{:.1}/frame ~{:.1}/frame", + *added as f64 / frames, + *modified as f64 / frames + )); + } + line.push_str(&format!( + " · image re-upload {:.2} MB/frame", + churn.image_bytes as f64 / frames / (1024.0 * 1024.0) + )); + info!("{line}"); + + // The offenders: an asset touched in most frames is a per-frame rewrite, whatever its size. + let mut top: Vec<_> = churn.images.iter().map(|(id, v)| (*id, *v)).collect(); + top.sort_by_key(|(_, c)| std::cmp::Reverse((c.frames, c.bytes))); + for ( + id, + ImageChurn { + frames: n, bytes, .. + }, + ) in top.into_iter().take(6) + { + let dims = images.get(id).map_or((0, 0), |i| { + ( + i.texture_descriptor.size.width, + i.texture_descriptor.size.height, + ) + }); + info!( + "[asset-churn] image {id:?} touched in {n}/{} frames · {}x{} · {:.2} MB", + churn.frames, + dims.0, + dims.1, + bytes as f64 / (1024.0 * 1024.0) + ); + } + churn.frames = 0; + churn.counts.clear(); + churn.images.clear(); + churn.image_bytes = 0; +} diff --git a/crates/benilla/src/char_select/mod.rs b/crates/benilla/src/char_select/mod.rs index 512f1681..15c7bef3 100644 --- a/crates/benilla/src/char_select/mod.rs +++ b/crates/benilla/src/char_select/mod.rs @@ -146,9 +146,25 @@ impl Roster { /// roster at the entry edge, before the server's `SMSG_LOGIN_VERIFY_WORLD` snap lands /// (decision 0737). pub(crate) fn pending_map(&self) -> Option { + self.pending_row().map(|c| c.map) + } + + /// The picked character's `(map, wow xyz)` — **where the world we are about to load actually + /// is**, known from the roster row a whole server round-trip before `SMSG_LOGIN_VERIFY_WORLD` + /// says so. The streamers aim at this during world entry (decision 0777); without it the only + /// answer available before the snap is the hardcoded Northshire anchor + /// ([`crate::SPAWN_XY`]), which is a guess that is wrong for every character who isn't a fresh + /// human — and a wrong guess here does not merely idle, it spends the entry's IO budget + /// decoding tiles that are dropped a moment later. + pub(crate) fn pending_entry(&self) -> Option<(u32, [f32; 3])> { + self.pending_row() + .map(|c| (c.map, [c.position.x, c.position.y, c.position.z])) + } + + /// The roster row for the pick in flight. + fn pending_row(&self) -> Option<&Character> { self.pending_pick .and_then(|g| self.chars.iter().find(|c| c.guid == g)) - .map(|c| c.map) } } @@ -306,12 +322,21 @@ fn debug_glue_roundtrip( /// The logout-boundary smoke (`WOW_LOGOUT_SMOKE=1`, meant with the `WOW_CHAR` fast path): once /// seated in the world, linger, request the `/logout` round-trip, confirm the return to /// CharSelect, linger again (the glue theme should be the only thing audible over the logs' -/// world-teardown lines), and exit — the world-audio boundary is provable end-to-end without a -/// hand on the keyboard. Inert without the env. +/// world-teardown lines), **enter the world a second time**, and exit. Inert without the env. +/// +/// The re-entry leg is not decoration. Since decision 0777 the world is *released* on the way out +/// (`terrain_stream::release_world`), so the second entry is a materially different code path from +/// the first — it streams a map the streamer has already torn down once — and a teardown that +/// forgets to reset its own bookkeeping fails exactly here and nowhere else. The world-audio +/// boundary this smoke was written for is still checked on the way through. +#[allow(clippy::too_many_arguments)] // a smoke test that drives the whole round trip fn debug_logout_smoke( state: Res>, player: Res, commands: Res, + mut roster: ResMut, + pick: Res, + streamer: Res, time: Res