feat: enhance slow frame timing warning

Cargo.lock

@@ -663,7 +663,7 @@ checksum = "42f5e15c9953c5e4ccceeb2e7382a716482c34515315f7b03532b8b4e8393d2d"
 
 [[package]]
 name = "pacman"
-version = "0.78.2"
+version = "0.78.3"
 dependencies = [
  "anyhow",
  "bevy_ecs",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "pacman"
-version = "0.78.2"
+version = "0.78.3"
 authors = ["Xevion"]
 edition = "2021"
 rust-version = "1.86.0"

src/game.rs

@@ -714,12 +714,23 @@ impl Game {
             timings.add_total_timing(total_duration, new_tick);
 
             // Log performance warnings for slow frames
-            if total_duration.as_millis() > 20 {
-                // Warn if frame takes more than 20ms
+            if total_duration.as_millis() > 17 {
+                // Warn if frame takes too long
+                let slowest_systems = timings.get_slowest_systems();
+                let systems_context = if slowest_systems.is_empty() {
+                    "No specific systems identified".to_string()
+                } else {
+                    slowest_systems
+                        .iter()
+                        .map(|(id, duration)| format!("{} ({:.2?})", id, duration))
+                        .collect::<Vec<String>>()
+                        .join(", ")
+                };
+
                 warn!(
-                    duration_ms = total_duration.as_millis(),
-                    frame_dt = ?std::time::Duration::from_secs_f32(dt),
+                    total = format!("{:.3?}", total_duration),
                     tick = new_tick,
+                    systems = systems_context,
                     "Frame took longer than expected"
                 );
             }

src/systems/collision.rs

@@ -3,7 +3,7 @@ use bevy_ecs::{
     entity::Entity,
     event::{EventReader, EventWriter},
     query::With,
-    system::{Commands, Query, Res, ResMut},
+    system::{Commands, Query, Res, ResMut, Single},
 };
 use tracing::{debug, trace, warn};
 
@@ -123,7 +123,7 @@ pub fn ghost_collision_system(
     mut stage_events: EventWriter<StageTransition>,
     mut score: ResMut<ScoreResource>,
     mut game_state: ResMut<GameStage>,
-    pacman_query: Query<Entity, With<PlayerControlled>>,
+    player: Single<Entity, With<PlayerControlled>>,
     ghost_query: Query<(Entity, &Ghost), With<GhostCollider>>,
     mut ghost_state_query: Query<&mut GhostState>,
     mut events: EventWriter<AudioEvent>,
@@ -131,9 +131,9 @@ pub fn ghost_collision_system(
     for event in collision_events.read() {
         if let GameEvent::Collision(entity1, entity2) = event {
             // Check if one is Pacman and the other is a ghost
-            let (pacman_entity, ghost_entity) = if pacman_query.get(*entity1).is_ok() && ghost_query.get(*entity2).is_ok() {
+            let (pacman_entity, ghost_entity) = if *entity1 == *player && ghost_query.get(*entity2).is_ok() {
                 (*entity1, *entity2)
-            } else if pacman_query.get(*entity2).is_ok() && ghost_query.get(*entity1).is_ok() {
+            } else if *entity2 == *player && ghost_query.get(*entity1).is_ok() {
                 (*entity2, *entity1)
             } else {
                 continue;

src/systems/player.rs

@@ -1,12 +1,11 @@
 use bevy_ecs::{
-    event::{EventReader, EventWriter},
+    event::EventReader,
     query::{With, Without},
-    system::{Query, Res, ResMut},
+    system::{Query, Res, ResMut, Single},
 };
 use tracing::trace;
 
 use crate::{
-    error::GameError,
     events::{GameCommand, GameEvent},
     map::{builder::Map, graph::Edge},
     systems::{
@@ -33,31 +32,21 @@ pub fn player_control_system(
     mut state: ResMut<GlobalState>,
     mut debug_state: ResMut<DebugState>,
     mut audio_state: ResMut<AudioState>,
-    mut players: Query<&mut BufferedDirection, (With<PlayerControlled>, Without<Frozen>)>,
-    mut errors: EventWriter<GameError>,
+    mut player: Option<Single<&mut BufferedDirection, (With<PlayerControlled>, Without<Frozen>)>>,
 ) {
     // Handle events
     for event in events.read() {
         if let GameEvent::Command(command) = event {
             match command {
                 GameCommand::MovePlayer(direction) => {
-                    // Get the player's movable component (ensuring there is only one player)
-                    let mut buffered_direction = match players.single_mut() {
-                        Ok(tuple) => tuple,
-                        Err(e) => {
-                            errors.write(GameError::InvalidState(format!(
-                                "No/multiple entities queried for player system: {}",
-                                e
-                            )));
-                            return;
-                        }
-                    };
-
-                    trace!(direction = ?*direction, "Player direction buffered for movement");
-                    *buffered_direction = BufferedDirection::Some {
-                        direction: *direction,
-                        remaining_time: 0.25,
-                    };
+                    // Only handle movement if there's an unfrozen player
+                    if let Some(player_single) = player.as_mut() {
+                        trace!(direction = ?*direction, "Player direction buffered for movement");
+                        ***player_single = BufferedDirection::Some {
+                            direction: *direction,
+                            remaining_time: 0.25,
+                        };
+                    }
                 }
                 GameCommand::Exit => {
                     state.exit = true;
@@ -168,24 +157,23 @@ pub fn player_movement_system(
 }
 
 /// Applies tunnel slowdown based on the current node tile
-pub fn player_tunnel_slowdown_system(map: Res<Map>, mut q: Query<(&Position, &mut MovementModifiers), With<PlayerControlled>>) {
-    if let Ok((position, mut modifiers)) = q.single_mut() {
-        let node = position.current_node();
-        let in_tunnel = map
-            .tile_at_node(node)
-            .map(|t| t == crate::constants::MapTile::Tunnel)
-            .unwrap_or(false);
+pub fn player_tunnel_slowdown_system(map: Res<Map>, player: Single<(&Position, &mut MovementModifiers), With<PlayerControlled>>) {
+    let (position, mut modifiers) = player.into_inner();
+    let node = position.current_node();
+    let in_tunnel = map
+        .tile_at_node(node)
+        .map(|t| t == crate::constants::MapTile::Tunnel)
+        .unwrap_or(false);
 
-        if modifiers.tunnel_slowdown_active != in_tunnel {
-            trace!(
-                node,
-                in_tunnel,
-                speed_multiplier = if in_tunnel { 0.6 } else { 1.0 },
-                "Player tunnel slowdown state changed"
-            );
-        }
-
-        modifiers.tunnel_slowdown_active = in_tunnel;
-        modifiers.speed_multiplier = if in_tunnel { 0.6 } else { 1.0 };
+    if modifiers.tunnel_slowdown_active != in_tunnel {
+        trace!(
+            node,
+            in_tunnel,
+            speed_multiplier = if in_tunnel { 0.6 } else { 1.0 },
+            "Player tunnel slowdown state changed"
+        );
     }
+
+    modifiers.tunnel_slowdown_active = in_tunnel;
+    modifiers.speed_multiplier = if in_tunnel { 0.6 } else { 1.0 };
 }

src/systems/profiling.rs

@@ -52,6 +52,11 @@ impl TimingBuffer {
         self.last_tick = current_tick;
     }
 
+    /// Gets the most recent timing from the buffer.
+    pub fn get_most_recent_timing(&self) -> Duration {
+        self.buffer.back().copied().unwrap_or(Duration::ZERO)
+    }
+
     /// Gets statistics for this timing buffer.
     ///
     /// # Panics
@@ -248,6 +253,61 @@ impl SystemTimings {
         // Use the formatting module to format the data
         format_timing_display(timing_data)
     }
+
+    /// Returns a list of systems with their timings, likely responsible for slow frame timings.
+    ///
+    /// First, checks if any systems took longer than 2ms on the most recent tick.
+    /// If none exceed 2ms, accumulates systems until the top 30% of total timing
+    /// is reached, stopping at 5 systems maximum.
+    ///
+    /// Returns tuples of (SystemId, Duration) in a SmallVec capped at 5 items.
+    pub fn get_slowest_systems(&self) -> SmallVec<[(SystemId, Duration); 5]> {
+        let mut system_timings: Vec<(SystemId, Duration)> = Vec::new();
+        let mut total_duration = Duration::ZERO;
+
+        // Collect most recent timing for each system (excluding Total)
+        for id in SystemId::iter() {
+            if id == SystemId::Total {
+                continue;
+            }
+
+            if let Some(buffer) = self.timings.get(&id) {
+                let recent_timing = buffer.lock().get_most_recent_timing();
+                system_timings.push((id, recent_timing));
+                total_duration += recent_timing;
+            }
+        }
+
+        // Sort by duration (highest first)
+        system_timings.sort_by(|a, b| b.1.cmp(&a.1));
+
+        // Check for systems over 2ms threshold
+        let over_threshold: SmallVec<[(SystemId, Duration); 5]> = system_timings
+            .iter()
+            .filter(|(_, duration)| duration.as_millis() >= 2)
+            .copied()
+            .collect();
+
+        if !over_threshold.is_empty() {
+            return over_threshold;
+        }
+
+        // Accumulate top systems until 30% of total is reached (max 5 systems)
+        let threshold = total_duration.as_nanos() as f64 * 0.3;
+        let mut accumulated = 0u128;
+        let mut result = SmallVec::new();
+
+        for (id, duration) in system_timings.iter().take(5) {
+            result.push((*id, *duration));
+            accumulated += duration.as_nanos();
+
+            if accumulated as f64 >= threshold {
+                break;
+            }
+        }
+
+        result
+    }
 }
 
 pub fn profile<S, M>(id: SystemId, system: S) -> impl FnMut(&mut bevy_ecs::world::World)

src/systems/state.rs

@@ -15,7 +15,7 @@ use bevy_ecs::{
     event::{EventReader, EventWriter},
     query::{With, Without},
     resource::Resource,
-    system::{Commands, NonSendMut, Query, Res, ResMut},
+    system::{Commands, NonSendMut, Query, Res, ResMut, Single},
 };
 
 #[derive(Resource, Clone)]
@@ -122,7 +122,7 @@ pub fn stage_system(
     mut audio_events: EventWriter<AudioEvent>,
     mut stage_event_reader: EventReader<StageTransition>,
     mut blinking_query: Query<Entity, With<Blinking>>,
-    mut player_query: Query<(Entity, &mut Position), With<PlayerControlled>>,
+    player: Single<(Entity, &mut Position), With<PlayerControlled>>,
     mut ghost_query: Query<(Entity, &Ghost, &mut Position), (With<GhostCollider>, Without<PlayerControlled>)>,
     atlas: NonSendMut<SpriteAtlas>,
 ) {
@@ -132,11 +132,7 @@ pub fn stage_system(
     // Handle stage transition requests before normal ticking
     for event in stage_event_reader.read() {
         let StageTransition::GhostEatenPause { ghost_entity } = *event;
-        let pac_node = player_query
-            .single_mut()
-            .ok()
-            .map(|(_, pos)| pos.current_node())
-            .unwrap_or(map.start_positions.pacman);
+        let pac_node = player.1.current_node();
 
         debug!(ghost_entity = ?ghost_entity, node = pac_node, "Ghost eaten, entering pause state");
         new_state = Some(GameStage::GhostEatenPause {
@@ -240,18 +236,13 @@ pub fn stage_system(
     match (old_state, new_state) {
         (GameStage::Playing, GameStage::GhostEatenPause { ghost_entity, node, .. }) => {
             // Freeze the player & ghosts
-            for entity in player_query
-                .iter_mut()
-                .map(|(e, _)| e)
-                .chain(ghost_query.iter_mut().map(|(e, _, _)| e))
-            {
+            commands.entity(player.0).insert(Frozen);
+            for (entity, _, _) in ghost_query.iter_mut() {
                 commands.entity(entity).insert(Frozen);
             }
 
             // Hide the player & eaten ghost
-            for (player_entity, _) in player_query.iter_mut() {
-                commands.entity(player_entity).insert(Hidden);
-            }
+            commands.entity(player.0).insert(Hidden);
             commands.entity(ghost_entity).insert(Hidden);
 
             // Spawn bonus points entity at Pac-Man's position
@@ -275,11 +266,8 @@ pub fn stage_system(
         }
         (GameStage::GhostEatenPause { ghost_entity, .. }, GameStage::Playing) => {
             // Unfreeze and reveal the player & all ghosts
-            for entity in player_query
-                .iter_mut()
-                .map(|(e, _)| e)
-                .chain(ghost_query.iter_mut().map(|(e, _, _)| e))
-            {
+            commands.entity(player.0).remove::<(Frozen, Hidden)>();
+            for (entity, _, _) in ghost_query.iter_mut() {
                 commands.entity(entity).remove::<(Frozen, Hidden)>();
             }
 
@@ -288,11 +276,8 @@ pub fn stage_system(
         }
         (GameStage::Playing, GameStage::PlayerDying(DyingSequence::Frozen { .. })) => {
             // Freeze the player & ghosts
-            for entity in player_query
-                .iter_mut()
-                .map(|(e, _)| e)
-                .chain(ghost_query.iter_mut().map(|(e, _, _)| e))
-            {
+            commands.entity(player.0).insert(Frozen);
+            for (entity, _, _) in ghost_query.iter_mut() {
                 commands.entity(entity).insert(Frozen);
             }
         }
@@ -303,39 +288,32 @@ pub fn stage_system(
             }
 
             // Start Pac-Man's death animation
-            if let Ok((player_entity, _)) = player_query.single_mut() {
-                commands
-                    .entity(player_entity)
-                    .insert((Dying, player_death_animation.0.clone()));
-            }
+            commands.entity(player.0).insert((Dying, player_death_animation.0.clone()));
 
             // Play the death sound
             audio_events.write(AudioEvent::PlayDeath);
         }
         (GameStage::PlayerDying(DyingSequence::Animating { .. }), GameStage::PlayerDying(DyingSequence::Hidden { .. })) => {
             // Hide the player
-            if let Ok((player_entity, _)) = player_query.single_mut() {
-                commands.entity(player_entity).insert(Hidden);
-            }
+            commands.entity(player.0).insert(Hidden);
         }
         (_, GameStage::LevelRestarting) => {
-            if let Ok((player_entity, mut pos)) = player_query.single_mut() {
-                *pos = Position::Stopped {
-                    node: map.start_positions.pacman,
-                };
+            let (player_entity, mut pos) = player.into_inner();
+            *pos = Position::Stopped {
+                node: map.start_positions.pacman,
+            };
 
-                // Freeze the blinking, force them to be visible (if they were hidden by blinking)
-                for entity in blinking_query.iter_mut() {
-                    commands.entity(entity).insert(Frozen).remove::<Hidden>();
-                }
-
-                // Reset the player animation
-                commands
-                    .entity(player_entity)
-                    .remove::<(Frozen, Dying, LinearAnimation, Looping)>()
-                    .insert(player_animation.0.clone());
+            // Freeze the blinking, force them to be visible (if they were hidden by blinking)
+            for entity in blinking_query.iter_mut() {
+                commands.entity(entity).insert(Frozen).remove::<Hidden>();
             }
 
+            // Reset the player animation
+            commands
+                .entity(player_entity)
+                .remove::<(Frozen, Dying, LinearAnimation, Looping)>()
+                .insert(player_animation.0.clone());
+
             // Reset ghost positions and state
             for (ghost_entity, ghost, mut ghost_pos) in ghost_query.iter_mut() {
                 *ghost_pos = Position::Stopped {
@@ -354,22 +332,18 @@ pub fn stage_system(
         }
         (_, GameStage::Starting(StartupSequence::CharactersVisible { .. })) => {
             // Unhide the player & ghosts
-            for entity in player_query
-                .iter_mut()
-                .map(|(e, _)| e)
-                .chain(ghost_query.iter_mut().map(|(e, _, _)| e))
-            {
+            commands.entity(player.0).remove::<Hidden>();
+            for (entity, _, _) in ghost_query.iter_mut() {
                 commands.entity(entity).remove::<Hidden>();
             }
         }
         (GameStage::Starting(StartupSequence::CharactersVisible { .. }), GameStage::Playing) => {
             // Unfreeze the player & ghosts & blinking
-            for entity in player_query
-                .iter_mut()
-                .map(|(e, _)| e)
-                .chain(ghost_query.iter_mut().map(|(e, _, _)| e))
-                .chain(blinking_query.iter_mut())
-            {
+            commands.entity(player.0).remove::<Frozen>();
+            for (entity, _, _) in ghost_query.iter_mut() {
+                commands.entity(entity).remove::<Frozen>();
+            }
+            for entity in blinking_query.iter_mut() {
                 commands.entity(entity).remove::<Frozen>();
             }
         }

tests/player.rs

@@ -214,11 +214,9 @@ fn test_player_control_system_no_player_entity() {
     // Run the system - should write an error
     world
         .run_system_once(player_control_system)
-        .expect("System should run successfully");
+        .expect("System should run successfully even with no player entity");
 
-    // Check that an error was written (we can't easily check Events without manual management,
-    // so for this test we just verify the system ran without panicking)
-    // In a real implementation, you might expose error checking through the ECS world
+    // The system should run successfully and simply ignore movement commands when there's no player
 }
 
 #[test]