Here’s a not-so-brief story about troubleshooting a problem that was at times vexing, impossible, incredibly challenging, frustrating, and all around just a terrible time with the bare-metal STM32G4 firmware for the moteus brushless motor controller.
Background
First, some things for context:
moteus has a variety of testing done on every firmware release. There are unit tests that run with pieces of the firmware compiled to run in a host environment. There is a hardware-in-the-loop dynamometer test fixture that is used to run a separate battery of tests. There is also an end-of-line test fixture that is used to run tests on every board and some other firmware level performance tests.
Because of all that testing, we’re pretty confident to release new firmware images once all the tests have passed, and try to ship out boards with firmware that is within a week or two of the newest on all boards and devices that go out the door. That said, there is some effort made to ensure that large orders all have the same firmware on them. Thus, my saga started when I went to re-program a few dozen boards using the end-of-line test fixture so that they could all match the most recent version.
The first symptom
When I went to re-program them, a large portion of the boards failed tests surrounding the quality of the current sense measurements, indicating there was too much noise in the current sense measurements, specifically when driving 0 current. That could mean that there were soldering problems on the board, or that the test fixture had corroded contacts, or potentially firmware issues. In response, the test fixture got its contacts cleaned very thoroughly, I verified this was happening across many boards all of which had passed earlier, and there were only 3 changesets that affected the firmware in any way, all of which seemed pretty innocuous.
Once I had given up on the problem being a fluke, I opened up tview on the end-of-line fixture and sure enough, wow, there was a problem:
Note how the values of servo_stats.adc_cur3_raw seem to bounce between what looks like their true value and 2048. I have seen problems like this before, related to ADC configuration and clock rate (as – have – others), but absolutely nothing about the ADC configuration has changed in more than a year, so surely that can’t be it, can it?
The first diagnostic step
So, first things first. Now that I can observe a problem, is it reproducible. I used git bisect across the relevant firmware versions, and sure enough, one of the changes was positively correlated with the problem: 64f2a82575795d782ff3806ea2036f4cd2f02ef0 However, that change does absolutely nothing with the ADCs or the current sense pipeline, or the STM32 register configuration at all. So, I tried to create a more minimal version of that change which would still trigger the problem. What I got was this:
diff --git a/fw/bldc_servo_structs.h b/fw/bldc_servo_structs.h
index abbe26e..f06c16c 100644
--- a/fw/bldc_servo_structs.h
+++ b/fw/bldc_servo_structs.h
@@ -509,7 +509,7 @@ struct BldcServoConfig {
// debug UART at full control rate.
uint32_t emit_debug = 0;
- uint32_t field1;
+ uint32_t field1 = 0;
BldcServoConfig() {
pid_dq.kp = 0.005f;
So, adding the initialization of a member in a random structure (the one that holds PID gains among others), triggered the issue. If the initialization was only of a uint8_t or uint16_t, no problem, but a uint32_t, float, or uint64_t did it.
Well, “that’s odd”.
Clearly that change shouldn’t have any impact, so if the problem is at the C++ level, it must be undefined behavior somewhere else, and if it isn’t at the C++ level, it could be anywhere. So, my next step was to look at the difference in the disassembly to see what that code change wrought that the STM32 would see.
This is from “meld”, with a set of custom filters to remove most spurious changes related to addresses changing. But yikes, that one extra initialization results in a *lot* of churn in the assembly. If we look at the structure constructor, the change we expect is there in that we can see that the field is getting newly initialized.
However, with “-O3” optimizations on, gcc-11 makes all kinds of different decisions at various points. Instructions are re-ordered, different registers are used, entire blocks of code are re-ordered in their memory layout and execution, and extra padding is added or removed. There are many changes, any of which could be interacting with whatever undefined behavior is in the system.
Taking a step back
Since looking at the disassembly wasn’t going to be easy, I decided to take a step back and see if I could observe what was different in the system when it was running between the good and not-good states. Most likely some peripheral was configured incorrectly, with the ADCs being a prime candidate, but the clock tree could also be a culprit.
When debugging STM32s, I sometimes use the PyCortexMDebug project, which lets gdb use the vendor provided SVDs to interpret the contents of all registers. Here, I wanted to print out every register on every peripheral just to see what was different. PycortexMDebug doesn’t natively give you a way to do that. However, it can list all the peripherals it knows about, which I wrote to a file and pre-processed to remove the human level annotation. Then using gdb’s “python-interactive” mode, I could do a:
python-interactive
> regs = [x.strip() for x in open('/tmp/all_regs.txt').readlines()']
> for reg in regs:
> gdb.execute('svd/x ' + reg)
Which did the trick — at least after copy and pasting the output from the terminal. I didn’t bother figuring out how to get it written to a file. So, now, I have two giant files with every peripheral register, one from a firmware that was working, and one from a firmware that was exhibiting the extra noise. I went through them line by line and found…. nothing.
Some registers were different of course, but the only ones were timer values, and data registers on the ADC and SPI peripherals, and the system control block depending upon if the code happened to be in an interrupt when I stopped to sample it. No configuration values or anything that would point to a problem. Sigh.
More backing up
OK. So maybe there is a peripheral register that isn’t in the SVD that would correlate with the problem? My next step was to use gdb to dump the entire peripheral address space to an srec file in both cases.
dump srec memory /tmp/out.srec 0x40000000 0x51000000
Note, this does take a *long* time, at least 15 minutes with the hardware I was using.
What did I earn for my hard earned wait? Bupkis, nothing, nada, squat. After looking through every single byte that was different, the only ones that had changed were the same ones that the svd method above turned up, plus a bit of random noise in the “reserved” section between peripherals that looked like genuine bus noise. Notably, not any configuration registers on any peripheral at all.
Even more backing up
OK. So if the problem isn’t in a peripheral register, maybe there is some difference in program state that is causing the problem? Maybe a stack overflow or something? So, I switched to SRAM dumps. First, I modified my startup assembly to start out with guard bytes across all of SRAM so that I could verify the stack hadn’t overflowed (not even close). I also used that to verify that the code which was copied into CCM SRAM on startup hadn’t overflowed or been stomped on (it hadn’t). Next I did a diff between the working and non-working states.
Here, there were a lot more differences as the firmware has a lot of state that varies from run to run. With the structure of the moteus firmware, most storage ends up being allocated on the C/C++ stack from a fixed size pool. This means that most of the variables don’t have a useful entry in the symbol table, even though their address is consistent from run to run. To identify what each change was, I started the firmware afresh with a breakpoint on _start, then added a hardware watchpoint on the address of interest.
b _start
run
watch *0x20004560 # (for example)
continue (as many times as necessary)
And then looked to see what modified that particular memory location to determine what it was doing. I methodically went through every difference, about 50 of them. I found things like the buffer used to hold CAN-FD frames, timers, nonce counters, the values read by the position sensor and current sensor, and many other things that all seemed perfectly reasonable.
Yet another approach doomed to give no useful information.
Back to an earlier approach
Whatever the problem was, it appeared to be in state on the STM32 that was not accessible to mere mortals. Probably a peripheral got into a bad state that wasn’t exposed via its registers or something. If I couldn’t find the state that was different, could I at least make a “minimal code difference” which was actually minimal?
My C++ minimal difference was pretty small, just the addition of an “=0” to a field initializer. However, that resulted in significant changes in the output program. To make things a little bit more controllable, I tried adding some __asm__("nop") entries to the constructor in question and sure enough, some counts of NOPs would trigger the problem and others wouldn’t. However, they still resulted in large differences in the output.
So then I undertook the painstaking step of gradually turning off optimizations in each function that I saw had changed. In some cases it was as easy as sticking a __attribute__((optimize("O1"))) on the definition. However, in many cases gcc/C++ requires the inline definitions be pulled out-of-line to make that annotation. Both because of that, and just because of bad luck, often these changes would result in my “nop” trick no longer triggering a failure. I worked methodically though, trying new functions until I was eventually able to make a minimal assembly diff that failed.
diff --git a/fw/bldc_servo_structs.h b/fw/bldc_servo_structs.h
index 95db9fe..8916d4e 100644
--- a/fw/bldc_servo_structs.h
+++ b/fw/bldc_servo_structs.h
@@ -533,6 +533,11 @@ struct BldcServoConfig {
pid_position.ilimit = 0.0f;
pid_position.kd = 0.05f;
pid_position.sign = -1.0f;
+
+ asm volatile (
+ "nop;"
+ "nop;"
+ );
}
template <typename Archive>
And the assembly diff is solely:
Solely the addition of the 2 nops!
WTF!
As before, I’m using the same regexes with meld to exclude spurious changes related to addresses and literals. The exact set of expressions is below:
asm_address ^.{20}
stm32_pc 08[0-9a-f]{6}
stm32_pc2 (80[012345][0-9a-f]{4})
stm32_addr \+0x[0-9a-f]+>
stm32_literal #[0-9]{2,5}
Trying to understand this a bit more
So far we have learned that simply adding two NOPs to one function that is totally unrelated to the problem in question causes the ADC to become noisy in an odd way. I tried some experimenting to learn more about the failure.
What does adding more NOPs do? The answer… 1 or 2 NOPs fails, 3 or 4 NOPs works, 5 or 6 fails, etc.
Hmmm…. my current top two theories are that either a) it is the instruction layout or b) the execution timing that results in the difference. To rule out one or the other, I made up a series of 8 NOPs, and then substituted a jump in for the first NOP that skipped to one of the later NOPs. That way I could adjust the execution cycle time of the relevant function one by one without changing any layout. That had no effect. Which meant it must have to be the physical layout of the code, not the timing.
The grind
At this point, I undertook what was perhaps the most arduous debugging task yet. To figure out which code was unhappy about having its instruction address changed, I bisected adding NOPs. This wasn’t super straightforward, because as mentioned, gcc’s optimizations generally mean that adding a NOP to a random function results in all kinds of changes all over the place. My procedure was roughly like this:
- Identify where in the address space I wanted to add a NOP.
- Find a nearby function that was written by me, and not a template expansion or library function.
- Switch it to be O1/O0
- See if I can still trigger the problem at any of my former test points by adding NOPs (turning off optimizations on the one function sometimes re-ordered everything)
- If I can’t, then pick a different function and go back to 1
- If I can, then bisect over all my current test points (which may be in a different order than the last bisection) to find the latest address space point where I can add a NOP to trigger the problem
While brutal, I figured this was sure to result in finding the culprit.
And sure enough, after about 15 steps, each taking around 5-10 minutes, it did. I thought the following two lines were the culprit:
ADC12_COMMON->CCR =
(map_adc_prescale(kAdcPrescale) << ADC_CCR_PRESC_Pos) |
(1 << ADC_CCR_DUAL_Pos); // dual mode, regular + injected
ADC345_COMMON->CCR =
(map_adc_prescale(kAdcPrescale) << ADC_CCR_PRESC_Pos) |
(1 << ADC_CCR_DUAL_Pos); // dual mode, regular + injected
The two lines that configure the ADC prescaler! But, wait, didn’t we verify that the ADC prescaler as read from the peripheral registers was the same in both instances? Why yes, we certainly did.
Working:
(gdb) svd/x ADC12_COMMON
Registers in ADC12_Common:
CSR: 0x000A000A ADC Common status register
CCR: 0x000C0001 ADC common control register
CDR: 0x00000000 ADC common regular data register for dual and triple modes
(gdb) svd/x ADC345_COMMON
Registers in ADC345_Common:
CSR: 0x000A000A ADC Common status register
CCR: 0x000C0001 ADC common control register
CDR: 0x05250000 ADC common regular data register for dual and triple modes
Not working:
(gdb) svd/x ADC12_COMMON
Registers in ADC12_Common:
CSR: 0x000A000A ADC Common status register
CCR: 0x000C0001 ADC common control register
CDR: 0x00000000 ADC common regular data register for dual and triple modes
(gdb) svd/x ADC345_COMMON
Registers in ADC345_Common:
CSR: 0x000A000A ADC Common status register
CCR: 0x000C0001 ADC common control register
CDR: 0x05270002 ADC common regular data register for dual and triple modes
For good measure, I tested using stepi to walk through the initialization in the bad state to see if it was somehow related to wall clock timing, but that didn’t make a difference.
Narrowing things down
To avoid the “flavor-of-the-day” the gcc optimizer gives you and make my life easier for experimenting, I rewrote those two lines in inline assembler, just hard-coding the required CCR value:
asm volatile(
"str %2, [%0];"
"str %2, [%1];"
:
: "r" (&ADC12_COMMON->CCR),
"r" (&ADC345_COMMON->CCR),
"r" (0x000C0001)
);
I added in NOPs before, in between, and after the two stores. To my surprise, in all 3 places failures could be induced, but only on every 4th NOP. Which meant my identification of these two lines was incorrect.
Thus, false alarm. I kept moving down the function, replacing sections with inline assembler and then bisecting with NOPs until I reached the following section:
ADC1->CR |= ADC_CR_ADEN;
ADC2->CR |= ADC_CR_ADEN;
ADC3->CR |= ADC_CR_ADEN;
ADC4->CR |= ADC_CR_ADEN;
ADC5->CR |= ADC_CR_ADEN;
Here, all 5 ADCs are turned on in rapid succession after previously having all their pre-requisite startup operations and delays performed. NOPs placed before this could cause the ADCs to get into the bad state, but NOPs immediately after did not. Placing NOPs between them always seemed to make the following sections work without problem. Once I had at least 3 NOPs between each, then no amount of change above could cause a failure.
Finally, a decent hypothesis and solution
It seems that the ADCs on the STM32G4 do not like to be turned on in rapid succession, and if they do, bad things can happen like having the prescaler flipped to a different value without it showing in the corresponding register. In this case, the flash accelerator was probably delaying the initialization when the ADEN sets happened such that they crossed a fetch boundary. Then when two of them ended up in the same pre-fetch block, they would get turned on too quickly together. Maybe it causes a local brownout or something? Somewhat recently I upgraded to gcc-11, which probably did a better job of packing these enables into a smaller amount of code space.
I guess that’s an errata for you.
With that understanding, a solution is trivial. Just initialize the ADCs one by one instead of all at once. The initialization sequence for the ADC is documented as requiring a wait until the ADRDY flag is set, so the fix is just to wait for that for each ADC in turn before enabling the next one. For good measure, since initialization isn’t time critical, I switched the whole process to be serial for each ADC, as I expect that is the more tested path with the hardware.
What is the lesson? Hardware is hard? Persistence pays off? I guess you can decide!
As a bonus, now that I know one of the prime symptoms to look for to troubleshoot bad prescalers (unusual bit flips around 2048), I discovered that I could get a bit more performance around the 0 current point by increasing the moteus prescalers a bit (75df013).
A Modicum of Fun 