diff --git a/Cargo.lock b/Cargo.lock index 9399b7b..a7c5f2a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -528,6 +528,12 @@ version = "2.7.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "32a282da65faaf38286cf3be983213fcf1d2e2a58700e808f83f4ea9a4804bc0" +[[package]] +name = "micromap" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "18c087666f377f857b49564f8791b481260c67825d6b337e1e38ddf54a985a88" + [[package]] name = "nonmax" version = "0.5.5" @@ -575,6 +581,7 @@ dependencies = [ "glam 0.30.5", "lazy_static", "libc", + "micromap", "once_cell", "parking_lot", "pathfinding", @@ -588,6 +595,7 @@ dependencies = [ "strum", "strum_macros", "thiserror", + "thousands", "tracing", "tracing-error", "tracing-subscriber", @@ -992,6 +1000,12 @@ dependencies = [ "syn", ] +[[package]] +name = "thousands" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3bf63baf9f5039dadc247375c29eb13706706cfde997d0330d05aa63a77d8820" + [[package]] name = "thread_local" version = "1.1.7" diff --git a/Cargo.toml b/Cargo.toml index 2f5454a..e73321e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,6 +27,8 @@ phf = { version = "0.12.1", features = ["macros"] } bevy_ecs = "0.16.1" bitflags = "2.9.1" parking_lot = "0.12.3" +micromap = "0.1.0" +thousands = "0.2.0" [profile.release] lto = true diff --git a/src/app.rs b/src/app.rs index 227b0c3..850bd34 100644 --- a/src/app.rs +++ b/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::() { - let mut timings = timings.timings.lock(); - let total = timings.values().sum::(); - 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 diff --git a/src/systems/profiling.rs b/src/systems/profiling.rs index 0f3995d..bc03662 100644 --- a/src/systems/profiling.rs +++ b/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>, + pub timings: Mutex, 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 = 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::() / 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::() / count; + let std_dev = variance.sqrt(); + + ( + Duration::from_secs_f64(mean / 1000.0), + Duration::from_secs_f64(std_dev / 1000.0), + ) + } } pub fn profile(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::() { - timings.timings.lock().insert(name, duration); + if let Some(timings) = world.get_resource::() { + timings.add_timing(name, duration); } } } diff --git a/tests/profiling.rs b/tests/profiling.rs new file mode 100644 index 0000000..471772c --- /dev/null +++ b/tests/profiling.rs @@ -0,0 +1,40 @@ +use pacman::systems::profiling::SystemTimings; +use std::time::Duration; + +#[test] +fn test_timing_statistics() { + let timings = SystemTimings::default(); + + // Add some test data + timings.add_timing("test_system", Duration::from_millis(10)); + timings.add_timing("test_system", Duration::from_millis(12)); + timings.add_timing("test_system", Duration::from_millis(8)); + + let stats = timings.get_stats(); + let (avg, std_dev) = stats.get("test_system").unwrap(); + + // Average should be 10ms, standard deviation should be small + assert!((avg.as_millis() as f64 - 10.0).abs() < 1.0); + assert!(std_dev.as_millis() > 0); + + let (total_avg, total_std) = timings.get_total_stats(); + assert!((total_avg.as_millis() as f64 - 10.0).abs() < 1.0); + assert!(total_std.as_millis() > 0); +} + +#[test] +fn test_window_size_limit() { + let timings = SystemTimings::default(); + + // Add more than 90 timings to test window size limit + for i in 0..100 { + timings.add_timing("test_system", Duration::from_millis(i)); + } + + let stats = timings.get_stats(); + let (avg, _) = stats.get("test_system").unwrap(); + + // Should only keep the last 90 values, so average should be around 55ms + // (average of 10-99) + assert!((avg.as_millis() as f64 - 55.0).abs() < 5.0); +}