Debugging Embedded Rust: Article 3
The supporting code for this article lives in this GitHub repo.
The first two articles built a mental model of what a Rust build produces, then put it to work in a live debugging session: a breakpoint, a register dump, a look at memory, and a look at what optimisation does and doesn't take away from source-level debugging.
Every one of those examples watched the firmware the same way: stop the processor, look, resume. For a counter ticking round a loop, that's harmless. This article starts with a bug where that technique works perfectly, moves to one where it actively lies to you, and ends with the alternative, watching the system without ever stopping it.
Part 1: The breakpoint tells the truth
Our examples so far have behaved themselves. Time to break something.
The application is meant to toggle the user LED every 500 ms. Compile and flash it with:
cargo run -p project2-clock-bug
Flashed onto the NUCLEO-F446RE, it blinks noticeably faster than that. The firmware builds cleanly, nothing panics, and the processor is plainly still running, so this is not a crash. It's a running program doing the wrong thing.
The blinking delay depends on a clock frequency handed to the delay routine:
// The delay maths below assumes the core runs at this frequency. This is the
// value that turns out to be wrong: the delay is calibrated for 16 MHz while
// the core is actually clocked at 84 MHz, so every wait finishes too early
// and the LED blinks far faster than 500 ms.
const ASSUMED_CORE_CLOCK_HZ: u32 = 16_000_000;
// Busy-wait for `ms` milliseconds using the Cortex-M SysTick timer.
// The delay is measured in *clock cycles*, so it's only as accurate as the
// `core_clock_hz` we're told to assume.
fn delay_ms(syst: &mut SYST, ms: u32, core_clock_hz: u32) {
// SysTick's reload register (RVR) is only 24 bits, so a single countdown
// can't exceed this many cycles. Longer delays are split into chunks.
const MAX_RELOAD: u32 = 0x00FF_FFFF; // SysTick RVR is 24 bits wide
// Total cycles to wait = cycles-per-millisecond * milliseconds.
// (core_clock_hz / 1000) is cycles per ms; u64 avoids overflow on the product.
let mut remaining_cycles = (core_clock_hz / 1000) as u64 * ms as u64;
// Burn down the cycle count, one SysTick countdown at a time.
while remaining_cycles > 0 {
// Never load more than the 24-bit reload register can hold.
let chunk = remaining_cycles.min(MAX_RELOAD as u64) as u32;
syst.set_reload(chunk); // program this countdown's length
syst.clear_current(); // reset the current value and the wrap flag
syst.enable_counter(); // start counting down toward zero
while !syst.has_wrapped() {} // spin until SysTick hits zero (the actual wait)
syst.disable_counter(); // stop the timer before the next chunk
remaining_cycles -= chunk as u64; // account for the cycles just waited
}
}
// Hand the delay routine the *assumed* clock rather than the real configured
// one. This single line is the root cause the article tracks down: the value
// looks reasonable in the source, but it doesn't match the hardware.
let core_clock_hz = ASSUMED_CORE_CLOCK_HZ;
Sixteen megahertz looks entirely reasonable sitting there in the source. Reasonable and correct are not the same thing, and the whole point of this exercise is to stop trusting the former.
Rather than start editing the delay maths, we ask the debugger what the program believes the clock frequency to be. The breakpoint has to land somewhere careful: after the clock has actually been reconfigured and after core_clock_hz has been assigned. Those aren't the same line here. init_clocks runs early in main; core_clock_hz isn't set until several lines later, just before the loop. Break too early and the local doesn't exist yet, and the print gives you nonsense. The first spot where both are guaranteed done is the top of the loop body:
(gdb) break main.rs:59
(gdb) continue
(gdb) print core_clock_hz
$1 = 16000000
Is the Cortex-M actually running at 16 MHz?
We can answer that without trusting the software's own arithmetic. The HAL exposes a Clocks struct, but that's just a number the HAL computed for itself, and if the HAL's clock setup is what's wrong, its Clocks struct will be confidently wrong in exactly the same way. So we go to the source of truth: the register that actually drives the clock switch.
(gdb) x/1xw 0x40023808
0x40023808: 0x0000100a
That address is RCC_CFGR on the STM32F446RE. Decoding the bitfields is a job for the reference manual, not for us here; what matters is where the value came from. It came from the peripheral, not from the firmware's opinion of the peripheral. Decode it and it says the system clock is running at 84 MHz.
There's the mismatch, in two numbers that should have been one:
A delay calibrated for 16 MHz, running on a core clocked at 84, finishes roughly five times too early. Hence the frantic LED.
The tempting fix is to change the constant to 84_000_000. Don't. That just swaps one hand-typed number for another, and it'll be wrong again the moment someone retunes the PLL. The real value was already in the program the whole time: init_clocks returns a Clocks struct, and we were even reading clocks.sysclk().raw() from it, into a variable annotated #[allow(unused_variables)] because nothing used it. The fix is to use it:
// Before: the delay runs on a hand-typed constant that stopped matching
// the hardware the moment init_clocks reprogrammed SYSCLK to 84 MHz.
#[allow(unused_variables)]
let core_clock_hz = ASSUMED_CORE_CLOCK_HZ;
loop {
led.toggle();
delay_ms(&mut syst, 500, core_clock_hz);
}
// After: the delay runs on the frequency the HAL actually configured,
// so there is no second copy of the number left to drift out of sync.
loop {
led.toggle();
delay_ms(&mut syst, 500, clocks.sysclk().raw());
}
With that change, ASSUMED_CORE_CLOCK_HZ and both #[allow(unused_variables)] attributes can go; they only existed to keep the compiler quiet about a value that was wrong and a value that was right but ignored. The delay is now correct at 16 MHz, 84 MHz, or whatever the PLL is set to later, without anyone touching the delay code.
The habit to take from this is smaller than the bug, and more useful:
Don't adjust the constant until the symptom goes away. Check the assumption that produced the constant.
Nudging the delay value until the LED looked about right would have "fixed" it and left the real defect in place; the firmware would still believe in a 16 MHz clock, and that belief would resurface in every UART baud rate, timer period, and protocol delay derived from the same configuration. The debugger let us trade "the LED is too fast" for "the delay uses a clock frequency that doesn't match the configured system clock," and only the second of those is a cause.
That whole investigation worked because the bug didn't care about time. The clock was misconfigured whether or not a debugger was attached; halting the core to read core_clock_hz couldn't have altered the answer. The breakpoint stopped the world, we looked, and what we saw was true. Not every bug is so accommodating.
Part 2: The breakpoint lies
Suppose the same firmware runs a small watchdog. A hardware timer, TIM6, fires every 10 ms. The main loop is supposed to set a flag, TICK_SERVICED, once per iteration to prove it's keeping up. On each tick the interrupt clears that flag and looks at what it held a moment before: if it was already false, the main loop hasn't been round since the last tick, so MISSED_DEADLINE goes up. Enough missed deadlines and the firmware decides it's stalled and does something about it.
#[interrupt]
fn TIM6_DAC() {
cortex_m::interrupt::free(|cs| {
if let Some(tim6) = TIM6.borrow(cs).borrow_mut().as_mut() {
tim6.clear_flags(Flag::Update);
}
});
if !TICK_SERVICED.swap(false, Ordering::AcqRel) {
MISSED_DEADLINE.fetch_add(1, Ordering::Relaxed);
}
}
Two details in there earn their keep before we go further. The critical section guards the TIM6 handle, which main also needs in order to start and configure the timer; sharing a peripheral across normal and interrupt context is what the Mutex<RefCell<Option<_>>> dance is for. And TICK_SERVICED is cleared with a single atomic swap rather than a read followed by a write, so "what was it?" and "reset it" happen as one indivisible step the main loop can't slip inside.
In action, the symptom is an occasional false alarm: MISSED_DEADLINE is non-zero when nothing, as far as anyone can tell, was ever actually late. So we reach for the tool that just cracked Part 1, and drop a breakpoint in the main loop to watch the counter across a halt.
To inspect state at a single instant we need to halt the core, so we're back on the GDB/OpenOCD path from Part 1. Build this firmware and start OpenOCD against it:
cargo build -p project3-tim6-deadline
openocd -f openocd.cfg
In a separate terminal, attach GDB:
gdb-multiarch -x .gdbinit target/thumbv7em-none-eabihf/debug/project3-tim6-deadline
The .gdbinit drops us at a breakpoint on main, halted before the loop has started and before TIM6 is armed, so the first thing to do is let the firmware get going. A continue runs it into the loop; a couple of seconds later, Ctrl-C halts it again, now with the timer live:
(gdb) continue
^C
Program received signal SIGINT, Interrupt.
With the core stopped mid-run, force a clean starting point. MISSED_DEADLINE and TICK_SERVICED are atomics, and in the debugger an AtomicU32 isn't a bare integer, it's a small nest of wrappers, so the value lives at .v.value.0:
(gdb) set var project3_tim6_deadline::MISSED_DEADLINE.v.value.0 = 0
(gdb) set var project3_tim6_deadline::TICK_SERVICED.v.value.0 = 0
Now read TIM6's count register straight from memory, at 0x4000_1024. We read it, wait five real seconds without resuming the core, and read it again:
(gdb) x/1xw 0x40001024
0x40001024: 0x00003f76
(gdb) x/1xw 0x40001024
0x40001024: 0x0000a3a0
The core executed nothing between those two reads, and the counter still moved by tens of thousands. TIM6 is a peripheral, not part of the Cortex-M core, and the STM32's debug-freeze default (DBGMCU_APB1_FZ) leaves it running when a breakpoint stops the CPU. So for five seconds the timer kept firing its 10 ms interrupt into a core that couldn't answer, roughly 500 deadlines with nobody home to deal with them. Every instinct says MISSED_DEADLINE should now be in the hundreds. Resume, halt again, and read it:
(gdb) continue
^C
(gdb) print project3_tim6_deadline::MISSED_DEADLINE.v.value.0
We get one... Not a few hundred. One, every time you run it.
The counter isn't broken; the NVIC is behaving exactly as designed, and the design is the surprise. A Cortex-M interrupt has a single pending bit per line, not a queue. While the core sat halted, TIM6 re-asserted its interrupt every 10 ms, and each assertion set a bit that was already set. Five hundred assertions, one bit, no accumulation. On resume the handler runs once, services what it finds, and the roughly five hundred periods that elapsed leave exactly the trace a single pending interrupt leaves: one.
The wrong intuition is a very natural one: N periods went by, so there should be N events. What the hardware actually promises is at most one pending invocation per line, however many times it re-triggered while nothing could service it. The breakpoint didn't uncover a real missed-deadline bug. It produced a single, perfectly reproducible false positive that exists only because we stopped to look; the act of measuring moved the reading.
The catch is: the instrument was capable of changing the thing it measured. Halting the CPU is a real event with real consequences for everything on the board that keeps running without it, and here it turned a "did anything go wrong?" signal from 0 into 1 without a single genuine deadline ever being missed. Which leaves an obvious question unanswered: if the breakpoint can't be trusted here, what does this firmware do when we leave it alone?
Part 3: Watching without stopping
To answer that, we need to read MISSED_DEADLINE without halting the core at all, and in embedded Rust the usual tool for that is defmt. Instead of stopping to inspect, the firmware logs:
defmt::info!("missed_deadline = {}", MISSED_DEADLINE.load(Ordering::Relaxed));
Two pieces are worth holding apart in your head:
defmt is the encoding, not the pipe. It defines a compact log format; the transport decides how the bytes get off the chip, and RTT is the common choice with probe-rs. With probe-rs set as the Cargo runner, the whole thing collapses into cargo run: build, flash, start, and watch the log stream into the same terminal, all without asking the core to stop once.
cargo run -p project3-tim6-deadline
The firmware arms TIM6 and then reports the counter periodically, while the loop runs completely undisturbed:
37.098035 [INFO ] project3: TIM6 armed, 10ms deadline monitoring live (project3_tim6_deadline src/main.rs:68)
38.886917 [INFO ] missed_deadline = 0 (project3_tim6_deadline src/main.rs:81)
40.675877 [INFO ] missed_deadline = 0 (project3_tim6_deadline src/main.rs:81)
42.464836 [INFO ] missed_deadline = 0 (project3_tim6_deadline src/main.rs:81)
...
Flat zero, and it stays there for as long as you feel like watching it. The main loop's simulated work sits comfortably inside the 10 ms budget, so it sets TICK_SERVICED many times between ticks and the ISR always finds the flag already true. Nothing is late. The only "missed" deadline in the whole exercise was the one we manufactured in Part 2 by freezing the core, and here it simply never appears; the running system was healthy all along.
None of this makes logging free. A log call is still instructions and still bytes leaving the chip, and lean hard enough on it and you can shift the timing you were trying to observe; the observer effect doesn't vanish, it just shrinks.
So the two ways of watching answer two different questions:
Neither wins outright. A breakpoint is the right call when you need the precise state of the machine at one instant, and Part 1 is exactly that case: a value frozen in memory, read at leisure, true when you read it. Logging is the right call when you need to know what happened over time while the system kept running, which is where the breakpoint failed in Part 2. The more a bug depends on timing, the more that choice matters, and getting it wrong doesn't simply fail to answer the question. It can hand you a wrong answer indistinguishable from a right one.
Where we go next
All three parts started in the same place: a symptom, an assumption in the source, and a piece of live target state to check the second against the first. All ended on the same rule: find out what the running system is actually doing before you trust any story about why.
What changed was the instrument, and whether it could be trusted. On a clock misconfiguration that didn't care whether the CPU was moving, the breakpoint gave a clean, exact answer. On a deadline check that cared enormously, the same breakpoint gave a reproducible, but also wrong one; only logging the untouched system showed the truth.
The articles ahead push into the cases where this bites hardest: reading a Cortex-M fault down to the exact faulting instruction, chasing stack corruption that shows up thousands of instructions after the real damage, and untangling interrupt and concurrency bugs where the processor never technically crashed at all.
This article was written by Dr David Cabanis, principal member technical staff at Doulos and author of the book Embedded Software with Rust.
