diff --git a/crates/benilla-world/Cargo.toml b/crates/benilla-world/Cargo.toml index 2c5bec0c..2d615251 100644 --- a/crates/benilla-world/Cargo.toml +++ b/crates/benilla-world/Cargo.toml @@ -14,7 +14,9 @@ workspace = true default = ["dev"] # `bevy/debug` names systems and parameters in ECS diagnostics (else "Enable the debug feature to # see the name"); set here so `benilla-worldview`, which reports those names, gets it too. -dev = ["benilla-formats/dev", "benilla-assets/dev", "bevy/debug"] +# `bevy/trace` wraps every system in a `tracing` span, which `sys_timing`'s `WOW_SYSTEM_TIMING` +# layer times; it is span creation only (no Tracy), and the player build drops it with `dev`. +dev = ["benilla-formats/dev", "benilla-assets/dev", "bevy/debug", "bevy/trace"] [dependencies] avian3d = "0.6" diff --git a/crates/benilla-world/src/boot.rs b/crates/benilla-world/src/boot.rs index b727ecb9..54bdb45a 100644 --- a/crates/benilla-world/src/boot.rs +++ b/crates/benilla-world/src/boot.rs @@ -18,7 +18,7 @@ pub fn tuned_default_plugins(primary_window: Window) -> PluginGroupBuilder { // Quiet wgpu/naga; the ring keeps the last stderr lines for the crash report (`log_ring`). .set(bevy::log::LogPlugin { filter: "wgpu=error,naga=warn".into(), - custom_layer: |_| Some(Box::new(crate::log_ring::LogRing)), + custom_layer: |_| Some(Box::new(crate::sys_timing::log_layers())), ..default() }) // Asset loads parse synchronously on the IO pool, and Bevy's default 4 threads saturate on diff --git a/crates/benilla-world/src/lib.rs b/crates/benilla-world/src/lib.rs index 6d9cb0bb..e75237e9 100644 --- a/crates/benilla-world/src/lib.rs +++ b/crates/benilla-world/src/lib.rs @@ -154,6 +154,7 @@ pub mod static_gx; pub mod static_merge; pub mod straddle; pub mod sun; +pub mod sys_timing; pub mod surface; pub mod terrain_stream; pub mod thread_qos; diff --git a/crates/benilla-world/src/sys_timing.rs b/crates/benilla-world/src/sys_timing.rs new file mode 100644 index 00000000..bf58d5f7 --- /dev/null +++ b/crates/benilla-world/src/sys_timing.rs @@ -0,0 +1,135 @@ +//! `WOW_SYSTEM_TIMING=1`: per-system wall time, once a second, from the `tracing` `"system"` spans +//! Bevy wraps every system in (`function_system.rs`). A measuring lever only — the layer is always +//! installed beside [`crate::log_ring`] and does nothing unless the variable is set. +//! +//! Systems are timed on span enter/exit, so a system's time is its own wall time (which for a +//! parallel system may overlap another's). Sorted costliest-first, ms per run, so a crowded-frame +//! hotspot names itself without a profiler. + +use std::collections::HashMap; +use std::sync::Mutex; +use std::time::Instant; + +use bevy::log::tracing::field::{Field, Visit}; +use bevy::log::tracing::span::Attributes; +use bevy::log::tracing::{Id, Subscriber}; +use bevy::log::tracing_subscriber::layer::Context; +use bevy::log::tracing_subscriber::Layer; + +/// The layer; installed always, active only with `WOW_SYSTEM_TIMING`. +pub struct SystemTiming { + on: bool, + /// Span id → system name, filled once at system init. + names: Mutex>, + /// Span id → the instant its current run entered. + entered: Mutex>, + /// System name → `(total_ms, runs)` since the last print. + totals: Mutex>, + last: Mutex, +} + +impl SystemTiming { + pub fn new() -> Self { + let on = std::env::var_os("WOW_SYSTEM_TIMING").is_some(); + if on { + eprintln!("[sys-timing] armed — per-system ms once a second"); + } + Self { + on, + names: Mutex::new(HashMap::new()), + entered: Mutex::new(HashMap::new()), + totals: Mutex::new(HashMap::new()), + last: Mutex::new(Instant::now()), + } + } +} + +impl Default for SystemTiming { + fn default() -> Self { + Self::new() + } +} + +/// The log ring and this timer as one layer for `LogPlugin::custom_layer`. A free function so +/// `Layer::and` resolves here, where Bevy's prelude (`SystemCondition::and`) is not in scope. +pub fn log_layers() -> impl Layer + Send + Sync + 'static +{ + use bevy::log::tracing_subscriber::Registry; + >::and_then( + crate::log_ring::LogRing, + SystemTiming::new(), + ) +} + +/// Reads the `name` field off a span. +struct NameVisitor<'a>(&'a mut String); + +impl Visit for NameVisitor<'_> { + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "name" { + *self.0 = value.to_string(); + } + } + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + if field.name() == "name" && self.0.is_empty() { + *self.0 = format!("{value:?}"); + } + } +} + +impl Layer for SystemTiming { + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context<'_, S>) { + if !self.on || attrs.metadata().name() != "system" { + return; + } + let mut name = String::new(); + attrs.record(&mut NameVisitor(&mut name)); + if !name.is_empty() { + self.names.lock().unwrap().insert(id.clone(), name); + } + } + + fn on_enter(&self, id: &Id, _ctx: Context<'_, S>) { + if !self.on { + return; + } + if self.names.lock().unwrap().contains_key(id) { + self.entered.lock().unwrap().insert(id.clone(), Instant::now()); + } + } + + fn on_exit(&self, id: &Id, _ctx: Context<'_, S>) { + if !self.on { + return; + } + let Some(start) = self.entered.lock().unwrap().remove(id) else { + return; + }; + let ms = start.elapsed().as_secs_f64() * 1000.0; + let Some(name) = self.names.lock().unwrap().get(id).cloned() else { + return; + }; + let mut totals = self.totals.lock().unwrap(); + let entry = totals.entry(name).or_insert((0.0, 0)); + entry.0 += ms; + entry.1 += 1; + let mut last = self.last.lock().unwrap(); + if last.elapsed().as_secs_f64() < 1.0 { + return; + } + *last = Instant::now(); + let mut rows: Vec<(f64, String)> = totals + .drain() + .map(|(name, (total, runs))| (total / runs.max(1) as f64, name)) + .collect(); + drop(totals); + rows.sort_by(|a, b| b.0.total_cmp(&a.0)); + eprintln!("[sys-timing] ms per run, costliest first:"); + for (per_run, name) in rows.iter().take(30) { + if *per_run < 0.02 { + break; + } + eprintln!("[sys-timing] {per_run:8.3} {name}"); + } + } +}