feat: add profiling

Cargo.lock

@@ -576,6 +576,7 @@ dependencies = [
  "lazy_static",
  "libc",
  "once_cell",
+ "parking_lot",
  "pathfinding",
  "phf",
  "rand",

Cargo.toml

@@ -6,7 +6,7 @@ edition = "2021"
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
-tracing = { version = "0.1.40", features = ["max_level_debug", "release_max_level_debug"]}
+tracing = { version = "0.1.41", features = ["max_level_debug", "release_max_level_debug"]}
 tracing-error = "0.2.0"
 tracing-subscriber = {version = "0.3.17", features = ["env-filter"]}
 lazy_static = "1.5.0"
@@ -17,7 +17,7 @@ pathfinding = "4.14"
 once_cell = "1.21.3"
 thiserror = "2.0.14"
 anyhow = "1.0"
-glam = { version = "0.30.5", features = [] }
+glam = "0.30.5"
 serde = { version = "1.0.219", features = ["derive"] }
 serde_json = "1.0.142"
 smallvec = "1.15.1"
@@ -26,6 +26,7 @@ strum_macros = "0.27.2"
 phf = { version = "0.12.1", features = ["macros"] }
 bevy_ecs = "0.16.1"
 bitflags = "2.9.1"
+parking_lot = "0.12.3"
 
 [profile.release]
 lto = true

src/app.rs

@@ -5,13 +5,14 @@ use sdl2::render::TextureCreator;
 use sdl2::ttf::Sdl2TtfContext;
 use sdl2::video::WindowContext;
 use sdl2::{AudioSubsystem, EventPump, Sdl, VideoSubsystem};
-use tracing::warn;
+use tracing::{field, info, warn};
 
 use crate::error::{GameError, GameResult};
 
 use crate::constants::{CANVAS_SIZE, LOOP_TIME, SCALE};
 use crate::game::Game;
 use crate::platform::get_platform;
+use crate::systems::profiling::SystemTimings;
 
 pub struct App {
     pub game: Game,
@@ -64,12 +65,6 @@ impl App {
         let game = Game::new(canvas, texture_creator, event_pump)?;
         // game.audio.set_mute(cfg!(debug_assertions));
 
-        // Initial draw
-        // game.draw(&mut canvas, &mut backbuffer)
-        //     .map_err(|e| GameError::Sdl(e.to_string()))?;
-        // game.present_backbuffer(&mut canvas, &backbuffer, glam::Vec2::ZERO)
-        //     .map_err(|e| GameError::Sdl(e.to_string()))?;
-
         Ok(App {
             game,
             focused: true,
@@ -116,17 +111,23 @@ impl App {
                 return false;
             }
 
-            // if let Err(e) = self.game.draw(&mut self.canvas, &mut self.backbuffer) {
+            // Show timings if the loop took more than 25% of the loop time
-            //     error!("Failed to draw game: {}", e);
+            let show_timings = start.elapsed() > (LOOP_TIME / 4);
-            // }
+            if show_timings || true {
+                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();
+                }
+            }
 
+            // Sleep if we still have time left
             if start.elapsed() < LOOP_TIME {
                 let time = LOOP_TIME.saturating_sub(start.elapsed());
                 if time != Duration::ZERO {
                     get_platform().sleep(time, self.focused);
                 }
-            } else {
-                warn!("Game loop behind schedule by: {:?}", start.elapsed() - LOOP_TIME);
             }
 
             true

src/game/mod.rs

@@ -19,6 +19,7 @@ use crate::systems::{
     control::player_system,
     input::input_system,
     movement::movement_system,
+    profiling::{profile, SystemTimings},
     render::{directional_render_system, render_system, BackbufferResource, MapTextureResource},
 };
 use crate::texture::animated::AnimatedTexture;
@@ -171,6 +172,7 @@ impl Game {
         world.insert_resource(map);
         world.insert_resource(GlobalState { exit: false });
         world.insert_resource(ScoreResource(0));
+        world.insert_resource(SystemTimings::default());
         world.insert_resource(Bindings::default());
         world.insert_resource(DeltaTime(0f32));
 
@@ -188,13 +190,13 @@ impl Game {
 
         schedule.add_systems(
             (
-                input_system,
+                profile("input", input_system),
-                player_system,
+                profile("player", player_system),
-                movement_system,
+                profile("movement", movement_system),
-                collision_system,
+                profile("collision", collision_system),
-                blinking_system,
+                profile("blinking", blinking_system),
-                directional_render_system,
+                profile("directional_render", directional_render_system),
-                render_system,
+                profile("render", render_system),
             )
                 .chain(),
         );

src/systems/mod.rs

@@ -9,4 +9,5 @@ pub mod components;
 pub mod control;
 pub mod input;
 pub mod movement;
+pub mod profiling;
 pub mod render;

src/systems/profiling.rs

@@ -0,0 +1,32 @@
+use bevy_ecs::prelude::Resource;
+use bevy_ecs::system::{IntoSystem, System};
+use parking_lot::Mutex;
+use std::collections::HashMap;
+use std::time::Duration;
+
+#[derive(Resource, Default, Debug)]
+pub struct SystemTimings {
+    pub timings: Mutex<HashMap<&'static str, Duration>>,
+}
+
+pub fn profile<S, M>(name: &'static str, system: S) -> impl FnMut(&mut bevy_ecs::world::World)
+where
+    S: IntoSystem<(), (), M> + 'static,
+{
+    let mut system: S::System = IntoSystem::into_system(system);
+    let mut is_initialized = false;
+    move |world: &mut bevy_ecs::world::World| {
+        if !is_initialized {
+            system.initialize(world);
+            is_initialized = true;
+        }
+
+        let start = std::time::Instant::now();
+        system.run((), world);
+        let duration = start.elapsed();
+
+        if let Some(mut timings) = world.get_resource_mut::<SystemTimings>() {
+            timings.timings.lock().insert(name, duration);
+        }
+    }
+}