Recording a Run Once

alternate title: “a trace in time saves nine”

November 06, 2026

Every question I had about a run of the simulation used to be answered by a throwaway probe — an example binary built outside the repository, written for that one question and run again from tick 0, often for hours — and by the time I gave up on the approach there were some twenty of them. A week of the village to count the firings at each hearth, the same week again to follow the coin, and again to see who baked at one hearth on day 3. A probe looked something like this one, which counts firings a day by hearth.

//! Firings a day, by hearth: a week of the village, from tick 0.

use std::collections::BTreeMap;

use kernel::clock::TICKS_PER_DAY;
use kernel::num::Tick;
use kernel::rng::WorldSeed;
use kernel::world::World;
use sim::town::corpus::corpus;
use sim::town::think::TownDriver;
use sim::town::{Town, TownEvent};

fn main() {
    let seed = WorldSeed::new(1);
    let rules = std::fs::read_to_string("assets/sim/towns/village.ron").expect("the rules");
    let layout = sim::town::pack::generate(&rules, seed).expect("the village");
    let world = World::builder(seed).with(Town::new(seed, layout)).build();

    let week = Tick::new(7 * u64::from(TICKS_PER_DAY));
    let world = sim::run(world, week, &mut TownDriver);

    let fire = corpus().acts.id("fire").expect("the fire act");
    let mut firings = BTreeMap::new();
    for entry in world.log().iter() {
        if let Some(TownEvent::Used { act, object: Some(hearth), .. }) = entry.event::<TownEvent>()
            && *act == fire
        {
            let day = entry.tick().get() / u64::from(TICKS_PER_DAY) + 1;
            *firings.entry((day, *hearth)).or_insert(0u32) += 1;
        }
    }
    for ((day, hearth), count) in firings {
        println!("day {day}  {hearth}  {count}");
    }
}

Every line of it is reasonable and the whole is untenable. The question is compiled into the binary, so the next question is another binary. The answer is had by simulating a week of the village from its first tick, so the next question is also another week. A run’s answers were lost with it, which is to say that two questions about the same run cost two runs.

The tracer I have just merged into ewsim records a run once, in full, and answers anything afterwards — any villager’s perspective at any tick, the world’s state at any tick, any sequence of events — without running it again. It is three crates, a file format of my own and a command-line tool called simtrace.

ewsim is the simulation underneath a sandbox RPG I’m building in Rust, in which the player is one resident of a town of NPCs who each plan their own day. It is deterministic by construction, with fixed-point arithmetic, no wall-clock time and a tick of a tenth of a second, and its reference scenario, m1, is a village of 100 villagers living five in-game days at 864,000 ticks a day. A deterministic simulation can be recorded after the fact by running it again from its seed, and it can equally be broken by a recorder that so much as reorders a reduction. Most of the design follows from one or the other.

Three crates

tracer is the library the simulation links, tracer-derive holds its proc macros, and tracer-cli is the simtrace tool, which reads traces and links no simulation crate whatsoever. That last rule is enforced, not hoped for. The CI dependency check walks cargo tree one crate at a time and fails if the tool reaches the kernel, the content or any domain crate, through tracer or otherwise.

The split exists because the two sides want opposite things. The record side lives under the simulation’s rules (no floats, no std hash maps, a short list of permitted dependencies) and writes with nothing beyond postcard, zstd and roaring. The query side wants DataFusion, Arrow and Parquet, whose answers may well be floats. The tool began as a cli feature of tracer, and moved out to a crate of its own once it was clear that one crate could not sit on both sides of that line.

Recording is behind a record feature that is off by default, and with it off every emit is an empty inline function. This is the whole of the hot path.

#[inline(always)]
pub fn push(&mut self, id: u64, build: impl FnOnce() -> R) {
    #[cfg(feature = "record")]
    self.rows.push((id, build()));
    #[cfg(not(feature = "record"))]
    let _ = (id, build);
}

The record arrives as a closure, so with recording off it is never so much as built. The simulation crates go one step further and take tracer as an optional dependency behind a trace feature of their own, so an ordinary build does not know that the tracer exists.

I did consider tracing, which the project already uses for profiling. It is built for spans and logs, and what I wanted was typed, deterministic records to be queried, so it stays where it is.

Types that describe themselves

I wanted to install the tool once, outside any worktree, and have it read the traces of every branch and of builds that do not exist yet. To that end a trace carries everything needed to read it, and the tool knows nothing of the simulation’s types.

Every traced value is written with postcard and described by a closed vocabulary of thirteen wire types — booleans, unsigned and signed integers, strings, bytes, fixed-point numbers, ticks, spans, IDs of a named kind, enums, options, lists and structs. A new simulation type is a composition of these, so the vocabulary does not grow as the simulation does. The kernel’s number and ID types say how they are written by hand, once, and everything built from them derives it.

A record type is then one table, declared where the simulation defines it.

#[derive(Clone, Debug, tracer::Record)]
#[record(table = "events")]
pub struct EventRow {
    #[record(tick)]
    pub tick: Tick,
    /// Its place in the log: its event ID's serial.
    pub order: u64,
    #[record(key)]
    pub who: Option<NpcId>,
    #[record(key)]
    pub object: Option<ObjectId>,
    #[record(key)]
    pub act: Option<ActId>,
    // … its kind, and its name in the log
    pub event: TownEvent,
}

From that the derive writes the table’s schema (which goes into the trace’s manifest), the encoding into columns and the keys the index is built from. Getting it wrong is a compile error at the field, so a #[record(key)] on a String is refused with “a key is an ID, an unsigned integer, or an option of one” and never discovered at query time. A record without a tick, or a field marked twice, is refused the same way.

Compatibility falls out of the same arrangement. Enum variants are stored by index and named from the stored schema, so adding or reordering variants changes nothing for a reader. A wire type is itself stored as a tag and a length-prefixed body, tags are never reused, and a reader that meets a tag it does not know reads it as Unknown { tag }, skips the column by its length and says so once. It never guesses.

A trace of the village has ten tables of the simulation’s and two of the tracer’s own. The simulation’s are events, decisions, claims and provenance, and a table of changes and a table of frames each for villagers, objects and beliefs. The tracer’s are names and calls, both of which come up below.

Names from the run

A trace is full of numbers that mean something only to the content the run loaded, and the tool has no content. The manifest therefore carries the run’s name tables, which say what its content called each act, object kind, knowledge item, mood, need state and site. Names given during the run (who each villager is, what each object is) are rows in the names table, each from the tick it was given.

A reader shows IDs by those names, and an ID that nobody named by its kind and number, as act#3. The consequence I cared about is that a query names things, as in act = 'bake', and that two runs whose content numbers its acts differently are queried alike.

State traced on change

Events say what happened. Most of my questions were about what was true — where the bowl was all day, what a villager’s purse held when it starved — and for those the state itself has to be recorded. #[derive(Traced)] on a state type makes two tables from it, one of changes and one of whole frames.

#[cfg_attr(feature = "trace", derive(tracer::Traced))]
#[cfg_attr(
    feature = "trace",
    traced(id = "NpcId", changes = "agent_changes", frames = "agent_frames")
)]
pub struct Agent {
    pub pos: Pos,
    /// The way it faces, in 256ths of a turn clockwise from north.
    pub facing: u8,
    pub needs: Needs,
    #[cfg_attr(feature = "trace", traced(skip))]
    pub weights: WeightTable<Consideration>,
    // …
}

A change row holds, per traced field, its new value if it changed and nothing if it did not. The diff is the least interesting code in the tracer, which I take as a point in its favour. This is the derive’s template for it, trimmed of its fully qualified paths.

fn change(&self, previous: &#frame, tick: u64) -> Option<#change> {
    let change = #change {
        tick,
        id: previous.id,
        gone: false,
        #(#idents: (self.#idents != previous.#idents)
            .then(|| Clone::clone(&self.#idents)),)*
    };
    let changed = false #(|| change.#idents.is_some())*;
    changed.then_some(change)
}

A field added to Agent is therefore traced the day it is added, with no more code. A Tracker keeps each entity’s last frame and diffs each look at it against that, so an entity seen for the first time is written whole and one seen again is written only where it differs.

pub fn seen(&mut self, id: T::Id, value: &T, tick: u64) -> Option<T::Change> {
    match self.last.get_mut(&id) {
        Some(previous) => {
            let change = value.change(previous, tick)?;
            T::apply(previous, &change);
            Some(change)
        }
        None => {
            self.last.insert(id, value.frame(id, tick));
            Some(value.whole(id, tick))
        }
    }
}

What the design left open was whether every villager and every object would be diffed on every tick, and the answer I settled on is that only what a commit touched is looked at. The object rows already carried change bits, which are now cleared as each commit begins. The villagers had nothing of the kind, so with trace on they sit behind a map that notes each one written.

#[inline]
fn touch(&mut self, id: NpcId) {
    #[cfg(feature = "trace")]
    self.touched.insert(id);
    #[cfg(not(feature = "trace"))]
    let _ = id;
}

pub fn get_mut(&mut self, id: &NpcId) -> Option<&mut Agent> {
    if self.map.contains_key(id) {
        self.touch(*id);
    }
    self.map.get_mut(id)
}

Reading goes straight through to the map, and with trace off nothing is noted at all. Two pieces of an object’s state live outside its row (a heat source’s warmth, and who has reserved which of its stations), and for those the recorder simply compares what the town holds with what it last saw.

A keyframe of every traced row is written at tick 0 and at each in-game day. The traced state at any tick is then the last keyframe with the changes since applied, which the tool can work out with no simulation at all.

Recording only reads

The recorder is a driver wrapped around the run’s own. As each tick begins it reads what the ticks before it logged and what the last commit touched, hands the rows on and passes the tick through unchanged. It decides nothing.

Parallel phases are where this could have gone wrong. Records emitted in a parallel phase are collected in a buffer per worker and, at the end of the tick, merged and sorted by stable ID, exactly as every other reduction in the kernel is.

let mut rows: Vec<(u64, R)> = buffers.into_iter().flat_map(|b| b.rows).collect();
rows.sort_by_key(|(id, _)| *id);
rows.into_iter().map(|(_, row)| row).collect()

The sort is a stable one, and one entity’s records are emitted by one worker in a phase, so they keep the order they were emitted in however the work was split. A run’s trace is consequently the same, byte for byte, on one thread and on all cores. cargo xtask det now runs a second time with tracing on, and must print the same state hashes as the untraced run and write the same trace both ways.

Encoded rows cross a bounded channel to a writer thread, 64 batches deep, and when the channel is full the simulation waits and no row is dropped. (I had crossbeam-channel on the list for this. std::sync::mpsc::sync_channel gives the same backpressure, so it never became a dependency.)

Because the simulation is deterministic and replays, there is no need to decide in advance which runs deserve a trace. cargo xtask trace <scenario> builds the headless client with trace on and runs the scenario again from its seed, and cargo xtask long --trace records the long scenarios as they are checked, so that a failure in one is queried and not run again. Traces are written under $EWSIM_TRACES or the system’s temporary folder, and never into the repository. Ordinary runs pay nothing.

The container

A run’s folder holds a manifest and, per table, append-only segment files of one in-game hour each.

<run>/manifest              MANIFEST_MAGIC, then the manifest's sections
<run>/<table>/<n>.seg       one segment per table per span of ticks (an in-game hour):
                            SEGMENT_MAGIC, its blocks, its footer's sections, and the
                            footer's offset as eight little-endian bytes
block                       its header's sections, then its columns, each length-prefixed
                            and zstd-compressed

A segment is a run of blocks of up to 32,768 rows, sorted by tick and then by the entity they are about, stored a column at a time, each column compressed with zstd and carrying a checksum. Its footer lists every block’s offset, tick range and key ranges, and holds roaring bitmaps from each key value — a villager, an object, an act, an event kind — to the blocks that mention it. A segment is closed, footer and all, once its hour is over, so a crash loses at most the open one.

Storing each column apart does three things at once. A column whose type a reader does not know can be skipped by its length, columns compress better alone, and a block’s columns map directly onto Arrow arrays, so that a query which names two columns decodes two columns.

The tool maps segments read-only and decodes nothing it has not been pointed at. Narrowing a question to its blocks is two filters over the footer, the first by tick range and the second by bitmap.

let holding = key.map(|(c, keys)| blocks_holding(footer, c, keys));
let wanted: Vec<usize> = (0..footer.blocks.len())
    .filter(|&b| {
        let (first, last) = footer.blocks[b].ticks;
        first <= to && last >= from
    })
    .filter(|&b| {
        holding
            .as_ref()
            .is_none_or(|h| h.contains(u32::try_from(b).unwrap_or(u32::MAX)))
    })
    .collect();

One villager’s day touches only the blocks its bitmap names, which is what makes a question about one villager cheap in a table that holds all hundred.

I did weigh Parquet as the primary format. It would have brought statistics, page indexes and bloom filters with no format of my own to keep, but it would also have put Arrow in the writer, and so in the simulation’s build, and per-entity lookups would, as far as I can tell, have been slower. It stays as an export (simtrace export --parquet) for DuckDB, Python or a spreadsheet.

The cost is that the format is mine to keep. It carries two versions, a major.minor for the container and a single number for the wire vocabulary, and the manifest, footers and block headers are all lists of tagged, length-prefixed sections that an older reader skips. The container is at 1.5 already, each of those five minor versions having added a section to the manifest (name tables, snapshots, stored views, the tables a run left out, and the pairs of tables a traced type is recorded in.) A reader reads every major version up to its own and refuses a newer one with the command that reinstalls it.

A test compares a small fixed trace’s bytes with a checked-in fixture, and fails unless the version was raised in the same commit. Record schemas have no version of their own, since the schema in the manifest is the version.

Beliefs and 509 MB

The first day of m1 that I traced in full came to 509 MB, and 475 MB of that was one table. Each villager holds beliefs, each belief has a confidence that fades continuously, and I had dutifully written a row for every fade and every refreshed sighting. belief_changes held 207 million rows for a single in-game day.

A belief change is now written only when the belief is formed or dropped, when its provenance changes, or when its confidence, salience or charge moves into another band a tenth wide.

if let Some(last) = self.beliefs.last(&id) {
    let now = Minute::from_tick(kernel::num::Tick::new(tick));
    let is = Banded::of(&state.frame(id, tick), now, self.bands);
    if Banded::of(last, now, self.bands) == is {
        return None;
    }
}
self.beliefs.seen(id, state, tick)

The belief as last written and the belief as it stands are compared at the same minute, since a fading value read at two different minutes would differ by construction. Keyframes stay whole and exact, so between them a belief is known to its band, and at each of them exactly. The width of a band is content (trace_band, beside the rest of the memory rules), so it can be narrowed for a run that needs it.

Beliefs are also recorded only when asked for, with --beliefs. A day of m1 is now about 36 MB without them and 53 MB with them. A trace without them says so in its manifest, with the reason, and a query that reads a belief table is given that reason in lieu of an empty answer. The claims the beliefs are about, and the provenance of each, are small and are always recorded.

Decisions and calls

The decisions table holds every think — the goal chosen, its score, the roll, the plan found, and the five best choices passed over with why each lost.

pub enum Lost {
    /// The thinker kept the plan it had.
    Kept,
    /// It was among those weighed by the roll, and the roll fell elsewhere.
    Roll,
    /// It scored below those the roll weighed.
    Lower,
}

The rows are built from the same planner steps that sim-cli trace shows when it explains a single think live, and a test holds simtrace why to what that command says of the same thinks. I believe that is the only way two tools explaining one decision stay in agreement. Five was a choice (how much of each think to keep was an open question for a while), and the whole list is still to be had by replay, as described further down.

Not every think weighs anything. A villager who is spoken to hears the speaker out, and one with a step of its plan under way simply goes on with it, and both are recorded as such, so that every think acted on says what the villager was about. A villager may also think ahead, for a tick that has not yet come. Such a think is held back and written only once its fate is known, which is to say acted on at its tick, or given up because the villager thought again first.

For seeing inside the commit side there is an attribute, which is on exactly five methods so far — use_act, walk, take, put_down and errand_at.

#[cfg_attr(feature = "trace", tracer::instrument(who, object))]
fn take(&mut self, who: NpcId, object: ObjectId, fx: &mut Effects<'_, Town>) {
    // …
}

With recording on, the method becomes a wrapper around itself that writes a row to the calls table, with the tick, the arguments it names, and what it returned as debug text. The first named argument indexes the row if it can be a key. With recording off the attribute expands to the method exactly as written.

SQL over the segments

simtrace sql is DataFusion over the trace’s tables. My first version read each table a query named whole into Arrow record batches and registered the result, which was an eminently reasonable way to query a test fixture and no way at all to query 207 million rows.

The second made each table a TableProvider that decodes only the columns a query projects and only the blocks its predicates leave. Comparisons with the tick, and a key given by its number or by its name, are answered from the footers and bitmaps before any block is decoded.

Ok(filters
    .iter()
    .map(|f| match self.parts.iter().any(|p| usable(&p.schema, f)) {
        // The footers and bitmaps narrow the blocks read; the predicate is checked
        // again on the rows.
        true => TableProviderFilterPushDown::Inexact,
        false => TableProviderFilterPushDown::Unsupported,
    })
    .collect())

Reporting them as inexact means that DataFusion checks every predicate again on the rows, so narrowing never changes an answer. The third version made each segment a partition of the scan, read a block at a time, so segments are read in parallel and a scan of any size holds a few blocks at once.

Columns are mapped from the trace’s wire types and never from the simulation’s. A fixed-point number is a decimal, a tick is an integer that the table output shows as day 2, 07:30:05.3, and an enum whose variants carry payloads is a struct, so that event['ErrandDone']['finished'] works. IDs are shown as the names the run gave them at the row’s tick, with the number in a column beside them, so baker (npc:22) is also who_id = 22.

Firings a day by hearth, which is the probe at the top of this post and once cost a week of simulation, is now this.

simtrace sql run "SELECT object, tick / 864000 + 1 AS day, count(*)
                  FROM events WHERE act = 'fire'
                  GROUP BY 1, 2 ORDER BY 2, 3 DESC"

Several runs can be named in one query, in which case each table is the union of their columns by name, with nulls where a run lacks a column and a run column in front. A field added between two builds does not stop a comparison of their runs.

DataFusion was not the only candidate. SQLite virtual tables over the segments would have been complete, familiar and small, but row by row, so whole-run aggregates would have been slow. DuckDB has the best ergonomics of the lot and a large C++ build, and anyone who wants it can point it at an exported Parquet table.

Views the trace carries

The canned commands are not code in the tool.

simtrace agent m1 22 --from 864000 --to 1728000
simtrace why m1 22 1300000
simtrace object m1 310
simtrace seq m1 bake-given-up

Each is a SQL view with named parameters, written in the simulation beside the record types it reads and stored in the manifest when a run is recorded. The tool runs the view its trace carries, so a command means what the recording build meant by it, irrespective of how old the tool is, and the tool holds no table or column name of its own (a test over its source holds it to that.)

The probes became views as well. This is the one that counts fill-up errands by villager.

View::new(
    "fillings",
    "fill-up errands begun, done and given up, by who",
    "SELECT who, \
            sum(CASE WHEN name = 'errand at' AND event['ErrandAt']['stage'] = 0 \
                     THEN 1 ELSE 0 END) AS begun, \
            sum(CASE WHEN name = 'errand done' AND event['ErrandDone']['finished'] \
                     THEN 1 ELSE 0 END) AS done, \
            sum(CASE WHEN name = 'gave up' THEN 1 ELSE 0 END) AS given_up \
     FROM events WHERE act = 'fill up' AND name IN ('errand at', 'errand done', 'gave up') \
     GROUP BY who ORDER BY done DESC, who",
)

There are six of them — hearths, fillings, coin, minutes, starved and failed-reports — and they answer, from one trace, the questions the probes answered by running m1 again. A view that a trace lacks is reported as such, with the views it does have, and simtrace sql is still there for everything else.

The world at a tick

simtrace at <run> <tick> gives the traced state at a tick from the last keyframe and the changes since, with no simulation involved. What is not traced — random streams, caches — cannot be had that way, and for it there is --exact.

Beside each keyframe the recorder writes a snapshot of the whole world in the kernel’s own format. simtrace at --exact replays the day’s snapshot to the tick with the build that recorded the run, and gives the state hash after that tick’s commit and, if asked, one villager’s whole state. simtrace why --all gets every term of a think by the same replay, where the trace itself keeps only the best five.

The manifest names the commit that recorded the run. The tool builds that commit’s headless client in a git worktree on first use, says that it is doing so, and keeps it in a cache of the two builds last used (a build is large.) A run recorded from a working tree with uncommitted changes is no commit, and the tool declines to replay it. Nothing else in the tool needs the recording build.

Running all of this on m1 for the first time found three things to fix. simtrace at now rebuilds from the changes alone when asked for a tick before any keyframe has rows (no belief is held as the village begins), CSV output writes a nested column as text, and the build cache gives its client the snapshot’s whole path.

Anyway, thanks for reading!

bree’s blog