diff --git a/Cargo.lock b/Cargo.lock index 6edadda..9ea7b87 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -663,7 +663,7 @@ checksum = "42f5e15c9953c5e4ccceeb2e7382a716482c34515315f7b03532b8b4e8393d2d" [[package]] name = "pacman" -version = "0.78.2" +version = "0.78.3" dependencies = [ "anyhow", "bevy_ecs", diff --git a/Cargo.toml b/Cargo.toml index ae958f9..f575ed7 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/game.rs b/src/game.rs index af5697f..fe2010e 100644 --- a/src/game.rs +++ b/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::>() + .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" ); } diff --git a/src/systems/profiling.rs b/src/systems/profiling.rs index eb90ecf..8941842 100644 --- a/src/systems/profiling.rs +++ b/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(id: SystemId, system: S) -> impl FnMut(&mut bevy_ecs::world::World)