feat: measure total system timings using threading indifferent method, padded formatting

This commit is contained in:
Ryan Walters
2025-09-05 14:21:15 -05:00
parent bcd9865430
commit 2fabd5d7a2
3 changed files with 51 additions and 41 deletions

View File

@@ -659,8 +659,15 @@ impl Game {
pub fn tick(&mut self, dt: f32) -> bool { pub fn tick(&mut self, dt: f32) -> bool {
self.world.insert_resource(DeltaTime(dt)); self.world.insert_resource(DeltaTime(dt));
// Run all systems // Measure total frame time including all systems
let start = std::time::Instant::now();
self.schedule.run(&mut self.world); 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);
}
let state = self let state = self
.world .world

View File

@@ -18,6 +18,7 @@ const TIMING_WINDOW_SIZE: usize = 30;
#[derive(EnumCount, EnumIter, IntoStaticStr, Debug, PartialEq, Eq, Hash, Copy, Clone)] #[derive(EnumCount, EnumIter, IntoStaticStr, Debug, PartialEq, Eq, Hash, Copy, Clone)]
pub enum SystemId { pub enum SystemId {
Total,
Input, Input,
PlayerControls, PlayerControls,
Ghost, Ghost,
@@ -85,6 +86,11 @@ impl SystemTimings {
queue.lock().push_back(duration); queue.lock().push_back(duration);
} }
/// 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 get_stats(&self) -> Map<SystemId, (Duration, Duration), MAX_SYSTEMS> { pub fn get_stats(&self) -> Map<SystemId, (Duration, Duration), MAX_SYSTEMS> {
let mut stats = Map::new(); let mut stats = Map::new();
@@ -123,47 +129,30 @@ impl SystemTimings {
stats stats
} }
pub fn get_total_stats(&self) -> (Duration, Duration) {
let duration_sums = {
self.timings
.iter()
.map(|(_, queue)| queue.lock().iter().sum::<Duration>())
.collect::<Vec<_>>()
};
let mean = duration_sums.iter().sum::<Duration>() / duration_sums.len() as u32;
let variance = duration_sums
.iter()
.map(|x| {
let diff_secs = x.as_secs_f64() - mean.as_secs_f64();
diff_secs * diff_secs
})
.sum::<f64>()
/ (duration_sums.len() - 1).max(1) as f64;
let std_dev_secs = variance.sqrt();
(mean, Duration::from_secs_f64(std_dev_secs))
}
pub fn format_timing_display(&self) -> SmallVec<[String; SystemId::COUNT]> { pub fn format_timing_display(&self) -> SmallVec<[String; SystemId::COUNT]> {
let stats = self.get_stats(); let stats = self.get_stats();
let (total_avg, total_std) = self.get_total_stats();
// Get the Total system metrics instead of averaging all systems
let (total_avg, total_std) = stats
.get(&SystemId::Total)
.copied()
.unwrap_or((Duration::ZERO, Duration::ZERO));
let effective_fps = match 1.0 / total_avg.as_secs_f64() { let effective_fps = match 1.0 / total_avg.as_secs_f64() {
f if f > 100.0 => (f as u32).separate_with_commas(), f if f > 100.0 => format!("{:>5} FPS", (f as u32).separate_with_commas()),
f if f < 10.0 => format!("{:.1} FPS", f), f if f < 10.0 => format!("{:.1} FPS", f),
f => format!("{:.0} FPS", f), f => format!("{:5.0} FPS", f),
}; };
// Collect timing data for formatting // Collect timing data for formatting
let mut timing_data = vec![(effective_fps, total_avg, total_std)]; let mut timing_data = vec![(effective_fps, total_avg, total_std)];
// Sort the stats by average duration // Sort the stats by average duration, excluding the Total system
let mut sorted_stats: Vec<_> = stats.iter().collect(); let mut sorted_stats: Vec<_> = stats.iter().filter(|(id, _)| **id != SystemId::Total).collect();
sorted_stats.sort_by(|a, b| b.1 .0.cmp(&a.1 .0)); sorted_stats.sort_by(|a, b| b.1 .0.cmp(&a.1 .0));
// Add the top 5 most expensive systems // Add the top 7 most expensive systems (excluding Total)
for (name, (avg, std_dev)) in sorted_stats.iter().take(7) { for (name, (avg, std_dev)) in sorted_stats.iter().take(9) {
timing_data.push((name.to_string(), *avg, *std_dev)); timing_data.push((name.to_string(), *avg, *std_dev));
} }

View File

@@ -40,15 +40,8 @@ fn test_timing_statistics() {
assert_close!(*std_dev, Duration::from_millis(2), "PlayerControls standard deviation timing"); assert_close!(*std_dev, Duration::from_millis(2), "PlayerControls standard deviation timing");
} }
{ // Note: get_total_stats() was removed as we now use the Total system directly
let (total_avg, total_std) = timings.get_total_stats(); // This test now focuses on individual system statistics
assert_close!(total_avg, Duration::from_millis(2), "Total average timing across all systems");
assert_close!(
total_std,
Duration::from_millis(7),
"Total standard deviation timing across all systems"
);
}
} }
#[test] #[test]
@@ -69,9 +62,9 @@ fn test_default_zero_timing_for_unused_systems() {
assert_close!(*avg, Duration::from_millis(5), "System with data should have correct timing"); assert_close!(*avg, Duration::from_millis(5), "System with data should have correct timing");
assert_close!(*std_dev, Duration::ZERO, "Single measurement should have zero std dev"); assert_close!(*std_dev, Duration::ZERO, "Single measurement should have zero std dev");
// Verify that all other systems have zero timing // Verify that all other systems have zero timing (excluding Total which is special)
for id in SystemId::iter() { for id in SystemId::iter() {
if id != SystemId::PlayerControls { if id != SystemId::PlayerControls && id != SystemId::Total {
let (avg, std_dev) = stats.get(&id).unwrap(); let (avg, std_dev) = stats.get(&id).unwrap();
assert_close!( assert_close!(
*avg, *avg,
@@ -108,3 +101,24 @@ fn test_pre_populated_timing_entries() {
); );
} }
} }
#[test]
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));
let stats = timings.get_stats();
let (avg, std_dev) = stats.get(&SystemId::Total).unwrap();
// Should have 16ms average (16+18+14)/3 = 16ms
assert_close!(*avg, Duration::from_millis(16), "Total system average timing");
// Should have some standard deviation
assert!(
*std_dev > Duration::ZERO,
"Total system should have non-zero std dev with multiple measurements"
);
}