feat: special formatting with game tick counter, remove date from tracing formatter

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

@@ -1,11 +1,16 @@
+use std::collections::HashMap;
 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;
+use sdl2::render::RendererInfo;
 use sdl2::{AudioSubsystem, Sdl};
+use tracing::debug;
 
 /// Main application wrapper that manages SDL initialization, window lifecycle, and the game loop.
 ///
@@ -50,15 +55,51 @@ impl App {
             .build()
             .map_err(|e| GameError::Sdl(e.to_string()))?;
 
+        #[derive(Debug)]
+        struct DriverDetail {
+            info: RendererInfo,
+            index: usize,
+        }
+
+        let drivers: HashMap<&'static str, DriverDetail> = sdl2::render::drivers()
+            .enumerate()
+            .map(|(index, d)| (d.name, DriverDetail { info: d, index }))
+            .collect::<HashMap<_, _>>();
+
+        let get_driver =
+            |name: &'static str| -> Option<u32> { drivers.get(name.to_lowercase().as_str()).map(|d| d.index as u32) };
+
+        {
+            let mut names = drivers.keys().collect::<Vec<_>>();
+            names.sort_by_key(|k| get_driver(k));
+            debug!("Drivers: {names:?}")
+        }
+
+        // Count the number of times each pixel format is supported by each driver
+        let pixel_format_counts: HashMap<PixelFormatEnum, usize> = drivers
+            .values()
+            .flat_map(|d| d.info.texture_formats.iter())
+            .fold(HashMap::new(), |mut counts, format| {
+                *counts.entry(*format).or_insert(0) += 1;
+                counts
+            });
+
+        debug!("Pixel format counts: {pixel_format_counts:?}");
+
+        let index = get_driver("direct3d");
+        debug!("Driver index: {index:?}");
+
         let mut canvas = window
             .into_canvas()
             .accelerated()
+            // .index(index)
             .build()
             .map_err(|e| GameError::Sdl(e.to_string()))?;
 
         canvas
             .set_logical_size(CANVAS_SIZE.x, CANVAS_SIZE.y)
             .map_err(|e| GameError::Sdl(e.to_string()))?;
+        debug!("Renderer: {:?}", canvas.info());
 
         let texture_creator = canvas.texture_creator();
 
@@ -91,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/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,3 +1,5 @@
+#![allow(dead_code)]
+
 //! Buffered writer for tracing logs that can store logs before console attachment.
 
 use parking_lot::Mutex;

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/tracing_buffer.rs

@@ -1,5 +1,8 @@
+#![allow(dead_code)]
+
 //! Buffered tracing setup for handling logs before console attachment.
 
+use crate::formatter::CustomFormatter;
 use crate::platform::buffered_writer::BufferedWriter;
 use std::io;
 use tracing::{debug, Level};
@@ -88,6 +91,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/debug.rs

@@ -7,7 +7,7 @@ use crate::systems::{Collider, CursorPosition, NodeId, Position, SystemTimings};
 use crate::texture::ttf::{TtfAtlas, TtfRenderer};
 use bevy_ecs::resource::Resource;
 use bevy_ecs::system::{Query, Res};
-use glam::{IVec2, UVec2, Vec2};
+use glam::{IVec2, Vec2};
 use sdl2::pixels::Color;
 use sdl2::rect::{Point, Rect};
 use sdl2::render::{Canvas, Texture};
@@ -215,8 +215,6 @@ pub fn debug_render_system(
     if !debug_state.enabled {
         return;
     }
-    let scale = constants::LARGE_SCALE as f32;
-
     // Create debug text renderer
     let text_renderer = TtfRenderer::new(1.0);
 
@@ -249,8 +247,8 @@ pub fn debug_render_system(
                 let pos = position.get_pixel_position(&map.graph).unwrap();
 
                 // Transform position and size using common methods
-                let pos = (pos * scale).as_ivec2();
-                let size = (collider.size * scale) as u32;
+                let pos = (pos * constants::LARGE_SCALE).as_ivec2();
+                let size = (collider.size * constants::LARGE_SCALE) as u32;
 
                 Rect::from_center(Point::from((pos.x, pos.y)), size, size)
             })
@@ -266,7 +264,7 @@ pub fn debug_render_system(
     }
 
     canvas.set_draw_color(Color {
-        a: f32_to_u8(0.6),
+        a: f32_to_u8(0.65),
         ..Color::RED
     });
     canvas.set_blend_mode(sdl2::render::BlendMode::Blend);
@@ -280,8 +278,8 @@ pub fn debug_render_system(
             .nodes()
             .enumerate()
             .filter_map(|(id, node)| {
-                let pos = transform_position_with_offset(node.position, scale);
-                let size = (2.0 * scale) as u32;
+                let pos = transform_position_with_offset(node.position, constants::LARGE_SCALE);
+                let size = (2.0 * constants::LARGE_SCALE) as u32;
                 let rect = Rect::new(pos.x - (size as i32 / 2), pos.y - (size as i32 / 2), size, size);
 
                 // If the node is the one closest to the cursor, draw it immediately
@@ -311,7 +309,7 @@ pub fn debug_render_system(
     // Render node ID if a node is highlighted
     if let Some(closest_node_id) = closest_node {
         let node = map.graph.get_node(closest_node_id as NodeId).unwrap();
-        let pos = transform_position_with_offset(node.position, scale);
+        let pos = transform_position_with_offset(node.position, constants::LARGE_SCALE);
 
         let node_id_text = closest_node_id.to_string();
         let text_pos = Vec2::new((pos.x + 10) as f32, (pos.y - 5) as f32);
@@ -323,7 +321,7 @@ pub fn debug_render_system(
                 &node_id_text,
                 text_pos,
                 Color {
-                    a: f32_to_u8(0.4),
+                    a: f32_to_u8(0.9),
                     ..Color::WHITE
                 },
             )

src/systems/input.rs

@@ -6,8 +6,13 @@ use bevy_ecs::{
     system::{NonSendMut, Res, ResMut},
 };
 use glam::Vec2;
-use sdl2::{event::Event, keyboard::Keycode, EventPump};
+use sdl2::{
+    event::{Event, WindowEvent},
+    keyboard::Keycode,
+    EventPump,
+};
 use smallvec::{smallvec, SmallVec};
+use tracing::{debug, info};
 
 use crate::systems::components::DeltaTime;
 use crate::{
@@ -293,7 +298,15 @@ pub fn input_system(
                     simple_key_events.push(SimpleKeyEvent::KeyUp(key));
                 }
             }
-            Event::RenderTargetsReset { .. } | Event::Window { .. } => {
+            Event::Window { win_event, .. } => match win_event {
+                WindowEvent::Resized(w, h) => {
+                    info!("Window resized to {}x{}", w, h);
+                }
+                _ => {
+                    debug!("Window event: {:?}", win_event);
+                }
+            },
+            Event::RenderTargetsReset { .. } => {
                 // No-op
             }
             _ => {