Debugging Embedded Code
Every other volume assumed the code would work. This one is about the rest of the time. Debugging firmware is harder than debugging a program on a computer, because the thing you want to inspect has no screen and stops talking the moment it breaks - so most of the work is arranging, in advance, for it to tell you what happened.
- Exactly what a printf costs, and why adding one can hide the bug
- How to log for a few stores instead of a few milliseconds
- The GDB commands that repay learning, especially watchpoints
- How a debug probe reaches a chip that has locked up completely
- How to read a HardFault: the status registers and the stacked frame
- Which questions need a logic analyser, and which need a scope
17.1 printf over UART
printf is the first debugging tool everybody reaches for, and on a chip it is the one most likely to change the thing you are measuring.
It is not free, and the cost is easy to work out exactly. A UART frame is ten bit times, so a message of N characters takes 10N bit times, whatever else is true.
message chars at 9600 at 115200 at 921600
ok\n 3 3.12 ms 0.26 ms 0.03 ms
temp=23.5C t=145233\n 20 20.83 ms 1.74 ms 0.22 ms
state=RUN adc=2048 err=0 t=145233\n 34 35.42 ms 2.95 ms 0.37 ms
That is transmission alone, before any formatting. And formatting is not free either. A printf
with %d costs a few thousand cycles in most libraries, and one with %f can cost ten times that.
That is why many embedded libraries leave floating-point support out.
What it does to a deadline
2. what that does to a 10 ms control loop
1 line per pass: 2.95 ms of 10.0 ms fits
2 lines per pass: 5.90 ms of 10.0 ms fits
3 lines per pass: 8.85 ms of 10.0 ms fits
4 lines per pass: 11.81 ms of 10.0 ms MISSES THE DEADLINE
Three lines of logging fit. The fourth does not, and the control loop starts running late. Worse,
the usual blocking printf waits for each character to go out, so the processor is stopped for the
whole time rather than merely busy.
Add printf to find a timing bug and the timing changes. The bug moves, or disappears, and comes
back when you take the logging out. Any bug that behaves differently when you observe it is a timing
bug, and that is itself useful information.
Make printf cheap
Three fixes, in order of how much they buy.
- Do not block. Push into the transmit ring buffer from Volume 13, and let the interrupt send it. The call costs a memcpy rather than milliseconds
- Raise the baud rate. 921600 costs an eighth of what 115200 does, and costs nothing else
- Do not format on the chip. Send numbers, and let the computer at the other end do the words
Better: record now, print later
The last of those leads somewhere useful. If a message is a fixed-size record rather than a string, writing one is a handful of stores, which is cheap enough to do inside an interrupt.
typedef struct {
uint32_t when; /* tick count */
uint16_t value; /* whatever the event carries */
uint8_t event;
uint8_t seq;
} record_t; /* eight bytes, and no formatting at all */
static record_t trace[TRACE_SLOTS];
static void trace_add(event_t ev, uint16_t value, uint32_t now)
{
record_t *r = &trace[trace_next & (TRACE_SLOTS - 1u)];
r->when = now;
r->value = value;
r->event = (uint8_t)ev;
r->seq = trace_seq++;
trace_next++;
}
Four stores and a mask. Then the words happen later, from the main loop or from the debugger, when nothing is time critical:
seq when event value
0 145230 ms STATE 2
1 145231 ms ADC_DONE 2048
2 145233 ms UART_RX 17
3 145240 ms OVERRUN 1
each record is 8 bytes, written with four stores
the whole buffer is 64 bytes of RAM
Sixty-four bytes of RAM buys a record of the last eight things that happened, with timestamps, costing almost nothing to write. After a fault you can read it out of RAM and see the run-up.
Leaving the trace buffer out of the release build. It is the one thing that will tell you what happened on a device in the field. Keep it, keep it small, and put it in a RAM section the start-up code does not clear.
A bug appears only when logging is switched off. What does that tell you?
Show the answer
Answer: C. Logging changes timing, and nothing else about the program. A bug that appears or vanishes with it depends on timing, which usually means a race, a missed deadline, or an interrupt arriving at an awkward moment.
17.2 GDB basics
A debugger does not run your program differently. It stops the core and reads the real registers and the real memory, which is why it answers questions logging cannot.
GDB is the one you will meet, whether directly or behind an IDE's buttons. A dozen commands cover almost everything.
| Command | Short | What it does |
|---|---|---|
break main.c:42 |
b |
stop when line 42 is reached |
break uart_send if len > 64 |
stop only when the condition holds | |
continue |
c |
run until the next stop |
next |
n |
one line, stepping over calls |
step |
s |
one line, stepping into calls |
finish |
run until this function returns | |
backtrace |
bt |
the chain of calls that got here |
print expr |
p |
evaluate and show, including struct members |
x/16xb &buf |
show 16 bytes of memory in hex | |
info registers |
i r |
every core register |
watch counter |
stop when a variable changes | |
display/i $pc |
show the next instruction at every stop |
The two that repay learning
Conditional breakpoints. Stopping every time a function is called is useless when it is called
ten thousand times. break spi_write if reg == 0x2A stops on the one call you care about.
Watchpoints. watch counter stops the moment anything writes to that variable, and tells you
what wrote to it. For memory corruption - a value changing that nothing should be changing - this is
the single most effective tool there is, and most people never learn it.
A Cortex-M has a small number of hardware watchpoint units, usually two or four. Within that limit a watchpoint costs nothing and the program runs at full speed. Ask for more than the chip has and GDB falls back to single-stepping the whole program, which is thousands of times slower. If a watchpoint makes your program crawl, that is what happened.
Debugging optimised code
Volume 15 covered why this is harder. In practice:
- "value optimised out" means the variable is in a register that has been reused; look at
info registers, or make itvolatiletemporarily - Stepping that jumps backwards and forwards is instruction reordering, not a bug
- A function missing from
backtracewas inlined -Oggives most of the optimisation with the debugging information intact
Debugging a build you will never ship. If the bug only happens at -Os, debug at -Os. Switching
to -O0 to get a tidy debugging experience often makes the bug disappear, which tells you nothing
except that it is timing or undefined behaviour.
A global counter has the wrong value and you cannot find what writes it. Which tool finds it fastest?
Show the answer
Answer: B. A watchpoint stops on any write from anywhere, including code you have not thought of. That is usually the culprit, since a buffer overrun writing over it mentions the variable nowhere.
17.3 JTAG, SWD and breakpoints
The debug hardware lives inside the chip, beside the core. It can stop the processor, read memory and set breakpoints with no code of yours running at all.
That last part is what makes it different from logging. A device that has locked up completely, with interrupts disabled and the main loop dead, can still be halted and inspected.
SWD and JTAG
5 pins: TCK TMS TDI TDO TRST
- the older standard
- several chips can be
chained on one connection
- more pins than a small
package can spare
2 pins: SWDIO SWCLK
- designed for Arm chips
- the same abilities as JTAG
for debugging one device
- what almost every small
board uses today
For a single microcontroller, SWD does everything JTAG does and costs three fewer pins. Use it unless something specific needs JTAG.
Two kinds of breakpoint
A hardware breakpoint is a comparator in the debug unit watching the address bus. A Cortex-M has a handful - often six - and they work in flash, where the code cannot be modified.
A software breakpoint replaces the instruction at that address with a BKPT, and puts the
original back when you continue. There is no limit to how many you can have, and it only works in
RAM, because flash cannot be written a byte at a time while running.
Firmware runs from flash, so your breakpoints are hardware ones and there are only a few. "Cannot
set breakpoint" usually means they are all used - clear the ones you have forgotten about with
delete.
Getting output without a UART
Two mechanisms worth knowing, because they cost no pins and very little time.
Semihosting lets printf on the chip be executed by the debugger on your computer. It needs no
UART at all. The catch is that it halts the core for each call, so it is far slower than a UART and
useless for anything timing sensitive. The program will also not run at all without a debugger
attached, which has surprised many people at a demonstration.
ITM and SWO are a trace peripheral on larger Cortex-M parts. Writing a byte to a register is a single store, and it goes out of a dedicated pin to the probe. That is fast enough to leave enabled, and is the closest thing to free logging that a microcontroller offers.
GDB refuses to set a seventh breakpoint in flash. Why?
Show the answer
Answer: A. Software breakpoints need to write to the code, which is not possible in flash while it runs. So breakpoints in flash use the debug unit's comparators, and there are only a few.
17.4 HardFault handlers
A HardFault is not a mystery. The core records why it faulted and pushes the state that caused it, and the whole of debugging one is reading those registers.
Most chips ship with a fault handler that is an infinite loop, so the symptom is a board that stops. Replacing it with one that records what happened is perhaps the highest-value hour in embedded development.
What the core pushes
Before entering the handler, the core stacks eight registers. The one that matters is the program counter: the instruction that faulted.
What the core records
Two registers say why. The Configurable Fault Status Register holds one bit per cause. The HardFault Status Register says whether a more specific fault was escalated into a HardFault because its own handler was not enabled.
1. writing through a null pointer
CFSR 0x00000082 HFSR 0x40000000
HFSR FORCED: a configurable fault escalated to HardFault
MemManage: tried to read or write a forbidden address
MMFAR 0x00000000 is the address that was refused
stacked PC 0x08000312 <- the instruction that faulted
2. reading a peripheral that is not clocked
CFSR 0x00008200 HFSR 0x40000000
BusFault: a data access failed, and BFAR says where
BFAR 0x40021000 is the address that faulted
stacked PC 0x08000488 <- the instruction that faulted
The second one is worth dwelling on, because it is the most common fault a beginner meets and the
least obvious. Touching a peripheral register before enabling that peripheral's clock is a bus
error, and BFAR holds the exact address you touched - which the reference manual will identify in
seconds.
3. calling through a corrupted function pointer
CFSR 0x00020000
UsageFault: invalid state, usually a bad function pointer
stacked PC 0x20001A44 <- the instruction that faulted
4. dividing by zero, with DIV_0_TRP enabled
CFSR 0x02000000
UsageFault: division by zero
stacked PC 0x080008A6 <- the instruction that faulted
In the third, look at the PC: 0x20001A44 is in RAM, not flash. The core was trying to execute data.
That is the signature of a corrupted function pointer or a smashed return address, and the address
alone tells you so.
Division by zero and unaligned access do not fault by default on a Cortex-M. They are enabled by two bits in the Configuration and Control Register:
SCB->CCR |= SCB_CCR_DIV_0_TRP_Msk | SCB_CCR_UNALIGN_TRP_Msk;
Without them, dividing by zero silently gives zero and an unaligned access silently works or gives rubbish. With them, both stop at the instruction responsible.
From an address to a line
The stacked PC is a number. Two ways to turn it into a line of your code:
- Look it up in the map file from Volume 09: find the largest symbol address below it
- Run
addr2line -e firmware.elf 0x08000312, which gives the file and line directly
Leaving the default fault handler as while (1);. It is the difference between a bug you diagnose
in ten minutes and one you never find. Write the handler once, record CFSR, HFSR, the fault
addresses and the stacked frame into uncleared RAM, and reuse it in every project.
A fault reports a stacked PC of 0x20000C10 on a chip with flash at 0x08000000 and RAM at 0x20000000. What does that tell you immediately?
Show the answer
Answer: D. Code lives in flash. A program counter pointing into RAM means the core jumped somewhere it should never have gone. That is a corrupted function pointer, a smashed return address, or a jump through uninitialised memory.
17.5 Logic analysers and oscilloscopes
Some bugs are not in your code at all. When the question is what the pins actually did, no amount of software will answer it.
A debugger tells you what the processor believes. A logic analyser tells you what happened on the wire, which is a different thing, and sometimes the only thing that matters.
Which instrument answers which question
| Question | Instrument |
|---|---|
| What is the program doing? | debugger |
| What did the bytes on the bus say? | logic analyser |
| Is the signal a clean square wave? | oscilloscope |
| Why does the chip reset under load? | oscilloscope, on the supply |
| How long does this function take? | toggle a pin, then either |
| Are the pull-ups missing? | oscilloscope, looking at the rise |
The split is roughly: a logic analyser answers questions about what the digital values were, and an oscilloscope answers questions about the shape of the signal.
The pin-toggle trick
The cheapest timing measurement there is, and it costs about two cycles:
void TIM2_IRQHandler(void)
{
GPIOA->BSRR = DEBUG_PIN; /* high: entering */
/* the work being measured */
GPIOA->BSRR = DEBUG_PIN << 16; /* low: leaving */
}
Now the pulse width on a scope is exactly how long the handler takes, with no effect on timing worth mentioning. Watch the gaps between pulses for the rate, and the jitter for whether something else is interrupting it.
Use the set/reset register from Volume 10 rather than |=. It is a single store, so the measurement
does not add a read-modify-write to the thing being measured, and cannot be interrupted part way.
What a logic analyser shows that nothing else does
Most cheap analysers decode protocols. Capture SPI or I2C and it shows the bytes, the addresses and the acknowledgements, alongside the raw lines. That settles arguments that can otherwise run for days:
- Is the device replying at all, or is the master talking to nobody?
- Is the address the one you think, after the shift from Volume 13?
- Did the NACK come from the device, or is nothing pulling the line down?
- Is the clock the frequency you configured?
- Is the chip select going low before the clock starts, and staying low to the end?
If the bytes are right but the device misbehaves, look at the shape. Slow rise times from a missing or oversized pull-up, ringing from a long wire, a supply that dips when a motor starts. None of these show up as wrong data on an analyser, and all of them show up immediately on a scope.
A board that resets when something switches on is nearly always a brown-out, and the supply rail is the first thing to look at rather than the last.
Reaching for instruments before thinking. Most bugs are found faster by reading the code, checking the return values you are ignoring, and asking what changed since it last worked. The instruments are for when you have a specific question that only the hardware can answer.
An I2C sensor returns zeros. A logic analyser shows the address byte going out and no acknowledgement. What does that rule out?
Show the answer
Answer: B. Nothing acknowledged the address, so the conversation never got as far as the read sequence. The remaining candidates are the address value, the wiring, the pull-ups, the device's power, and the device itself.
What you learned
- A UART frame is ten bit times, so a 34-character line costs 2.95 ms at 115200 baud
- Four such lines per pass overran a 10 ms control loop, and blocking
printfstops the loop entirely - A bug that changes when you add logging is a timing bug, which is itself a clue
- Push log output into a ring buffer, raise the baud rate, and format on the computer instead
- A fixed-size trace record costs four stores, so it can be written inside an interrupt
- Keep the trace buffer in the shipped build, in RAM the start-up code does not clear
- Conditional breakpoints and watchpoints are the two GDB features worth learning properly
- Watchpoints are free within the chip's hardware limit, and crawl beyond it
- SWD does everything JTAG does for one chip, using two pins instead of five
- Breakpoints in flash are hardware comparators, and there are only a few
- A fault handler that records CFSR, HFSR and the stacked frame is the best hour you will spend
- The stacked PC is the faulting instruction;
addr2lineturns it into a line of your code - A PC in RAM means a corrupted function pointer or return address
- Enable the divide-by-zero and unaligned traps, which are off by default
- Toggle a pin with
BSRRto measure timing with no effect on it - A logic analyser says what the values were; a scope says what shape they were
Practice
A fault handler reports CFSR = 0x00000100, HFSR = 0x40000000, and a stacked PC of 0x0800A312.
What happened, and what would you do next?
Show the solution
The value 0x00000100 is bit 8, which is IBUSERR in the BusFault byte, so the core could not
fetch an instruction. The value 0x40000000 in HFSR is FORCED, meaning the BusFault handler was
not enabled so it escalated to HardFault. That is normal, and not itself informative.
BFARVALID is not set, so BFAR holds nothing useful. That is expected for an instruction fetch
failure.
The stacked PC of 0x0800A312 is in flash, so the core was trying to execute a reasonable-looking
address. The likely causes are a jump to an address just past the end of the program, a corrupted vector
table entry, or flash that was never programmed there.
Next: run addr2line -e firmware.elf 0x0800A312. If it lands in a real function, look at what calls
it, since the fetch failing at a valid address suggests the address was reached wrongly. If it lands
outside everything, compare it against the map file to see where the program actually ends.
Your main loop must complete every 5 ms. Somebody has added logging and it now takes 12 ms. The logging must stay. What are the options, and which would you choose?
Show the solution
Make the logging not block. Push the bytes into the transmit ring buffer and return. The call becomes a copy of a few dozen bytes, and the interrupt sends them in the background. This alone usually solves it, and it is the first thing to try.
Raise the baud rate. From 115200 to 921600 divides the transmission time by eight. It costs nothing but checking that both ends can manage it, and the divisor error from Volume 13.
Send less. Trace records rather than formatted text: eight bytes instead of thirty-four, and no formatting on the chip.
Log less often. Every tenth pass, or only on change, or only when something interesting happens.
I would do the first two immediately, because they are cheap and do not change what is logged. If the loop still does not fit, move to trace records, which is a bigger change but removes the formatting cost as well as the transmission cost.
What I would not do is raise the loop period to 12 ms. The 5 ms requirement came from somewhere, and logging is not a reason to break it.
A variable config.checksum is occasionally wrong. Nothing in the code writes it except
config_load. Describe how you would find the culprit.
Show the solution
A watchpoint, which is what they are for.
watch config.checksum
continue
When anything writes to that address the program stops and GDB reports the old and new values, and
backtrace shows what was executing. Since no code mentions the variable, the write will be through
a pointer - which means the backtrace points at the real bug directly.
The likely causes, in order. An array write running past its end into the neighbouring variable. A
pointer into a struct that is one member too far. A memcpy with the wrong length. Or a stack that
has grown into the data.
If the watchpoint cannot be set because the chip's units are all used, delete the others first. If
it can be set but the program becomes unusably slow, GDB has fallen back to single-stepping, which
means the address or size was not something the hardware could watch.
Failing all that, put a canary either side of the variable, as Volume 14's guarded allocator did, and check it periodically. That narrows down when rather than where, which is still progress.
Write the fault handler you would put in every project. What does it record, and where?
Show the solution
/* In a RAM section the linker script places outside .bss, so the start-up
code does not clear it. */
typedef struct {
uint32_t magic;
uint32_t cfsr, hfsr, mmfar, bfar;
uint32_t r0, r1, r2, r3, r12, lr, pc, xpsr;
uint32_t count;
} fault_record_t;
extern fault_record_t fault_record; /* placed by the linker script */
void hard_fault_handler_c(const uint32_t *frame)
{
fault_record.magic = 0xFA017EC0u;
fault_record.cfsr = SCB->CFSR;
fault_record.hfsr = SCB->HFSR;
fault_record.mmfar = SCB->MMFAR;
fault_record.bfar = SCB->BFAR;
fault_record.r0 = frame[0]; fault_record.r1 = frame[1];
fault_record.r2 = frame[2]; fault_record.r3 = frame[3];
fault_record.r12 = frame[4]; fault_record.lr = frame[5];
fault_record.pc = frame[6]; fault_record.xpsr = frame[7];
fault_record.count++;
/* put the hardware somewhere safe, then reset */
NVIC_SystemReset();
}
The handler needs a few lines of assembly in front of it to pass the right stack pointer. The
frame may be on the main stack or the process stack, depending on which was in use. The usual
form tests bit 2 of EXC_RETURN in LR and selects MSP or PSP accordingly.
On the next start-up, check the magic value. If it matches, a fault happened: report the record over whatever interface exists, add it to a counter in flash, or light an LED. Then clear the magic.
The reset at the end is a judgement call. Resetting recovers the device and loses the live state; sitting in a loop keeps everything for a debugger but leaves the device dead. A common compromise is to loop if a debugger is attached and reset otherwise, which most cores can detect.
An SPI display works on one board and shows nothing on another, with identical firmware. The logic analyser shows the same bytes on both. Where do you look?
Show the solution
The analyser has told you something valuable: the software is not the problem. Identical bytes means the driver, the mode, the bit order and the chip select timing are all the same.
So the difference is electrical or physical.
On a scope, look at the shape of the clock. Ringing or slow edges on the longer board mean reflections or capacitance. The display may then sample at the wrong moment, even though the analyser samples at a different point and reads the data correctly.
Look at the supply. A dip when the backlight switches on can reset or confuse the display without affecting the bus.
Check the voltage levels. A 3.3 V master and a 5 V display may work on one board and not another if the thresholds are marginal.
Then check the physical. A different display revision, a connector not seated, a missing series resistor, a longer ribbon cable.
The general lesson is the one the analyser gave you for free. Proving the digital values are correct moves the whole search from software to hardware, which is worth doing early.
Interview corner
Debugging without a debugger
"How do you debug a problem you cannot reproduce on the bench?"
Show the solution
"By making the device record enough to diagnose itself, because I will not be there when it happens.
A trace buffer in RAM that survives a reset: fixed-size records, eight bytes each, written with a few stores so they are safe in an interrupt. State transitions, errors, and the interesting events. A fault handler that records CFSR, HFSR and the stacked frame into the same uncleared region. The reset reason register and a count of each kind of reset. And high-water marks for the stack and the buffers.
Then a way to read all of that back - a command over the existing interface, or a screen in a service mode.
That turns 'it fails once a week in the field' into a record of the last few seconds before it failed. Without it, you are guessing; with it, the first failure is usually enough."
HardFault
"Your board hits a HardFault. Walk me through what you do."
Show the solution
"First, read the fault registers rather than guessing. CFSR says what kind of fault: a MemManage bit, a BusFault bit, or a UsageFault bit. HFSR usually just says FORCED, which means a configurable fault escalated because its handler was not enabled - so the real information is in CFSR. If MMARVALID or BFARVALID is set, the corresponding address register holds the address that was refused.
Then the stacked frame. The core pushes eight registers, with the PC at offset 0x18 from the stack
pointer. That PC is the faulting instruction, and addr2line turns it into a file and line.
The pattern tells you a lot before you even look it up. A PC in RAM means a corrupted function pointer or return address. A BusFault with BFAR pointing at a peripheral usually means its clock was never enabled. A MemManage on address zero is a null pointer.
I would also make sure the divide-by-zero and unaligned traps are enabled, because they are off by default and without them those faults are silent."
printf
"What is wrong with debugging by printf on a microcontroller?"
Show the solution
"It changes the timing of the thing you are measuring. A 34-character line at 115200 baud is about 3 milliseconds of transmission, and a blocking implementation stops the processor for all of it. In a 10 millisecond control loop, four such lines miss the deadline. So the bug moves, or disappears, and comes back when the logging comes out.
It is still useful, and I would make it cheap before giving it up. Push into the transmit ring buffer so it does not block, raise the baud rate, and send fewer characters.
Where timing really matters I would not format on the chip at all. A trace buffer of fixed-size binary records costs a few stores, which is cheap enough for an interrupt, and the words happen later on the computer. And for pure timing questions, toggling a spare pin and watching it on a scope costs two cycles and tells you exactly how long something took."
Choosing the tool
"When would you reach for a logic analyser rather than a debugger?"
Show the solution
"When the question is what actually happened on the wires, rather than what the program thinks happened. A debugger shows me the processor's view - the value my driver believes it read. An analyser shows the bytes that really went past, with the protocol decoded.
The clearest case is a peripheral that is not responding. The analyser settles in seconds whether the address went out correctly, whether anything acknowledged, and whether the clock is the frequency I configured. Those are things the software cannot tell me, because from the software's side a device that is not there and a device that is silent look identical.
I would reach for a scope rather than an analyser when the values are right but the behaviour is wrong. Edges that are too slow, ringing, or a supply dipping under load. Those are shape problems, and an analyser samples digitally so it hides them.
Before either, though, I would read the code and check the return values being ignored. Most bugs do not need instruments."
Next, Volume 18 closes the course. A revision sheet for everything in it, thirty practice problems, twenty interview questions, ten bug hunts, and a deck of flashcards.