feat(server): report tick and world statistics

crates/server/src/client_stream.rs

@@ -1,10 +1,11 @@
 // SPDX-License-Identifier: AGPL-3.0-only
 
-//! Per-connection chunk-streaming state.
+//! Per-connection outbound streaming state: chunk subscription tracking and the authority-stream sink.
 
 use std::collections::HashSet;
 
-use net::ChunkSink;
+use net::{AuthoritySink, ChunkSink};
+use shared::protocol::authority::{AuthorityMessage, ServerStats};
 use shared::protocol::chunk::ChunkMessage;
 use shared::world::{Chunk, ChunkData, ChunkPos};
 
@@ -39,10 +40,12 @@ pub fn desired_diff<S: std::hash::BuildHasher>(
     DesiredDiff { added, removed }
 }
 
-/// Tracks one connected client's chunk subscription and what has been delivered to it.
+/// Tracks one connected client's chunk subscription, what has been delivered to it, and the sinks used to push to it.
 pub struct ClientStream {
     /// Outbound handle onto the client's chunk stream.
     sink: ChunkSink,
+    /// Outbound handle onto the client's authority stream, carried here so both per-connection sinks share one lifetime and one lookup key.
+    authority: AuthoritySink,
     /// The chunk positions the client currently wants resident, already clamped to [`SERVER_MAX_RADIUS`].
     desired: HashSet<ChunkPos>,
     /// Positions already delivered to the client as [`ChunkMessage::Chunk`].
@@ -52,9 +55,10 @@ pub struct ClientStream {
 impl ClientStream {
     /// Creates a stream for a freshly connected client that has not yet subscribed.
     #[must_use]
-    pub fn new(sink: ChunkSink) -> Self {
+    pub fn new(sink: ChunkSink, authority: AuthoritySink) -> Self {
         Self {
             sink,
+            authority,
             desired: HashSet::new(),
             sent: HashSet::new(),
         }
@@ -113,6 +117,13 @@ impl ClientStream {
         }
         delivered
     }
+
+    /// Pushes a diagnostics snapshot onto the client's authority stream.
+    ///
+    /// Non-blocking, and silently ignored when the connection has already gone away; see [`AuthoritySink::send`].
+    pub fn send_stats(&self, stats: ServerStats) {
+        self.authority.send(AuthorityMessage::ServerStats(stats));
+    }
 }
 
 #[cfg(test)]

crates/server/src/main.rs

@@ -12,6 +12,8 @@ pub mod client_stream;
 pub mod player;
 /// On-disk persistence: region files and the atomic durability layer.
 pub mod save;
+/// Measurement of the simulation loop's achieved tick rate and per-tick cost.
+pub mod tick_stats;
 /// Authoritative chunk storage and generation logic for the server.
 pub mod world_server;
 
@@ -24,12 +26,14 @@ use anyhow::Context;
 use bevy_ecs::prelude::{Query, ResMut, Schedule, With, World};
 use glam::Vec3;
 use shared::generator::{VoxelGenerator, WorldGenConfig};
+use shared::protocol::authority::ServerStats;
 use shared::world::{Chunk, ChunkPos, EntityPos};
 use tracing::{debug, info, warn};
 
 use client_stream::ClientStream;
 use net::{NetworkServer, ServerEvent};
 use player::{Player, Position, ViewDistance};
+use tick_stats::{TickMeter, TickWindow};
 use world_server::{ServerWorld, cylinder_chunks};
 
 /// Nominal simulation rate, in ticks per second. Sole source of truth for both the loop's target period and the advisory rate advertised to clients in the handshake.
@@ -139,6 +143,39 @@ fn main() -> anyhow::Result<()> {
     run_simulation(&mut world, &network)
 }
 
+/// Assembles the diagnostics snapshot pushed to clients at the end of a measurement window.
+///
+/// The world and ECS figures are read at the moment of the call rather than averaged over the window: they describe a level of occupancy, for which the current value is the meaningful reading. Only the timing figures in `window` are aggregates.
+fn collect_server_stats(
+    world: &mut World,
+    window: &TickWindow,
+    connected_clients: usize,
+    started_at: Instant,
+) -> ServerStats {
+    let (loaded_chunks, chunks_in_flight) = {
+        let server_world = world.resource::<ServerWorld>();
+        (server_world.loaded_count(), server_world.in_flight_count())
+    };
+    let players = world
+        .query_filtered::<(), With<Player>>()
+        .iter(world)
+        .count();
+    let entities = world.entities().len();
+
+    ServerStats {
+        measured_tps: window.measured_tps,
+        mean_tick_ms: window.mean_tick_ms,
+        max_tick_ms: window.max_tick_ms,
+        tick_budget_percent: window.tick_budget_percent,
+        loaded_chunks: u32::try_from(loaded_chunks).unwrap_or(u32::MAX),
+        chunks_in_flight: u32::try_from(chunks_in_flight).unwrap_or(u32::MAX),
+        connected_clients: u32::try_from(connected_clients).unwrap_or(u32::MAX),
+        entities,
+        players: u32::try_from(players).unwrap_or(u32::MAX),
+        uptime_secs: started_at.elapsed().as_secs(),
+    }
+}
+
 /// Runs the authoritative simulation loop forever, at the fixed cadence given by [`TICK_PERIOD`].
 fn run_simulation(world: &mut World, network: &NetworkServer) -> ! {
     // Chunk diffs are computed against an all-air baseline so each delivered payload is self-contained: the client renders only server-owned content and has no generator to reconstruct a worldgen baseline. Allocated once and shared across every delivery.
@@ -147,15 +184,23 @@ fn run_simulation(world: &mut World, network: &NetworkServer) -> ! {
     // Per-connection streaming state, keyed by the stable session id the network thread assigns.
     let mut clients: HashMap<u64, ClientStream> = HashMap::new();
 
+    let started_at = Instant::now();
+    let mut meter = TickMeter::new(started_at, TICK_PERIOD);
+
     loop {
         let tick_start = Instant::now();
 
         // Fold network events into per-client subscription state.
         for event in network.poll_events() {
             match event {
-                ServerEvent::ClientConnected { id, hello, chunks } => {
+                ServerEvent::ClientConnected {
+                    id,
+                    hello,
+                    chunks,
+                    authority,
+                } => {
                     info!(id, name = %hello.player_identity.display_name, "client connected");
-                    clients.insert(id, ClientStream::new(chunks));
+                    clients.insert(id, ClientStream::new(chunks, authority));
                 }
                 ServerEvent::ClientDisconnected { id, reason } => {
                     info!(id, %reason, "client disconnected");
@@ -193,6 +238,16 @@ fn run_simulation(world: &mut World, network: &NetworkServer) -> ! {
 
         // Sleep only the unused remainder of the tick's budget, so the period stays [`TICK_PERIOD`] rather than growing with the cost of the work above. A tick that overruns its budget does not sleep at all; the overrun is reported because it is the signal that the server is falling behind its nominal rate.
         let elapsed = tick_start.elapsed();
+        meter.record(elapsed);
+
+        // Diagnostics are pushed on the authority stream once per measurement window, not per tick: the figures describe the window, and per-tick delivery would be pure waste.
+        if let Some(window) = meter.take_window(tick_start + elapsed) {
+            let stats = collect_server_stats(world, &window, clients.len(), started_at);
+            for client in clients.values() {
+                client.send_stats(stats);
+            }
+        }
+
         if elapsed > TICK_PERIOD {
             warn!(
                 elapsed_ms = elapsed.as_secs_f32() * 1000.0,

crates/server/src/tests/tick_stats.rs

@@ -0,0 +1,112 @@
+// SPDX-License-Identifier: AGPL-3.0-only
+
+//! Unit tests for the simulation loop's timing measurement.
+
+use super::*;
+
+/// The nominal 20 Hz period the server budgets each tick.
+const PERIOD: Duration = Duration::from_millis(50);
+
+/// Asserts two f32 values agree to within a tolerance that survives the accumulated division and multiplication.
+fn close(actual: f32, expected: f32) {
+    assert!(
+        (actual - expected).abs() < 0.01,
+        "expected {expected}, got {actual}"
+    );
+}
+
+#[test]
+fn empty_window_reports_zeroes_rather_than_dividing_by_zero() {
+    let window = summarise(0, Duration::ZERO, Duration::ZERO, REPORT_INTERVAL, PERIOD);
+
+    close(window.measured_tps, 0.0);
+    close(window.mean_tick_ms, 0.0);
+    close(window.tick_budget_percent, 0.0);
+}
+
+#[test]
+fn a_window_at_the_nominal_rate_reports_the_nominal_rate() {
+    // Twenty ticks of 10 ms each, filling exactly one second of wall clock.
+    let window = summarise(
+        20,
+        Duration::from_millis(200),
+        Duration::from_millis(10),
+        Duration::from_secs(1),
+        PERIOD,
+    );
+
+    close(window.measured_tps, 20.0);
+    close(window.mean_tick_ms, 10.0);
+    close(window.max_tick_ms, 10.0);
+    // 10 ms of a 50 ms budget is one fifth of the period.
+    close(window.tick_budget_percent, 20.0);
+}
+
+#[test]
+fn an_overrunning_server_reports_a_rate_below_nominal() {
+    // Ten ticks of 100 ms each: the body alone exceeds the 50 ms budget, so only half the nominal count fits in the second.
+    let window = summarise(
+        10,
+        Duration::from_secs(1),
+        Duration::from_millis(140),
+        Duration::from_secs(1),
+        PERIOD,
+    );
+
+    close(window.measured_tps, 10.0);
+    close(window.mean_tick_ms, 100.0);
+    close(window.tick_budget_percent, 200.0);
+}
+
+#[test]
+fn the_maximum_is_reported_separately_from_the_mean() {
+    // Nine cheap ticks and one stall: the mean stays inside budget while the maximum does not.
+    let window = summarise(
+        10,
+        Duration::from_millis(100),
+        Duration::from_millis(91),
+        Duration::from_secs(1),
+        PERIOD,
+    );
+
+    close(window.mean_tick_ms, 10.0);
+    close(window.max_tick_ms, 91.0);
+    assert!(window.tick_budget_percent < 100.0);
+}
+
+#[test]
+fn a_window_closes_only_once_the_interval_has_elapsed() {
+    let start = Instant::now();
+    let mut meter = TickMeter::new(start, PERIOD);
+    meter.record(Duration::from_millis(10));
+
+    assert!(
+        meter
+            .take_window(start + Duration::from_millis(999))
+            .is_none()
+    );
+    assert!(meter.take_window(start + REPORT_INTERVAL).is_some());
+}
+
+#[test]
+fn closing_a_window_resets_the_accumulators() {
+    let start = Instant::now();
+    let mut meter = TickMeter::new(start, PERIOD);
+    meter.record(Duration::from_millis(40));
+    let _ = meter.take_window(start + REPORT_INTERVAL);
+
+    meter.record(Duration::from_millis(10));
+    let second = meter
+        .take_window(start + REPORT_INTERVAL + REPORT_INTERVAL)
+        .unwrap_or(TickWindow {
+            measured_tps: 0.0,
+            mean_tick_ms: 0.0,
+            max_tick_ms: 0.0,
+            tick_budget_percent: 0.0,
+        });
+
+    // The 40 ms tick belonged to the first window and must not leak into the second's maximum.
+    close(second.mean_tick_ms, 10.0);
+    close(second.max_tick_ms, 10.0);
+    close(second.measured_tps, 1.0);
+}

crates/server/src/tick_stats.rs

@@ -0,0 +1,115 @@
+// SPDX-License-Identifier: AGPL-3.0-only
+
+//! Measurement of the simulation loop's own timing.
+
+use std::time::{Duration, Instant};
+
+/// Wall-clock cadence at which a measurement window closes and a report is produced.
+///
+/// One second is short enough to surface a stall promptly and long enough that the report costs nothing next to the ticks it summarises.
+pub const REPORT_INTERVAL: Duration = Duration::from_secs(1);
+
+/// The summary produced when a measurement window closes.
+#[derive(Debug, Clone, Copy, PartialEq)]
+pub struct TickWindow {
+    /// Ticks completed in the window, expressed per second.
+    pub measured_tps: f32,
+    /// Mean duration of a tick body in the window, in milliseconds.
+    pub mean_tick_ms: f32,
+    /// Longest tick body in the window, in milliseconds.
+    pub max_tick_ms: f32,
+    /// Share of the nominal tick period consumed by the mean tick body, in percent.
+    pub tick_budget_percent: f32,
+}
+
+/// Accumulates tick timings and closes a measurement window on a fixed cadence.
+#[derive(Debug)]
+pub struct TickMeter {
+    /// Nominal period one tick is budgeted, against which utilisation is computed.
+    period: Duration,
+    /// Instant the current window opened; the window closes once [`REPORT_INTERVAL`] has elapsed from here.
+    window_start: Instant,
+    /// Tick bodies recorded in the current window.
+    ticks: u32,
+    /// Summed duration of every tick body in the current window.
+    total: Duration,
+    /// Longest single tick body in the current window.
+    max: Duration,
+}
+
+impl TickMeter {
+    /// Opens the first measurement window at `now`, budgeting each tick `period`.
+    #[must_use]
+    pub fn new(now: Instant, period: Duration) -> Self {
+        Self {
+            period,
+            window_start: now,
+            ticks: 0,
+            total: Duration::ZERO,
+            max: Duration::ZERO,
+        }
+    }
+
+    /// Records one completed tick body of duration `elapsed`.
+    pub fn record(&mut self, elapsed: Duration) {
+        self.ticks = self.ticks.saturating_add(1);
+        self.total = self.total.saturating_add(elapsed);
+        self.max = self.max.max(elapsed);
+    }
+
+    /// Closes the window and returns its summary once [`REPORT_INTERVAL`] has elapsed since it opened, otherwise returns [`None`].
+    ///
+    /// On close the accumulators reset and a fresh window opens at `now`, so windows tile the timeline without gaps or overlap.
+    pub fn take_window(&mut self, now: Instant) -> Option<TickWindow> {
+        let elapsed = now.saturating_duration_since(self.window_start);
+        if elapsed < REPORT_INTERVAL {
+            return None;
+        }
+
+        let window = summarise(self.ticks, self.total, self.max, elapsed, self.period);
+        self.window_start = now;
+        self.ticks = 0;
+        self.total = Duration::ZERO;
+        self.max = Duration::ZERO;
+        Some(window)
+    }
+}
+
+/// Derives a window summary from its raw accumulators.
+///
+/// Split out from [`TickMeter::take_window`] so the arithmetic is exercisable without driving a clock. A window containing no ticks reports zeroes throughout rather than dividing by zero, which is the correct reading of "nothing completed".
+fn summarise(
+    ticks: u32,
+    total: Duration,
+    max: Duration,
+    elapsed: Duration,
+    period: Duration,
+) -> TickWindow {
+    if ticks == 0 || elapsed.is_zero() {
+        return TickWindow {
+            measured_tps: 0.0,
+            mean_tick_ms: 0.0,
+            max_tick_ms: max.as_secs_f32() * 1000.0,
+            tick_budget_percent: 0.0,
+        };
+    }
+
+    let mean = total.as_secs_f32() / f32::from(u16::try_from(ticks).unwrap_or(u16::MAX));
+    let period_secs = period.as_secs_f32();
+
+    TickWindow {
+        measured_tps: f32::from(u16::try_from(ticks).unwrap_or(u16::MAX)) / elapsed.as_secs_f32(),
+        mean_tick_ms: mean * 1000.0,
+        max_tick_ms: max.as_secs_f32() * 1000.0,
+        // A zero period would mean no budget exists to consume, so utilisation is undefined and reported as zero.
+        tick_budget_percent: if period_secs > 0.0 {
+            mean / period_secs * 100.0
+        } else {
+            0.0
+        },
+    }
+}
+
+#[cfg(test)]
+#[path = "tests/tick_stats.rs"]
+mod tests;