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

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

@@ -2,6 +2,7 @@
 
 //! 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};
@@ -90,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());