diff --git a/Cargo.lock b/Cargo.lock index d8b5c6fa..041d8b6e 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]] @@ -4734,6 +4740,8 @@ dependencies = [ "blake3", "half", "image", + "naga", + "naga_oil", "serde", "serde_json", "skate-core", @@ -4741,6 +4749,8 @@ dependencies = [ "skate-mods", "skate-net", "skate-vehicles", + "tracing-log", + "wgpu", ] [[package]] @@ -5199,6 +5209,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 4fc732d7..b8322e32 100644 --- a/README.md +++ b/README.md @@ -54,3 +54,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 67f58914..cd6bdeaa 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", "debug"] } +tracing-log = "0.2" skate-core.workspace = true skate-data.workspace = true half = "=2.7.1" @@ -35,3 +36,8 @@ skate-vehicles = { path = "../skate-vehicles" } skate-net = { path = "../skate-net" } blake3 = "=1.8.7" image = { version = "=0.25.10", default-features = false, features = ["png", "jpeg"] } + +[dev-dependencies] +naga = { version = "=27.0.3", features = ["wgsl-in"] } +naga_oil = { version = "=0.20.0", default-features = false } +wgpu = { version = "=27.0.1", default-features = false, features = ["vulkan", "naga-ir"] } diff --git a/crates/skate-game/src/app.rs b/crates/skate-game/src/app.rs index 77724e88..e71c4564 100644 --- a/crates/skate-game/src/app.rs +++ b/crates/skate-game/src/app.rs @@ -65,7 +65,11 @@ pub(crate) fn build( ..default() }), ..default() - }), + }).build().disable::() + // Gameplay and menu navigation both use raw XInput. No game system + // consumes Bevy gamepad events/rumble; its second device backend can + // stall PreUpdate (70.68 ms in the University capture). + .disable::(), ) .insert_resource(bevy::winit::WinitSettings {focused_mode:bevy::winit::UpdateMode::Continuous,unfocused_mode:bevy::winit::UpdateMode::Continuous}) .insert_resource(config) @@ -119,5 +123,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..949a8abf 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" | "--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") => { 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/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/input.rs b/crates/skate-game/src/input.rs index 951bbe9c..4539f222 100644 --- a/crates/skate-game/src/input.rs +++ b/crates/skate-game/src/input.rs @@ -34,14 +34,15 @@ impl Plugin for InputPlugin { } } -pub(crate) fn poll_controllers(mut input: ResMut,config:Res,net:Option>,windows:Query<&Window>) { +pub(crate) fn poll_controllers(mut input: ResMut,config:Res,net:Option>,windows:Query<&Window>,mut capabilities:Local<[platform::CapabilityCache;4]>) { let previous = input.status; let focused=windows.iter().any(|w|w.focused); let active=net.is_some_and(|n|n.active()); input.collect(std::array::from_fn(|slot| { if active && ((!focused && config.multiplayer.controller.is_none()) || config.multiplayer.controller.is_some_and(|selected|selected as usize!=slot)) { + capabilities[slot].invalidate(); Err(platform::DeviceError::Disconnected) - } else {platform::poll(slot)} + } else {platform::poll_cached(slot, &mut capabilities[slot])} })); for (index, (&before, &after)) in previous.iter().zip(&input.status).enumerate() { if before != after { diff --git a/crates/skate-game/src/input/platform.rs b/crates/skate-game/src/input/platform.rs index b161f7c7..99ad31d0 100644 --- a/crates/skate-game/src/input/platform.rs +++ b/crates/skate-game/src/input/platform.rs @@ -17,6 +17,34 @@ pub(crate) enum DeviceError { UnsupportedPlatform, } +/// Device identity is metadata; raw input is still sampled every host frame. +/// Refresh periodically as well as after errors, so hot swaps cannot leave a +/// subtype cached indefinitely even if Windows never exposes a disconnect. +#[derive(Default)] +pub(crate) struct CapabilityCache { + value: Option<(u8, std::time::Instant)>, +} +impl CapabilityCache { + pub(crate) fn invalidate(&mut self) { + self.value = None; + } + fn get( + &mut self, + now: std::time::Instant, + read: impl FnOnce() -> Result, + ) -> Result { + if let Some((subtype, expires)) = self.value { + if now < expires { + return Ok(subtype); + } + } + self.value = None; + let subtype = read()?; + self.value = Some((subtype, now + std::time::Duration::from_secs(1))); + Ok(subtype) + } +} + #[cfg(windows)] mod windows { use super::*; @@ -62,26 +90,33 @@ mod windows { fn XInputGetCapabilities(index: u32, flags: u32, capabilities: *mut Capabilities) -> u32; } - pub(super) fn poll(index: u32) -> Result { + pub(super) fn poll( + index: u32, + cache: &mut CapabilityCache, + ) -> Result { let mut state = MaybeUninit::::uninit(); // SAFETY: properly aligned writable storage with the SDK's exact C ABI. let result = unsafe { XInputGetState(index, state.as_mut_ptr()) }; + if result != 0 { + cache.invalidate(); + } if result == 1167 { return Err(DeviceError::Disconnected); } if result != 0 { return Err(DeviceError::State(result)); } - let mut capabilities = MaybeUninit::::uninit(); - // TU3 8296D480 obtains subtype with capability flags=1. A capability - // failure stays explicit; it must not invent the converter's byte 13. - // SAFETY: same output-storage contract as above. - let result = unsafe { XInputGetCapabilities(index, 1, capabilities.as_mut_ptr()) }; - if result != 0 { - return Err(DeviceError::Capabilities(result)); - } - // SAFETY: both successful SDK calls initialized their complete structs. - let (state, capabilities) = unsafe { (state.assume_init(), capabilities.assume_init()) }; + let subtype = cache.get(std::time::Instant::now(), || { + let mut capabilities = MaybeUninit::::uninit(); + // SAFETY: writable storage with the SDK ABI; read only on success. + let result = unsafe { XInputGetCapabilities(index, 1, capabilities.as_mut_ptr()) }; + if result != 0 { + return Err(DeviceError::Capabilities(result)); + } + Ok(unsafe { capabilities.assume_init() }.subtype) + })?; + // SAFETY: successful XInputGetState initialized the complete structure. + let state = unsafe { state.assume_init() }; Ok(DevicePacket { number: state.number, state: XboxState { @@ -90,15 +125,52 @@ mod windows { left: [state.gamepad.left_x, state.gamepad.left_y], right: [state.gamepad.right_x, state.gamepad.right_y], }, - subtype: capabilities.subtype, + subtype, }) } } -pub(crate) fn poll(index: usize) -> Result { +pub(crate) fn poll_cached( + index: usize, + cache: &mut CapabilityCache, +) -> Result { assert!(index < 4); #[cfg(windows)] - return windows::poll(index as u32); + return windows::poll(index as u32, cache); #[cfg(not(windows))] Err(DeviceError::UnsupportedPlatform) } + +#[cfg(test)] +mod cache_tests { + use super::*; + #[test] + fn capability_cache_refreshes_and_never_caches_errors() { + let start = std::time::Instant::now(); + let mut cache = CapabilityCache::default(); + assert_eq!(cache.get(start, || Ok(1)), Ok(1)); + assert_eq!( + cache.get(start + std::time::Duration::from_millis(999), || panic!( + "redundant capability query" + )), + Ok(1) + ); + assert_eq!( + cache.get(start + std::time::Duration::from_secs(1), || Ok(2)), + Ok(2) + ); + cache.invalidate(); + assert_eq!( + cache.get(start, || Err(DeviceError::Capabilities(5))), + Err(DeviceError::Capabilities(5)) + ); + assert_eq!(cache.get(start, || Ok(3)), Ok(3)); + cache.invalidate(); + assert_eq!(cache.get(start, || Ok(4)), Ok(4)); + } +} + +// Preserve the uncached API for menu-only polling. +pub(crate) fn poll(index: usize) -> Result { + poll_cached(index, &mut CapabilityCache::default()) +} 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 858ab4ad..68395f36 100644 --- a/crates/skate-game/src/map_render.rs +++ b/crates/skate-game/src/map_render.rs @@ -109,6 +109,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 8cc5e50e..d57f9e57 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 353a3efb..fd37e252 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)] @@ -237,14 +237,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..91accae0 --- /dev/null +++ b/crates/skate-game/src/profiling.rs @@ -0,0 +1,658 @@ +//! 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, + 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; + 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-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 + .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, + 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); + } + } + 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, + min_us: options.min_us, + filtered: AtomicU64::new(0), + }); + 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),"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()?; + 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":"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." + ); + 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); +#[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) { + 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>) { + 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") + && 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)) { + 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 + .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":duration}))); + } + } + } +} + +#[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(),"retail_bindless":device.as_ref().map(|d|bevy::pbr::material_uses_bindless_resources::(d)),"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, + 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)) + } + #[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"], + 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() + .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)); + // 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", + 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!(!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" + ); + std::fs::remove_file(path).unwrap(); + } +} diff --git a/crates/skate-game/src/retail_character.rs b/crates/skate-game/src/retail_character.rs index 2d2b2414..2340780f 100644 --- a/crates/skate-game/src/retail_character.rs +++ b/crates/skate-game/src/retail_character.rs @@ -334,6 +334,7 @@ fn update( mut customiser: ResMut>, mut shadow: ResMut, time: Res