companion: the hub tick's spikes: advancement scans, log writes, lazy indexes

The companion hub's tick had 3-20 ms spikes while it worked. Spans inside the tick (HORIZON_SPIKES now prints each slow hub tick with its spans and the thread's CPU time) split them into CPU work and waits: - CPU, guest_advancements (1.5-5.3 ms): every inventory change scanned all ~1900 inventory_changed criteria, and every recipe unlocked (an iron ingot unlocks dozens) scanned all ~1300 recipe_unlocked ones. The tree now indexes inventory_changed criteria by the items that can pass them (tags resolved; the few without an item list are always tried) and recipe_unlocked criteria by recipe, so a change tries the 20-40 that could match. - Waits (wall well above CPU, e.g. 10.5 ms for 0.15 ms of CPU): each companion report was logged on the game thread, an unbuffered stderr write plus a latest.log write under a mutex; a full pipe or a slow disk held the tick. The logger now formats the line and keeps it for crash reports on the calling thread and hands the I/O to a "Log writer" thread; flush() waits for it (crash report, exit). - CPU, companion_book / companion_block_drops (1-1.4 ms each): built on the first work order's tick. Built on a worker when the world opens (2-5 ms there, done long before the first order). Skills script (tools/test_companion_skills.py, hub tick, ms): before (2 runs) after (3 runs) mean p99 worst mean p99 worst CPU worst collect 0.082 0.97 3.02 0.070 0.71 1.58 0.99 make 0.108 1.30 5.35 0.078 0.94 1.39 1.38 ore 0.119 1.53 10.51 0.077 0.18 11.47* 0.23 smelt 0.071 0.79 3.91 0.056 0.13 0.30 0.30 Slow hub ticks logged over whole runs: CPU over 1 ms 46 -> 4, worst CPU 5.32 -> 1.38 ms. * one tick with 0.23 ms of CPU: the thread off its core while another agent compiled (load 7-12), in spans that do no I/O. The skills script prints the hub's p99 and CPU mean/p99/worst, and --logs keeps each run's client log. Co-Authored-By: Claude Opus 5.5 <[email protected]>
2026-11-09 02:29:50 -10:00 · 2026-10-20 23:56:08 +02:00
1 parent 8cb8a1a83b
commit 060c795e3c
@@ -53,6 +53,10 @@ pub struct Tree {
    pub by_id: HashMap<String, usize>,
    /// trigger id -> (advancement index, criterion index).
    pub by_trigger: HashMap<String, Vec<(usize, usize)>>,
+    /// `recipe_unlocked` criteria by the recipe they name (`index_recipes`);
+    /// those naming none in `recipes_any`.
+    by_recipe: HashMap<String, Vec<(usize, usize)>>,
+    recipes_any: Vec<(usize, usize)>,
 }
 fn frame(v: &Value) -> Frame {
    match v.as_str() {
@@ -93,12 +97,111 @@ impl Tree {
                tree.list.push(a);
            }
        }
+        tree.index_recipes();
        tree
    }
+    /// Index the `recipe_unlocked` criteria by recipe: a grant that unlocks
+    /// twenty recipes tested every one of the ~1,300 recipe advancements'
+    /// criteria for each (several ms in one tick).
+    pub fn index_recipes(&mut self) {
+        self.by_recipe.clear();
+        self.recipes_any.clear();
+        for &(ai, ci) in self
+            .by_trigger
+            .get("minecraft:recipe_unlocked")
+            .into_iter()
+            .flatten()
+        {
+            match self.list[ai].criteria[ci].conditions["recipes"].as_str() {
+                Some(r) => self
+                    .by_recipe
+                    .entry(r.to_owned())
+                    .or_default()
+                    .push((ai, ci)),
+                None => self.recipes_any.push((ai, ci)),
+            }
+        }
+    }
+    /// The `recipe_unlocked` criteria that could pass for `recipe`, in tree
+    /// order (the others name another recipe).
+    pub fn recipe_criteria(&self, recipe: &str) -> Vec<(usize, usize)> {
+        let mut out = self.recipes_any.clone();
+        out.extend(self.by_recipe.get(recipe).into_iter().flatten());
+        out.sort_unstable();
+        out
+    }
    pub fn get(&self, id: &str) -> Option<&Advancement> {
        self.by_id.get(id).map(|&i| &self.list[i])
    }
 }
+
+/// The `inventory_changed` criteria by the items they need. A criterion whose
+/// item predicates include one limited to some items (an id, a `#tag`, a
+/// list) can only pass with one of those in the inventory, so an inventory
+/// change tests only the criteria of the items it holds, plus those that
+/// need no particular item. The same answers as testing them all: the ~1,300
+/// recipe advancements each have one, and testing every one of them cost a
+/// player (or a companion) 1–4 ms on every tick its inventory changed.
+#[derive(Default)]
+pub struct InventoryIndex {
+    by_item: HashMap<String, Vec<(usize, usize)>>,
+    any: Vec<(usize, usize)>,
+}
+impl InventoryIndex {
+    /// `tag` gives a `#tag`'s item ids (none for a tag that doesn't exist,
+    /// which matches nothing).
+    pub fn build<'t>(tree: &Tree, tag: impl Fn(&str) -> Vec<&'t str>) -> Self {
+        fn ids<'t>(v: &Value, tag: &impl Fn(&str) -> Vec<&'t str>, out: &mut Vec<String>) {
+            match v {
+                Value::String(s) => match s.strip_prefix('#') {
+                    Some(t) => out.extend(tag(t).into_iter().map(str::to_owned)),
+                    None => out.push(s.clone()),
+                },
+                Value::Array(a) => a.iter().for_each(|x| ids(x, tag, out)),
+                _ => {}
+            }
+        }
+        let mut index = Self::default();
+        let Some(list) = tree.by_trigger.get("minecraft:inventory_changed") else {
+            return index;
+        };
+        for &(ai, ci) in list {
+            let items = &tree.list[ai].criteria[ci].conditions["items"];
+            // `id_matches`: only a string or a list limits the items.
+            let limited = items.as_array().and_then(|a| {
+                a.iter()
+                    .map(|p| &p["items"])
+                    .find(|v| v.is_string() || v.is_array())
+            });
+            match limited {
+                Some(v) => {
+                    let mut out = Vec::new();
+                    ids(v, &tag, &mut out);
+                    out.sort();
+                    out.dedup();
+                    for id in out {
+                        index.by_item.entry(id).or_default().push((ai, ci));
+                    }
+                }
+                None => index.any.push((ai, ci)),
+            }
+        }
+        index
+    }
+    /// The criteria an inventory holding these item ids could pass, in
+    /// tree order.
+    pub fn candidates<'a>(&self, held: impl IntoIterator<Item = &'a str>) -> Vec<(usize, usize)> {
+        let mut out = self.any.clone();
+        for id in held {
+            if let Some(list) = self.by_item.get(id) {
+                out.extend_from_slice(list);
+            }
+        }
+        out.sort_unstable();
+        out.dedup();
+        out
+    }
+}
 fn collect(root: &Path, dir: &Path, ns: &str, out: &mut Vec<(String, std::path::PathBuf)>) {
    let Ok(entries) = std::fs::read_dir(dir) else {
        return;
@@ -1090,6 +1193,94 @@ mod tests {
            stack.id = "minecraft:tnt".into();
        }
    }
+    /// Only the criteria the held items could pass are tested; those that
+    /// need no particular item always are.
+    #[test]
+    fn inventory_index_keeps_the_criteria_the_items_could_pass() {
+        let criteria = [
+            serde_json::json!({"items": [{"items": "minecraft:diamond"}]}),
+            serde_json::json!({"items": [{"items": "#minecraft:planks"}]}),
+            serde_json::json!({"items": [{"count": {"min": 2}}]}),
+            serde_json::json!({"items": [{"count": 1}, {"items": ["minecraft:stick", "minecraft:apple"]}]}),
+            serde_json::json!({"slots": {"empty": 0}}),
+            serde_json::json!({"items": [{"items": "#minecraft:no_such_tag"}]}),
+        ];
+        let mut tree = Tree::default();
+        for (i, conditions) in criteria.into_iter().enumerate() {
+            tree.list.push(Advancement {
+                id: format!("test:{i}"),
+                parent: None,
+                display: None,
+                criteria: vec![Criterion {
+                    name: "c".into(),
+                    trigger: "minecraft:inventory_changed".into(),
+                    conditions,
+                }],
+                requirements: vec![vec!["c".into()]],
+                rewards: Rewards::default(),
+            });
+            tree.by_trigger
+                .entry("minecraft:inventory_changed".into())
+                .or_default()
+                .push((i, 0));
+        }
+        let index = InventoryIndex::build(&tree, |tag| match tag {
+            "minecraft:planks" => vec!["minecraft:oak_planks", "minecraft:birch_planks"],
+            _ => Vec::new(),
+        });
+        let found = |held: &[&str]| -> Vec<usize> {
+            index
+                .candidates(held.iter().copied())
+                .into_iter()
+                .map(|(ai, _)| ai)
+                .collect()
+        };
+        assert_eq!(found(&[]), [2, 4]);
+        assert_eq!(found(&["minecraft:dirt"]), [2, 4]);
+        assert_eq!(
+            found(&["minecraft:oak_planks", "minecraft:diamond"]),
+            [0, 1, 2, 4]
+        );
+        assert_eq!(found(&["minecraft:apple", "minecraft:apple"]), [2, 3, 4]);
+    }
+    /// A recipe unlocked tests only the criteria that name it.
+    #[test]
+    fn recipe_index_keeps_the_criteria_of_the_recipe() {
+        let mut tree = Tree::default();
+        for (i, conditions) in [
+            serde_json::json!({"recipes": "minecraft:oak_planks"}),
+            serde_json::json!({"recipes": "minecraft:stick"}),
+            serde_json::json!({}),
+            serde_json::json!({"recipes": "minecraft:oak_planks"}),
+        ]
+        .into_iter()
+        .enumerate()
+        {
+            tree.list.push(Advancement {
+                id: format!("test:{i}"),
+                parent: None,
+                display: None,
+                criteria: vec![Criterion {
+                    name: "c".into(),
+                    trigger: "minecraft:recipe_unlocked".into(),
+                    conditions,
+                }],
+                requirements: vec![vec!["c".into()]],
+                rewards: Rewards::default(),
+            });
+            tree.by_trigger
+                .entry("minecraft:recipe_unlocked".into())
+                .or_default()
+                .push((i, 0));
+        }
+        tree.index_recipes();
+        assert_eq!(
+            tree.recipe_criteria("minecraft:oak_planks"),
+            [(0, 0), (2, 0), (3, 0)]
+        );
+        assert_eq!(tree.recipe_criteria("minecraft:stick"), [(1, 0), (2, 0)]);
+        assert_eq!(tree.recipe_criteria("minecraft:torch"), [(2, 0)]);
+    }
    #[test]
    fn bucket_axolotl_block_advancements_require_the_placed_block() {
        let ctx = Entities {
@@ -91,6 +91,8 @@ pub(super) struct AdvState {
    /// The tree being read on another thread since the world opened
    /// (`prefetch_advancement_tree`), taken by the first `advancement_tree`.
    pub(super) pending_tree: Option<std::thread::JoinHandle<Tree>>,
+    /// `inventory_changed`'s criteria by item, built for `tree`.
+    inventory_index: Option<(Arc<Tree>, Arc<adv::InventoryIndex>)>,
 }
 /// The game's world for predicates.
 struct View<'a, 'g>(&'a Game<'g>);
@@ -229,9 +231,31 @@ impl Game<'_> {
                _ => Tree::load(&self.options.resources.join("data")),
            };
            self.adv.tree = Arc::new(tree);
+            // With the tree, while the world loads: built on the first
+            // inventory change it cost that tick ~10 ms.
+            self.inventory_index();
        }
        self.adv.tree.clone()
    }
+    /// `inventory_changed`'s criteria by item, for the tree in place.
+    fn inventory_index(&mut self) -> Arc<adv::InventoryIndex> {
+        let tree = self.adv.tree.clone();
+        if let Some((built, index)) = &self.adv.inventory_index
+            && Arc::ptr_eq(built, &tree)
+        {
+            return index.clone();
+        }
+        let items = self.res.items();
+        let index = Arc::new(adv::InventoryIndex::build(&tree, |tag| {
+            items
+                .item_tags
+                .get(tag)
+                .map(|t| t.iter().map(String::as_str).collect())
+                .unwrap_or_default()
+        }));
+        self.adv.inventory_index = Some((tree, index.clone()));
+        index
+    }
    /// Start reading the advancement files on another thread while the world
    /// loads. The first tick's first criterion trigger used to read and parse
    /// all of them on the game thread (about 60 ms).
@@ -394,6 +418,16 @@ impl Game<'_> {
        let Some(list) = tree.by_trigger.get(name) else {
            return;
        };
+        self.trigger_criteria(&tree, list, test);
+    }
+    /// `trigger` for some of a trigger's criteria: (advancement, criterion)
+    /// indexes in `tree`, in tree order.
+    fn trigger_criteria(
+        &mut self,
+        tree: &Tree,
+        list: &[(usize, usize)],
+        test: impl Fn(&Value, &dyn adv::World) -> bool,
+    ) {
        let mut hits = Vec::new();
        {
            let view = View(self);
@@ -437,9 +471,14 @@ impl Game<'_> {
        } else {
            self.recipe_toast(unlocked);
        }
+        if unlocked.is_empty() || self.remote.is_some() || self.no_player_here() {
+            return;
+        }
+        self.load_advancements();
+        let tree = self.adv.tree.clone();
        for r in unlocked {
-            let r = r.clone();
-            self.trigger("minecraft:recipe_unlocked", move |c, _| {
+            let list = tree.recipe_criteria(r);
+            self.trigger_criteria(&tree, &list, |c, _| {
                c["recipes"].as_str() == Some(r.as_str())
            });
        }
@@ -566,7 +605,15 @@ impl Game<'_> {
                    .is_some_and(|i| s.count >= i.max_stack)
            })
            .count() as f64;
-        self.trigger("minecraft:inventory_changed", move |c, w| {
+        // Only the criteria the items held could pass (`InventoryIndex`).
+        if self.remote.is_some() || self.no_player_here() {
+            return;
+        }
+        self.load_advancements();
+        let tree = self.adv.tree.clone();
+        let index = self.inventory_index();
+        let list = index.candidates(stacks.iter().map(|s| s.id.as_str()));
+        self.trigger_criteria(&tree, &list, move |c, w| {
            let slots = &c["slots"];
            let range = |k: &str, v: f64| {
                let r = &slots[k];
@@ -971,10 +1018,8 @@ impl Game<'_> {
            });
            positions.push((a.x, a.y));
        }
-        let mut tree = Tree {
-            list,
-            ..Tree::default()
-        };
+        let mut tree = Tree::default();
+        tree.list = list;
        for (i, a) in tree.list.iter().enumerate() {
            tree.by_id.insert(a.id.clone(), i);
        }
@@ -92,13 +92,27 @@ pub(super) struct Cost {
    total: std::time::Duration,
    max: std::time::Duration,
    views: std::time::Duration,
+    /// Every tick's time since the last report, for its 99th percentile
+    /// (at most a few thousand between `companion cost` calls).
+    each: Vec<f32>,
+    /// The thread's CPU time in those ticks: wall time beyond it is the
+    /// thread waiting (for a core, on a busy machine), not work.
+    cpu_total: std::time::Duration,
+    cpu_each: Vec<f32>,
 }

 impl Cost {
-    pub fn hub(&mut self, d: std::time::Duration) {
+    pub fn hub(&mut self, d: std::time::Duration, cpu: Option<std::time::Duration>) {
        self.ticks += 1;
        self.total += d;
        self.max = self.max.max(d);
+        if self.each.len() < 1 << 16 {
+            self.each.push(d.as_secs_f32() * 1000.0);
+            if let Some(cpu) = cpu {
+                self.cpu_total += cpu;
+                self.cpu_each.push(cpu.as_secs_f32() * 1000.0);
+            }
+        }
    }
    pub fn views(&mut self, d: std::time::Duration) {
        self.total += d;
@@ -107,10 +121,21 @@ impl Cost {
    /// Mean and worst milliseconds a tick, then clears.
    fn take(&mut self) -> Value {
        let n = self.ticks.max(1) as f64;
+        fn p99(each: &mut [f32]) -> f32 {
+            each.sort_by(f32::total_cmp);
+            each.get((each.len() * 99 / 100).min(each.len().saturating_sub(1)))
+                .copied()
+                .unwrap_or(0.0)
+        }
+        let cpu_n = self.cpu_each.len().max(1) as f64;
        let v = json!({
            "ticks": self.ticks,
            "mean_ms": self.total.as_secs_f64() * 1000.0 / n,
            "max_ms": self.max.as_secs_f64() * 1000.0,
+            "p99_ms": p99(&mut self.each),
+            "cpu_mean_ms": self.cpu_total.as_secs_f64() * 1000.0 / cpu_n,
+            "cpu_max_ms": self.cpu_each.iter().copied().fold(0.0f32, f32::max),
+            "cpu_p99_ms": p99(&mut self.cpu_each),
            "views_ms": self.views.as_secs_f64() * 1000.0 / n,
        });
        *self = Self::default();
@@ -457,6 +482,7 @@ impl Game<'_> {
        self.companion_report(&mut b, CompanionReport::SkillStarted(skill));
        host.companions.push(b);
        self.lan = Some(host);
+        self.companion_prepare_work();
        Ok(())
    }

@@ -573,6 +599,11 @@ impl Game<'_> {
            .into_iter()
            .filter(|f| f.active)
            .collect();
+        // The work skills' indexes, on a worker while the world loads: ready
+        // long before a companion's first task asks for them.
+        if !self.settings.extras.no_ai {
+            self.companion_prepare_work();
+        }
    }

    /// Per tick before the hub's: the companions saved with the world come
@@ -147,7 +147,9 @@ impl Game<'_> {
            );
        }
        while let Some(command) = b.commands.pop_front() {
-            self.companion_apply(host, b, command, owner);
+            horizon_client::spans::time("companion_apply", || {
+                self.companion_apply(host, b, command, owner);
+            });
        }
        let Some(g) = host.hub.guest(b.conn) else {
            return true;
@@ -172,7 +174,9 @@ impl Game<'_> {
        b.near_owner = c::distance(pos, owner) <= c::COME_ALONG;
        self.companion_notice_hurt(host, b, pos, health);
        if b.ticks.is_multiple_of(10) {
-            self.companion_callouts(b, pos, owner);
+            horizon_client::spans::time("companion_callouts", || {
+                self.companion_callouts(b, pos, owner);
+            });
        }
        // Eating ends when the item is used up (or the use stops).
        if let Some((before, item)) = b.eating.clone() {
@@ -193,7 +197,7 @@ impl Game<'_> {
                self.companion_gear(host, b);
            }
        } else if b.ticks.is_multiple_of(20) {
-            self.companion_gear(host, b);
+            horizon_client::spans::time("companion_gear", || self.companion_gear(host, b));
        }
        // Self-preservation: it backs off when badly hurt.
        if !b.retreating && health > 0.0 && health < c::RETREAT_BELOW {
@@ -212,9 +216,15 @@ impl Game<'_> {
        if b.eating.is_none() && hungry && (b.target.is_none() || !danger_close) {
            self.companion_start_eating(host, b);
        }
-        self.companion_work_reflexes(host, b);
-        self.companion_pick_target(host, b, pos, owner);
-        self.companion_move(host, b, pos, owner);
+        horizon_client::spans::time("companion_reflexes", || {
+            self.companion_work_reflexes(host, b);
+        });
+        horizon_client::spans::time("companion_target", || {
+            self.companion_pick_target(host, b, pos, owner);
+        });
+        horizon_client::spans::time("companion_move", || {
+            self.companion_move(host, b, pos, owner);
+        });
        if b.jump {
            b.keys.jump = true;
            b.jump = false;
@@ -136,56 +136,64 @@ enum Reach {
    Failed,
 }

+/// The crafting recipes by the item they make.
+pub(super) fn build_book(res: &super::Resources) -> BookIndex {
+    let mut by_result: HashMap<String, Vec<Arc<CraftRecipe>>> = HashMap::new();
+    for (name, r) in &res.recipes().crafting {
+        let (cells, width, height, result) = match r {
+            Recipe::Shaped {
+                width,
+                height,
+                cells,
+                result,
+            } => (
+                cells
+                    .iter()
+                    .map(|c| c.as_ref().map(|i| i.1.clone()))
+                    .collect(),
+                *width,
+                *height,
+                result,
+            ),
+            Recipe::Shapeless {
+                ingredients,
+                result,
+            } => (
+                ingredients.iter().map(|i| Some(i.1.clone())).collect(),
+                0,
+                0,
+                result,
+            ),
+            Recipe::Special(_) => continue,
+        };
+        let Some(item) = result.item.as_deref().filter(|_| result.extra.is_none()) else {
+            continue;
+        };
+        by_result
+            .entry(item.to_owned())
+            .or_default()
+            .push(Arc::new(CraftRecipe {
+                id: format!("minecraft:{name}"),
+                result: item.to_owned(),
+                cells,
+                width,
+                height,
+                count: result.count,
+            }));
+    }
+    BookIndex { by_result }
+}
+
 impl Game<'_> {
-    /// The recipe index, built once.
+    /// The recipe index: built on a worker thread when the first body
+    /// joined (`companion_prepare_work`), else here.
    pub(super) fn companion_book(&mut self) -> Arc<BookIndex> {
+        self.companion_prepared_work();
        if let Some(b) = &self.companions.work.book {
            return b.clone();
        }
-        let mut by_result: HashMap<String, Vec<Arc<CraftRecipe>>> = HashMap::new();
-        for (name, r) in &self.res.recipes().crafting {
-            let (cells, width, height, result) = match r {
-                Recipe::Shaped {
-                    width,
-                    height,
-                    cells,
-                    result,
-                } => (
-                    cells
-                        .iter()
-                        .map(|c| c.as_ref().map(|i| i.1.clone()))
-                        .collect(),
-                    *width,
-                    *height,
-                    result,
-                ),
-                Recipe::Shapeless {
-                    ingredients,
-                    result,
-                } => (
-                    ingredients.iter().map(|i| Some(i.1.clone())).collect(),
-                    0,
-                    0,
-                    result,
-                ),
-                Recipe::Special(_) => continue,
-            };
-            let Some(item) = result.item.as_deref().filter(|_| result.extra.is_none()) else {
-                continue;
-            };
-            by_result
-                .entry(item.to_owned())
-                .or_default()
-                .push(Arc::new(CraftRecipe {
-                    id: format!("minecraft:{name}"),
-                    result: item.to_owned(),
-                    cells,
-                    width,
-                    height,
-                    count: result.count,
-                }));
-        }
-        let book = Arc::new(BookIndex { by_result });
+        let _span = horizon_client::spans::Span::new("companion_book");
+        let book = Arc::new(build_book(&self.res));
        self.companions.work.book = Some(book.clone());
        book
    }
@@ -146,6 +146,13 @@ pub(super) struct WorkCache {
    pub book: Option<Arc<super::companion_craft::BookIndex>>,
    /// Block name → the items its loot table gives without a tool match.
    pub block_drops: Option<Arc<HashMap<String, Vec<String>>>>,
+    /// Both being built on a worker thread (`companion_prepare_work`).
+    pub prepared: Option<
+        std::thread::JoinHandle<(
+            super::companion_craft::BookIndex,
+            HashMap<String, Vec<String>>,
+        )>,
+    >,
    pub mob_drops: HashMap<String, Arc<Vec<String>>>,
    /// Each block's name and its states' ids (a block's states are listed together).
    pub blocks: std::sync::OnceLock<Vec<(String, std::ops::Range<usize>)>>,
@@ -400,6 +407,27 @@ fn carried_any(inventory: &[Option<ItemStack>], items: &[String]) -> u32 {
        .sum()
 }

+/// Block name → the items its loot table gives without a tool match.
+fn build_block_drops(res: &super::Resources) -> HashMap<String, Vec<String>> {
+    let items = res.items();
+    let mut drops: HashMap<String, Vec<String>> = HashMap::new();
+    let mut last = "";
+    for f in &res.facts().states {
+        // A block's states are listed together.
+        if *f.name == *last || drops.contains_key(&*f.name) {
+            continue;
+        }
+        last = &f.name;
+        let table = format!("minecraft:blocks/{}", c::short_id(&f.name));
+        let got = items
+            .loot_json(&table)
+            .map(work::loot_items)
+            .unwrap_or_default();
+        drops.insert(f.name.to_string(), got);
+    }
+    drops
+}
+
 impl Game<'_> {
    // ---- commands -------------------------------------------------------------------

@@ -442,6 +470,7 @@ impl Game<'_> {
        command: CompanionCommand,
        resume: Skill,
    ) -> Result<Task, String> {
+        let _span = horizon_client::spans::Span::new("companion_task");
        let g = host.hub.guest(b.conn).ok_or("no body")?;
        let (skill, kind) = match command {
            CompanionCommand::Collect { what, count } => {
@@ -605,6 +634,7 @@ impl Game<'_> {
        owner: [f64; 3],
    ) {
        let started = std::time::Instant::now();
+        let _span = horizon_client::spans::Span::new("companion_work");
        let Some(mut task) = b.work.tasks.pop() else {
            b.skill = Skill::Follow;
            return;
@@ -797,32 +827,61 @@ impl Game<'_> {
        }
    }

-    /// What each block drops without a tool match (`work::loot_items`), once.
+    /// What each block drops without a tool match (`work::loot_items`):
+    /// built on a worker thread when the first body joined, else here.
    fn block_drops(&mut self) -> Arc<HashMap<String, Vec<String>>> {
+        self.companion_prepared_work();
        if let Some(d) = &self.companions.work.block_drops {
            return d.clone();
        }
-        let items = self.res.items();
-        let mut drops: HashMap<String, Vec<String>> = HashMap::new();
-        let mut last = "";
-        for f in &self.res.facts().states {
-            // A block's states are listed together.
-            if *f.name == *last || drops.contains_key(&*f.name) {
-                continue;
-            }
-            last = &f.name;
-            let table = format!("minecraft:blocks/{}", c::short_id(&f.name));
-            let got = items
-                .loot_json(&table)
-                .map(work::loot_items)
-                .unwrap_or_default();
-            drops.insert(f.name.to_string(), got);
-        }
-        let drops = Arc::new(drops);
+        let _span = horizon_client::spans::Span::new("companion_block_drops");
+        let drops = Arc::new(build_block_drops(&self.res));
        self.companions.work.block_drops = Some(drops.clone());
        drops
    }

+    /// A world opened (or a body joined): the work skills' indexes of the
+    /// game's data (recipes, block drops) are built on a worker thread, not
+    /// by the first order's tick (~1–1.5 ms each on an M4 Pro).
+    pub(super) fn companion_prepare_work(&mut self) {
+        let cache = &mut self.companions.work;
+        if cache.book.is_some() || cache.block_drops.is_some() || cache.prepared.is_some() {
+            return;
+        }
+        let res = self.res.clone();
+        cache.prepared = std::thread::Builder::new()
+            .name("companion work".into())
+            .spawn(move || {
+                let started = std::time::Instant::now();
+                let built = (
+                    super::companion_craft::build_book(&res),
+                    build_block_drops(&res),
+                );
+                if horizon_client::spans::enabled() {
+                    eprintln!(
+                        "Horizon: companion work indexes built in {:.2} ms",
+                        started.elapsed().as_secs_f32() * 1000.0
+                    );
+                }
+                built
+            })
+            .ok();
+    }
+
+    /// The indexes `companion_prepare_work` built, once they are asked for.
+    pub(super) fn companion_prepared_work(&mut self) {
+        let cache = &mut self.companions.work;
+        let joined = cache.prepared.take().map(|h| {
+            let _span = horizon_client::spans::Span::new("companion_work_join");
+            h.join()
+        });
+        let Some(Ok((book, drops))) = joined else {
+            return;
+        };
+        cache.book.get_or_insert_with(|| Arc::new(book));
+        cache.block_drops.get_or_insert_with(|| Arc::new(drops));
+    }
+
    /// What a mob kind drops (`minecraft:entities/<kind>`), once per kind.
    fn mob_drops(&mut self, kind: &str) -> Arc<Vec<String>> {
        if let Some(d) = self.companions.work.mob_drops.get(kind) {
@@ -912,7 +912,14 @@ impl Game<'_> {
        let Some(mut host) = self.lan.take() else {
            return;
        };
-        let metered = (!host.companions.is_empty()).then(std::time::Instant::now);
+        let metered = (!host.companions.is_empty()).then(|| {
+            let spans = horizon_client::spans::enabled().then(horizon_client::spans::mark);
+            (
+                std::time::Instant::now(),
+                horizon_client::spans::thread_cpu(),
+                spans,
+            )
+        });
        // What the tick sends a guest goes to its connection at the end.
        let holding = lan::Holding::start();
        // The host's own commands' (and command blocks') players moving
@@ -923,7 +930,7 @@ impl Game<'_> {
        if !self.admin_feedback.is_empty() {
            self.send_admin_feedback(&mut host, None);
        }
-        let state = self.lan_host_state(&host);
+        let state = horizon_client::spans::time("lan_host_state", || self.lan_host_state(&host));
        // A dedicated server runs the hub without a host player.
        if state.is_some() || host.hub.config.dedicated {
            // Companions have no client to send the entities to.
@@ -960,11 +967,13 @@ impl Game<'_> {
                // (`tick_server`): the network is read once, before the first.
                let pass = self.level_pass;
                let mut events = if pass.first {
-                    host.hub.poll(&mut ctx)
+                    horizon_client::spans::time("hub_poll", || host.hub.poll(&mut ctx))
                } else {
                    Vec::new()
                };
-                events.extend(host.hub.tick_level(&mut ctx));
+                events.extend(horizon_client::spans::time("hub_level", || {
+                    host.hub.tick_level(&mut ctx)
+                }));
                if pass.last {
                    host.hub.end_tick();
                }
@@ -1040,7 +1049,9 @@ impl Game<'_> {
                    // Routed on the next companion tick (game/companion_ai.rs).
                    HostEvent::Said { name, text } => self.companion_ai.guest_said(name, text),
                    HostEvent::Packet(conn, packet) => {
-                        self.lan_guest_packet(&mut host, conn, *packet);
+                        horizon_client::spans::time("lan_packet", || {
+                            self.lan_guest_packet(&mut host, conn, *packet);
+                        });
                        if !host.commands.is_empty() {
                            self.lan = Some(host);
                            self.run_guest_commands();
@@ -1050,21 +1061,46 @@ impl Game<'_> {
                }
            }
        }
-        self.lan_flush_effects(&mut host);
+        use horizon_client::spans::time;
+        time("lan_effects", || self.lan_flush_effects(&mut host));
        if !host.companions.is_empty() {
-            horizon_client::spans::time("companions", || self.tick_companions(&mut host));
+            time("companions", || self.tick_companions(&mut host));
        }
-        self.tick_guests(&mut host);
-        self.lan_living_flags(&mut host);
-        self.tick_server_travel(&mut host);
-        self.lan_swings(&mut host);
-        self.lan_update_streaming(&host);
-        self.lan_update_models(&mut host);
-        self.lan_update_waypoints(&mut host, state.as_ref());
+        time("lan_guests", || self.tick_guests(&mut host));
+        time("lan_living", || self.lan_living_flags(&mut host));
+        time("lan_travel", || self.tick_server_travel(&mut host));
+        time("lan_swings", || self.lan_swings(&mut host));
+        time("lan_streaming", || self.lan_update_streaming(&host));
+        time("lan_models", || self.lan_update_models(&mut host));
+        time("lan_waypoints", || {
+            self.lan_update_waypoints(&mut host, state.as_ref());
+        });
        drop(holding);
        lan::flush_all(host.hub.guests.iter().map(|g| &g.sender));
-        if let Some(started) = metered {
-            host.cost.hub(started.elapsed());
+        if let Some((started, cpu_started, spans)) = metered {
+            let took = started.elapsed();
+            let cpu = horizon_client::spans::thread_cpu()
+                .zip(cpu_started)
+                .map(|(end, start)| end.saturating_sub(start));
+            host.cost.hub(took, cpu);
+            // HORIZON_SPIKES=MS: a companions' hub tick slower than MS, by span,
+            // with the thread's CPU time (less than the wall time: it waited).
+            if let Some(threshold) = self.options.spikes
+                && let Some(mark) = spans
+                && took.as_secs_f32() * 1000.0 > threshold
+            {
+                let cpu = cpu.map_or(f32::NAN, |c| c.as_secs_f32() * 1000.0);
+                let list: Vec<String> = horizon_client::spans::since(mark)
+                    .iter()
+                    .filter(|(_, ms)| *ms >= 0.05)
+                    .map(|(n, ms)| format!("{n} {ms:.2}"))
+                    .collect();
+                log::info!(
+                    "Horizon: slow companion hub tick {:.2} ms, cpu {cpu:.2} ms: {}",
+                    took.as_secs_f32() * 1000.0,
+                    list.join(", ")
+                );
+            }
        }
        self.lan = Some(host);
    }
@@ -177,9 +177,9 @@ impl Game<'_> {
        conn: u32,
        f: impl FnOnce(&mut Self) -> R,
    ) -> Option<R> {
-        let swap = self.enter_guest(host, conn)?;
+        let swap = horizon_client::spans::time("enter_guest", || self.enter_guest(host, conn))?;
        let result = f(self);
-        self.leave_guest(host, swap);
+        horizon_client::spans::time("leave_guest", || self.leave_guest(host, swap));
        Some(result)
    }

@@ -1402,7 +1402,7 @@ impl Game<'_> {
            let Some(gi) = host.hub.guests.iter().position(|g| g.conn == conn) else {
                continue;
            };
-            self.guest_sleep_tick(host, gi);
+            horizon_client::spans::time("guest_sleep", || self.guest_sleep_tick(host, gi));
            if host.hub.guests[gi].dead || self.on_server_trip(conn) {
                continue;
            }
@@ -1411,6 +1411,7 @@ impl Game<'_> {
            let using = play.using.is_some();
            let delayed = play.destroy_delay > 0 || play.use_delay > 0 || play.attack_ticks < 100;
            if digging.is_some() || using || delayed {
+                let _span = horizon_client::spans::Span::new("guest_dig_use");
                self.as_guest(host, conn, |g| {
                    g.attack_ticks = g.attack_ticks.saturating_add(1);
                    if let Some((pos, face)) = digging {
@@ -1433,28 +1434,37 @@ impl Game<'_> {
                    }
                });
            }
-            self.guest_delayed_destroy(host, conn);
+            horizon_client::spans::time("guest_destroy", || self.guest_delayed_destroy(host, conn));
            if host.hub.guests[gi].companion {
                // Its body moves on the server (game/companion_body.rs).
-                self.companion_body_tick(host, conn);
+                horizon_client::spans::time("companion_body", || {
+                    self.companion_body_tick(host, conn)
+                });
            } else {
                self.guest_server_tick(host, conn);
            }
            // Player.tick's statistics and ServerPlayer.tick's triggers, then
            // PlayerAdvancements.flushDirty.
            let sleeping = host.hub.guests[gi].sleeping;
-            self.as_guest(host, conn, |g| {
-                g.count_tick_stats(sleeping);
-                g.tick_advancements();
-                g.update_player_attributes();
+            horizon_client::spans::time("guest_player_tick", || {
+                self.as_guest(host, conn, |g| {
+                    horizon_client::spans::time("guest_stats", || g.count_tick_stats(sleeping));
+                    horizon_client::spans::time("guest_advancements", || g.tick_advancements());
+                    g.update_player_attributes();
+                })
            });
-            host.hub.flush_progress(conn);
-            self.guest_dig_feedback(host, conn);
-            let picked = self.guest_pickups(host, gi);
+            horizon_client::spans::time("guest_progress", || host.hub.flush_progress(conn));
+            horizon_client::spans::time("guest_dig_feedback", || {
+                self.guest_dig_feedback(host, conn)
+            });
+            let picked =
+                horizon_client::spans::time("guest_pickups", || self.guest_pickups(host, gi));
            if host.hub.guests[gi].companion && !picked.is_empty() {
-                self.companion_picked_up(host, conn, picked);
+                horizon_client::spans::time("companion_picked", || {
+                    self.companion_picked_up(host, conn, picked);
+                });
            }
-            self.guest_orbs(host, gi);
+            horizon_client::spans::time("guest_orbs", || self.guest_orbs(host, gi));
            let g = &mut host.hub.guests[gi];
            if g.health <= 0.0 && !g.dead {
                g.dead = true;
@@ -12,7 +12,7 @@ use std::collections::VecDeque;
 use std::fs::{self, File, OpenOptions};
 use std::io::{self, Read, Seek, SeekFrom, Write};
 use std::path::{Path, PathBuf};
-use std::sync::Mutex;
+use std::sync::{Mutex, mpsc};

 use chrono::{DateTime, Local, NaiveDate};

@@ -201,16 +201,74 @@ pub fn open_latest(dir: &Path) -> io::Result<Option<Latest>> {
    Ok(Some(Latest { file, _lock: lock }))
 }

-struct State {
+/// What the writer thread is told.
+enum Out {
+    /// Lines for the file, dated, and the message for stderr (Horizon's own).
+    Write {
+        date: NaiveDate,
+        lines: Vec<String>,
+        stderr: Option<String>,
+    },
+    /// Answer once everything before is written.
+    Flush(mpsc::SyncSender<()>),
+}
+
+/// The file side of the log, on its own thread: a line costs the thread that logs it a
+/// format and a channel send, never a write that can wait (a full stderr pipe, a slow disk).
+/// The game's companions log every report from their tick; written there, a report could hold
+/// the frame for milliseconds while the CPU sat idle.
+struct Writer {
    file: Option<Latest>,
    dir: PathBuf,
    /// The day the open file's lines belong to.
    date: NaiveDate,
-    recent: VecDeque<String>,
+}
+
+impl Writer {
+    fn run(mut self, out: mpsc::Receiver<Out>) {
+        let stderr = io::stderr();
+        for msg in out {
+            match msg {
+                Out::Write {
+                    date,
+                    lines,
+                    stderr: message,
+                } => {
+                    if let Some(message) = message {
+                        let _ = writeln!(stderr.lock(), "{message}");
+                    }
+                    if date != self.date {
+                        if let Some(latest) = &mut self.file
+                            && let Err(e) = roll(&mut latest.file, &self.dir, self.date)
+                        {
+                            let _ = writeln!(
+                                stderr.lock(),
+                                "Horizon: could not roll over the log: {e}"
+                            );
+                        }
+                        self.date = date;
+                    }
+                    if let Some(latest) = &mut self.file {
+                        let mut text = lines.join("\n");
+                        text.push('\n');
+                        let _ = latest.file.write_all(text.as_bytes());
+                    }
+                }
+                Out::Flush(done) => {
+                    if let Some(latest) = &mut self.file {
+                        let _ = latest.file.flush();
+                    }
+                    let _ = done.send(());
+                }
+            }
+        }
+    }
 }

 struct Logger {
-    state: Mutex<State>,
+    out: mpsc::Sender<Out>,
+    /// The last lines, kept here (not on the writer) so a crash report has them at once.
+    recent: Mutex<VecDeque<String>>,
    /// What the main thread is called in the log: "Render thread", or "Server thread" for the
    /// dedicated server, as in vanilla.
    main_thread: &'static str,
@@ -233,53 +291,66 @@ impl log::Log for Logger {
            return;
        }
        let message = record.args().to_string();
-        if ours(record.target()) {
-            eprintln!("{message}");
-        }
        let current = std::thread::current();
        let thread = match current.name() {
            Some("main") => self.main_thread,
            Some(name) => name,
            None => "unnamed",
        };
-        self.write(thread, record.level(), &message);
+        let stderr = ours(record.target()).then(|| message.clone());
+        self.send(thread, record.level(), &message, stderr);
    }

+    /// Waits (a second at most) until every line logged before is in the file.
    fn flush(&self) {
-        if let Some(latest) = &mut self.state.lock().unwrap_or_else(|e| e.into_inner()).file {
-            let _ = latest.file.flush();
+        let (done, wait) = mpsc::sync_channel(1);
+        if self.out.send(Out::Flush(done)).is_ok() {
+            let _ = wait.recv_timeout(std::time::Duration::from_secs(1));
        }
    }
 }

 impl Logger {
    fn write(&self, thread: &str, level: log::Level, message: &str) {
+        self.send(thread, level, message, None);
+    }
+
+    fn send(&self, thread: &str, level: log::Level, message: &str, stderr: Option<String>) {
        let now = Local::now();
-        let mut state = self.state.lock().unwrap_or_else(|e| e.into_inner());
-        let state = &mut *state;
-        if now.date_naive() != state.date {
-            if let Some(latest) = &mut state.file
-                && let Err(e) = roll(&mut latest.file, &state.dir, state.date)
-            {
-                eprintln!("Horizon: could not roll over the log: {e}");
-            }
-            state.date = now.date_naive();
-        }
        // As log4j writes a multi-line message: the pattern once, the rest as it is.
-        for (i, line) in message.lines().enumerate() {
-            let line = if i == 0 {
-                format_line(&now, thread, level, line)
-            } else {
-                line.to_owned()
-            };
-            if let Some(latest) = &mut state.file {
-                let _ = writeln!(latest.file, "{line}");
-            }
-            state.recent.push_back(line);
-            if state.recent.len() > RECENT {
-                state.recent.pop_front();
+        let lines: Vec<String> = message
+            .lines()
+            .enumerate()
+            .map(|(i, line)| {
+                if i == 0 {
+                    format_line(&now, thread, level, line)
+                } else {
+                    line.to_owned()
+                }
+            })
+            .collect();
+        {
+            let mut recent = self.recent.lock().unwrap_or_else(|e| e.into_inner());
+            for line in &lines {
+                if recent.len() == RECENT {
+                    recent.pop_front();
+                }
+                recent.push_back(line.clone());
            }
        }
+        let msg = Out::Write {
+            date: now.date_naive(),
+            lines,
+            stderr,
+        };
+        if let Err(mpsc::SendError(Out::Write {
+            stderr: Some(message),
+            ..
+        })) = self.out.send(msg)
+        {
+            // No writer (it could not start): the terminal still gets Horizon's messages.
+            eprintln!("{message}");
+        }
    }
 }

@@ -304,14 +375,24 @@ pub fn init(home: &Path, main_thread: &'static str) {
            None
        }
    };
-    let logger = LOGGER.get_or_init(|| Logger {
-        state: Mutex::new(State {
+    let logger = LOGGER.get_or_init(|| {
+        let (out, receive) = mpsc::channel();
+        let writer = Writer {
            file,
            dir,
            date: Local::now().date_naive(),
-            recent: VecDeque::new(),
-        }),
-        main_thread,
+        };
+        if let Err(e) = std::thread::Builder::new()
+            .name("Log writer".into())
+            .spawn(move || writer.run(receive))
+        {
+            eprintln!("Horizon: could not start the log writer: {e}");
+        }
+        Logger {
+            out,
+            recent: Mutex::new(VecDeque::new()),
+            main_thread,
+        }
    });
    if log::set_logger(logger).is_ok() {
        log::set_max_level(log::LevelFilter::Info);
@@ -341,10 +422,9 @@ pub fn write_as(thread: &str, level: log::Level, message: &str) {
 /// The last lines written, oldest first (for crash reports).
 pub fn recent_lines() -> Vec<String> {
    LOGGER.get().map_or_else(Vec::new, |l| {
-        l.state
+        l.recent
            .lock()
            .unwrap_or_else(|e| e.into_inner())
-            .recent
            .iter()
            .cloned()
            .collect()
@@ -29,6 +29,25 @@ pub fn time<T>(name: &'static str, f: impl FnOnce() -> T) -> T {
    SPANS.with(|s| s.borrow_mut().push((name, ms)));
    out
 }
+/// A span from `new` until dropped, for a block `time` can't wrap.
+pub struct Span(Option<(&'static str, Instant)>);
+impl Span {
+    pub fn new(name: &'static str) -> Self {
+        Self(
+            ENABLED
+                .load(Ordering::Relaxed)
+                .then(|| (name, Instant::now())),
+        )
+    }
+}
+impl Drop for Span {
+    fn drop(&mut self) {
+        if let Some((name, started)) = self.0 {
+            let ms = started.elapsed().as_secs_f32() * 1000.0;
+            SPANS.with(|s| s.borrow_mut().push((name, ms)));
+        }
+    }
+}
 /// The CPU time this thread has used, where the platform tells it: a tick
 /// with more wall time than CPU time waited (for a lock, or for a core on a
 /// busy machine).
@@ -41,9 +60,25 @@ pub fn thread_cpu() -> Option<Duration> {
    #[cfg(not(unix))]
    None
 }
+/// Whether spans are being recorded (`HORIZON_SPIKES`).
+pub fn enabled() -> bool {
+    ENABLED.load(Ordering::Relaxed)
+}
+/// Where this thread's spans are now, for `since`.
+pub fn mark() -> usize {
+    SPANS.with(|s| s.borrow().len())
+}
+/// The spans recorded since `mark`, summed by name, slowest first; they
+/// stay for `take`. A part of the frame (the companions' hub tick) reports
+/// its own slow ticks this way.
+pub fn since(mark: usize) -> Vec<(&'static str, f32)> {
+    SPANS.with(|s| sum(s.borrow().get(mark..).unwrap_or_default().to_vec()))
+}
 /// The frame's spans, summed by name, slowest first; clears them.
 pub fn take() -> Vec<(&'static str, f32)> {
-    let spans = SPANS.with(|s| std::mem::take(&mut *s.borrow_mut()));
+    sum(SPANS.with(|s| std::mem::take(&mut *s.borrow_mut())))
+}
+fn sum(spans: Vec<(&'static str, f32)>) -> Vec<(&'static str, f32)> {
    let mut sums: Vec<(&'static str, f32)> = Vec::new();
    for (name, ms) in spans {
        match sums.iter_mut().find(|(n, _)| *n == name) {
@@ -310,6 +310,8 @@ def main():
    parser.add_argument('--offscreen', action='store_true')
    parser.add_argument('--shots', type=Path, help='keep screenshots in this folder')
    parser.add_argument('--runs', type=int, default=1)
+    parser.add_argument('--logs', type=Path,
+                        help='copy each run\'s client log here (with HORIZON_SPIKES=MS it lists slow hub ticks)')
    args = parser.parse_args()
    client, resources = args.client.resolve(), args.resources.resolve()
    shots = args.shots.resolve() if args.shots else None
@@ -331,9 +333,15 @@ def main():
                    raise
                finally:
                    stop(process)
+                    if args.logs:
+                        args.logs.mkdir(parents=True, exist_ok=True)
+                        log.seek(0)
+                        (args.logs / f'client-{run + 1}.log').write_text(log.read())
        print(f'run {run + 1}: ' + ', '.join(
            f'{k} {t:.0f} s (work {c["work_mean_ms"]:.3f} ms mean, {c["work_max_ms"]:.2f} worst; '
-            f'hub {c["mean_ms"]:.3f} mean, {c["max_ms"]:.2f} worst; worst path search {c.get("plan_max_ms", 0):.2f})'
+            f'hub {c["mean_ms"]:.3f} mean, {c["p99_ms"]:.2f} p99, {c["max_ms"]:.2f} worst over {c["ticks"]} ticks; '
+            f'hub CPU {c["cpu_mean_ms"]:.3f} mean, {c["cpu_p99_ms"]:.2f} p99, {c["cpu_max_ms"]:.2f} worst; '
+            f'worst path search {c.get("plan_max_ms", 0):.2f})'
            for k, (t, c) in numbers.items()))
    print('Companion skills passed: collect, make from nothing, tool check, mining, smelt, give, '
          'stop and resume, sleep, bow and melee')