From 71af0e867f8ae9d50ee33731df8ca2fdb17976f4 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:16:03 +0100 Subject: [PATCH 01/24] Add bounded opt-in CPU timelines and GPU pass diagnostics --- Build-Release.ps1 | 1 + Cargo.lock | 17 + README.md | 5 + .../examples/map-performance-inventory.rs | 61 ++ crates/skate-game/Cargo.toml | 3 +- crates/skate-game/src/app.rs | 3 +- crates/skate-game/src/config.rs | 2 + crates/skate-game/src/main.rs | 18 +- crates/skate-game/src/map_render.rs | 1 + crates/skate-game/src/map_transition.rs | 5 +- crates/skate-game/src/physics/frame.rs | 8 +- crates/skate-game/src/profiling.rs | 562 ++++++++++++++++++ crates/skate-game/src/retail_exposure.rs | 6 + crates/skate-game/src/skate_world.rs | 35 ++ docs/performance-tracing.md | 145 +++++ 15 files changed, 859 insertions(+), 13 deletions(-) create mode 100644 crates/skate-data/examples/map-performance-inventory.rs create mode 100644 crates/skate-game/src/profiling.rs create mode 100644 docs/performance-tracing.md diff --git a/Build-Release.ps1 b/Build-Release.ps1 index 2784498b..27ef0bb2 100644 --- a/Build-Release.ps1 +++ b/Build-Release.ps1 @@ -80,6 +80,7 @@ try { Copy-Item -LiteralPath docs/installation.md -Destination "$stage/docs/installation.md" Copy-Item -LiteralPath docs/retail-renderer.md -Destination "$stage/docs/retail-renderer.md" Copy-Item -LiteralPath docs/crash-reports.md -Destination "$stage/docs/crash-reports.md" + Copy-Item -LiteralPath docs/performance-tracing.md -Destination "$stage/docs/performance-tracing.md" Copy-Item -LiteralPath docs/updates.md -Destination "$stage/docs/updates.md" New-Item -ItemType Directory -Path "$stage/licenses" -Force | Out-Null Copy-Item -LiteralPath tools/vendor/utt/LICENSE -Destination "$stage/licenses/UTT.txt" diff --git a/Cargo.lock b/Cargo.lock index 07dccbec..be18cdc1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -354,6 +354,7 @@ checksum = "1fd310426290cec560221f9750c2f4484be4a8eeea7de3483c423329b465c40e" dependencies = [ "bevy_dylib", "bevy_internal", + "tracing", ] [[package]] @@ -462,6 +463,7 @@ dependencies = [ "downcast-rs 2.0.2", "log", "thiserror 2.0.20", + "tracing", "variadics_please", "wasm-bindgen", "web-sys", @@ -702,6 +704,7 @@ dependencies = [ "slotmap", "smallvec", "thiserror 2.0.20", + "tracing", "variadics_please", ] @@ -1016,6 +1019,7 @@ dependencies = [ "bevy_platform", "bevy_utils", "tracing", + "tracing-error", "tracing-log", "tracing-oslog", "tracing-subscriber", @@ -1283,6 +1287,7 @@ dependencies = [ "naga", "nonmax", "offset-allocator", + "profiling", "send_wrapper", "smallvec", "thiserror 2.0.20", @@ -4204,6 +4209,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3d595e54a326bc53c1c197b32d295e14b169e3cfeaa8dc82b529f947fba6bcf5" dependencies = [ "profiling-procmacros", + "tracing", ] [[package]] @@ -4739,6 +4745,7 @@ dependencies = [ "skate-mods", "skate-net", "skate-vehicles", + "tracing-log", ] [[package]] @@ -5185,6 +5192,16 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-error" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b1581020d7a273442f5b45074a6a57d5757ad0a47dac0e9f0bd57b81936f3db" +dependencies = [ + "tracing", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.2.0" diff --git a/README.md b/README.md index aaa67fa2..a8fb18a9 100644 --- a/README.md +++ b/README.md @@ -48,3 +48,8 @@ are shipped. The included format-demo map is original procedural content. Implementation notes are in [`docs/`](docs/). Patched Bevy dependencies and their licenses are in [`vendor/`](vendor/). This is an unofficial project, not affiliated with EA. + +## Advanced diagnostics + +Windows builds support opt-in [performance timeline capture](docs/performance-tracing.md) +through the `--trace` CLI option, including optional GPU pass diagnostics. diff --git a/crates/skate-data/examples/map-performance-inventory.rs b/crates/skate-data/examples/map-performance-inventory.rs new file mode 100644 index 00000000..4b03b3af --- /dev/null +++ b/crates/skate-data/examples/map-performance-inventory.rs @@ -0,0 +1,61 @@ +//! Read-only map inventory; no window, renderer, physics initialization or conversion. +use skate_data::skate_map::SkateMap; +use std::collections::{HashMap, HashSet}; +use std::hash::{Hash, Hasher}; +fn main() -> Result<(), String> { + let path = std::env::args_os() + .nth(1) + .ok_or("Usage: map-performance-inventory MAP.skate")?; + let map = SkateMap::load(std::path::Path::new(&path))?; + let mut buckets: HashMap<(u32, u32, u32, u64), Vec> = HashMap::new(); + let mut bytes = 0usize; + let mut unique_bytes = 0usize; + let mut unique = 0; + for (i, t) in map.textures.iter().enumerate() { + bytes += t.rgba.len(); + let mut hash = std::collections::hash_map::DefaultHasher::new(); + t.rgba.hash(&mut hash); + let bucket = buckets + .entry((t.width, t.height, t.color_space, hash.finish())) + .or_default(); + if !bucket.iter().any(|&j| map.textures[j].rgba == t.rgba) { + bucket.push(i); + unique += 1; + unique_bytes += t.rgba.len(); + } + } + let mut bounds = vec![([f32::INFINITY; 3], [f32::NEG_INFINITY; 3], 0u64); map.materials.len()]; + let mut cells = HashSet::new(); + for tri in map.geometry.indices.chunks_exact(3) { + let material = map.geometry.vertices[tri[0] as usize].material as usize - 1; + let b = &mut bounds[material]; + b.2 += 1; + let mut center = [0.; 3]; + for &i in tri { + let p = map.geometry.vertices[i as usize].position; + for a in 0..3 { + b.0[a] = b.0[a].min(p[a]); + b.1[a] = b.1[a].max(p[a]); + center[a] += p[a] / 3.; + } + } + cells.insert(( + material, + (center[0] / 32.).floor() as i32, + (center[2] / 32.).floor() as i32, + )); + } + let used: Vec<_> = bounds.iter().filter(|b| b.2 > 0).collect(); + let spans: Vec<_> = [50.,100.,250.,500.].into_iter().map(|threshold| { + let matching: Vec<_> = used.iter().filter(|b|(b.1[0]-b.0[0]).max(b.1[2]-b.0[2])>threshold).collect(); + serde_json::json!({"horizontal_extent_over_metres":threshold,"raw_material_groups":matching.len(),"triangles":matching.iter().map(|b|b.2).sum::()}) + }).collect(); + println!("{}",serde_json::to_string_pretty(&serde_json::json!({ + "schema":1,"map_version":map.version,"vertices":map.geometry.vertices.len(),"triangles":map.geometry.indices.len()/3, + "materials":map.materials.len(),"used_raw_material_groups":used.len(),"raw_material_32m_cells":cells.len(), + "textures":map.textures.len(),"unique_texture_payloads":unique,"decoded_texture_bytes":bytes,"unique_decoded_texture_bytes":unique_bytes, + "rail_records":map.rails.len(),"bounds":spans, + "interpretation":"Raw material groups before renderer canonicalization; cells are triangle-centroid estimates, not actual proposed batches. Texture bytes exclude role expansion, mip chains and GPU allocation. No visibility or frame-time measurement." + })).unwrap()); + Ok(()) +} diff --git a/crates/skate-game/Cargo.toml b/crates/skate-game/Cargo.toml index 9cd5bde7..02024130 100644 --- a/crates/skate-game/Cargo.toml +++ b/crates/skate-game/Cargo.toml @@ -23,7 +23,8 @@ default = ["dev-dynamic"] dev-dynamic = ["bevy/dynamic_linking"] [dependencies] -bevy = { workspace = true, features = ["jpeg"] } +bevy = { workspace = true, features = ["jpeg", "trace"] } +tracing-log = "0.2" skate-core.workspace = true skate-data.workspace = true half = "=2.7.1" diff --git a/crates/skate-game/src/app.rs b/crates/skate-game/src/app.rs index e4c9be8d..df561e55 100644 --- a/crates/skate-game/src/app.rs +++ b/crates/skate-game/src/app.rs @@ -65,7 +65,7 @@ pub(crate) fn build( ..default() }), ..default() - }), + }).build().disable::(), ) .insert_resource(bevy::winit::WinitSettings {focused_mode:bevy::winit::UpdateMode::Continuous,unfocused_mode:bevy::winit::UpdateMode::Continuous}) .insert_resource(config) @@ -119,5 +119,6 @@ pub(crate) fn build( app.add_plugins(crate::multiplayer::MultiplayerPlugin); app.add_plugins(crate::scoring_hud::ScoringHudPlugin); app.add_systems(Last, crate::crash_context::sample); + crate::profiling::install(&mut app); app } diff --git a/crates/skate-game/src/config.rs b/crates/skate-game/src/config.rs index d19e5382..1bd7023a 100644 --- a/crates/skate-game/src/config.rs +++ b/crates/skate-game/src/config.rs @@ -34,6 +34,8 @@ impl Config { let mut args = std::env::args_os().skip(1); while let Some(arg) = args.next() { match arg.to_str() { + Some("--trace" | "--trace-seconds" | "--trace-delay") => { args.next().ok_or("Trace option requires a value")?; } + Some("--trace-wait" | "--trace-gpu") => {} Some("--net-host") => config.multiplayer.host = Some(args.next().ok_or("Missing host bind address")?.to_string_lossy().parse().map_err(|_|"Invalid host bind address")?), Some("--net-local") => { let bind=args.next().ok_or("--net-local requires bind and peer addresses")?.to_string_lossy().parse().map_err(|_|"Invalid bind address")?; diff --git a/crates/skate-game/src/main.rs b/crates/skate-game/src/main.rs index a2b8596f..569091ea 100644 --- a/crates/skate-game/src/main.rs +++ b/crates/skate-game/src/main.rs @@ -30,6 +30,7 @@ mod physics; mod skater_animation; mod verification; mod performance; +mod profiling; mod graphics_menu; mod modding; mod customiser; @@ -54,14 +55,20 @@ fn main() -> bevy::app::AppExit { Ok(false) => {} } if let Some(code) = crash_report::entry() { std::process::exit(code); } + let _trace = match profiling::init() { + Ok(guard) => guard, + Err(error) => { eprintln!("{error}"); return bevy::app::AppExit::error(); } + }; + let _startup = bevy::log::info_span!("startup").entered(); eprintln!("REPORT_META stage=configuration_and_installation"); - let config = match config::Config::from_env() { + let config = match bevy::log::info_span!("load_configuration_and_map").in_scope(config::Config::from_env) { Ok(config) => config, Err(error) => { eprintln!("{error}"); return bevy::app::AppExit::error(); } }; + profiling::map_metadata(&config); eprintln!("REPORT_META startup=map_fingerprint:{:016x} difficulty:{} multiplayer_requested:{} custom_appearance:{} renderer:Vulkan", config.map_fingerprint, config.difficulty.key(), config.multiplayer.host.is_some() || config.multiplayer.direct.is_some(), config.multiplayer.appearance.is_some()); eprintln!("REPORT_META stage=gameplay_configuration"); if let Err(error) = skate_data::input_config::StockGameplayConfig::load(&config.asset_root) { @@ -69,7 +76,7 @@ fn main() -> bevy::app::AppExit { return bevy::app::AppExit::error(); } eprintln!("REPORT_META stage=asset_manifest"); - let manifest = match skate_data::GameAssets::load(&config.asset_root) { + let manifest = match bevy::log::info_span!("load_manifest").in_scope(|| skate_data::GameAssets::load(&config.asset_root)) { Ok(manifest) => manifest, Err(error) => { eprintln!("{error}"); @@ -77,7 +84,7 @@ fn main() -> bevy::app::AppExit { } }; eprintln!("REPORT_META stage=stock_graphs"); - let graphs = match graph_runtime::StockGraphs::load(&config.asset_root, &manifest) { + let graphs = match bevy::log::info_span!("load_graphs").in_scope(|| graph_runtime::StockGraphs::load(&config.asset_root, &manifest)) { Ok(graphs) => graphs, Err(error) => { eprintln!("{error}"); @@ -93,7 +100,7 @@ fn main() -> bevy::app::AppExit { } eprintln!("SKATE_DIFFICULTY mode={} native_index={}", config.difficulty.key(), config.difficulty as u32); eprintln!("REPORT_META stage=physics_initialization"); - let mut physics = match physics::GamePhysics::load_with_difficulty(&config.asset_root, config.map.as_ref(), config.difficulty) { + let mut physics = match bevy::log::info_span!("load_physics").in_scope(|| physics::GamePhysics::load_with_difficulty(&config.asset_root, config.map.as_ref(), config.difficulty)) { Ok(physics) => physics, Err(error) => { eprintln!("{error}"); @@ -106,7 +113,7 @@ fn main() -> bevy::app::AppExit { physics.board.set_transform(spawn); } eprintln!("REPORT_META stage=skater_initialization"); - let skater = match physics::SkaterRuntime::load(&config.asset_root, &graphs, &physics, config.difficulty.key()) { + let skater = match bevy::log::info_span!("load_skater").in_scope(|| physics::SkaterRuntime::load(&config.asset_root, &graphs, &physics, config.difficulty.key())) { Ok(skater) => skater, Err(error) => { eprintln!("{error}"); @@ -130,6 +137,7 @@ fn main() -> bevy::app::AppExit { let mut app = app::build(config, manifest, graphs, physics, skater); app.insert_resource(controls); eprintln!("REPORT_META stage=app_run"); + drop(_startup); app.run() } diff --git a/crates/skate-game/src/map_render.rs b/crates/skate-game/src/map_render.rs index 84fd2487..dc66ceec 100644 --- a/crates/skate-game/src/map_render.rs +++ b/crates/skate-game/src/map_render.rs @@ -104,6 +104,7 @@ impl PreparedScene { } } pub fn publish(mut self, world: &mut World) { + let _span = info_span!("publish_map_assets").entered(); let owned = MapAssets { meshes: self.meshes.publish(world), materials: self.materials.publish(world), retail: self.retail.publish(world), sky: self.sky.publish(world), diff --git a/crates/skate-game/src/map_transition.rs b/crates/skate-game/src/map_transition.rs index 84975a3e..021e73a3 100644 --- a/crates/skate-game/src/map_transition.rs +++ b/crates/skate-game/src/map_transition.rs @@ -102,8 +102,9 @@ fn start(world: &World, entry: Entry) -> Result { let progress = Arc::new(AtomicU8::new(0)); let stage = progress.clone(); let job = std::thread::Builder::new().name("map-loader".into()).spawn(move || { + let _span = info_span!("load_map_transition").entered(); let started = Instant::now(); - let map = selected.path.as_deref().map(skate_data::skate_map::SkateMap::load).transpose()?; + let map = info_span!("read_map").in_scope(|| selected.path.as_deref().map(skate_data::skate_map::SkateMap::load).transpose())?; let map_fingerprint = crate::config::map_fingerprint(selected.path.as_deref())?; let read_time = started.elapsed(); let validation_started = Instant::now(); @@ -125,7 +126,7 @@ fn start(world: &World, entry: Entry) -> Result { let simulation_started = Instant::now(); let simulation = (|| -> Result<_, String> { stage.store(1, Ordering::Relaxed); - let physics = GamePhysics::load_with_difficulty(&root, map.as_ref(), difficulty)?; + let physics = info_span!("load_physics").in_scope(|| GamePhysics::load_with_difficulty(&root, map.as_ref(), difficulty))?; stage.store(2, Ordering::Relaxed); let skater = SkaterRuntime::load_for_world(&root, &graphs, &physics, difficulty.key(), Some(source))?; let mut controls = PlayerControls::load(&root)?; diff --git a/crates/skate-game/src/physics/frame.rs b/crates/skate-game/src/physics/frame.rs index 0e6086cb..be15f027 100644 --- a/crates/skate-game/src/physics/frame.rs +++ b/crates/skate-game/src/physics/frame.rs @@ -53,13 +53,13 @@ pub(super) fn advance( .riding .start_wheel_queries(&physics.board, &physics.world)?; let skeleton_queries = super::foot_ik_queries::query(&physics.world, &skater.skeleton)?; - let animation = animation_phase::advance( + let animation = bevy::log::info_span!("fixed_animation_graphs").in_scope(|| animation_phase::advance( physics, skater, controls, graphs, &physics.animation_profile, - ) + )) .map_err(|e| format!("Animation tick{}: {e}", physics.ticks))?; super::offboard_audit_trace::stage(tick, "animation", physics, skater, controls); #[cfg(test)] @@ -228,14 +228,14 @@ pub(super) fn advance( //World8275ECA4 ends skeleton tests after state/forces and before solving. //Teleport resets previous observations, but preserves this pending batch. skeleton_queries.publish(&mut skater.player_input.player); - solve::advance(physics, skater, skater.ground.steering.targets)?; + bevy::log::info_span!("fixed_collision_and_solve").in_scope(|| solve::advance(physics, skater, skater.ground.steering.targets))?; super::offboard_audit_trace::stage(tick, "solve", physics, skater, controls); #[cfg(test)] super::offboard_root_trace::trace(tick, "solve", skater); //ProcessOutput82DB6EE8 resets the packet before its component publishers. //All consumers of the preceding output have completed this frame's input. super::player_input::reset_outputs(&mut skater.player_input.physical); - physics.finish_skater(skater)?; + bevy::log::info_span!("fixed_finish_skater").in_scope(|| physics.finish_skater(skater))?; super::offboard_audit_trace::stage(tick, "finish", physics, skater, controls); #[cfg(test)] super::offboard_root_trace::trace(tick, "finish", skater); diff --git a/crates/skate-game/src/profiling.rs b/crates/skate-game/src/profiling.rs new file mode 100644 index 00000000..053b2bc3 --- /dev/null +++ b/crates/skate-game/src/profiling.rs @@ -0,0 +1,562 @@ +//! Bounded, local-only CPU timeline. GPU diagnostics are delayed duration counters. +use bevy::{ + log::{ + tracing::{ + self, Subscriber, + span::{Attributes, Id}, + }, + tracing_subscriber::{ + self as subscriber, Layer, + layer::{Context, SubscriberExt}, + registry::LookupSpan, + }, + }, + prelude::*, +}; +use serde_json::{Value, json}; +use std::{ + cell::RefCell, + collections::HashMap, + fs::OpenOptions, + io::{BufWriter, Write}, + path::PathBuf, + sync::{ + Arc, OnceLock, + atomic::{AtomicBool, AtomicU64, Ordering}, + mpsc::{SyncSender, sync_channel}, + }, + thread::JoinHandle, + time::{Duration, Instant}, +}; + +const MAX_BYTES: usize = 128 * 1024 * 1024; +static CAPTURE: OnceLock> = OnceLock::new(); +static NEXT_THREAD: AtomicU64 = AtomicU64::new(1); +thread_local! { + static THREAD: u64 = NEXT_THREAD.fetch_add(1, Ordering::Relaxed); + static ENTERED: RefCell> = const { RefCell::new(Vec::new()) }; +} +#[derive(Debug, Default)] +struct Options { + path: Option, + seconds: u64, + delay: u64, + wait: bool, + gpu: bool, +} +impl Options { + fn parse(args: impl Iterator) -> Result { + let mut result = Self { + seconds: 30, + ..Self::default() + }; + let mut args = args; + let mut modifiers = false; + while let Some(arg) = args.next() { + match arg.to_str() { + Some("--trace") => { + if result.path.is_some() { + return Err("Duplicate --trace".into()); + } + result.path = Some( + args.next() + .ok_or("--trace requires a new output JSON path")? + .into(), + ); + } + Some("--trace-seconds" | "--trace-delay") => { + modifiers = true; + let value = args + .next() + .and_then(|a| a.to_str().and_then(|v| v.parse::().ok())) + .ok_or("Trace duration must be an integer")?; + if value > 600 || (arg == "--trace-seconds" && value == 0) { + return Err("Trace seconds: 1..600; delay: 0..600".into()); + } + if arg == "--trace-seconds" { + result.seconds = value; + } else { + result.delay = value; + } + } + Some("--trace-wait") => { + modifiers = true; + result.wait = true; + } + Some("--trace-gpu") => { + modifiers = true; + result.gpu = true; + } + // Consume values of other CLI options; never interpret them as trace flags. + Some("--net-local") => { + args.next(); + args.next(); + } + Some( + "--net-host" | "--net-session" | "--spawn-offset" | "--player-title" + | "--appearance" | "--controller" | "--assets" | "--map" | "--teleport" + | "--difficulty" | "--verify", + ) => { + args.next(); + } + _ => {} + } + } + if modifiers && result.path.is_none() { + return Err("Trace modifiers require --trace FILE.json".into()); + } + if result.wait && result.delay != 0 { + return Err("Choose --trace-wait or --trace-delay".into()); + } + Ok(result) + } +} +struct Capture { + origin: Instant, + active: AtomicBool, + start: AtomicBool, + stop: AtomicBool, + dropped: AtomicU64, + sender: SyncSender, + gpu: bool, +} +impl Capture { + fn send(&self, value: Value) { + if self.sender.try_send(value).is_err() { + self.dropped.fetch_add(1, Ordering::Relaxed); + } + } + fn counter(&self, name: &str, args: Value) { + if self.active.load(Ordering::Relaxed) { + self.send(json!({"name":name,"ph":"C","pid":1,"tid":0,"ts":self.origin.elapsed().as_micros() as u64,"args":args})); + } + } +} +pub(crate) struct Guard(Arc, Option>>); +impl Drop for Guard { + fn drop(&mut self) { + self.0.stop.store(true, Ordering::Relaxed); + if let Some(writer) = self.1.take() { + if !matches!(writer.join(), Ok(Ok(()))) { + eprintln!("TRACE export failed; capture may be incomplete"); + } + } + } +} + +pub(crate) fn init() -> Result, String> { + let options = Options::parse(std::env::args_os().skip(1))?; + init_options(options) +} +fn init_options(options: Options) -> Result, String> { + let mut guard = None; + let layer = if let Some(path) = options.path { + // create_new refuses to destroy a previous recording. + let file = OpenOptions::new() + .write(true) + .create_new(true) + .open(&path) + .map_err( + |_| "Cannot create trace: use a new filename in an existing writable directory", + )?; + let (sender, receiver) = sync_channel::(8192); + let capture = Arc::new(Capture { + origin: Instant::now(), + active: AtomicBool::new(!options.wait && options.delay == 0), + start: AtomicBool::new(false), + stop: AtomicBool::new(false), + dropped: AtomicU64::new(0), + sender, + gpu: options.gpu, + }); + CAPTURE + .set(capture.clone()) + .map_err(|_| "Trace already initialized")?; + let state = capture.clone(); + let writer = std::thread::Builder::new().name("trace-export".into()).spawn(move || { + let result = (|| -> std::io::Result<()> { + let mut writer = BufWriter::new(file); + writer.write_all(b"{\"traceEvents\":[\n")?; + let mut bytes = 0; + let mut started = state.active.load(Ordering::Relaxed).then(Instant::now); + let mut reason = "stopped"; + loop { + if state.stop.load(Ordering::Relaxed) { break; } + if started.is_none() && (state.start.swap(false, Ordering::Relaxed) || (!options.wait && state.origin.elapsed().as_secs() >= options.delay)) { + started = Some(Instant::now()); + state.active.store(true, Ordering::Relaxed); + } + if started.is_some_and(|s| s.elapsed() >= Duration::from_secs(options.seconds)) { reason = "duration"; break; } + if let Ok(event) = receiver.recv_timeout(Duration::from_millis(20)) { + let line = serde_json::to_vec(&event)?; + if bytes + line.len() + 2 > MAX_BYTES { reason = "size_limit"; break; } + writer.write_all(&line)?; + writer.write_all(b",\n")?; + bytes += line.len() + 2; + } + } + state.active.store(false, Ordering::Relaxed); + // Drain the bounded queue on normal stop so end-of-frame events survive. + while let Ok(event) = receiver.try_recv() { + let line = serde_json::to_vec(&event)?; + if bytes + line.len() + 2 > MAX_BYTES { reason = "size_limit"; break; } + writer.write_all(&line)?; writer.write_all(b",\n")?; bytes += line.len() + 2; + } + let footer = json!({"name":"capture_complete","ph":"i","s":"g","pid":1,"tid":0,"ts":state.origin.elapsed().as_micros() as u64,"args":{"reason":reason,"dropped_events":state.dropped.load(Ordering::Relaxed)}}); + serde_json::to_writer(&mut writer, &footer)?; + writer.write_all(b"],\"displayTimeUnit\":\"ms\"}\n")?; + writer.flush()?; + eprintln!("TRACE complete ({reason}); open the requested JSON in https://ui.perfetto.dev"); + Ok(()) + })(); + state.active.store(false, Ordering::Relaxed); + if result.is_err() { eprintln!("TRACE export failed; check free disk space and destination access"); } + result + }).map_err(|_| "Cannot start trace writer")?; + capture.send(json!({"name":"build","ph":"M","pid":1,"tid":0,"args":{"build_id":env!("SKATE_BUILD_ID"),"version":env!("CARGO_PKG_VERSION"),"revision":env!("SKATE_RELEASE_REVISION"),"bevy":"0.18.1","wgpu":"27.0.1","debug_assertions":cfg!(debug_assertions),"gpu_requested":options.gpu,"seconds":options.seconds,"delay":options.delay,"wait":options.wait}})); + eprintln!( + "TRACE armed; F9 starts waiting capture, F10 stops/exports. Recording does not stop gameplay." + ); + guard = Some(Guard(capture.clone(), Some(writer))); + Some( + Timeline(capture).with_filter(subscriber::filter::FilterFn::new(|m| { + m.is_span() + && (m.target().starts_with("bevy_") || m.target().starts_with("skate3rust")) + })), + ) + } else { + None + }; + // Per-layer filters keep spans completely disabled in normal play. No environment + // filter is applied to the recorder; RUST_LOG cannot silently remove its systems. + let filter = subscriber::EnvFilter::try_from_default_env() + .unwrap_or_else(|_| subscriber::EnvFilter::new("info,wgpu=error,naga=warn")); + let logs = subscriber::fmt::layer() + .with_writer(std::io::stderr) + .with_filter(subscriber::filter::FilterFn::new(|m| m.is_event())) + .with_filter(filter); + tracing::subscriber::set_global_default(subscriber::registry().with(layer).with(logs)) + .map_err(|_| "Cannot install profiling/log subscriber")?; + let _ = tracing_log::LogTracer::init(); + Ok(guard) +} + +struct Timeline(Arc); +#[derive(Default)] +struct SystemName(String); +impl tracing::field::Visit for SystemName { + fn record_debug(&mut self, _: &tracing::field::Field, _: &dyn std::fmt::Debug) {} + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "name" && value.len() <= 512 && !value.contains(['/', '\\', '\n']) { + self.0 = value.into(); + } + } +} +impl LookupSpan<'a>> Layer for Timeline { + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + // Only Bevy ECS system labels may supply dynamic text. All other fields, + // source locations, thread names and log events are deliberately omitted. + if attrs.metadata().target().starts_with("bevy_ecs") + && matches!(attrs.metadata().name(), "system" | "system_commands") + { + let mut name = SystemName::default(); + attrs.record(&mut name); + if let Some(span) = ctx.span(id) { + span.extensions_mut().insert(name); + } + } + } + fn on_enter(&self, id: &Id, _: Context<'_, S>) { + if self.0.active.load(Ordering::Relaxed) { + ENTERED.with(|stack| stack.borrow_mut().push((id.into_u64(), Instant::now()))); + } + } + fn on_exit(&self, id: &Id, ctx: Context<'_, S>) { + let start = ENTERED.with(|stack| { + let mut stack = stack.borrow_mut(); + let index = stack.iter().rposition(|(key, _)| *key == id.into_u64())?; + Some(stack.remove(index).1) + }); + if let Some(start) = start.filter(|_| self.0.active.load(Ordering::Relaxed)) { + if let Some(span) = ctx.span(id) { + let ext = span.extensions(); + let label = ext + .get::() + .filter(|s| !s.0.is_empty()) + .map(|s| s.0.as_str()) + .unwrap_or(span.metadata().name()); + THREAD.with(|tid| self.0.send(json!({"name":label,"cat":span.metadata().name(),"ph":"X","pid":1,"tid":tid,"ts":start.duration_since(self.0.origin).as_micros() as u64,"dur":start.elapsed().as_micros() as u64}))); + } + } + } +} + +#[derive(Resource, Default)] +struct Frames { + last: Option, + fixed: u32, + frame: u64, + diagnostics: HashMap, +} +pub(crate) fn install(app: &mut App) { + let Some(capture) = CAPTURE.get() else { + return; + }; + if capture.gpu { + app.add_plugins(bevy::render::diagnostic::RenderDiagnosticsPlugin); + } + if let Some(render) = app.get_sub_app_mut(bevy::render::RenderApp) { + render.add_systems( + bevy::render::Render, + render_counters.after(bevy::render::RenderSystems::Cleanup), + ); + } + app.init_resource::() + .add_systems(First, begin_frame) + .add_systems(FixedFirst, |mut frames: ResMut| { + frames.fixed += 1; + }) + .add_systems(Last, end_frame); +} +fn render_counters( + mut frame: Local, + meshes: Res>, + images: Res>, + pipelines: Res, +) { + *frame += 1; + let capture = CAPTURE.get().unwrap(); + if *frame % 60 == 1 && capture.active.load(Ordering::Relaxed) { + capture.counter("render_resources",json!({"prepared_meshes":meshes.iter().count(),"prepared_images":images.iter().count(),"waiting_pipelines":pipelines.waiting_pipelines().count()})); + } +} +pub(crate) fn map_metadata(config: &crate::config::Config) { + let Some(capture) = CAPTURE.get() else { + return; + }; + capture.send(json!({"name":"loaded_map","ph":"i","s":"g","pid":1,"tid":0,"ts":capture.origin.elapsed().as_micros() as u64,"args":{"fingerprint":format!("{:016x}",config.map_fingerprint),"difficulty":config.difficulty.key(),"geometry":config.map.as_ref().map(|m|json!({"version":m.version,"triangles":m.geometry.indices.len()/3,"materials":m.materials.len(),"textures":m.textures.len(),"rail_records":m.rails.len()}))}})); +} +fn begin_frame(mut frames: ResMut) { + let capture = CAPTURE.get().unwrap(); + let now = Instant::now(); + if let Some(last) = frames.last.replace(now) { + capture.counter( + "frame_interval_ms", + json!({"value":now.duration_since(last).as_secs_f64()*1000.}), + ); + } + frames.fixed = 0; + frames.frame += 1; +} +fn end_frame( + mut frames: ResMut, + keys: Res>, + config: Res, + fixed: Res>, + meshes: Res>, + images: Res>, + entities: Query, + diagnostics: Res, + device: Option>, + windows: Query<&Window>, + cameras: Query<(&Camera, &Msaa)>, + menu: Option>, + map: Res, + transition: Res, + adapter: Option>, +) { + let capture = CAPTURE.get().unwrap(); + if keys.just_pressed(KeyCode::F9) { + capture.start.store(true, Ordering::Relaxed); + } + if keys.just_pressed(KeyCode::F10) { + capture.stop.store(true, Ordering::Relaxed); + } + if !capture.active.load(Ordering::Relaxed) { + return; + } + capture.counter("frame", json!({"number":frames.frame,"fixed_schedule_iterations":frames.fixed,"fixed_period_ms":fixed.timestep().as_secs_f64()*1000.,"cpu_main_until_trace_sample_ms":frames.last.unwrap().elapsed().as_secs_f64()*1000.})); + if frames.frame % 60 == 1 { + if let Some(adapter) = adapter { + capture.send(json!({"name":"adapter","ph":"i","s":"g","pid":1,"tid":0,"ts":capture.origin.elapsed().as_micros() as u64,"args":{"vendor":adapter.vendor,"device":adapter.device,"backend":format!("{:?}",adapter.backend)}})); + } + capture.send(json!({"name":"game_configuration","ph":"i","s":"g","pid":1,"tid":0,"ts":capture.origin.elapsed().as_micros() as u64,"args":{"graphics":menu.as_ref().map(|m|m.diagnostic_settings()),"paused":menu.as_ref().is_some_and(|m|m.open),"map_loading":transition.busy(),"map_generation":map.generation}})); + capture.counter( + "assets", + json!({"meshes":meshes.len(),"images":images.len(),"entities":entities.iter().count()}), + ); + capture.send(json!({"name":"configuration","ph":"i","s":"g","pid":1,"tid":0,"ts":capture.origin.elapsed().as_micros() as u64,"args":{"map_fingerprint":format!("{:016x}",config.map_fingerprint),"difficulty":config.difficulty.key(),"timestamp_queries":device.as_ref().is_some_and(|d|d.features().contains(bevy::render::settings::WgpuFeatures::TIMESTAMP_QUERY)),"windows":windows.iter().map(|w|json!({"width":w.physical_width(),"height":w.physical_height(),"present_mode":format!("{:?}",w.present_mode)})).collect::>(),"cameras":cameras.iter().map(|(c,m)|json!({"size":c.physical_target_size().map(|s|[s.x,s.y]),"msaa":m.samples()})).collect::>()}})); + } + for diagnostic in diagnostics.iter() { + let path = diagnostic.path().as_str(); + // Built-in render paths only. Do not export arbitrary plugin diagnostic labels. + if !path.starts_with("render/") || path.len() > 1024 || path.contains(['\\', ':']) { + continue; + } + let Some(measurement) = diagnostic.measurement() else { + continue; + }; + if frames + .diagnostics + .get(path) + .is_some_and(|(_, time)| *time == measurement.time) + { + continue; + } + if frames.diagnostics.len() >= 2048 && !frames.diagnostics.contains_key(path) { + continue; + } + let next = frames.diagnostics.len(); + let entry = frames + .diagnostics + .entry(path.into()) + .or_insert((next, measurement.time)); + entry.1 = measurement.time; + // View names may originate in mods. Keep a stable numeric series ID and + // only allowlisted engine pass/measurement labels in the exported name. + if let Some(label) = render_label(path, entry.0) { + capture.counter(&label, json!({"value":measurement.value})); + } + } +} + +fn render_label(path: &str, id: usize) -> Option { + let field = path.rsplit('/').next()?; + if !matches!( + field, + "elapsed_cpu" + | "elapsed_gpu" + | "vertex_shader_invocations" + | "clipper_invocations" + | "clipper_primitives_out" + | "fragment_shader_invocations" + | "compute_shader_invocations" + ) { + return None; + } + let pass = path + .split('/') + .find(|s| { + matches!( + *s, + "main_opaque_pass_3d" + | "main_transparent_pass_3d" + | "main_transmissive_pass_3d" + | "early_mesh_preprocessing" + | "late_mesh_preprocessing" + | "retail_exposure_meter" + | "retail_exposed_tone" + | "prepass" + | "early_prepass" + | "late_prepass" + | "tonemapping" + | "upscaling" + | "depth_downsample" + | "ui" + ) + }) + .unwrap_or("other_pass"); + Some(format!("render/{id}/{pass}/{field}")) +} + +#[cfg(test)] +mod tests { + use super::*; + #[test] + fn disabled_subscriber_rejects_spans() { + let logs = subscriber::fmt::layer() + .with_filter(subscriber::filter::FilterFn::new(|m| m.is_event())); + tracing::subscriber::with_default(subscriber::registry().with(logs), || { + assert!(tracing::info_span!("disabled_probe").is_disabled()); + }); + } + #[test] + fn full_queue_drops_without_blocking() { + let (sender, _receiver) = sync_channel(1); + let capture = Capture { + origin: Instant::now(), + active: AtomicBool::new(true), + start: AtomicBool::new(false), + stop: AtomicBool::new(false), + dropped: AtomicU64::new(0), + sender, + gpu: false, + }; + for _ in 0..3 { + capture.counter("test", json!({"value":1})); + } + assert_eq!(capture.dropped.load(Ordering::Relaxed), 2); + } + fn parse(args: &[&str]) -> Result { + Options::parse(args.iter().map(std::ffi::OsString::from)) + } + #[test] + fn bounds_and_dependencies() { + for args in [ + vec!["--trace-seconds", "0"], + vec!["--trace", "a", "--trace-seconds", "601"], + vec!["--trace", "a", "--trace-delay", "-1"], + vec!["--trace-gpu"], + vec!["--trace", "a", "--trace-wait", "--trace-delay", "1"], + vec!["--trace", "a", "--trace", "b"], + ] { + assert!(parse(&args).is_err()); + } + let options = parse(&["--trace", "a", "--trace-seconds", "600", "--trace-wait"]).unwrap(); + assert!(options.wait); + assert_eq!(options.seconds, 600); + assert!( + parse(&["--player-title", "--trace"]) + .unwrap() + .path + .is_none() + ); + } + #[test] + fn viewer_export_wait_stop_and_privacy() { + let path = + std::env::temp_dir().join(format!("skate-trace-test-{}.json", std::process::id())); + let _ = std::fs::remove_file(&path); + let guard = init_options(Options { + path: Some(path.clone()), + seconds: 1, + wait: true, + ..Options::default() + }) + .unwrap() + .unwrap(); + assert!(!guard.0.active.load(Ordering::Relaxed)); + guard.0.start.store(true, Ordering::Relaxed); + let deadline = Instant::now() + Duration::from_secs(2); + while !guard.0.active.load(Ordering::Relaxed) && Instant::now() < deadline { + std::thread::sleep(Duration::from_millis(5)); + } + assert!(guard.0.active.load(Ordering::Relaxed)); + tracing::info_span!( + "safe_test_span", + secret = "CANARY_SECRET", + path = "C:\\CANARY_PERSONAL\\asset" + ) + .in_scope(|| tracing::info!("CANARY_LOG")); + drop(guard); + let text = std::fs::read_to_string(&path).unwrap(); + let parsed: Value = serde_json::from_str(&text).unwrap(); + assert!( + parsed["traceEvents"] + .as_array() + .unwrap() + .iter() + .any(|e| e["name"] == "safe_test_span" && e["ph"] == "X") + ); + assert_eq!( + parsed["traceEvents"].as_array().unwrap().last().unwrap()["name"], + "capture_complete" + ); + assert!(!text.contains("CANARY")); + assert_eq!( + render_label("render/CANARY_SECRET/main_opaque_pass_3d/elapsed_gpu", 7).unwrap(), + "render/7/main_opaque_pass_3d/elapsed_gpu" + ); + std::fs::remove_file(path).unwrap(); + } +} diff --git a/crates/skate-game/src/retail_exposure.rs b/crates/skate-game/src/retail_exposure.rs index 6052b6bb..1216dbcb 100644 --- a/crates/skate-game/src/retail_exposure.rs +++ b/crates/skate-game/src/retail_exposure.rs @@ -228,6 +228,8 @@ impl ViewNode for ExposureNode { return Ok(()); }; let post = view.post_process_write(); + use bevy::render::diagnostic::RecordDiagnostics; + let diagnostics = context.diagnostic_recorder(); let meter = context.render_device().create_bind_group( "retail meter", &cache.get_bind_group_layout(&p.compute_layout), @@ -251,8 +253,10 @@ impl ViewNode for ExposureNode { timestamp_writes: None, }); pass.set_pipeline(compute); + let span = diagnostics.pass_span(&mut pass, "retail_exposure_meter"); pass.set_bind_group(0, &meter, &[]); pass.dispatch_workgroups(1, 1, 1); + span.end(&mut pass); } let mut pass = context.begin_tracked_render_pass(RenderPassDescriptor { label: Some("retail exposed tone"), @@ -267,8 +271,10 @@ impl ViewNode for ExposureNode { occlusion_query_set: None, }); pass.set_render_pipeline(tone); + let span = diagnostics.pass_span(&mut pass, "retail_exposed_tone"); pass.set_bind_group(0, &output, &[]); pass.draw(0..3, 0..1); + span.end(&mut pass); Ok(()) } } diff --git a/crates/skate-game/src/skate_world.rs b/crates/skate-game/src/skate_world.rs index 597b71e0..4175f345 100644 --- a/crates/skate-game/src/skate_world.rs +++ b/crates/skate-game/src/skate_world.rs @@ -21,6 +21,7 @@ use skate_data::skate_map::SkateMap; use std::collections::HashMap; pub(crate) fn validate_runtime(map: &SkateMap) -> Result<(), String> { + let _span = info_span!("validate_map").entered(); let archive = retail_archive(map)?; if map.geometry.collision.is_empty() && archive.is_none() { return Err("SKATE map has no collision geometry".into()); @@ -421,6 +422,39 @@ fn render_groups( groups } +#[cfg(test)] +mod performance_inventory { + use super::*; + /// Explicit read-only inventory, never initializes Bevy or a GPU. Asset path + /// stays in the environment; output contains counts/bounds only. + #[test] + #[ignore = "requires SKATE_MAP_INVENTORY and SKATE_MAP_INVENTORY_OUT"] + fn runtime_batches() { + let map = SkateMap::load(std::path::Path::new(&std::env::var_os("SKATE_MAP_INVENTORY").unwrap())).unwrap(); + let textures = render_texture_ids(&map.textures); + let materials = render_material_ids(&map.materials, &textures); + let groups = render_groups(&map.geometry, &materials); + let mut spans = [0usize;4]; + let mut triangles = [0usize;4]; + let mut cells = std::collections::HashSet::new(); + for (material, indices) in &groups { + let mut min = Vec3::splat(f32::INFINITY); + let mut max = Vec3::splat(f32::NEG_INFINITY); + for &i in indices { let p=Vec3::from_array(map.geometry.vertices[i as usize].position); min=min.min(p); max=max.max(p); } + let extent=(max.x-min.x).max(max.z-min.z); + for (i,threshold) in [50.,100.,250.,500.].iter().enumerate() { + if extent>*threshold {spans[i]+=1;triangles[i]+=indices.len()/3;} + } + for tri in indices.chunks_exact(3) { + let p=tri.iter().map(|&i|Vec3::from_array(map.geometry.vertices[i as usize].position)/3.).sum::(); + cells.insert((*material,(p.x/32.).floor() as i32,(p.z/32.).floor() as i32)); + } + } + let result=serde_json::json!({"schema":1,"runtime_material_batches":groups.len(),"extent_threshold_metres":[50,100,250,500],"batches_over_threshold":spans,"triangles_in_batches_over_threshold":triangles,"centroid_32m_cells":cells.len(),"note":"Exact current material canonicalization and grouping; no frustum, occlusion or runtime frame measurement"}); + std::fs::write(std::env::var_os("SKATE_MAP_INVENTORY_OUT").unwrap(),serde_json::to_vec_pretty(&result).unwrap()).unwrap(); + } +} + pub(crate) fn spawn( map: &SkateMap, commands: &mut crate::map_render::SceneCommands, @@ -431,6 +465,7 @@ pub(crate) fn spawn( tuning: &crate::retail_render::MaterialTuning, ) { // Texture roles have different transfer functions even when sharing a record. + let _span = info_span!("prepare_map_geometry_and_textures").entered(); let texture_ids = render_texture_ids(&map.textures); let mut cache = HashMap::<(u32, u8), Handle>::new(); let mut texture = |id: u32, role: u8| -> Option> { diff --git a/docs/performance-tracing.md b/docs/performance-tracing.md new file mode 100644 index 00000000..7942ae24 --- /dev/null +++ b/docs/performance-tracing.md @@ -0,0 +1,145 @@ +# Advanced performance capture + +Windows releases built from this revision include the recorder. No Rust, engine rebuild, +profiler installation, network listener or menu setting is needed to **record**. +From a terminal in the installed release directory: + +```bat +skate3rust.exe --trace university-cpu.json --trace-wait --trace-seconds 30 +``` + +Load University normally, settle at the area you want to measure, press **F9**, and +skate for 30 seconds. **F10** stops and exports early. Continue playing or close +normally; the capture does not terminate gameplay. Use a new output filename for +each launch: existing files are never overwritten. The destination directory must +already exist and be writable. Relative filenames resolve from the working directory. + +For GPU pass diagnostics, repeat the same route and settings in a separate launch: + +```bat +skate3rust.exe --trace university-gpu.json --trace-wait --trace-seconds 30 --trace-gpu +``` + +For startup/loading, omit `--trace-wait`. For unattended delayed recording use +`--trace-delay 60` instead of `--trace-wait`. Delay is measured from recorder +initialization, not map readiness. Duration defaults to 30 seconds (range 1–600); +delay range is 0–600 seconds. There is one capture per process. F9 cannot restart +a completed recording. Trace modifiers without `--trace` are rejected. Existing +`--assets` and `--map` options can select prepared data as usual. + +Open the completed JSON using **Open trace file** in [Perfetto](https://ui.perfetto.dev/). +Select a CPU slice to see its duration; search for `physics::advance`, +`fixed_collision_and_solve`, `fixed_animation_graphs`, `prepare_mesh_bind_groups`, +`prepare_windows`, or `present_frames`. Expand counter tracks for frame intervals +and render pass diagnostics. Load after recording to avoid viewer GPU contention. +Nothing in the recorder uploads captures. Share the JSON file explicitly when needed. + +## What the measurements mean + +- CPU thread slices use Bevy 0.18.1's built-in ECS/system, schedule and render + instrumentation plus startup/map/physics subspans. They measure **wall time inside + a scope**, including waits and descheduling, not exclusively CPU execution time. + Worker threads have anonymous numeric IDs. Nested slices must not be summed as + independent work. Re-entered spans emit separate intervals. Scopes crossing a + capture boundary can be absent; partial frames should be excluded from analysis. +- `frame_interval_ms` measures successive main-app `First` samples. It includes + pacing and scheduling effects; it is not a monitor presentation/scanout measurement. + `fixed_schedule_iterations` counts fixed schedule loops, not successful physics + steps. `fixed_period_ms` reports the existing native-derived timestep. The main + sample duration stops at the trace system in `Last`; unordered `Last` systems, + including the FPS pacer, may fall outside it. Use their CPU spans separately. +- Render preparation, command encoding, queue submission and `present_frames` + **are CPU intervals**. A long `prepare_windows` can reflect waiting for the GPU + or presentation rather than expensive mesh preparation. Main and render apps + are pipelined, so their work need not correspond to the same displayed frame. +- With `--trace-gpu`, `render/.../elapsed_gpu` counters are **measured GPU timestamp + durations in milliseconds**, when the device supports them. `elapsed_cpu` is + CPU pass encoding time. Other render counters are pipeline invocation statistics. + Results arrive asynchronously and are sampled only when a new diagnostic arrives. + They are plotted at CPU receipt time, **not on a calibrated GPU timeline**; do not + infer exact GPU start times or associate them blindly with that main frame. + Anonymous series IDs distinguish views; only recognized pass names are retained. +- Bevy's instrumented passes are covered, with added diagnostics for the custom + retail exposure meter and tone pass. This is not complete GPU-frame coverage: + other custom passes may be uninstrumented, and nested pass durations can overlap. + Never add all counters to claim total GPU frame time. Missing GPU counters mean + unavailable measurements, not zero GPU cost. +- Asset counters show main-world asset entries, not VRAM usage. Map meshes/images + use `RENDER_WORLD` ownership and can leave those main-world collections after + upload. Treat counts as lifecycle clues, not resident memory or draw-call counts. +- Metadata includes the existing build ID/revision, engine versions, map fingerprint, + initial map counts, timestep, numeric adapter IDs/backend, window dimensions, + camera target sizes/MSAA and graphics settings. Map names, source filenames, + local asset paths, player names, environment dumps, CLI arguments and log payloads + are omitted. The map fingerprint identifies content without publishing its path. + +## Bounds, overhead and failure behavior + +The writer runs on a separate thread with an 8,192-event queue. Full queues drop +events instead of waiting for disk; `capture_complete.args.dropped_events` reports +loss. A nonzero count makes the timeline incomplete. The event body is limited to +128 MiB, plus a small JSON header/footer, and ends early with `size_limit` if reached. +The time limit also exports while gameplay continues. A normal return, startup +error or Rust unwind drops the guard and finishes the file. Forced process termination, +native crashes, power loss or disk errors can leave incomplete JSON; this is not a +crash-safe journal. The crash supervisor retains its existing independent behavior. + +CPU recording costs timestamps, span bookkeeping, JSON values and queue operations; +export costs CPU and disk bandwidth. GPU queries/readback and pipeline statistics +add overhead. This implementation has **not** had its overhead benchmarked in-game. +Compare CPU-only and GPU-enabled runs, and treat heavily instrumented results as +diagnostic evidence rather than baseline FPS. GPU instrumentation remains installed +for the entire `--trace-gpu` launch, including while waiting and after export. CPU +span subscription also remains installed after export, although event creation stops. +Relaunch without tracing for normal play. With no `--trace`, no recorder, writer, +sampling systems or GPU diagnostics are installed; the log subscriber rejects spans +before recording. Built-in trace callsites remain compiled but disabled. + +The application retains its existing Vulkan device configuration. GPU timestamp +and pipeline statistics support depends on adapter features and drivers; the trace +does not force unsupported features or change device limits. Bevy 0.18.1 supports +these diagnostics on Vulkan/DX12, and internally bounds timestamp/query capacity. +CPU capture works when GPU measurements are unavailable. No textures, shaders, +resolution, culling policy, density, animation cadence or simulation timestep are +changed by the launch flags. Do not combine this workflow with the older +`SKATE_PERF_REPORT`/camera-sweep benchmark environment options: that is a separate +benchmark mode with different controls and collection semantics. + +## Developer support and tooling choice + +The package always enables Bevy's `trace` feature; the normal static release build +(`cargo build --release --locked -p skate-game --bin skate3rust --no-default-features`) +therefore supports the CLI. No separate `trace_chrome` or `trace_tracy` build feature +is necessary. The custom subscriber retains event logging and the existing panic +hook while filtering timeline and log layers independently; `RUST_LOG` controls +logs and cannot silently remove CPU trace systems. + +Bevy's stock Chrome backend is convenient but its default formatter includes span +fields and lacks our capture controls/privacy bounds. Tracy offers live CPU/GPU +correlation and richer analysis, but requires matching capture/viewer tooling and +an alternative instrumented build. It is a developer escalation, not a requirement +for distributed capture. RenderDoc is useful for inspecting actual draws, resources, +pipeline state and overdraw on Vulkan; replay/capture overhead means its numbers +should not be substituted for an ordinary frame-time profile. Capture only after +the user launches the game. wgpu API tracing is primarily reproduction/replay of +GPU API traffic, not a replacement for CPU or hardware duration profiling, and may +contain asset contents. It is intentionally not enabled by these flags. + +Versioned official references: [Bevy 0.18.1 profiling guide](https://github.com/bevyengine/bevy/blob/v0.18.1/docs/profiling.md), +[Bevy 0.18.1 render diagnostics](https://docs.rs/bevy_render/0.18.1/bevy_render/diagnostic/struct.RenderDiagnosticsPlugin.html), +[wgpu 27 source](https://github.com/gfx-rs/wgpu/tree/v27.0.1), and +[RenderDoc documentation](https://renderdoc.org/docs/getting_started/quick_start.html). +The pinned local Bevy/wgpu source is the authority for this implementation; newer +Bevy documentation uses some different diagnostic names. + +For static inventory without starting the game: + +```text +cargo run --release --locked -p skate-data --example map-performance-inventory -- MAP.skate +``` + +This reports texture payload identity, material bounds and a spatial-cell estimate. +For exact renderer canonicalization, the ignored, data-only +`skate_world::performance_inventory::runtime_batches` test accepts +`SKATE_MAP_INVENTORY` and `SKATE_MAP_INVENTORY_OUT`. Neither initializes Bevy or a GPU. +Keep private inventory paths and personal launchers out of published docs/artifacts. From b34b5eae9a223729f8967aa9e389548ee1a28f72 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:19:38 +0100 Subject: [PATCH 02/24] Assess University bottlenecks and remove frame-state allocation --- crates/skate-game/src/crash_report.rs | 3 + crates/skate-game/src/retail_shadow.rs | 9 +- docs/university-performance-assessment.md | 199 ++++++++++++++++++++++ 3 files changed, 208 insertions(+), 3 deletions(-) create mode 100644 docs/university-performance-assessment.md diff --git a/crates/skate-game/src/crash_report.rs b/crates/skate-game/src/crash_report.rs index 5431a9b9..69fe4121 100644 --- a/crates/skate-game/src/crash_report.rs +++ b/crates/skate-game/src/crash_report.rs @@ -25,6 +25,9 @@ struct Capture { impl Capture { fn line(&mut self, stream: &str, line: &[u8], elapsed: f64) { let line = sanitize(&String::from_utf8_lossy(line)); + // Advanced capture status must reach the launch console even while the + // supervisor keeps normal logs bounded and private. Sanitize first. + if line.starts_with("TRACE ") { eprintln!("{line}"); } let entry = format!("+{elapsed:.3}s {stream}: {line}"); if let Some(value) = line.strip_prefix("REPORT_META ") { if let Some((key, _)) = value.split_once('=') { diff --git a/crates/skate-game/src/retail_shadow.rs b/crates/skate-game/src/retail_shadow.rs index 878eb785..573b8ec2 100644 --- a/crates/skate-game/src/retail_shadow.rs +++ b/crates/skate-game/src/retail_shadow.rs @@ -57,12 +57,15 @@ fn upload( queue: Res, ) { if let Some(buffer) = buffers.get(BUFFER.id()) { - let bytes: Vec = [state.0, state.1] + let values = [state.0, state.1] .into_iter() .chain(state.2) .flat_map(|v| v.to_array()) - .flat_map(f32::to_le_bytes) - .collect(); + .flat_map(f32::to_le_bytes); + let mut bytes = [0u8; 144]; + for (destination, value) in bytes.iter_mut().zip(values) { + *destination = value; + } // Keep the buffer and all material bind groups alive; upload 144 frame bytes. queue.write_buffer(&buffer.buffer, 0, &bytes); } diff --git a/docs/university-performance-assessment.md b/docs/university-performance-assessment.md new file mode 100644 index 00000000..51d80c50 --- /dev/null +++ b/docs/university-performance-assessment.md @@ -0,0 +1,199 @@ +# University: performance assessment, 9 September 2026 + +This investigation preserves the current rendered image and native-derived gameplay +contract. It does not lower resolution, texture precision, sampler fidelity, density, +draw distance, shadows, animation quality or physics cadence. It introduces no LOD. +No game, Steam, recomp or automated gameplay was launched. There is **no measured +FPS gain** and no conclusion yet that University is CPU- or GPU-bound on the user's PC. + +Baseline: `57742e0` (the available `origin/main` at worktree creation), Bevy 0.18.1, +wgpu 27.0.1, vendored PBR/core-pipeline patches. Static inventory used the existing +fresh installation's University v14 package, SHA-256 +`b63e57a84884e639c5ce433a84834a840ae96bfdacad8f34c457d28211315f42`. +The local `main` ref was older; no checkout or remote ref was modified to change it. + +## Evidence and scale + +The data-only inventory decoded the existing package and the ignored renderer test +ran the actual `render_texture_ids`, `render_material_ids` and `render_groups` +functions. Neither initializes a window, Bevy application or GPU. + +| Quantity | Observed | +|---|---:| +| Package bytes | 281,255,761 | +| Render vertices / triangles | 2,075,425 / 1,645,617 | +| Material records / actual material batches | 8,546 / 4,870 | +| Texture records / byte-identical unique payloads | 2,046 / 2,021 | +| Decoded texture bytes / unique bytes | 772,544,512 / 766,686,208 | +| Rail records | 4,201 | +| Batches wider than 50 m horizontally / their triangles | 2,021 / 1,226,659 | +| Wider than 100 m / their triangles | 624 / 435,401 | +| Wider than 250 m / their triangles | 54 / 35,027 | +| Wider than 500 m / their triangles | 6 / 10,191 | +| Estimated occupied 32 m material cells | 19,604 | + +Extent buckets overlap. The cell estimate assigns triangle centroids to an XZ grid; +it is not a measured culling result or a proposed mesh implementation. Existing +installation validation logs separately report 1,133,649 collision triangles, +5,537 query clusters and 27,008 grind primitives. These are existing log evidence, +not new runtime profiles. Decoded texture bytes exclude lightmap half-float +expansion, sampler-role duplication, mip chains, sky/character textures and GPU +allocation overhead. They must not be called VRAM consumption. + +## Rendering and map data path + +`config.rs::from_env` reads the selected package and computes a map fingerprint. +`skate_world.rs::validate_runtime` validates supported extensions/collision. +`world.rs::setup` takes the decoded map out of `Config`; startup does not retain +the full package permanently. `skate_world.rs::spawn` canonicalizes resources, +reindexes material groups and emits static identity-transform mesh entities. +Textures and meshes use `RenderAssetUsages::RENDER_WORLD`, allowing main-world +payloads to leave after upload. No per-frame map reparse or map-wide transform +rewrite was found in this path. + +`map_render.rs::PreparedScene` reserves handles, builds detached scene commands +and publishes at a schedule boundary. `map_transition.rs::start` reads/validates +on a loader thread and constructs rendering alongside physics on another worker. +`commit` retires map-owned entities/materials/images/meshes before publishing the +new world. The decoded transition package is dropped on the worker. Live old and +prepared new worlds coexist during preparation; a temporary memory peak is expected. +GPU extraction/removal is asynchronous, so counting just main-world assets is +insufficient to establish either a leak or complete retirement. + +**Culling and batching — highest-priority structural experiment, conditional on +the trace.** Material grouping reduces 8,546 source groups to 4,870 draws' worth of +mesh/material entities before Bevy visibility and batching. It combines distant +geometry with identical material identity into one larger bound. Existing frustum +and optional hierarchical occlusion operate at mesh/instance granularity: they +cannot reject individual disconnected regions inside one visible material mesh. +`graphics_menu.rs::apply` already configures `DepthPrepass` and `OcclusionCulling`; +adding those again is not an optimisation. `vendor/bevy_pbr/src/render/gpu_preprocess.rs` +and the core 3D phase nodes own preprocessing and draw execution. + +If GPU invocation counts are high while most geometry is behind buildings, evaluate +spatial subdivision **only for large opaque/masked batches**, with conservative +full-triangle bounds. Keep vertex bit patterns, indices, UVs, normals, tangent +frames, materials and shadow participation unchanged. Test camera cuts and fast +turns; do not accept occlusion false negatives or pop-in. A blanket grid raises the +group estimate about fourfold, potentially worsening queue/binning/submission cost. +Transparent batches cannot be split casually: changing mesh centers changes sort +order, and coplanar/decal order can affect pixels. No split is enabled here. + +**Material changes, pipeline traffic and instancing — potentially substantial, +but not established by batch count.** `retail_render.rs::RetailWorldMaterial` has +eight texture/sampler roles, per-material uniforms and a shared storage binding; +it does not declare a bindless resource layout. `RetailKey` adds two-sidedness to +Bevy's pipeline keys; alpha/MSAA/prepass and mesh layout also affect specialization. +`vendor/bevy_pbr/src/material.rs` queues and bins using pipeline/material/mesh keys. +Distinct handles are not automatically one draw merely because they use one shader. +Prepared mesh and waiting-pipeline counters plus system spans now expose the cost. + +Investigate bindless/texture-array material access only if queue or binding costs +dominate and hardware limits permit it. Preserve every sampling mode, mip policy, +color-space interpretation and fallback path. Atlas packing is not automatically +lossless: borders, repeat addressing and derivatives matter. The `.skate` path +already bakes world geometry; repeated source props are not currently retained as +one local mesh plus transforms. Recovering instancing must prove all vertex data, +per-instance lighting and material inputs match. No geometry welding, approximate +matching or loss of baked lightmap distinctions is justified. + +**Textures/material duplication — existing wins, limited byte-identity headroom.** +`render_texture_ids` hashes width/height/color space/payload then confirms equality, +so hash collisions cannot incorrectly merge images. Image cache keys include the +canonical texture and role. Roles deliberately differ: lightmaps expand to linear +half floats, cube maps need six layers, some data remains mip zero, and other roles +build mips and use different address modes. Combining roles solely because bytes +match can change output. Existing exact payload dedup saves only 5,858,304 decoded +bytes in University. Material canonicalization includes retail definitions as well +as PBR fields; removing apparently unused definition fields needs a full proof that +the build consumes no distinction. Texture compression/reduction is outside this +zero-degradation task unless mathematically lossless and supported end-to-end. + +**Foliage, alpha and shader cost — GPU capture required.** Retail materials preserve +two-sidedness; alpha mask/blend semantics and `retail_depth.wgsl` rejection are +significant. `retail_world.wgsl` samples diffuse/lightmap and conditional detail, +normal, macro/decal/specular resources. Samples precede some rejection to preserve +implicit derivatives. The family and texture flags are material-uniform, so these +branches are not necessarily divergent across pixels. Moving a sample after +discard, flattening detail or disabling backfaces can change pixels. Specializing +families could reduce instructions at the price of pipeline variants; measure +`elapsed_gpu`/fragment invocations and inspect generated draws first. Density, +alpha cutoff, texture precision and draw-distance reductions are disallowed. + +**Uploads, lifetimes and exposure — narrow safe change made.** The shared shadow, +clock and ocean PCA state in `retail_shadow.rs::upload` already updates an existing +GPU buffer without invalidating every material. This change replaces its temporary +144-byte heap vector with a fixed stack array; scalar order, little-endian bytes, +buffer, write size and scheduling are unchanged. It saves one allocation per upload +call; no frame-time benefit is claimed. The clock/PCA changes each frame, so simply +skipping updates is unsafe. `retail_exposure.rs::upload` writes 32 settings bytes; +`ExposureNode::run` creates two bind groups per view/frame and executes the meter +and tone passes. Caching bind groups keyed by the actual source/target identity is +a candidate if CPU encoding cost matters, but must invalidate on resize/MSAA/target +changes and account for ping-pong views. Added pass diagnostics measure these custom +passes without changing shader math or their order. Exposure's temporal adaptation +must not be decimated. + +`render_capacity.rs` already reserves instance capacity with bounded growth before +Bevy writes buffers. Do not replace that with exact-size per-frame reallocations. +Render preparation stalls can also be presentation backpressure; the official +[Bevy profiling guide](https://github.com/bevyengine/bevy/blob/v0.18.1/docs/profiling.md) +specifically discusses this ambiguity. CPU command time is not GPU execution time. + +## Simulation, transforms and scheduling + +`app.rs` orders fixed input → controls → physics and Update assets → physics +presentation → animation → verification. `physics.rs::advance` uses the native-derived +clock period, runs the monolithic fixed frame and republishes cadence. `physics/frame.rs` +preserves preceding-query consumption, animation/input/state selection, movement, +shared solve and output publication order. Added spans isolate animation graphs, +collision/solve and finishing work. They do not parallelize or reorder any phase. + +`skate_world.rs` constructs `BoardWorld` from the embedded retail collision archive. +`skate-core/src/physics/board_world/query_index.rs` already builds a bounds hierarchy +over authored clusters, traverses intersecting nodes and sorts matches back into +source order. Narrow phase checks volumes/triangles; wheels, feet, camera and board/ +skeleton assemblies have distinct query consumers. `physics/solve.rs` also handles +dynamic/network bodies. Retail map size alone does not establish fixed-step cost. +The query index allocates result/stack vectors; scratch reuse is a plausible CPU +optimisation if profiles show query pressure. Preserve result order, tie handling, +contact retention and delayed query visibility. Replacing the solver, simplifying +collision, reducing ticks, or changing contact ordering would violate the task. + +`grind_world` retains 4,201 authored splines with 27,008 primitives and an octree +provider; it is not a naive all-rails scan for every normal query. Candidate counts +and selection work need focused subspans if the fixed-frame profile implicates it. +`retail_irradiance.rs::sample` already has a six-entry, 2.5-metre hysteresis cache, +then bounds-filtered nearest-probe selection. A spatial index could help cache misses, +but must retain nearest/tie selection and hysteresis exactly. + +`presentation.rs::capture` only captures a new pose generation, retains previous/ +current snapshots and records replay. `animation.rs` interpolates bone transforms +for display. Snapshot copying and hierarchy propagation are candidates if those +systems dominate, not grounds to reduce bone update rate or interpolation quality. +Static map transforms are separate from these moving character hierarchies. +Multiplayer/mod/vehicle systems are additional workload; profiles should state +whether mods or online play were active rather than attributing all time to University. + +`graphics_menu.rs::pace` sleeps in `Last` when capped; window presentation may add +another wait. The new frame-interval counter and CPU spans preserve both behaviors. +Do not remove waits, alter fixed cadence or infer GPU saturation from a capped FPS +number. Timing variation must be investigated without modifying native input/physics. + +## Next decision requires a user capture + +Use [the capture workflow](performance-tracing.md). Record 30 seconds after loading: +stand briefly, rotate the camera, then skate through a representative University +area. Repeat the same settings/route with `--trace-gpu`; record a separate startup +trace if the problem is loading or first-use hitching. Include where the slowdown +occurred, approximate time in the capture, and whether mods/multiplayer were active. +Do not change quality settings between captures. + +Analyse steady-state frame-interval p50/p95/p99, fixed iteration counts, dominant +CPU slices, waits, prepared-resource/pipeline counts, and asynchronously received +GPU pass durations/invocations. A high CPU queue cost favors batching/material work; +high GPU opaque/foliage work favors conservative spatial subdivision or exact shader +specialization; dominant fixed solves favor order-preserving scratch/query work. +First-use-only stalls favor upload/pipeline cache work. Any nonzero dropped-event +count limits conclusions. Broad redesign waits for this evidence and manual visual +verification. No percentage gain or final bottleneck is asserted in this assessment. From c709b5d4a9ac60c1328ff3bf04395376b7ef69d1 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:22:13 +0100 Subject: [PATCH 03/24] Show capture build metadata on the viewer timeline --- crates/skate-game/src/profiling.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/skate-game/src/profiling.rs b/crates/skate-game/src/profiling.rs index 053b2bc3..36703377 100644 --- a/crates/skate-game/src/profiling.rs +++ b/crates/skate-game/src/profiling.rs @@ -213,7 +213,7 @@ fn init_options(options: Options) -> Result, String> { if result.is_err() { eprintln!("TRACE export failed; check free disk space and destination access"); } result }).map_err(|_| "Cannot start trace writer")?; - capture.send(json!({"name":"build","ph":"M","pid":1,"tid":0,"args":{"build_id":env!("SKATE_BUILD_ID"),"version":env!("CARGO_PKG_VERSION"),"revision":env!("SKATE_RELEASE_REVISION"),"bevy":"0.18.1","wgpu":"27.0.1","debug_assertions":cfg!(debug_assertions),"gpu_requested":options.gpu,"seconds":options.seconds,"delay":options.delay,"wait":options.wait}})); + capture.send(json!({"name":"build","ph":"i","s":"g","ts":0,"pid":1,"tid":0,"args":{"build_id":env!("SKATE_BUILD_ID"),"version":env!("CARGO_PKG_VERSION"),"revision":env!("SKATE_RELEASE_REVISION"),"bevy":"0.18.1","wgpu":"27.0.1","debug_assertions":cfg!(debug_assertions),"gpu_requested":options.gpu,"seconds":options.seconds,"delay":options.delay,"wait":options.wait}})); eprintln!( "TRACE armed; F9 starts waiting capture, F10 stops/exports. Recording does not stop gameplay." ); From 807160132ecc0fcc42cdb964a734f50ebb256da7 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:24:35 +0100 Subject: [PATCH 04/24] Record tracing build and static verification results --- docs/university-performance-assessment.md | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/docs/university-performance-assessment.md b/docs/university-performance-assessment.md index 51d80c50..f04671a9 100644 --- a/docs/university-performance-assessment.md +++ b/docs/university-performance-assessment.md @@ -197,3 +197,15 @@ specialization; dominant fixed solves favor order-preserving scratch/query work. First-use-only stalls favor upload/pipeline cache work. Any nonzero dropped-event count limits conclusions. Broad redesign waits for this evidence and manual visual verification. No percentage gain or final bottleneck is asserted in this assessment. + +## Verification + +The Windows static-CRT release compiled successfully using the existing shared +Cargo target cache and an explicit worktree-private EXE/PDB output. The final +executable's embedded source revision was checked against `c709b5d`; PE import +inspection found only Windows system libraries, with no Bevy/Rust DLL dependency. +Four release unit tests passed: option bounds/dependencies, disabled span filtering, +nonblocking full-queue drops, and F9-style activation/stop/valid JSON export with +secret/path/log canaries omitted. The data-only exact-runtime-batch inventory test +also passed. Existing compiler warnings remain; no game or GPU device was started. +Runtime frame timings, capture overhead and visual validation remain user tests. From 2a74581ac3f97cefff6f2877dc53e8b1963c9b54 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:34:02 +0100 Subject: [PATCH 05/24] Fix release trace labels and bound high-frequency slice volume --- crates/skate-game/Cargo.toml | 2 +- crates/skate-game/src/config.rs | 2 +- crates/skate-game/src/profiling.rs | 102 +++++++++++++++++++++- docs/performance-tracing.md | 21 ++++- docs/university-performance-assessment.md | 39 +++++++++ tools/analyse_performance_trace.py | 86 ++++++++++++++++++ 6 files changed, 246 insertions(+), 6 deletions(-) create mode 100644 tools/analyse_performance_trace.py diff --git a/crates/skate-game/Cargo.toml b/crates/skate-game/Cargo.toml index 02024130..a1efacec 100644 --- a/crates/skate-game/Cargo.toml +++ b/crates/skate-game/Cargo.toml @@ -23,7 +23,7 @@ default = ["dev-dynamic"] dev-dynamic = ["bevy/dynamic_linking"] [dependencies] -bevy = { workspace = true, features = ["jpeg", "trace"] } +bevy = { workspace = true, features = ["jpeg", "trace", "debug"] } tracing-log = "0.2" skate-core.workspace = true skate-data.workspace = true diff --git a/crates/skate-game/src/config.rs b/crates/skate-game/src/config.rs index 1bd7023a..949a8abf 100644 --- a/crates/skate-game/src/config.rs +++ b/crates/skate-game/src/config.rs @@ -34,7 +34,7 @@ impl Config { let mut args = std::env::args_os().skip(1); while let Some(arg) = args.next() { match arg.to_str() { - Some("--trace" | "--trace-seconds" | "--trace-delay") => { args.next().ok_or("Trace option requires a value")?; } + Some("--trace" | "--trace-seconds" | "--trace-delay" | "--trace-min-us") => { args.next().ok_or("Trace option requires a value")?; } Some("--trace-wait" | "--trace-gpu") => {} Some("--net-host") => config.multiplayer.host = Some(args.next().ok_or("Missing host bind address")?.to_string_lossy().parse().map_err(|_|"Invalid host bind address")?), Some("--net-local") => { diff --git a/crates/skate-game/src/profiling.rs b/crates/skate-game/src/profiling.rs index 36703377..57412b93 100644 --- a/crates/skate-game/src/profiling.rs +++ b/crates/skate-game/src/profiling.rs @@ -43,11 +43,13 @@ struct Options { delay: u64, wait: bool, gpu: bool, + min_us: u64, } impl Options { fn parse(args: impl Iterator) -> Result { let mut result = Self { seconds: 30, + min_us: 25, ..Self::default() }; let mut args = args; @@ -64,6 +66,14 @@ impl Options { .into(), ); } + Some("--trace-min-us") => { + modifiers = true; + result.min_us = args + .next() + .and_then(|a| a.to_str().and_then(|v| v.parse().ok())) + .filter(|v| *v <= 1000) + .ok_or("--trace-min-us requires 0..1000 microseconds")?; + } Some("--trace-seconds" | "--trace-delay") => { modifiers = true; let value = args @@ -119,8 +129,17 @@ struct Capture { dropped: AtomicU64, sender: SyncSender, gpu: bool, + min_us: u64, + filtered: AtomicU64, } impl Capture { + fn retain_duration(&self, micros: u64) -> bool { + if micros >= self.min_us { + return true; + } + self.filtered.fetch_add(1, Ordering::Relaxed); + false + } fn send(&self, value: Value) { if self.sender.try_send(value).is_err() { self.dropped.fetch_add(1, Ordering::Relaxed); @@ -168,6 +187,8 @@ fn init_options(options: Options) -> Result, String> { dropped: AtomicU64::new(0), sender, gpu: options.gpu, + min_us: options.min_us, + filtered: AtomicU64::new(0), }); CAPTURE .set(capture.clone()) @@ -202,7 +223,7 @@ fn init_options(options: Options) -> Result, String> { if bytes + line.len() + 2 > MAX_BYTES { reason = "size_limit"; break; } writer.write_all(&line)?; writer.write_all(b",\n")?; bytes += line.len() + 2; } - let footer = json!({"name":"capture_complete","ph":"i","s":"g","pid":1,"tid":0,"ts":state.origin.elapsed().as_micros() as u64,"args":{"reason":reason,"dropped_events":state.dropped.load(Ordering::Relaxed)}}); + let footer = json!({"name":"capture_complete","ph":"i","s":"g","pid":1,"tid":0,"ts":state.origin.elapsed().as_micros() as u64,"args":{"reason":reason,"dropped_events":state.dropped.load(Ordering::Relaxed),"filtered_short_spans":state.filtered.load(Ordering::Relaxed),"min_span_us":state.min_us}}); serde_json::to_writer(&mut writer, &footer)?; writer.write_all(b"],\"displayTimeUnit\":\"ms\"}\n")?; writer.flush()?; @@ -213,7 +234,7 @@ fn init_options(options: Options) -> Result, String> { if result.is_err() { eprintln!("TRACE export failed; check free disk space and destination access"); } result }).map_err(|_| "Cannot start trace writer")?; - capture.send(json!({"name":"build","ph":"i","s":"g","ts":0,"pid":1,"tid":0,"args":{"build_id":env!("SKATE_BUILD_ID"),"version":env!("CARGO_PKG_VERSION"),"revision":env!("SKATE_RELEASE_REVISION"),"bevy":"0.18.1","wgpu":"27.0.1","debug_assertions":cfg!(debug_assertions),"gpu_requested":options.gpu,"seconds":options.seconds,"delay":options.delay,"wait":options.wait}})); + capture.send(json!({"name":"build","ph":"i","s":"g","ts":0,"pid":1,"tid":0,"args":{"build_id":env!("SKATE_BUILD_ID"),"version":env!("CARGO_PKG_VERSION"),"revision":env!("SKATE_RELEASE_REVISION"),"bevy":"0.18.1","wgpu":"27.0.1","debug_assertions":cfg!(debug_assertions),"gpu_requested":options.gpu,"min_span_us":options.min_us,"seconds":options.seconds,"delay":options.delay,"wait":options.wait}})); eprintln!( "TRACE armed; F9 starts waiting capture, F10 stops/exports. Recording does not stop gameplay." ); @@ -244,6 +265,41 @@ fn init_options(options: Options) -> Result, String> { struct Timeline(Arc); #[derive(Default)] struct SystemName(String); +#[derive(Default)] +struct ScheduleName(String); +impl tracing::field::Visit for ScheduleName { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() != "name" { + return; + } + let name = format!("{value:?}"); + if matches!( + name.as_str(), + "Main" + | "First" + | "PreUpdate" + | "StateTransition" + | "RunFixedMainLoop" + | "FixedMain" + | "FixedFirst" + | "FixedPreUpdate" + | "FixedUpdate" + | "FixedPostUpdate" + | "FixedLast" + | "Update" + | "SpawnScene" + | "PostUpdate" + | "Last" + | "ExtractSchedule" + | "Render" + | "Startup" + | "PreStartup" + | "PostStartup" + ) { + self.0 = name; + } + } +} impl tracing::field::Visit for SystemName { fn record_debug(&mut self, _: &tracing::field::Field, _: &dyn std::fmt::Debug) {} fn record_str(&mut self, field: &tracing::field::Field, value: &str) { @@ -254,6 +310,15 @@ impl tracing::field::Visit for SystemName { } impl LookupSpan<'a>> Layer for Timeline { fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + if attrs.metadata().target().starts_with("bevy_ecs") + && attrs.metadata().name() == "schedule" + { + let mut name = ScheduleName::default(); + attrs.record(&mut name); + if let Some(span) = ctx.span(id) { + span.extensions_mut().insert(SystemName(name.0)); + } + } // Only Bevy ECS system labels may supply dynamic text. All other fields, // source locations, thread names and log events are deliberately omitted. if attrs.metadata().target().starts_with("bevy_ecs") @@ -278,6 +343,10 @@ impl LookupSpan<'a>> Layer for Timeline { Some(stack.remove(index).1) }); if let Some(start) = start.filter(|_| self.0.active.load(Ordering::Relaxed)) { + let duration = start.elapsed().as_micros() as u64; + if !self.0.retain_duration(duration) { + return; + } if let Some(span) = ctx.span(id) { let ext = span.extensions(); let label = ext @@ -285,7 +354,7 @@ impl LookupSpan<'a>> Layer for Timeline { .filter(|s| !s.0.is_empty()) .map(|s| s.0.as_str()) .unwrap_or(span.metadata().name()); - THREAD.with(|tid| self.0.send(json!({"name":label,"cat":span.metadata().name(),"ph":"X","pid":1,"tid":tid,"ts":start.duration_since(self.0.origin).as_micros() as u64,"dur":start.elapsed().as_micros() as u64}))); + THREAD.with(|tid| self.0.send(json!({"name":label,"cat":span.metadata().name(),"ph":"X","pid":1,"tid":tid,"ts":start.duration_since(self.0.origin).as_micros() as u64,"dur":duration}))); } } } @@ -481,11 +550,16 @@ mod tests { dropped: AtomicU64::new(0), sender, gpu: false, + min_us: 25, + filtered: AtomicU64::new(0), }; for _ in 0..3 { capture.counter("test", json!({"value":1})); } assert_eq!(capture.dropped.load(Ordering::Relaxed), 2); + assert!(!capture.retain_duration(24)); + assert!(capture.retain_duration(25)); + assert_eq!(capture.filtered.load(Ordering::Relaxed), 1); } fn parse(args: &[&str]) -> Result { Options::parse(args.iter().map(std::ffi::OsString::from)) @@ -499,12 +573,15 @@ mod tests { vec!["--trace-gpu"], vec!["--trace", "a", "--trace-wait", "--trace-delay", "1"], vec!["--trace", "a", "--trace", "b"], + vec!["--trace", "a", "--trace-min-us", "1001"], + vec!["--trace-min-us", "25"], ] { assert!(parse(&args).is_err()); } let options = parse(&["--trace", "a", "--trace-seconds", "600", "--trace-wait"]).unwrap(); assert!(options.wait); assert_eq!(options.seconds, 600); + assert_eq!(options.min_us, 25); assert!( parse(&["--player-title", "--trace"]) .unwrap() @@ -532,6 +609,11 @@ mod tests { std::thread::sleep(Duration::from_millis(5)); } assert!(guard.0.active.load(Ordering::Relaxed)); + // Headless ECS-only app proves real system labels survive release builds. + fn named_trace_test_system() {} + let mut app = App::new(); + app.add_systems(Update, named_trace_test_system); + app.update(); tracing::info_span!( "safe_test_span", secret = "CANARY_SECRET", @@ -553,6 +635,20 @@ mod tests { "capture_complete" ); assert!(!text.contains("CANARY")); + assert!(!text.contains("Enable the debug feature")); + assert!(parsed["traceEvents"].as_array().unwrap().iter().any(|e| { + e["cat"] == "system" + && e["name"] + .as_str() + .is_some_and(|n| n.ends_with("named_trace_test_system")) + })); + assert!( + parsed["traceEvents"] + .as_array() + .unwrap() + .iter() + .any(|e| e["cat"] == "schedule" && e["name"] == "Update") + ); assert_eq!( render_label("render/CANARY_SECRET/main_opaque_pass_3d/elapsed_gpu", 7).unwrap(), "render/7/main_opaque_pass_3d/elapsed_gpu" diff --git a/docs/performance-tracing.md b/docs/performance-tracing.md index 7942ae24..b1d9a721 100644 --- a/docs/performance-tracing.md +++ b/docs/performance-tracing.md @@ -27,6 +27,13 @@ delay range is 0–600 seconds. There is one capture per process. F9 cannot rest a completed recording. Trace modifiers without `--trace` are rejected. Existing `--assets` and `--map` options can select prepared data as usual. +CPU slices shorter than **25 microseconds** are omitted by default to keep high-FPS +captures useful within the file-size bound. Counters and metadata are not filtered. +Use `--trace-min-us 0` for an unfiltered, usually much shorter capture, or a value +up to 1000 for a coarser timeline. `capture_complete` reports `min_span_us` and +`filtered_short_spans`, separately from queue losses. Slice counts and summed slice +durations exclude those short scopes; do not treat the remainder as all CPU work. + Open the completed JSON using **Open trace file** in [Perfetto](https://ui.perfetto.dev/). Select a CPU slice to see its duration; search for `physics::advance`, `fixed_collision_and_solve`, `fixed_animation_graphs`, `prepare_mesh_bind_groups`, @@ -107,7 +114,9 @@ benchmark mode with different controls and collection semantics. ## Developer support and tooling choice -The package always enables Bevy's `trace` feature; the normal static release build +The package always enables Bevy's `trace` and `debug` features; `debug` retains ECS +diagnostic names and does **not** select Cargo's debug profile or change rendering. +The normal static release build (`cargo build --release --locked -p skate-game --bin skate3rust --no-default-features`) therefore supports the CLI. No separate `trace_chrome` or `trace_tracy` build feature is necessary. The custom subscriber retains event logging and the existing panic @@ -143,3 +152,13 @@ For exact renderer canonicalization, the ignored, data-only `skate_world::performance_inventory::runtime_batches` test accepts `SKATE_MAP_INVENTORY` and `SKATE_MAP_INVENTORY_OUT`. Neither initializes Bevy or a GPU. Keep private inventory paths and personal launchers out of published docs/artifacts. + +For a capture summary using only Python's standard library: + +```text +python tools/analyse_performance_trace.py CAPTURE.json > summary.json +``` + +The analyser streams the recorder's one-event-per-line format, reports frame-interval +percentiles and inclusive CPU slice statistics, and flags truncation, missing system +names and CPU-only captures. It does not infer GPU execution time from CPU spans. diff --git a/docs/university-performance-assessment.md b/docs/university-performance-assessment.md index f04671a9..7186416d 100644 --- a/docs/university-performance-assessment.md +++ b/docs/university-performance-assessment.md @@ -209,3 +209,42 @@ nonblocking full-queue drops, and F9-style activation/stop/valid JSON export wit secret/path/log canaries omitted. The data-only exact-runtime-batch inventory test also passed. Existing compiler warnings remain; no game or GPU device was started. Runtime frame timings, capture overhead and visual validation remain user tests. + +## First user capture: limited CPU evidence + +The user recorded a CPU-only capture with build `c709b5d`. Capture SHA-256: +`6ab11b1e174049507be2506f17d35ef6cd111fea63180ceb82a147c2067cf8d3`. +It contains 1,194,743 events and 668 frame-interval samples covering approximately +3.05 seconds of active recording. The 128 MiB byte bound terminated it early; +the queue reported zero drops. The earlier timestamp range includes the armed +waiting period and must not be mistaken for recorded gameplay duration. + +| Measurement | Median | 95th percentile | Interpretation | +|---|---:|---:|---| +| Main-frame interval | 3.59 ms | 7.50 ms | Instrumented, short sample; not scanout or baseline FPS | +| CPU command-buffer generation | 0.83 ms | 4.25 ms | Includes waits/descheduling; not GPU execution | +| CPU main opaque pass | 0.53 ms | 4.18 ms | Nested in command generation; do not add to it | +| Fixed collision/solve | 0.36 ms | 0.45 ms | 183 recorded fixed-step subspans | +| Fixed animation graphs | 0.12 ms | 0.22 ms | Fixed-step subspan, not all animation/presentation | + +Frame-interval p99 was 8.20 ms, maximum 9.21 ms and mean 4.57 ms. These values cannot +describe a full skating route or quantify recorder overhead. Prepared mesh/image +counts stayed at 4,927/2,173 over 11 sampled observations; waiting pipelines stayed +at zero. This window supplies no evidence of asset churn or first-use pipeline +compilation. The actual window/camera target was 2560×1369 while requested settings +were 2560×1440, 100% scale, 8× MSAA, uncapped, occlusion off. No setting was changed +to obtain those measurements. Device timestamp support was present, but GPU +diagnostics were not requested, so GPU costs remain unmeasured. + +The recording exposed a release instrumentation defect: system names appeared as +``. Consequently, the aggregate anonymous +system time cannot identify particular game or renderer systems. The recorder now +retains Bevy's diagnostic names in release builds and tests a real headless ECS +schedule to catch this regression. A 25 µs default slice threshold limits tiny +scheduler events; applying that filter offline to this old recording would reduce +its retained events from 1,194,743 to 61,607 (about 6.4 MB with the old labels). +That is a file-volume calculation, not a measured improvement in runtime overhead. + +Next: repeat with the corrected build and `--trace-gpu`, using the same scene and +settings. CPU command generation is a candidate for further investigation, but +this short trace does not yet support material/culling redesign or a physics change. diff --git a/tools/analyse_performance_trace.py b/tools/analyse_performance_trace.py new file mode 100644 index 00000000..da91d38c --- /dev/null +++ b/tools/analyse_performance_trace.py @@ -0,0 +1,86 @@ +"""Summarize this engine's line-oriented Chrome trace JSON without loading all events. + +Usage: python tools/analyse_performance_trace.py CAPTURE.json > summary.json +CPU durations are inclusive; totals across nested/parallel spans are not frame time. +""" +import argparse +from array import array +from collections import defaultdict +import json +import math + + +def stats(values): + ordered = sorted(values) + if not ordered: + return {"count": 0} + def percentile(p): + return ordered[max(0, math.ceil(p * len(ordered)) - 1)] + return {"count": len(ordered), "total_ms": sum(ordered), + "mean_ms": sum(ordered) / len(ordered), "p50_ms": percentile(.5), + "p95_ms": percentile(.95), "p99_ms": percentile(.99), "max_ms": ordered[-1]} + + +def analyse(path): + spans = defaultdict(lambda: array("d")) + frames = array("d") + render_durations = defaultdict(lambda: array("d")) + metadata = {} + resources = {} + active_begin = None + active_end = None + count = 0 + decoder = json.JSONDecoder() + with open(path, encoding="utf-8") as stream: + if stream.readline().strip() != '{"traceEvents":[': + raise ValueError("Expected a native engine recorder file (one event per line)") + for line in stream: + event, _ = decoder.raw_decode(line.lstrip()) + count += 1 + name = event.get("name", "") + if name in {"build", "loaded_map", "capture_complete", "adapter"}: + metadata[name] = event.get("args", {}) + if event.get("ph") == "X": + spans[(event.get("cat", ""), name)].append(event["dur"] / 1000) + ts = event["ts"] + active_begin = ts if active_begin is None else min(active_begin, ts) + active_end = max(active_end or 0, ts + event["dur"]) + if name == "frame_interval_ms": + frames.append(event["args"]["value"]) + if event.get("ph") == "C" and name.startswith("render/") and name.endswith(("/elapsed_gpu", "/elapsed_cpu")): + render_durations[name].append(event["args"]["value"]) + if name in {"assets", "render_resources", "configuration", "game_configuration"}: + resources.setdefault(name, {"first": event["args"], "last": event["args"], "samples": 0}) + resources[name]["last"] = event["args"] + resources[name]["samples"] += 1 + complete = metadata.get("capture_complete", {}) + warnings = [] + if not complete: + warnings.append("No completion marker: capture may be incomplete") + if complete.get("reason") == "size_limit": + warnings.append("Capture reached its byte limit before the requested duration") + if complete.get("dropped_events", 0): + warnings.append("Events were lost to the bounded writer queue") + if any("Enable the debug feature" in name for _, name in spans): + warnings.append("Release system names were unavailable; system attribution is invalid") + if complete.get("min_span_us", 0): + warnings.append("Short CPU slices are filtered; span totals/counts exclude them") + if not metadata.get("build", {}).get("gpu_requested", False): + warnings.append("CPU-only capture: no GPU execution durations were requested") + elif not any(name.endswith("/elapsed_gpu") for name in render_durations): + warnings.append("GPU diagnostics requested but no GPU duration samples found") + results = [{"category": cat, "name": name, **stats(values)} for (cat, name), values in spans.items()] + results.sort(key=lambda row: row["total_ms"], reverse=True) + return {"schema": 1, "event_count": count, "metadata": metadata, "warnings": warnings, + "active_cpu_span_window_ms": None if active_begin is None else (active_end-active_begin)/1000, + "frame_interval": stats(frames), "resource_samples": resources, + "cpu_spans_inclusive": results, + "render_pass_duration_counters": {name: stats(values) for name, values in render_durations.items()}, + "interpretation": "Main-frame intervals are not display scanout times. CPU slices include waits; nested/parallel totals must not be summed into frame time. GPU support is not proof of GPU timing measurement."} + + +if __name__ == "__main__": + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("capture") + options = parser.parse_args() + print(json.dumps(analyse(options.capture), indent=2)) From e3f6888dae35e59f946ca2cb0fb28497bc4727e3 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:35:56 +0100 Subject: [PATCH 06/24] Record corrected tracing build verification --- docs/university-performance-assessment.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/docs/university-performance-assessment.md b/docs/university-performance-assessment.md index 7186416d..a08d6180 100644 --- a/docs/university-performance-assessment.md +++ b/docs/university-performance-assessment.md @@ -248,3 +248,10 @@ That is a file-volume calculation, not a measured improvement in runtime overhea Next: repeat with the corrected build and `--trace-gpu`, using the same scene and settings. CPU command generation is a candidate for further investigation, but this short trace does not yet support material/culling redesign or a physics change. + +Corrected build `2a74581` passed all four release recorder tests, including actual +ECS system/schedule name assertions and the duration-filter boundary. The streaming +analyser reproduced the capture's event/sample counts and limitation flags. The +new private static-CRT release EXE/PDB built successfully; embedded revision and PE +imports were verified. The original recording and executable were retained. No +gameplay or GPU capture was launched by the agent. From d3f964bb2fafd3bca06519154752e80127cdb619 Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 02:52:56 +0100 Subject: [PATCH 07/24] Avoid identical character lighting asset updates based on trace evidence --- crates/skate-game/src/retail_character.rs | 49 ++++++++++++++++-- docs/university-performance-assessment.md | 61 +++++++++++++++++++++++ 2 files changed, 107 insertions(+), 3 deletions(-) diff --git a/crates/skate-game/src/retail_character.rs b/crates/skate-game/src/retail_character.rs index 98cd43c4..7f057bab 100644 --- a/crates/skate-game/src/retail_character.rs +++ b/crates/skate-game/src/retail_character.rs @@ -279,6 +279,7 @@ fn update( mut materials: ResMut>, mut shadow: ResMut, time: Res