feat: tracing, sleep timing calculations, use spin_sleeper for accurate sleeps on Windows

src/main.rs

@@ -1,8 +1,10 @@
 use crate::constants::{WINDOW_HEIGHT, WINDOW_WIDTH};
 use crate::game::Game;
-use sdl2::event::Event;
+use tracing::{event};
+use sdl2::event::{Event};
 use sdl2::keyboard::Keycode;
 use std::time::{Duration, Instant};
+use spin_sleep::sleep;
 
 #[cfg(target_os = "emscripten")]
 pub mod emscripten;
@@ -22,6 +24,20 @@ pub fn main() {
     let sdl_context = sdl2::init().unwrap();
     let video_subsystem = sdl_context.video().unwrap();
 
+    // Setup tracing
+    #[cfg(debug_assertions)]
+    {
+        use tracing_error::ErrorLayer;
+        use tracing_subscriber::layer::SubscriberExt;
+
+        let subscriber = tracing_subscriber::fmt()
+            .with_max_level(tracing::Level::DEBUG)
+            .finish()
+            .with(ErrorLayer::default());
+
+        tracing::subscriber::set_global_default(subscriber).expect("Could not set global default");
+    }
+
     let window = video_subsystem
         .window("Pac-Man", WINDOW_WIDTH, WINDOW_HEIGHT)
         .position_centered()
@@ -45,11 +61,18 @@ pub fn main() {
         .event_pump()
         .expect("Could not get SDL EventPump");
 
+    // Initial draw and tick
     game.draw();
     game.tick();
 
-    let loop_time = Duration::from_millis(1000 / 60);
+    let loop_time = Duration::from_secs(1) / 60;
+    let mut tick_no = 0u32;
 
+    // The start of a period of time over which we average the frame time.
+    let mut last_averaging_time = Instant::now();
+    let mut sleep_time = Duration::ZERO;
+
+    event!(tracing::Level::INFO, "Starting game loop ({:.3}ms)", loop_time.as_secs_f32() * 1000.0);
     let mut main_loop = || {
         let start = Instant::now();
 
@@ -72,14 +95,37 @@ pub fn main() {
         game.draw();
 
         if start.elapsed() < loop_time {
-            ::std::thread::sleep(loop_time - start.elapsed());
+            let time = loop_time - start.elapsed();
+            sleep(time);
+            sleep_time += time;
         } else {
-            println!(
+            event!(
+                tracing::Level::WARN,
                 "Game loop behind schedule by: {:?}",
                 start.elapsed() - loop_time
             );
         }
 
+        tick_no += 1;
+
+        if tick_no % (60 * 5) == 0 {
+            let average_fps = tick_no as f32 / last_averaging_time.elapsed().as_secs_f32();
+            let average_sleep = sleep_time / tick_no;
+            let average_process = loop_time - average_sleep;
+
+            event!(
+                tracing::Level::DEBUG,
+                "Timing Averages [fps={}] [sleep={:?}] [process={:?}]",
+                average_fps,
+                average_sleep,
+                average_process    
+            );
+
+            sleep_time = Duration::ZERO;
+            last_averaging_time = Instant::now();
+            tick_no = 0;
+        }
+
         true
     };