Merge pull request #874 from ludovic111/perf/server-tick-spikes

🤖 Agent: Merged. HORIZON_SPIKES logs slow server ticks with thread CPU time and spans; without it the tick runs exactly as before.

Cargo.lock

@@ -1435,6 +1435,7 @@ dependencies = [
  "naga",
  "png",
  "pollster",
+ "rustix 1.1.5",
  "serde",
  "serde_json",
  "sha2",

crates/horizon-client/Cargo.toml

@@ -51,6 +51,10 @@ horizon-dualsense = { path = "../horizon-dualsense" }
 # HTTPS to the Minecraft services (online-mode session join).
 ureq = { version = "2", default-features = false, features = ["tls"] }
 
+[target.'cfg(unix)'.dependencies]
+# The server thread's CPU time per tick (`HORIZON_SPIKES`, spans.rs).
+rustix = { version = "1", default-features = false, features = ["std", "time"] }
+
 [target.'cfg(windows)'.build-dependencies]
 # The icon resource in the .exe (build.rs).
 winresource = "0.1"

crates/horizon-client/src/game/dedicated.rs

@@ -683,7 +683,7 @@ impl Game<'_> {
                 self.ticks = self.ticks.max(1);
             }
             // MinecraftServer.tickServer: while paused only the connections run.
-            self.tick_server(paused)?;
+            self.tick_server_timed(paused)?;
             if idle_timeout > 0 {
                 self.kick_idle(idle_timeout);
             }

crates/horizon-client/src/game/integrated.rs

@@ -336,11 +336,11 @@ impl Game<'_> {
             self.run_tasks();
             if flags.paused.load(Ordering::Relaxed) {
                 // Only the connections run.
-                self.tick_server(true)?;
+                self.tick_server_timed(true)?;
             } else {
                 self.follow_distances(&flags);
                 let started = Instant::now();
-                self.tick_server(false)?;
+                self.tick_server_timed(false)?;
                 self.debug_charts.log_tick(started, started.elapsed());
                 flags.smoothed_tick_ms.store(
                     self.debug_charts.smoothed_tick_ms.to_bits(),

crates/horizon-client/src/game/levels.rs

@@ -23,7 +23,7 @@ use horizon_client::{
     save::SaveDir, streaming::Streaming, tick_chunk_membership::TickChunkMembership, world::World,
 };
 use horizon_world::level::{LevelEvent, Ticks};
-use std::{collections::HashMap, sync::Arc};
+use std::{collections::HashMap, sync::Arc, time::Instant};
 
 /// Server ticks a level other than the Overworld stays loaded with no player
 /// in it, before it is saved and closed (vanilla unloads a level's chunks
@@ -287,6 +287,37 @@ impl Game<'_> {
         self.close_idle_levels()
     }
 
+    /// `tick_server` as a server thread runs it. With `HORIZON_SPIKES=MS`, a
+    /// tick longer than MS is logged with its thread CPU time and spans.
+    pub(super) fn tick_server_timed(&mut self, paused: bool) -> Result<()> {
+        let Some(threshold) = self.options.spikes else {
+            return self.tick_server(paused);
+        };
+        let (started, cpu) = (Instant::now(), horizon_client::spans::thread_cpu());
+        let result = self.tick_server(paused);
+        let wall = started.elapsed().as_secs_f32() * 1000.0;
+        // Taken every tick: nothing else takes this thread's spans.
+        let spans = horizon_client::spans::take();
+        if wall > threshold {
+            let cpu = horizon_client::spans::thread_cpu()
+                .zip(cpu)
+                .map_or_else(String::new, |(end, start)| {
+                    format!(", cpu {:.1} ms", (end - start).as_secs_f32() * 1000.0)
+                });
+            let list: Vec<String> = spans
+                .iter()
+                .filter(|(_, ms)| *ms >= 0.5)
+                .map(|(n, ms)| format!("{n} {ms:.1}"))
+                .collect();
+            log::info!(
+                "Horizon: slow tick {wall:.1} ms{cpu} ({} mobs): {}",
+                self.mobs.len(),
+                list.join(", ")
+            );
+        }
+        result
+    }
+
     /// The levels this server tick runs, in `MinecraftServer.levels` order
     /// (the Overworld, the Nether, the End): every level with a player in
     /// it, or the Overworld while nobody is online.

crates/horizon-client/src/spans.rs

@@ -1,11 +1,12 @@
 //! Named timings within a frame, for finding what makes a frame slow:
 //! `HORIZON_SPIKES=MS` prints the spans of every frame whose CPU time
-//! exceeds MS milliseconds. Costs one clock read per span when enabled and
-//! a relaxed load otherwise.
+//! exceeds MS milliseconds, and of every server tick (dedicated or
+//! integrated) longer than MS. Costs one clock read per span when enabled
+//! and a relaxed load otherwise.
 use std::{
     cell::RefCell,
     sync::atomic::{AtomicBool, Ordering},
-    time::Instant,
+    time::{Duration, Instant},
 };
 
 static ENABLED: AtomicBool = AtomicBool::new(false);
@@ -28,6 +29,18 @@ pub fn time<T>(name: &'static str, f: impl FnOnce() -> T) -> T {
     SPANS.with(|s| s.borrow_mut().push((name, ms)));
     out
 }
+/// The CPU time this thread has used, where the platform tells it: a tick
+/// with more wall time than CPU time waited (for a lock, or for a core on a
+/// busy machine).
+pub fn thread_cpu() -> Option<Duration> {
+    #[cfg(unix)]
+    {
+        let t = rustix::time::clock_gettime(rustix::time::ClockId::ThreadCPUTime);
+        Some(Duration::new(t.tv_sec as u64, t.tv_nsec as u32))
+    }
+    #[cfg(not(unix))]
+    None
+}
 /// The frame's spans, summed by name, slowest first; clears them.
 pub fn take() -> Vec<(&'static str, f32)> {
     let spans = SPANS.with(|s| std::mem::take(&mut *s.borrow_mut()));
@@ -41,3 +54,29 @@ pub fn take() -> Vec<(&'static str, f32)> {
     sums.sort_by(|a, b| b.1.total_cmp(&a.1));
     sums
 }
+
+#[cfg(test)]
+mod tests {
+    /// The thread's CPU clock moves with work done on it, not with time
+    /// spent asleep.
+    #[cfg(unix)]
+    #[test]
+    fn thread_cpu_counts_work_not_sleep() {
+        let start = super::thread_cpu().unwrap();
+        std::thread::sleep(std::time::Duration::from_millis(50));
+        let slept = super::thread_cpu().unwrap() - start;
+        // Busy until the clock shows 10 ms of work (a loaded machine gives
+        // the thread less than its wall time).
+        let mut x = 0u64;
+        let busy = std::time::Instant::now();
+        let worked = loop {
+            x = std::hint::black_box(x.wrapping_mul(31).wrapping_add(7));
+            let worked = super::thread_cpu().unwrap() - start - slept;
+            if worked.as_millis() >= 10 || busy.elapsed().as_secs() >= 10 {
+                break worked;
+            }
+        };
+        assert!(slept.as_millis() < 25, "{slept:?} while asleep");
+        assert!(worked.as_millis() >= 10, "{worked:?} while busy");
+    }
+}