A flight recorder for firmware

The problem

The failures that cost me the most time on this console share a shape. The picture judders or freezes; the firmware reports nothing wrong. The emulator counts 60 frames a second, the wire counts every record sent, the error counters hold zero, and the monitor disagrees with all of them. Two earlier posts document hunts of exactly this shape: the heap that only sometimes existed and the week I spent optimising an innocent chip. Each took days, and each was won by manually shrinking a search space until the answer became visible.

The instrumentation I own explains why the hunts take days. This is a bare-metal fantasy console on a Nucleo-H753ZI that emulates game consoles and streams video over a few-MHz link to an RP2350, which scans out HDMI. The link runs one way, so the transmitter never learns what the receiver saw. The telemetry prints one summary line per second, and a one-second average hides a 40-microsecond spike completely. Attaching more logging costs time on a slow debug transport and moves the timing of the code under study. For timing-sensitive failures, that last property means the act of looking changes the evidence.

What I wanted for those weeks: capture the same workload twice, once on a build that works and once on a build that fails, then have a tool align the two captures and report the earliest difference that matters. The flight recorder framing fits, so that is the working name.

What was investigated first

Before writing anything I spent a day establishing what already exists, because most of this idea is old. SystemView and Tracealyzer have recorded fixed-size events into target RAM for a decade at sub-microsecond cost per event; whatever I built had to match that overhead class. Lauterbach's trace tooling reconstructs and navigates one recording. rr records and replays entire desktop processes. The closest system to my goal is Gist, a research tool that computes the difference between failing and successful runs and ranks suspect statements; it requires Intel PT and an x86 host. I found no tool that performs two-run comparison for a microcontroller over a commodity debug probe. That told me where the new work is: the comparison layer. The recording layer should stay conventional, and did.

The recorder

One event is 16 fixed bytes: a cycle-counter timestamp, an event id, a flags word, and two arguments whose meaning depends on the id.

I evaluated variable-length encodings and rejected them on arithmetic. The instrumented paths produce at most about 25 events per frame at 60 frames a second, or 24 KB/s; saving a third of that buys nothing. The fixed size buys a hot path of one atomic reservation and one 16-byte volatile write:

pub fn record(&self, cyc: u32, id: u16, flags: u16, a0: u32, a1: u32) -> bool {
    if self.state.load(Relaxed) != STATE_ARMED {
        return false;               // disarmed: one load and a branch
    }
    let slot = self.next.fetch_add(1, Relaxed);
    if (slot as usize) >= N {
        self.drops.fetch_add(1, Relaxed);
        if slot as usize == N {
            self.state.store(STATE_DONE, Release); // window closes itself
        }
        return false;
    }
    unsafe {
        write_volatile((self.entries.get() as *mut Event).add(slot as usize),
                       Event { cyc, id, flags, arg0: a0, arg1: a1 });
    }
    true
}

Three execution contexts touch the instrumented code: the thread-mode main loop, the audio interrupt executor, and the video-link interrupt executor. The fetch_add reservation makes concurrent recording safe from all three without a lock, since no two writers can receive the same slot. Two bits of the flags word record the writing context. The comparison stage needs that: two events swapping order across an interrupt boundary is scheduling noise, while the same swap within one context is a real reordering.

The buffer holds 8192 events (131,072 bytes of otherwise idle SRAM) and never wraps. It arms at a fixed frame number of the running game, fills once, and stops. I rejected a wrap-around ring after working through what the comparison needs: a wrapping ring retains whatever preceded the export, which aligns with nothing, while a window that always opens at frame 600 gives both runs the same slice of the same workload. At the expected event rates the window spans 5 to 11 seconds of gameplay. A full buffer ends the capture by design; within the window, every event that fired is present.

While armed, the recorder is silent on the debug link. It prints one line when it arms and one when the window closes. Export happens after the run: the firmware cleans the data cache over the buffer, then the probe reads the memory over SWD without halting the core. I measured the read at 0.29 seconds for 4 KiB including attach overhead, so a full window exports in a few seconds while the board keeps running.

The assumption that failed

With the recorder feature compiled out, every hook becomes an empty inline function, and I assumed the binary would be unchanged. I tested the assumption by diffing flashable images: the instrumented tree with the recorder stripped, against the image from before the recorder existed.

They differed. The text section had grown by exactly 8 bytes.

The cause was one hook call site that computed its argument before the empty function discarded it. The argument was a relaxed atomic load of the heap gauge, and compilers preserve atomic loads whose results go unused, so two instructions survived into a build that should have contained none. I moved the read inside the recorder module, where the stripped build never references it, and diffed again: text size now identical, with 157 scattered bytes still differing. Diffing the two disassemblies resolved those as well. Every differing byte sits in a data literal holding a source line number, shifted because the source files gained lines; the instruction streams match exactly. The claim that the hooks are free now rests on that measurement rather than on the word "inline".

Trace formats

The capture leaves the device as a 48-byte header plus the raw events, and the desktop tool seals it into a versioned file. Both layers follow the discipline of this project's crash-record format: magic, version, and a CRC computed over every byte, verified by a test that flips each byte of a valid blob and asserts the decoder rejects every mutation. The event catalogue carries its own checksum, stamped into every file; a file whose catalogue disagrees with the tool is refused with both checksums printed, because a plausible wrong decode would burn a day before anyone noticed it.

The header also records the build's identity: which allocator and which experiment flags were compiled in. The method depends on never confusing the working capture with the failing one, and bench operators eventually mislabel things, so the firmware stamps its own identity and the comparison tool refuses two traces that claim to be the same configuration.

Current output of the inspection command, against a small synthetic trace from the test suite:

rntrace inspect v1
file: schema=0xa3e4e8bd label=good git=0123456789abcdef...
device: build=0xabcdef0123456789 alloc=tlsf clock_hz=480000000 session=0x5eed0001
window: armed_frame=600 capacity=8192 writes=9 drops=0
events: 9 stored
  frame_start        3
  frame_end          3
  publish_attempt    3
frames: 600..602 (3 epochs)
span: 24791 us

Verification so far is host-side: 20 unit tests on the recorder core (including a multi-threaded producer test that asserts no slot collisions across 8000 concurrent reservations into a 4096-slot window) and 12 on the file layer, covering corruption, truncation, version and schema rejection.

Comparison rules, fixed before the comparator exists

The comparison engine is unwritten, and the order is deliberate: its rules were set down first, so the implementation cannot drift toward whatever makes its output look impressive.

Alignment will be structural. Cycle counters disagree between any two runs of real hardware, and aligning on timestamps would manufacture thousands of false differences; the anchor is the frame number both runs armed on, with order-preserving matching inside each frame. The first raw difference between two runs is usually meaningless, an interrupt arriving two cycles early or a counter nobody reads, so every difference must pass an explicit significance rule before it reaches the report. The report vocabulary is limited to observed, correlated, and consistent with. The word caused requires an intervention experiment: inject the suspected mechanism into the working build and watch the failure appear, or block it in the failing build and watch the failure stop.

The surrounding method is pre-registration. The procedure is written before the first flash; the uninstrumented baseline runs first; the instrumented baseline follows, and if recording changes the failure, that observation goes in the findings.

What the method caught on day one

The first validation target was a failure with unusual credentials: well documented, previously reproducible on demand, with a known cause to check the tool against. The uninstrumented baseline came back clean on both the working and the failing build. Hardware changes made since the original diagnosis had removed the failure's timing preconditions, and it no longer exists on the current rig.

That result cost a bench session and validated the premise in the same afternoon. A failure that lived in a timing envelope ended when the envelope moved, and no artefact anywhere in the system records that transition. Producing exactly that kind of artefact is the recorder's job.

Where things stand

Built, tested and committed: the recorder core, the firmware integration with its measured zero-cost-when-disabled property, the CRC-gated trace formats, the capture path over SWD, and the inspection tool. Missing: the comparison engine, and a validation failure that still fails. The known limitations are worth stating plainly. The recorder lives on the transmitter side, so failures whose evidence exists only in the receiver are invisible to it across the one-way link; the 32-bit cycle timestamp wraps every 8.95 seconds at 480 MHz and relies on the decoder's unwrapping; and a stop-when-full window anchored at frame 600 will miss any failure whose onset falls outside it.

Next: a recorder twin on the receiver side, writing the identical format, aimed at a documented receiver-side failure that reproduces today. That gives the comparison engine its first honest good-and-bad pair, and its first report will be the next post.