Measuring Blackbox logging overhead and looptime variation

If you want the absolute fastest looptime possible on Cleanflight, you need to be aware of the additional execution time cost that various features add on.

One great feature for tuning your craft’s performance is the Blackbox flight log. However, the choice between logging to an OpenLog device or to an onboard flash chip brings with it quite different performance impacts, and you may need to factor this in when you’re choosing your logging device.

Logging to an OpenLog logging device

When logging to an OpenLog, the Blackbox writes the log to the serial port’s transmit buffer in memory, then returns control to the flight loop immediately. It never waits for the OpenLog to catch up, or for the buffer to be ready. Cleanflight’s DMA support slowly streams the transmit buffer to the serial port in the background, allowing the rest of the system to continue execution with little to no overhead.

When logging to the serial port, the extra overhead that Blackbox adds to each flight loop iteration (in microseconds) looks like this:

93 60 62 62 63 62 63 62 62 62 61 63 63 64 66 65 62 65 61 63 62 63 66 69 63 65 61 62 61 62 65 62 90

Every 32 loop iterations Blackbox logs an “intraframe”, which allows Blackbox to resync the log when it encounters missing or damaged log iterations. Because these frames are larger than normal, they take longer to write to the buffer, and so appear as an increase in overhead of ~30μs over the baseline (up to 90μs). So when logging to an OpenLog, Blackbox adds a mean of 64μs of overhead to the looptime, with a tight standard deviation of 5μs. That overhead is illustrated with this density plot:

Logging to onboard flash (Naze32 full)

When the Blackbox is set up to log to an onboard flash chip, it writes the flight log slightly differently. When there is space available in the flash’s write buffer in memory, Blackbox can complete its write in a similar time to writing to the serial port’s transmit buffer, and so it can quickly continue with the rest of the flight loop. But unlike the serial port, the flash chip is not written to in the background by the DMA engine. So when the buffer fills up, the Blackbox must briefly pause to write it through to the flash chip over the SPI bus. The looptime overhead from Blackbox logging (in microseconds) looks like this:

209 56 54 189 56 196 56 55 190 56 55 189 56 55 189 60 55 193 56 55 188 58 55 189 56 55 190 55 190 56 55 188

In the iterations where Blackbox only writes to the write buffer, it finishes its work quickly in about 55μs. But when it must flush the buffer through to the flash chip itself, the overhead is 190μs! The mean Blackbox logging overhead is 105μs, a reasonable 1.6x that of writing to the serial port, but the standard deviation is 65μs, which is 13 times the deviation of logging to the serial port! This is visible as a strong twin-peak pattern in the density plot:

Why looptime deviation matters, and why it doesn’t

The problem with variance in looptime is that there are several algorithms in Cleanflight whose results depend on the delay between flight control loops, but don’t have any built-in correction to deal with looptime variation. With a fairly speedy looptime of 1500μs, a standard deviation of 65μs represents a potential for a 4.3% error in calculations which (depending on PID controller) could translate to noticeable noise in signals sent to motors and flight instability.

However, this variance only comes in to play if you set the “looptime” setting to a time faster than the slowest loop that the flight controller encounters. As long as you set the looptime to a longer value than the slowest possible loop (when the variance in execution time is at its worst), then Cleanflight can make sure that every flight control loop starts with a similar spacing, minimising error.

The worst case results when looptime is set to zero, because Cleanflight cannot add any delay between loops in order to smooth out variations in execution time.

Here’s what the whole-system looptime variation looks like when looptime is set to zero and Blackbox is logging to the serial port. The mean looptime achieved is 1230μs, and the standard deviation is 82μs (6.7%).

Note that this shows the sum of all looptime variation present in Cleanflight, not just the 5μs that’s due to Blackbox logging.

Here’s the system looptime variation (with looptime = 0) when Blackbox is logging to flash:

The mean was 1292μs and the standard deviation 102μs (7.9%).

We can use these graphs to decide on the best looptime to choose in order to minimise looptime variation. In the case of logging to the serial port, it looks like most loops can complete in under 1300μs, so let’s have Cleanflight aim to space its loops at 1300μs intervals by setting looptime to 1300:

The new mean is 1328μs and the standard deviation 68μs (5.1%). There is still a strange tri-peak distribution which would be nice to remove, but the centre peak is now much taller than its surroundings than it was before.

I think the three peaks are likely due to variations in the time taken to read sensors like the gyroscope and accelerometer and update the craft’s attitude estimate. Cleanflight attempts to begin the execution of its imuUpdate() routine at regular intervals, but Blackbox records its timestamp at the end of this routine, which is used to derive the variation shown above.

When logging to flash, our looptime will have to be set slower in order to encompass the secondary peaks in activity that we saw in the 1300-1400 looptime range. So let’s set looptime to 1400μs:

The mean is 1419μs and the standard deviation 56μs (4.0%), about half the standard deviation we had at looptime 0!

In the future

In the future I would like to investigate adding support for DMA to the Blackbox’s flash engine. This would allow the Blackbox to log to flash with a similar delay and variation as writing to the serial port, eliminating the 135μs flash-writing penalty observed above.