fix: use LARGE_SCALE for BatchedLineResource calculations

Cargo.lock

@@ -301,6 +301,15 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "deranged"
+version = "0.5.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d630bccd429a5bb5a64b5e94f693bfc48c9f8566418fda4c494cc94f911f87cc"
+dependencies = [
+ "powerfmt",
+]
+
 [[package]]
 name = "derive_more"
 version = "1.0.0"
@@ -561,6 +570,12 @@ dependencies = [
  "windows-sys 0.52.0",
 ]
 
+[[package]]
+name = "num-conv"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "51d515d32fb182ee37cda2ccdcb92950d6a3c2893aa280e540671c2cd0f3b1d9"
+
 [[package]]
 name = "num-traits"
 version = "0.2.19"
@@ -608,6 +623,7 @@ dependencies = [
  "strum_macros",
  "thiserror",
  "thousands",
+ "time",
  "tracing",
  "tracing-error",
  "tracing-subscriber",
@@ -722,6 +738,12 @@ dependencies = [
  "portable-atomic",
 ]
 
+[[package]]
+name = "powerfmt"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391"
+
 [[package]]
 name = "ppv-lite86"
 version = "0.2.21"
@@ -1032,6 +1054,36 @@ dependencies = [
  "once_cell",
 ]
 
+[[package]]
+name = "time"
+version = "0.3.43"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "83bde6f1ec10e72d583d91623c939f623002284ef622b87de38cfd546cbf2031"
+dependencies = [
+ "deranged",
+ "num-conv",
+ "powerfmt",
+ "serde",
+ "time-core",
+ "time-macros",
+]
+
+[[package]]
+name = "time-core"
+version = "0.1.6"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "40868e7c1d2f0b8d73e4a8c7f0ff63af4f6d19be117e90bd73eb1d62cf831c6b"
+
+[[package]]
+name = "time-macros"
+version = "0.2.24"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "30cfb0125f12d9c277f35663a0a33f8c30190f4e4574868a330595412d34ebf3"
+dependencies = [
+ "num-conv",
+ "time-core",
+]
+
 [[package]]
 name = "toml_datetime"
 version = "0.6.11"

Cargo.toml

@@ -24,6 +24,7 @@ pathfinding = "4.14"
 tracing = { version = "0.1.41", features = ["max_level_debug", "release_max_level_debug"]}
 tracing-error = "0.2.0"
 tracing-subscriber = {version = "0.3.20", features = ["env-filter"]}
+time = { version = "0.3.43", features = ["formatting", "macros"] }
 thiserror = "2.0.16"
 anyhow = "1.0"
 smallvec = "1.15.1"

src/app.rs

@@ -4,6 +4,7 @@ use std::time::{Duration, Instant};
 use crate::error::{GameError, GameResult};
 
 use crate::constants::{CANVAS_SIZE, LOOP_TIME, SCALE};
+use crate::formatter;
 use crate::game::Game;
 use crate::platform;
 use sdl2::pixels::PixelFormatEnum;
@@ -131,6 +132,9 @@ impl App {
             let dt = self.last_tick.elapsed().as_secs_f32();
             self.last_tick = start;
 
+            // Increment the global tick counter for tracing
+            formatter::increment_tick();
+
             let exit = self.game.tick(dt);
 
             if exit {

src/formatter.rs

@@ -0,0 +1,94 @@
+//! Custom tracing formatter with tick counter integration
+
+use std::fmt;
+use std::sync::atomic::{AtomicU64, Ordering};
+use time::macros::format_description;
+use time::{format_description::FormatItem, OffsetDateTime};
+use tracing::{Event, Subscriber};
+use tracing_subscriber::fmt::format::Writer;
+use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields};
+use tracing_subscriber::registry::LookupSpan;
+
+/// Global atomic counter for tracking game ticks
+static TICK_COUNTER: AtomicU64 = AtomicU64::new(0);
+
+/// Maximum value for tick counter display (16-bit hex)
+const TICK_DISPLAY_MASK: u64 = 0xFFFF;
+
+/// Cached format description for timestamps
+/// Uses 3 subsecond digits on Emscripten, 5 otherwise for better performance
+#[cfg(target_os = "emscripten")]
+const TIMESTAMP_FORMAT: &[FormatItem<'static>] = format_description!("[hour]:[minute]:[second].[subsecond digits:3]");
+
+#[cfg(not(target_os = "emscripten"))]
+const TIMESTAMP_FORMAT: &[FormatItem<'static>] = format_description!("[hour]:[minute]:[second].[subsecond digits:5]");
+
+/// A custom formatter that includes both timestamp and tick counter in hexadecimal
+///
+/// This formatter provides:
+/// - High-precision timestamps (HH:MM:SS.mmm on Emscripten, HH:MM:SS.mmmmm otherwise)
+/// - Hexadecimal tick counter for frame correlation
+/// - Standard log level and target information
+///
+/// Performance considerations:
+/// - Timestamp format is cached at compile time
+/// - Tick counter access is atomic and very fast
+/// - Combined formatting operations for efficiency
+pub struct CustomFormatter;
+
+impl<S, N> FormatEvent<S, N> for CustomFormatter
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(&self, ctx: &FmtContext<'_, S, N>, mut writer: Writer<'_>, event: &Event<'_>) -> fmt::Result {
+        // Format timestamp using cached format description
+        let now = OffsetDateTime::now_utc();
+        let formatted_time = now.format(&TIMESTAMP_FORMAT).map_err(|e| {
+            // Preserve the original error information for debugging
+            eprintln!("Failed to format timestamp: {}", e);
+            fmt::Error
+        })?;
+
+        // Get tick count and format everything together
+        let tick_count = get_tick_count();
+        let metadata = event.metadata();
+
+        // Combined formatting: timestamp, tick counter, level, and target in one write
+        write!(
+            writer,
+            "{} 0x{:04X} {:5} {}: ",
+            formatted_time,
+            tick_count & TICK_DISPLAY_MASK,
+            metadata.level(),
+            metadata.target()
+        )?;
+
+        // Format the fields (the actual log message)
+        ctx.field_format().format_fields(writer.by_ref(), event)?;
+
+        writeln!(writer)
+    }
+}
+
+/// Increment the global tick counter by 1
+///
+/// This should be called once per game tick/frame from the main game loop
+pub fn increment_tick() {
+    TICK_COUNTER.fetch_add(1, Ordering::Relaxed);
+}
+
+/// Get the current tick count
+///
+/// Returns the current value of the global tick counter
+pub fn get_tick_count() -> u64 {
+    TICK_COUNTER.load(Ordering::Relaxed)
+}
+
+/// Reset the tick counter to 0
+///
+/// This can be used for testing or when restarting the game
+#[allow(dead_code)]
+pub fn reset_tick_counter() {
+    TICK_COUNTER.store(0, Ordering::Relaxed);
+}

src/game.rs

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

src/lib.rs

@@ -6,6 +6,7 @@ pub mod audio;
 pub mod constants;
 pub mod error;
 pub mod events;
+pub mod formatter;
 pub mod game;
 pub mod map;
 pub mod platform;

src/main.rs

@@ -11,6 +11,7 @@ mod constants;
 
 mod error;
 mod events;
+mod formatter;
 mod game;
 mod map;
 mod platform;

src/platform/buffered_writer.rs

@@ -1,55 +0,0 @@
-//! 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()
-    }
-}

src/platform/emscripten.rs

@@ -2,6 +2,7 @@
 
 use crate::asset::Asset;
 use crate::error::{AssetError, PlatformError};
+use crate::formatter::CustomFormatter;
 use rand::{rngs::SmallRng, SeedableRng};
 use sdl2::rwops::RWops;
 use std::borrow::Cow;
@@ -33,8 +34,7 @@ pub fn init_console() -> Result<(), PlatformError> {
             fmt::layer()
                 .with_writer(|| EmscriptenConsoleWriter)
                 .with_ansi(false)
-                .without_time()
-                .with_target(false),
+                .event_format(CustomFormatter),
         )
         .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug")));
 

src/platform/mod.rs

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

src/platform/tracing_buffer.rs

@@ -1,12 +1,66 @@
+#![allow(dead_code)]
 //! Buffered tracing setup for handling logs before console attachment.
 
-use crate::platform::buffered_writer::BufferedWriter;
+use crate::formatter::CustomFormatter;
+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 {
@@ -88,6 +142,7 @@ pub fn setup_switchable_subscriber() -> SwitchableWriter {
     let _subscriber = tracing_subscriber::fmt()
         .with_ansi(cfg!(not(target_os = "emscripten")))
         .with_max_level(Level::DEBUG)
+        .event_format(CustomFormatter)
         .with_writer(make_writer)
         .finish()
         .with(ErrorLayer::default());

src/systems/profiling.rs

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

tests/profiling.rs

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