feat: enhance slow frame timing warning

This commit is contained in:
Ryan Walters
2025-09-08 19:18:18 -05:00
parent c163171304
commit 5bdf11dfb6
4 changed files with 77 additions and 6 deletions

2
Cargo.lock generated
View File

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

View File

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

View File

@@ -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"
);
}

View File

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