bench: spawn_natural sub-spans

Co-Authored-By: Claude Opus 5.5 <[email protected]>

crates/horizon-client-render/src/spans.rs

@@ -161,3 +161,24 @@ mod tests {
         assert!(worked.as_millis() >= 10, "{worked:?} while busy");
     }
 }
+
+/// Bench only: a span from here to the guard's drop.
+pub struct Guard(&'static str, Instant, Option<Duration>);
+pub fn guard(name: &'static str) -> Option<Guard> {
+    enabled().then(|| Guard(name, Instant::now(), thread_cpu()))
+}
+impl Drop for Guard {
+    fn drop(&mut self) {
+        let ms = self.1.elapsed().as_secs_f32() * 1000.0;
+        let cpu_ms = thread_cpu()
+            .zip(self.2)
+            .map_or(ms, |(e, s)| (e - s).as_secs_f32() * 1000.0);
+        SPANS.with(|s| {
+            s.borrow_mut().push(Span {
+                name: self.0,
+                ms,
+                cpu_ms,
+            })
+        });
+    }
+}

crates/horizon-client-render/src/streaming.rs

@@ -1240,8 +1240,11 @@ impl Streaming {
         let sweep = area != self.scan_area || self.scan_age >= 8;
         self.scan_area = area;
         self.scan_age = if sweep { 0 } else { self.scan_age + 1 };
+        let g = crate::spans::guard("st_relight_edits");
         self.requeue();
         self.relight_edits(world);
+        drop(g);
+        let g = crate::spans::guard("st_receive");
         let deferred = std::mem::take(&mut self.deferred);
         let received = self.shared.done.take();
         // Meshes made stale meanwhile, freed with the uploaded ones (`free`).
@@ -1322,6 +1325,8 @@ impl Streaming {
                 }
             }
         }
+        drop(g);
+        let g = crate::spans::guard("st_sweep");
         self.free(stale);
         let mut removed = Vec::new();
         if sweep {
@@ -1391,10 +1396,16 @@ impl Streaming {
             }
             self.save_checked_out(written);
         }
+        drop(g);
+        let g = crate::spans::guard("st_finalize");
+        drop(g);
+        let g = crate::spans::guard("st_retain");
         let (protos, finishing) = (&self.protos, &self.finishing);
         self.decorated.retain(|k| {
             protos.contains_key(k) || finishing.contains(k) || world.chunks.contains_key(k)
         });
+        drop(g);
+        let g = crate::spans::guard("st_finalize");
         // Finalize chunks whose neighbourhood is decorated.
         let candidates: Vec<(i32, i32)> = self.protos.keys().copied().collect();
         for (x, z) in candidates {
@@ -1425,6 +1436,8 @@ impl Streaming {
         // Decorate chunks whose 3x3 proto neighbourhood is available, in
         // vanilla's order: decoration is order dependent where write regions
         // overlap (see `DecorationOrder`).
+        drop(g);
+        let g = crate::spans::guard("st_decorate");
         let workers = self.threads.len();
         if self.decorates && self.order_area != Some((self.center, self.radius)) {
             let (decorated, chunks) = (&self.decorated, &world.chunks);
@@ -1546,6 +1559,8 @@ impl Streaming {
                 self.submit(Some((x, z)), 1, Job::Decorate(x, z, region, finals));
             }
         }
+        drop(g);
+        let g = crate::spans::guard("st_schedule");
         self.schedule_generation(world, workers);
         // Lighting once all neighbours exist, nearest first and only as
         // much of it as the workers can chew. Vanilla's light engine also
@@ -1555,6 +1570,8 @@ impl Streaming {
         // grew with the render distance and outlived the columns they
         // were queued for (#3629). What stays in `dirty_light` is asked
         // for again, from the current centre, as capacity frees.
+        drop(g);
+        let g = crate::spans::guard("st_light");
         let mut light: Vec<(i64, i32, i32)> = Vec::new();
         let mut gone: Vec<(i32, i32)> = Vec::new();
         for &(x, z) in world.dirty_light.iter() {
@@ -1567,7 +1584,20 @@ impl Streaming {
         for key in gone {
             world.dirty_light.remove(&key);
         }
+        drop(g);
+        let g = crate::spans::guard("st_light_submit");
         let room = (self.threads.len() * 4).saturating_sub(self.lighting.len());
+        if crate::spans::enabled() && self.sequence % 50 == 0 {
+            log::info!(
+                "stdbg dirty_light {} ready {} room {} decorated {} protos {} chunks {}",
+                world.dirty_light.len(),
+                light.len(),
+                room,
+                self.decorated.len(),
+                self.protos.len(),
+                world.chunks.len()
+            );
+        }
         nearest_first(&mut light, room);
         for (_, x, z) in light {
             let Some(region) = self.light_region(world, x, z) else {
@@ -1584,6 +1614,7 @@ impl Streaming {
                 Job::Light(x, z, region, self.sequence, self.sky_light),
             );
         }
+        drop(g);
         // A server draws nothing: its sections are never meshed.
         if !self.mesh {
             world.dirty_sections.clear();

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

@@ -2194,10 +2194,16 @@ impl Game<'_> {
                     .iter()
                     .filter_map(|g| Some((g.vehicle?, g.entity_id)))
                     .collect();
+                let g = horizon_client::spans::guard("ln_riding");
                 self.lan_riding(host_entity, &guests, &mut host.hub.riding);
+                drop(g);
+                let g = horizon_client::spans::guard("ln_entities");
                 self.lan_entities(host_entity, &host.mob_players, &mut host.hub, &mut states);
+                drop(g);
+                let g = horizon_client::spans::guard("ln_hooks_uuids");
                 self.lan_hook_states(host_entity, &host.play, &host.hub, &mut states);
                 self.lan_entity_uuids(&mut states);
+                drop(g);
             } else {
                 states.clear();
             }
@@ -2267,6 +2273,7 @@ impl Game<'_> {
                 // Player packets may already have been drained before
                 // scheduled block ticks (`tick_lan_packets`).
                 let pass = self.level_pass;
+                let g = horizon_client::spans::guard("ln_poll");
                 let mut events = if pass.first && !pass.packets_drained {
                     host.hub.poll(&mut ctx)
                 } else {
@@ -2275,7 +2282,10 @@ impl Game<'_> {
                 if !pass.packets_drained {
                     events.extend(host.hub.drain_packets(&mut ctx));
                 }
+                drop(g);
+                let g = horizon_client::spans::guard("ln_tick_level");
                 events.extend(host.hub.tick_level(&mut ctx));
+                drop(g);
                 if pass.last {
                     host.hub.end_tick();
                 }
@@ -2288,6 +2298,7 @@ impl Game<'_> {
                 host.hub.set_host_game_mode(state.uuid, state.game_mode);
             }
             self.wake_woken_guests(&mut host);
+            let g = horizon_client::spans::guard("ln_events");
             let Some(back) = self.lan_process_events(host, events, state.as_ref(), entities, spawn)
             else {
                 return;
@@ -2319,9 +2330,12 @@ impl Game<'_> {
                 .take()
                 .expect("the hub is back after the menu events");
         }
+        let g = horizon_client::spans::guard("ln_guests");
         if !paused {
             self.tick_guests(&mut host);
         }
+        drop(g);
+        let _g = horizon_client::spans::guard("ln_flush");
         self.lan = Some(host);
         // A blast from a guest's attack, and a mace's wind burst.
         self.flush_lan_explosions();

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

@@ -526,11 +526,22 @@ impl<'a> Game<'a> {
         if players.is_empty() {
             return;
         }
+        let g = horizon_client::spans::guard("sn_chunks");
         let mut scratch = std::mem::take(&mut self.spawn_scratch);
         let spawnable = self.spawning_chunks(&players, &mut scratch);
+        if horizon_client::spans::enabled() && self.world.game_time % 200 == 0 {
+            log::info!(
+                "sndbg mobs {} candidates {} players {}",
+                self.mobs.len(),
+                scratch.candidates.len(),
+                players.len()
+            );
+        }
         for &key in &scratch.candidates {
             *self.world.inhabited.entry(key).or_insert(0) += 1;
         }
+        drop(g);
+        let g = horizon_client::spans::guard("sn_state");
         let spawn_mobs = self.ui.rules.bool("spawn_mobs");
         let spawn_enemies = self.ui.rules.bool("spawn_monsters");
         let mut random = std::mem::replace(&mut self.world.random, LegacyRandom::new(0));
@@ -575,6 +586,8 @@ impl<'a> Game<'a> {
                 let j = random.next_int_bound(i as i32 + 1).unwrap_or(0) as usize;
                 scratch.candidates.swap(i, j);
             }
+            drop(g);
+            let _g = horizon_client::spans::guard("sn_loop");
             if !categories.is_empty() {
                 for chunk in scratch.candidates.drain(..) {
                     let mut spawn = |l: &GameLevel, r: &SpawnRequest| {
@@ -599,6 +612,7 @@ impl<'a> Game<'a> {
         self.world.random = random;
         // ServerChunkCache.lastSpawnState, for the debug overlay.
         self.spawn_counts.insert(self.dim, last_state);
+        let _g = horizon_client::spans::guard("sn_add");
         self.add_spawned(pending, false);
         self.spawn_scratch = scratch;
     }