feat: better profiling statistics, less spammy

src/app.rs

@@ -5,7 +5,8 @@ use sdl2::render::TextureCreator;
 use sdl2::ttf::Sdl2TtfContext;
 use sdl2::video::WindowContext;
 use sdl2::{AudioSubsystem, EventPump, Sdl, VideoSubsystem};
-use tracing::{field, info, warn};
+use thousands::Separable;
+use tracing::info;
 
 use crate::error::{GameError, GameResult};
 
@@ -16,6 +17,7 @@ use crate::systems::profiling::SystemTimings;
 
 pub struct App {
     pub game: Game,
+    last_timings: Instant,
     last_tick: Instant,
     focused: bool,
     _cursor_pos: Vec2,
@@ -68,6 +70,7 @@ impl App {
             game,
             focused: true,
             last_tick: Instant::now(),
+            last_timings: Instant::now() - Duration::from_secs_f32(0.5),
             _cursor_pos: Vec2::ZERO,
         })
     }
@@ -110,15 +113,26 @@ impl App {
                 return false;
             }
 
-            // Show timings if the loop took more than 25% of the loop time
-            let show_timings = start.elapsed() > (LOOP_TIME / 4);
-            if show_timings || true {
+            if self.last_timings.elapsed() > Duration::from_secs(1) {
+                // Show timing statistics over the last 90 frames
                 if let Some(timings) = self.game.world.get_resource::<SystemTimings>() {
-                    let mut timings = timings.timings.lock();
-                    let total = timings.values().sum::<Duration>();
-                    info!("Total: {:?}, Timings: {:?}", total, field::debug(&timings));
-                    timings.clear();
+                    let stats = timings.get_stats();
+                    let (total_avg, total_std) = timings.get_total_stats();
+
+                    let mut individual_timings = String::new();
+                    for (name, (avg, std_dev)) in stats.iter() {
+                        individual_timings.push_str(&format!("{}={:?} ± {:?} ", name, avg, std_dev));
+                    }
+
+                    let effective_fps = match 1.0 / total_avg.as_secs_f64() {
+                        f if f > 100.0 => (f as u32).separate_with_commas(),
+                        f if f < 10.0 => format!("{:.1} FPS", f),
+                        f => format!("{:.0} FPS", f),
+                    };
+
+                    info!("({effective_fps}) {total_avg:?} ± {total_std:?} ({individual_timings})");
                 }
+                self.last_timings = Instant::now();
             }
 
             // Sleep if we still have time left

src/systems/profiling.rs

@@ -1,12 +1,82 @@
 use bevy_ecs::prelude::Resource;
 use bevy_ecs::system::{IntoSystem, System};
+use micromap::Map;
 use parking_lot::Mutex;
-use std::collections::HashMap;
+use std::collections::VecDeque;
 use std::time::Duration;
 
+const TIMING_WINDOW_SIZE: usize = 90; // 1.5 seconds at 60 FPS
+
 #[derive(Resource, Default, Debug)]
 pub struct SystemTimings {
-    pub timings: Mutex<HashMap<&'static str, Duration>>,
+    pub timings: Mutex<Map<&'static str, VecDeque<Duration>, 15>>,
+}
+
+impl SystemTimings {
+    pub fn add_timing(&self, name: &'static str, duration: Duration) {
+        let mut timings = self.timings.lock();
+        let queue = timings.entry(name).or_insert_with(VecDeque::new);
+
+        queue.push_back(duration);
+        if queue.len() > TIMING_WINDOW_SIZE {
+            queue.pop_front();
+        }
+    }
+
+    pub fn get_stats(&self) -> Map<&'static str, (Duration, Duration), 10> {
+        let timings = self.timings.lock();
+        let mut stats = Map::new();
+
+        for (name, queue) in timings.iter() {
+            if queue.is_empty() {
+                continue;
+            }
+
+            let durations: Vec<f64> = queue.iter().map(|d| d.as_secs_f64() * 1000.0).collect();
+            let count = durations.len() as f64;
+
+            let sum: f64 = durations.iter().sum();
+            let mean = sum / count;
+
+            let variance = durations.iter().map(|x| (x - mean).powi(2)).sum::<f64>() / count;
+            let std_dev = variance.sqrt();
+
+            stats.insert(
+                *name,
+                (
+                    Duration::from_secs_f64(mean / 1000.0),
+                    Duration::from_secs_f64(std_dev / 1000.0),
+                ),
+            );
+        }
+
+        stats
+    }
+
+    pub fn get_total_stats(&self) -> (Duration, Duration) {
+        let timings = self.timings.lock();
+        let mut all_durations = Vec::new();
+
+        for queue in timings.values() {
+            all_durations.extend(queue.iter().map(|d| d.as_secs_f64() * 1000.0));
+        }
+
+        if all_durations.is_empty() {
+            return (Duration::ZERO, Duration::ZERO);
+        }
+
+        let count = all_durations.len() as f64;
+        let sum: f64 = all_durations.iter().sum();
+        let mean = sum / count;
+
+        let variance = all_durations.iter().map(|x| (x - mean).powi(2)).sum::<f64>() / count;
+        let std_dev = variance.sqrt();
+
+        (
+            Duration::from_secs_f64(mean / 1000.0),
+            Duration::from_secs_f64(std_dev / 1000.0),
+        )
+    }
 }
 
 pub fn profile<S, M>(name: &'static str, system: S) -> impl FnMut(&mut bevy_ecs::world::World)
@@ -25,8 +95,8 @@ where
         system.run((), world);
         let duration = start.elapsed();
 
-        if let Some(mut timings) = world.get_resource_mut::<SystemTimings>() {
-            timings.timings.lock().insert(name, duration);
+        if let Some(timings) = world.get_resource::<SystemTimings>() {
+            timings.add_timing(name, duration);
         }
     }
 }