Add metrics for timing subsections of State::tick

client/src/lib.rs

@@ -1787,6 +1787,7 @@ impl Client {
                 add_foreign_systems(dispatch_builder);
             },
             true,
+            None,
         );
         // TODO: avoid emitting these in the first place
         let _ = self

common/base/src/lib.rs

@@ -1,5 +1,3 @@
-#![feature(fundamental)]
-
 pub mod userdata_dir;
 
 pub use userdata_dir::userdata_dir;

common/state/src/state.rs

@@ -35,7 +35,7 @@ use specs::{
     storage::{MaskedStorage as EcsMaskedStorage, Storage as EcsStorage},
     Component, DispatcherBuilder, Entity as EcsEntity, WorldExt,
 };
-use std::sync::Arc;
+use std::{sync::Arc, time::Instant};
 use timer_queue::TimerQueue;
 use vek::*;
 
@@ -587,8 +587,19 @@ impl State {
         dt: Duration,
         add_systems: impl Fn(&mut DispatcherBuilder),
         update_terrain_and_regions: bool,
+        mut metrics: Option<&mut StateTickMetrics>,
     ) {
         span!(_guard, "tick", "State::tick");
+
+        // Timing code for server metrics
+        macro_rules! section_span {
+            ($guard:ident, $label:literal) => {
+                span!(span_guard, $label);
+                let metrics_guard = metrics.as_mut().map(|m| MetricsGuard::new($label, m));
+                let $guard = (span_guard, metrics_guard);
+            };
+        }
+
         // Change the time accordingly.
         self.ecs.write_resource::<TimeOfDay>().0 += dt.as_secs_f64() * DAY_CYCLE_FACTOR;
         self.ecs.write_resource::<Time>().0 += dt.as_secs_f64();
@@ -602,7 +613,7 @@ impl State {
             self.update_region_map();
         }
 
-        span!(guard, "create dispatcher");
+        section_span!(guard, "create dispatcher");
         // Run systems to update the world.
         // Create and run a dispatcher for ecs systems.
         let mut dispatch_builder =
@@ -613,11 +624,11 @@ impl State {
         let mut dispatcher = dispatch_builder.build();
         drop(guard);
 
-        span!(guard, "run systems");
+        section_span!(guard, "run systems");
         dispatcher.dispatch(&self.ecs);
         drop(guard);
 
-        span!(guard, "maintain ecs");
+        section_span!(guard, "maintain ecs");
         self.ecs.maintain();
         drop(guard);
 
@@ -626,7 +637,7 @@ impl State {
         }
 
         // Process local events
-        span!(guard, "process local events");
+        section_span!(guard, "process local events");
 
         let outcomes = self.ecs.read_resource::<EventBus<Outcome>>();
         let mut outcomes_emitter = outcomes.emitter();
@@ -669,3 +680,40 @@ impl State {
         self.ecs.write_resource::<TerrainChanges>().clear();
     }
 }
+
+// Timing code for server metrics
+#[derive(Default)]
+pub struct StateTickMetrics {
+    pub timings: Vec<(&'static str, Duration)>,
+}
+
+impl StateTickMetrics {
+    fn add(&mut self, label: &'static str, dur: Duration) {
+        // Check for duplicates!
+        debug_assert!(
+            self.timings.iter().all(|(l, _)| *l != label),
+            "Duplicate label in state tick metrics {label}"
+        );
+        self.timings.push((label, dur));
+    }
+}
+
+struct MetricsGuard<'a> {
+    start: Instant,
+    label: &'static str,
+    metrics: &'a mut StateTickMetrics,
+}
+
+impl<'a> MetricsGuard<'a> {
+    fn new(label: &'static str, metrics: &'a mut StateTickMetrics) -> Self {
+        Self {
+            start: Instant::now(),
+            label,
+            metrics,
+        }
+    }
+}
+
+impl Drop for MetricsGuard<'_> {
+    fn drop(&mut self) { self.metrics.add(self.label, self.start.elapsed()); }
+}

common/systems/tests/character_state.rs

@@ -80,6 +80,7 @@ mod tests {
                 dispatch::<character_behavior::Sys>(dispatch_builder, &[]);
             },
             false,
+            None,
         );
     }
 

common/systems/tests/phys/basic.rs

@@ -17,6 +17,7 @@ fn simple_run() {
             add_local_systems(dispatcher_builder);
         },
         false,
+        None,
     );
 }
 

common/systems/tests/phys/utils.rs

@@ -63,6 +63,7 @@ pub fn tick(state: &mut State, dt: Duration) {
             dispatch::<phys::Sys>(dispatch_builder, &[&character_behavior::Sys::sys_name()]);
         },
         false,
+        None,
     );
 }
 

server/src/lib.rs

@@ -684,6 +684,7 @@ impl Server {
         // 4) Tick the server's LocalState.
         // 5) Fetch any generated `TerrainChunk`s and insert them into the terrain.
         // in sys/terrain.rs
+        let mut state_tick_metrics = Default::default();
         self.state.tick(
             dt,
             |dispatcher_builder| {
@@ -697,6 +698,7 @@ impl Server {
                 }
             },
             false,
+            Some(&mut state_tick_metrics),
         );
 
         let before_handle_events = Instant::now();
@@ -1002,6 +1004,12 @@ impl Server {
                 .set((before_persistence_updates - before_entity_cleanup).as_nanos() as i64);
             tt.with_label_values(&["persistence_updates"])
                 .set((end_of_server_tick - before_persistence_updates).as_nanos() as i64);
+            for (label, duration) in state_tick_metrics.timings {
+                tick_metrics
+                    .state_tick_time
+                    .with_label_values(&[label])
+                    .set(duration.as_nanos() as i64);
+            }
             tick_metrics.tick_time_hist.observe(
                 end_of_server_tick
                     .duration_since(before_state_tick)

server/src/metrics.rs

@@ -57,6 +57,8 @@ pub struct TickMetrics {
     pub chunk_groups_count: IntGauge,
     pub entity_count: IntGauge,
     pub tick_time: IntGaugeVec,
+    /// Timing of some subsections of `State::tick`.
+    pub state_tick_time: IntGaugeVec,
     pub tick_time_hist: Histogram,
     pub build_info: IntGauge,
     pub start_time: IntGauge,
@@ -349,6 +351,13 @@ impl TickMetrics {
             Opts::new("tick_time", "time in ns required for a tick of the server"),
             &["period"],
         )?;
+        let state_tick_time = IntGaugeVec::new(
+            Opts::new(
+                "state_tick_time",
+                "time in ns for some subsections of State::tick",
+            ),
+            &["period"],
+        )?;
         // 33.33ms is the ideal tick time. So we have hight detail around it.
         // 300/700 are to detect high I/O blocks
         let bucket = vec![
@@ -386,6 +395,7 @@ impl TickMetrics {
         registry.register(Box::new(time_of_day.clone()))?;
         registry.register(Box::new(light_count.clone()))?;
         registry.register(Box::new(tick_time.clone()))?;
+        registry.register(Box::new(state_tick_time.clone()))?;
         registry.register(Box::new(tick_time_hist.clone()))?;
 
         Ok(Self {
@@ -394,6 +404,7 @@ impl TickMetrics {
             chunk_groups_count,
             entity_count,
             tick_time,
+            state_tick_time,
             tick_time_hist,
             build_info,
             start_time,