diff --git a/src/game.rs b/src/game.rs index 9fbd605..0601ce6 100644 --- a/src/game.rs +++ b/src/game.rs @@ -12,11 +12,12 @@ use crate::map::direction::Direction; use crate::systems::blinking::Blinking; use crate::systems::components::{GhostAnimation, GhostState, LastAnimationState}; use crate::systems::movement::{BufferedDirection, Position, Velocity}; -use crate::systems::profiling::SystemId; +use crate::systems::profiling::{SystemId, Timing}; use crate::systems::render::touch_ui_render_system; use crate::systems::render::RenderDirty; use crate::systems::{ self, combined_render_system, ghost_collision_system, present_system, Hidden, LinearAnimation, MovementModifiers, NodeId, + TouchState, }; use crate::systems::{ audio_system, blinking_system, collision_system, directional_render_system, dirty_render_system, eaten_ghost_system, @@ -369,13 +370,14 @@ impl Game { world.insert_resource(GlobalState { exit: false }); world.insert_resource(ScoreResource(0)); world.insert_resource(SystemTimings::default()); + world.insert_resource(Timing::default()); world.insert_resource(Bindings::default()); world.insert_resource(DeltaTime(0f32)); world.insert_resource(RenderDirty::default()); world.insert_resource(DebugState::default()); world.insert_resource(AudioState::default()); world.insert_resource(CursorPosition::default()); - world.insert_resource(systems::input::TouchState::default()); + world.insert_resource(TouchState::default()); world.insert_resource(StartupSequence::new( constants::startup::STARTUP_FRAMES, constants::startup::STARTUP_TICKS_PER_FRAME, @@ -633,14 +635,20 @@ impl Game { pub fn tick(&mut self, dt: f32) -> bool { self.world.insert_resource(DeltaTime(dt)); + // Note: We don't need to read the current tick here since we increment it after running systems + // Measure total frame time including all systems let start = std::time::Instant::now(); self.schedule.run(&mut self.world); let total_duration = start.elapsed(); - // Record the total timing - if let Some(timings) = self.world.get_resource::() { - timings.add_total_timing(total_duration); + // Increment tick counter and record the total timing + if let (Some(timings), Some(timing)) = ( + self.world.get_resource::(), + self.world.get_resource::(), + ) { + let new_tick = timing.increment_tick(); + timings.add_total_timing(total_duration, new_tick); } let state = self diff --git a/src/systems/debug.rs b/src/systems/debug.rs index cef2201..75e9dbd 100644 --- a/src/systems/debug.rs +++ b/src/systems/debug.rs @@ -152,11 +152,12 @@ fn transform_position_with_offset(pos: Vec2, scale: f32) -> IVec2 { fn render_timing_display( canvas: &mut Canvas, timings: &SystemTimings, + current_tick: u64, text_renderer: &TtfRenderer, atlas: &mut TtfAtlas, ) { // Format timing information using the formatting module - let lines = timings.format_timing_display(); + let lines = timings.format_timing_display(current_tick); let line_height = text_renderer.text_height(atlas) as i32 + 2; // Add 2px line spacing let padding = 10; @@ -208,6 +209,7 @@ pub fn debug_render_system( batched_lines: &Res, debug_state: &Res, timings: &Res, + timing: &Res, map: &Res, colliders: &Query<(&Collider, &Position)>, cursor: &Res, @@ -329,5 +331,8 @@ pub fn debug_render_system( } // Render timing information in the top-left corner - render_timing_display(canvas, timings, &text_renderer, &mut ttf_atlas.0); + // Use previous tick since current tick is incomplete (frame is still running) + let current_tick = timing.get_current_tick(); + let previous_tick = current_tick.saturating_sub(1); + render_timing_display(canvas, timings, previous_tick, &text_renderer, &mut ttf_atlas.0); } diff --git a/src/systems/profiling.rs b/src/systems/profiling.rs index 2b8d707..99bbe02 100644 --- a/src/systems/profiling.rs +++ b/src/systems/profiling.rs @@ -1,11 +1,11 @@ use bevy_ecs::system::IntoSystem; use bevy_ecs::{resource::Resource, system::System}; use circular_buffer::CircularBuffer; -use micromap::Map; use num_width::NumberWidth; use parking_lot::Mutex; use smallvec::SmallVec; use std::fmt::Display; +use std::sync::atomic::{AtomicU64, Ordering}; use std::time::Duration; use strum::{EnumCount, IntoEnumIterator}; use strum_macros::{EnumCount, EnumIter, IntoStaticStr}; @@ -16,6 +16,124 @@ const MAX_SYSTEMS: usize = SystemId::COUNT; /// The number of durations to keep in the circular buffer. const TIMING_WINDOW_SIZE: usize = 30; +/// A timing buffer that tracks durations and automatically inserts zero durations for skipped ticks. +#[derive(Debug, Default)] +pub struct TimingBuffer { + /// Circular buffer storing timing durations + buffer: CircularBuffer, + /// The last tick when this buffer was updated + last_tick: u64, +} + +impl TimingBuffer { + /// Adds a timing duration for the current tick. + /// + /// # Panics + /// + /// Panics if `current_tick` is less than `last_tick`, indicating time went backwards. + pub fn add_timing(&mut self, duration: Duration, current_tick: u64) { + if current_tick < self.last_tick { + panic!( + "Time went backwards: current_tick ({}) < last_tick ({})", + current_tick, self.last_tick + ); + } + + // Insert zero durations for any skipped ticks (but not the current tick) + if current_tick > self.last_tick { + let skipped_ticks = current_tick - self.last_tick - 1; + for _ in 0..skipped_ticks { + self.buffer.push_back(Duration::ZERO); + } + } + + // Add the actual timing + self.buffer.push_back(duration); + self.last_tick = current_tick; + } + + /// Gets statistics for this timing buffer. + /// + /// # Panics + /// + /// Panics if `current_tick` is less than `last_tick`, indicating time went backwards. + pub fn get_stats(&mut self, current_tick: u64) -> (Duration, Duration) { + // Insert zero durations for any skipped ticks since last update (but not the current tick) + if current_tick > self.last_tick { + let skipped_ticks = current_tick - self.last_tick - 1; + for _ in 0..skipped_ticks { + self.buffer.push_back(Duration::ZERO); + } + self.last_tick = current_tick; + } + + // Calculate statistics using Welford's algorithm + let mut sample_count = 0u16; + let mut running_mean = 0.0; + let mut sum_squared_diff = 0.0; + + let skip = self.last_tick.saturating_sub(current_tick); + for duration in self.buffer.iter().skip(skip as usize) { + let duration_secs = duration.as_secs_f32(); + sample_count += 1; + + let diff_from_mean = duration_secs - running_mean; + running_mean += diff_from_mean / sample_count as f32; + + let diff_from_new_mean = duration_secs - running_mean; + sum_squared_diff += diff_from_mean * diff_from_new_mean; + } + + if sample_count > 0 { + let variance = if sample_count > 1 { + sum_squared_diff / (sample_count - 1) as f32 + } else { + 0.0 + }; + + ( + Duration::from_secs_f32(running_mean), + Duration::from_secs_f32(variance.sqrt()), + ) + } else { + (Duration::ZERO, Duration::ZERO) + } + } +} + +/// A resource that tracks the current game tick using an atomic counter. +/// This ensures thread-safe access to the tick counter across systems. +#[derive(Resource, Debug)] +pub struct Timing { + /// Atomic counter for the current game tick + current_tick: AtomicU64, +} + +impl Timing { + /// Creates a new Timing resource starting at tick 0 + pub fn new() -> Self { + Self { + current_tick: AtomicU64::new(0), + } + } + + /// Gets the current tick value + pub fn get_current_tick(&self) -> u64 { + self.current_tick.load(Ordering::Relaxed) + } + + /// Increments the tick counter and returns the new value + pub fn increment_tick(&self) -> u64 { + self.current_tick.fetch_add(1, Ordering::Relaxed) + 1 + } +} + +impl Default for Timing { + fn default() -> Self { + Self::new() + } +} + #[derive(EnumCount, EnumIter, IntoStaticStr, Debug, PartialEq, Eq, Hash, Copy, Clone)] pub enum SystemId { Total, @@ -43,33 +161,24 @@ pub enum SystemId { impl Display for SystemId { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + // Use strum_macros::IntoStaticStr to get the static string write!(f, "{}", Into::<&'static str>::into(self).to_ascii_lowercase()) } } #[derive(Resource, Debug)] pub struct SystemTimings { - /// Map of system names to a queue of durations, using a circular buffer. - /// - /// Uses a RwLock to allow multiple readers for the HashMap, and a Mutex on the circular buffer for exclusive access. - /// This is probably overkill, but it's fun to play with. - /// - /// Also, we use a micromap::Map as the number of systems is generally quite small. - /// Just make sure to set the capacity appropriately, or it will panic. - /// - /// Pre-populated with all SystemId variants during initialization to avoid runtime allocations - /// and allow systems to have default zero timings when they don't submit data. - pub timings: Map>, MAX_SYSTEMS>, + /// Statically sized map of system names to timing buffers. + pub timings: micromap::Map, MAX_SYSTEMS>, } impl Default for SystemTimings { fn default() -> Self { - let mut timings = Map::new(); + let mut timings = micromap::Map::new(); // Pre-populate with all SystemId variants to avoid runtime allocations - // and provide default zero timings for systems that don't submit data for id in SystemId::iter() { - timings.insert(id, Mutex::new(CircularBuffer::new())); + timings.insert(id, Mutex::new(TimingBuffer::default())); } Self { timings } @@ -77,68 +186,39 @@ impl Default for SystemTimings { } impl SystemTimings { - pub fn add_timing(&self, id: SystemId, duration: Duration) { + pub fn add_timing(&self, id: SystemId, duration: Duration, current_tick: u64) { // Since all SystemId variants are pre-populated, we can use a simple read lock - let queue = self + let buffer = self .timings .get(&id) .expect("SystemId not found in pre-populated map - this is a bug"); - queue.lock().push_back(duration); + buffer.lock().add_timing(duration, current_tick); } /// Add timing for the Total system (total frame time including scheduler.run) - pub fn add_total_timing(&self, duration: Duration) { - self.add_timing(SystemId::Total, duration); + pub fn add_total_timing(&self, duration: Duration, current_tick: u64) { + self.add_timing(SystemId::Total, duration, current_tick); } - pub fn get_stats(&self) -> Map { - let mut stats = Map::new(); + pub fn get_stats(&self, current_tick: u64) -> micromap::Map { + let mut stats = micromap::Map::new(); // Iterate over all SystemId variants to ensure every system has an entry for id in SystemId::iter() { - let queue = self + let buffer = self .timings .get(&id) .expect("SystemId not found in pre-populated map - this is a bug"); - let queue_guard = queue.lock(); - // Welford's algorithm for a single-pass mean and variance calculation. - - let mut sample_count = 0.0; - let mut running_mean = 0.0; - let mut sum_squared_diff = 0.0; - - for duration in queue_guard.iter() { - let duration_secs = duration.as_secs_f64(); - sample_count += 1.0; - let diff_from_mean = duration_secs - running_mean; - running_mean += diff_from_mean / sample_count; - let diff_from_new_mean = duration_secs - running_mean; - sum_squared_diff += diff_from_mean * diff_from_new_mean; - } - - let (average, standard_deviation) = if sample_count > 0.0 { - let variance = if sample_count > 1.0 { - sum_squared_diff / (sample_count - 1.0) - } else { - 0.0 - }; - ( - Duration::from_secs_f64(running_mean), - Duration::from_secs_f64(variance.sqrt()), - ) - } else { - (Duration::ZERO, Duration::ZERO) - }; - + let (average, standard_deviation) = buffer.lock().get_stats(current_tick); stats.insert(id, (average, standard_deviation)); } stats } - pub fn format_timing_display(&self) -> SmallVec<[String; SystemId::COUNT]> { - let stats = self.get_stats(); + pub fn format_timing_display(&self, current_tick: u64) -> SmallVec<[String; SystemId::COUNT]> { + let stats = self.get_stats(current_tick); // Get the Total system metrics instead of averaging all systems let (total_avg, total_std) = stats @@ -185,8 +265,9 @@ where system.run((), world); let duration = start.elapsed(); - if let Some(timings) = world.get_resource::() { - timings.add_timing(id, duration); + if let (Some(timings), Some(timing)) = (world.get_resource::(), world.get_resource::()) { + let current_tick = timing.get_current_tick(); + timings.add_timing(id, duration, current_tick); } } } diff --git a/src/systems/render.rs b/src/systems/render.rs index ac9d325..05054c2 100644 --- a/src/systems/render.rs +++ b/src/systems/render.rs @@ -317,6 +317,7 @@ pub fn combined_render_system( batched_lines: Res, debug_state: Res, timings: Res, + timing: Res, map: Res, dirty: Res, renderables: Query<(Entity, &Renderable, &Position), Without>, @@ -367,6 +368,7 @@ pub fn combined_render_system( &batched_lines, &debug_state, &timings, + &timing, &map, &colliders, &cursor, @@ -381,11 +383,13 @@ pub fn combined_render_system( } // Record timings for each system independently + let current_tick = timing.get_current_tick(); + if let Some(duration) = render_duration { - timings.add_timing(SystemId::Render, duration); + timings.add_timing(SystemId::Render, duration, current_tick); } if let Some(duration) = debug_render_duration { - timings.add_timing(SystemId::DebugRender, duration); + timings.add_timing(SystemId::DebugRender, duration, current_tick); } } diff --git a/tests/profiling.rs b/tests/profiling.rs index 5cfa7c5..10bb0da 100644 --- a/tests/profiling.rs +++ b/tests/profiling.rs @@ -22,18 +22,18 @@ macro_rules! assert_close { fn test_timing_statistics() { let timings = SystemTimings::default(); - // 10ms average, 2ms std dev - timings.add_timing(SystemId::PlayerControls, Duration::from_millis(10)); - timings.add_timing(SystemId::PlayerControls, Duration::from_millis(12)); - timings.add_timing(SystemId::PlayerControls, Duration::from_millis(8)); + // Add consecutive timing measurements (no skipped ticks to avoid zero padding) + timings.add_timing(SystemId::PlayerControls, Duration::from_millis(10), 1); + timings.add_timing(SystemId::PlayerControls, Duration::from_millis(12), 2); + timings.add_timing(SystemId::PlayerControls, Duration::from_millis(8), 3); - // 2ms average, 1ms std dev - timings.add_timing(SystemId::Blinking, Duration::from_millis(3)); - timings.add_timing(SystemId::Blinking, Duration::from_millis(2)); - timings.add_timing(SystemId::Blinking, Duration::from_millis(1)); + // Add consecutive timing measurements for another system + timings.add_timing(SystemId::Blinking, Duration::from_millis(3), 1); + timings.add_timing(SystemId::Blinking, Duration::from_millis(2), 2); + timings.add_timing(SystemId::Blinking, Duration::from_millis(1), 3); { - let stats = timings.get_stats(); + let stats = timings.get_stats(3); let (avg, std_dev) = stats.get(&SystemId::PlayerControls).unwrap(); assert_close!(*avg, Duration::from_millis(10), "PlayerControls average timing"); @@ -49,9 +49,9 @@ fn test_default_zero_timing_for_unused_systems() { let timings = SystemTimings::default(); // Add timing data for only one system - timings.add_timing(SystemId::PlayerControls, Duration::from_millis(5)); + timings.add_timing(SystemId::PlayerControls, Duration::from_millis(5), 1); - let stats = timings.get_stats(); + let stats = timings.get_stats(1); // Verify all SystemId variants are present in the stats let expected_count = SystemId::iter().count(); @@ -86,12 +86,13 @@ fn test_pre_populated_timing_entries() { // Verify that we can add timing to any SystemId without panicking // (this would fail with the old implementation if the entry didn't exist) + // Use the same tick for all systems to avoid zero-padding for id in SystemId::iter() { - timings.add_timing(id, Duration::from_nanos(1)); + timings.add_timing(id, Duration::from_nanos(1), 1); } // Verify all systems now have non-zero timing - let stats = timings.get_stats(); + let stats = timings.get_stats(1); for id in SystemId::iter() { let (avg, _) = stats.get(&id).unwrap(); assert!( @@ -107,11 +108,11 @@ fn test_total_system_timing() { let timings = SystemTimings::default(); // Add some timing data to the Total system - timings.add_total_timing(Duration::from_millis(16)); - timings.add_total_timing(Duration::from_millis(18)); - timings.add_total_timing(Duration::from_millis(14)); + timings.add_total_timing(Duration::from_millis(16), 1); + timings.add_total_timing(Duration::from_millis(18), 2); + timings.add_total_timing(Duration::from_millis(14), 3); - let stats = timings.get_stats(); + let stats = timings.get_stats(3); let (avg, std_dev) = stats.get(&SystemId::Total).unwrap(); // Should have 16ms average (16+18+14)/3 = 16ms