Compare commits

..

3 Commits

Author SHA1 Message Date
Ryan Walters
af81390e30 fix: use LARGE_SCALE for BatchedLineResource calculations 2025-09-06 12:15:00 -05:00
Ryan Walters
2fabd5d7a2 feat: measure total system timings using threading indifferent method, padded formatting 2025-09-06 12:15:00 -05:00
Ryan Walters
bcd9865430 chore: move BufferedWriter into tracing_buffer.rs 2025-09-06 12:15:00 -05:00
6 changed files with 105 additions and 107 deletions

View File

@@ -34,7 +34,6 @@ use bevy_ecs::schedule::common_conditions::resource_changed;
use bevy_ecs::schedule::{Condition, IntoScheduleConfigs, Schedule, SystemSet};
use bevy_ecs::system::{Local, ResMut};
use bevy_ecs::world::World;
use glam::UVec2;
use sdl2::event::EventType;
use sdl2::image::LoadTexture;
use sdl2::render::{BlendMode, Canvas, ScaleMode, TextureCreator};
@@ -302,10 +301,7 @@ impl Game {
EventRegistry::register_event::<GameEvent>(&mut world);
EventRegistry::register_event::<AudioEvent>(&mut world);
let scale =
(UVec2::from(canvas.output_size().unwrap()).as_vec2() / UVec2::from(canvas.logical_size()).as_vec2()).min_element();
world.insert_resource(BatchedLinesResource::new(&map, scale));
world.insert_resource(BatchedLinesResource::new(&map, constants::LARGE_SCALE));
world.insert_resource(Self::create_ghost_animations(&atlas)?);
world.insert_resource(map);
world.insert_resource(GlobalState { exit: false });
@@ -659,8 +655,15 @@ impl Game {
pub fn tick(&mut self, dt: f32) -> bool {
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);
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
.world

View File

@@ -1,57 +0,0 @@
#![allow(dead_code)]
//! Buffered writer for tracing logs that can store logs before console attachment.
use parking_lot::Mutex;
use std::io::{self, Write};
use std::sync::Arc;
/// A thread-safe buffered writer that stores logs in memory until flushed.
#[derive(Clone)]
pub struct BufferedWriter {
buffer: Arc<Mutex<Vec<u8>>>,
}
impl BufferedWriter {
/// Creates a new buffered writer.
pub fn new() -> Self {
Self {
buffer: Arc::new(Mutex::new(Vec::new())),
}
}
/// Flushes all buffered content to the provided writer and clears the buffer.
pub fn flush_to<W: Write>(&self, mut writer: W) -> io::Result<()> {
let mut buffer = self.buffer.lock();
if !buffer.is_empty() {
writer.write_all(&buffer)?;
writer.flush()?;
buffer.clear();
}
Ok(())
}
/// Returns the current buffer size in bytes.
pub fn buffer_size(&self) -> usize {
self.buffer.lock().len()
}
}
impl Write for BufferedWriter {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let mut buffer = self.buffer.lock();
buffer.extend_from_slice(buf);
Ok(buf.len())
}
fn flush(&mut self) -> io::Result<()> {
// For buffered writer, flush is a no-op since we're storing in memory
Ok(())
}
}
impl Default for BufferedWriter {
fn default() -> Self {
Self::new()
}
}

View File

@@ -1,7 +1,5 @@
//! Platform abstraction layer for cross-platform functionality.
#[cfg(not(target_os = "emscripten"))]
pub mod buffered_writer;
#[cfg(not(target_os = "emscripten"))]
mod desktop;
#[cfg(not(target_os = "emscripten"))]

View File

@@ -1,15 +1,66 @@
#![allow(dead_code)]
//! Buffered tracing setup for handling logs before console attachment.
use crate::formatter::CustomFormatter;
use crate::platform::buffered_writer::BufferedWriter;
use parking_lot::Mutex;
use std::io;
use std::io::Write;
use std::sync::Arc;
use tracing::{debug, Level};
use tracing_error::ErrorLayer;
use tracing_subscriber::fmt::MakeWriter;
use tracing_subscriber::layer::SubscriberExt;
/// A thread-safe buffered writer that stores logs in memory until flushed.
#[derive(Clone)]
pub struct BufferedWriter {
buffer: Arc<Mutex<Vec<u8>>>,
}
impl BufferedWriter {
/// Creates a new buffered writer.
pub fn new() -> Self {
Self {
buffer: Arc::new(Mutex::new(Vec::new())),
}
}
/// Flushes all buffered content to the provided writer and clears the buffer.
pub fn flush_to<W: Write>(&self, mut writer: W) -> io::Result<()> {
let mut buffer = self.buffer.lock();
if !buffer.is_empty() {
writer.write_all(&buffer)?;
writer.flush()?;
buffer.clear();
}
Ok(())
}
/// Returns the current buffer size in bytes.
pub fn buffer_size(&self) -> usize {
self.buffer.lock().len()
}
}
impl Write for BufferedWriter {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let mut buffer = self.buffer.lock();
buffer.extend_from_slice(buf);
Ok(buf.len())
}
fn flush(&mut self) -> io::Result<()> {
// For buffered writer, flush is a no-op since we're storing in memory
Ok(())
}
}
impl Default for BufferedWriter {
fn default() -> Self {
Self::new()
}
}
/// A writer that can switch between buffering and direct output.
#[derive(Clone, Default)]
pub struct SwitchableWriter {

View File

@@ -18,6 +18,7 @@ const TIMING_WINDOW_SIZE: usize = 30;
#[derive(EnumCount, EnumIter, IntoStaticStr, Debug, PartialEq, Eq, Hash, Copy, Clone)]
pub enum SystemId {
Total,
Input,
PlayerControls,
Ghost,
@@ -85,6 +86,11 @@ impl SystemTimings {
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> {
let mut stats = Map::new();
@@ -123,47 +129,30 @@ impl SystemTimings {
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]> {
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() {
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 => format!("{:.0} FPS", f),
f => format!("{:5.0} FPS", f),
};
// Collect timing data for formatting
let mut timing_data = vec![(effective_fps, total_avg, total_std)];
// Sort the stats by average duration
let mut sorted_stats: Vec<_> = stats.iter().collect();
// Sort the stats by average duration, excluding the Total system
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));
// Add the top 5 most expensive systems
for (name, (avg, std_dev)) in sorted_stats.iter().take(7) {
// Add the top 7 most expensive systems (excluding Total)
for (name, (avg, std_dev)) in sorted_stats.iter().take(9) {
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");
}
{
let (total_avg, total_std) = timings.get_total_stats();
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"
);
}
// Note: get_total_stats() was removed as we now use the Total system directly
// This test now focuses on individual system statistics
}
#[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!(*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() {
if id != SystemId::PlayerControls {
if id != SystemId::PlayerControls && id != SystemId::Total {
let (avg, std_dev) = stats.get(&id).unwrap();
assert_close!(
*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"
);
}