diff --git a/crates/server/src/client_stream.rs b/crates/server/src/client_stream.rs index f4b78e8..42d81a6 100644 --- a/crates/server/src/client_stream.rs +++ b/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( 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, /// 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)] diff --git a/crates/server/src/main.rs b/crates/server/src/main.rs index 06ecc04..522a30b 100644 --- a/crates/server/src/main.rs +++ b/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::(); + (server_world.loaded_count(), server_world.in_flight_count()) + }; + let players = world + .query_filtered::<(), With>() + .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 = 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, diff --git a/crates/server/src/tests/tick_stats.rs b/crates/server/src/tests/tick_stats.rs new file mode 100644 index 0000000..a1432e7 --- /dev/null +++ b/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); +} diff --git a/crates/server/src/tick_stats.rs b/crates/server/src/tick_stats.rs new file mode 100644 index 0000000..ce186b6 --- /dev/null +++ b/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 { + 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;