xevion/Pac-Man
1
0
Fork 0
mirror of https://github.com/Xevion/Pac-Man.git synced 2025-12-09 22:07:53 -06:00
Code Issues Packages Projects Releases Wiki Activity

feat: enhance profiling with tick-based timing management and zero-padding for skipped frames

Browse Source
This commit is contained in:
Ryan Walters
2025-09-05 18:45:43 -05:00
parent a38423f006
commit b6b992b8fc
5 changed files with 182 additions and 83 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
src/game.rs
View File

@@ -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::<systems::profiling::SystemTimings>() {
timings.add_total_timing(total_duration);
// Increment tick counter and record the total timing
if let (Some(timings), Some(timing)) = (
self.world.get_resource::<systems::profiling::SystemTimings>(),
self.world.get_resource::<Timing>(),
) {
let new_tick = timing.increment_tick();
timings.add_total_timing(total_duration, new_tick);
}
let state = self

9
src/systems/debug.rs
View File

@@ -152,11 +152,12 @@ fn transform_position_with_offset(pos: Vec2, scale: f32) -> IVec2 {
fn render_timing_display(
canvas: &mut Canvas<Window>,
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<BatchedLinesResource>,
debug_state: &Res<DebugState>,
timings: &Res<SystemTimings>,
timing: &Res<crate::systems::profiling::Timing>,
map: &Res<Map>,
colliders: &Query<(&Collider, &Position)>,
cursor: &Res<CursorPosition>,
@@ -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);
}

195
src/systems/profiling.rs
View File

@@ -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<TIMING_WINDOW_SIZE, Duration>,
/// 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<SystemId, Mutex<CircularBuffer<TIMING_WINDOW_SIZE, Duration>>, MAX_SYSTEMS>,
/// Statically sized map of system names to timing buffers.
pub timings: micromap::Map<SystemId, Mutex<TimingBuffer>, 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<SystemId, (Duration, Duration), MAX_SYSTEMS> {
let mut stats = Map::new();
pub fn get_stats(&self, current_tick: u64) -> micromap::Map<SystemId, (Duration, Duration), MAX_SYSTEMS> {
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::<SystemTimings>() {
timings.add_timing(id, duration);
if let (Some(timings), Some(timing)) = (world.get_resource::<SystemTimings>(), world.get_resource::<Timing>()) {
let current_tick = timing.get_current_tick();
timings.add_timing(id, duration, current_tick);
}
}
}

8
src/systems/render.rs
View File

@@ -317,6 +317,7 @@ pub fn combined_render_system(
batched_lines: Res<BatchedLinesResource>,
debug_state: Res<DebugState>,
timings: Res<SystemTimings>,
timing: Res<crate::systems::profiling::Timing>,
map: Res<Map>,
dirty: Res<RenderDirty>,
renderables: Query<(Entity, &Renderable, &Position), Without<Hidden>>,
@@ -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);
}
}

35
tests/profiling.rs
View File

@@ -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