From c94ebc6b4b393e6a5bc522d1fc5387b37a25061d Mon Sep 17 00:00:00 2001 From: Ryan Walters Date: Fri, 5 Sep 2025 13:52:19 -0500 Subject: [PATCH] feat: special formatting with game tick counter, remove date from tracing formatter --- Cargo.lock | 52 +++++++++++++++++++ Cargo.toml | 1 + src/app.rs | 4 ++ src/formatter.rs | 94 ++++++++++++++++++++++++++++++++++ src/lib.rs | 1 + src/main.rs | 1 + src/platform/emscripten.rs | 4 +- src/platform/tracing_buffer.rs | 2 + 8 files changed, 157 insertions(+), 2 deletions(-) create mode 100644 src/formatter.rs diff --git a/Cargo.lock b/Cargo.lock index d7aaf89..8c462e8 100644 --- a/Cargo.lock +++ b/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" diff --git a/Cargo.toml b/Cargo.toml index fcaa510..f0f15a8 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/app.rs b/src/app.rs index db5d8b4..611b4b4 100644 --- a/src/app.rs +++ b/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 { diff --git a/src/formatter.rs b/src/formatter.rs new file mode 100644 index 0000000..58a3b66 --- /dev/null +++ b/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 FormatEvent 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); +} diff --git a/src/lib.rs b/src/lib.rs index e63462d..b849806 100644 --- a/src/lib.rs +++ b/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; diff --git a/src/main.rs b/src/main.rs index 5691daa..715fbc1 100644 --- a/src/main.rs +++ b/src/main.rs @@ -11,6 +11,7 @@ mod constants; mod error; mod events; +mod formatter; mod game; mod map; mod platform; diff --git a/src/platform/emscripten.rs b/src/platform/emscripten.rs index faf93f1..0be3be9 100644 --- a/src/platform/emscripten.rs +++ b/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"))); diff --git a/src/platform/tracing_buffer.rs b/src/platform/tracing_buffer.rs index b2576d9..dc7b760 100644 --- a/src/platform/tracing_buffer.rs +++ b/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());