world: WOW_SYSTEM_TIMING times systems via bevy's trace spans, once a second

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"

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

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;

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<HashMap<Id, String>>,
+    /// Span id → the instant its current run entered.
+    entered: Mutex<HashMap<Id, Instant>>,
+    /// System name → `(total_ms, runs)` since the last print.
+    totals: Mutex<HashMap<String, (f64, u64)>>,
+    last: Mutex<Instant>,
+}
+
+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<bevy::log::tracing_subscriber::Registry> + Send + Sync + 'static
+{
+    use bevy::log::tracing_subscriber::Registry;
+    <crate::log_ring::LogRing as Layer<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<S: Subscriber> Layer<S> 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}");
+        }
+    }
+}