From 87bf44241b7cebac2b52a2503590c27576fc3edf Mon Sep 17 00:00:00 2001
From: Imbris <imbrisf@gmail.com>
Date: Sun, 12 Mar 2023 17:02:47 -0400
Subject: [PATCH] Add metrics for timing subsections of State::tick

---
 client/src/lib.rs                       |  1 +
 common/base/src/lib.rs                  |  2 -
 common/state/src/state.rs               | 58 ++++++++++++++++++++++---
 common/systems/tests/character_state.rs |  1 +
 common/systems/tests/phys/basic.rs      |  1 +
 common/systems/tests/phys/utils.rs      |  1 +
 server/src/lib.rs                       |  8 ++++
 server/src/metrics.rs                   | 11 +++++
 8 files changed, 76 insertions(+), 7 deletions(-)

diff --git a/client/src/lib.rs b/client/src/lib.rs
index 34812b897b..f691919b4c 100644
--- a/client/src/lib.rs
+++ b/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
diff --git a/common/base/src/lib.rs b/common/base/src/lib.rs
index 098d881849..6e9b2771a7 100644
--- a/common/base/src/lib.rs
+++ b/common/base/src/lib.rs
@@ -1,5 +1,3 @@
-#![feature(fundamental)]
-
 pub mod userdata_dir;
 
 pub use userdata_dir::userdata_dir;
diff --git a/common/state/src/state.rs b/common/state/src/state.rs
index 96ac72f74e..6c151736ea 100644
--- a/common/state/src/state.rs
+++ b/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()); }
+}
diff --git a/common/systems/tests/character_state.rs b/common/systems/tests/character_state.rs
index f3fbfcf619..ea3bf849f5 100644
--- a/common/systems/tests/character_state.rs
+++ b/common/systems/tests/character_state.rs
@@ -80,6 +80,7 @@ mod tests {
                 dispatch::<character_behavior::Sys>(dispatch_builder, &[]);
             },
             false,
+            None,
         );
     }
 
diff --git a/common/systems/tests/phys/basic.rs b/common/systems/tests/phys/basic.rs
index f4f6d963f3..ee20ea9efb 100644
--- a/common/systems/tests/phys/basic.rs
+++ b/common/systems/tests/phys/basic.rs
@@ -17,6 +17,7 @@ fn simple_run() {
             add_local_systems(dispatcher_builder);
         },
         false,
+        None,
     );
 }
 
diff --git a/common/systems/tests/phys/utils.rs b/common/systems/tests/phys/utils.rs
index 6b9adf3bef..3785dcb1de 100644
--- a/common/systems/tests/phys/utils.rs
+++ b/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,
     );
 }
 
diff --git a/server/src/lib.rs b/server/src/lib.rs
index e40fb7778a..1569a3945d 100644
--- a/server/src/lib.rs
+++ b/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)
diff --git a/server/src/metrics.rs b/server/src/metrics.rs
index ac4a2e9d5d..1d146ee431 100644
--- a/server/src/metrics.rs
+++ b/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,