Logging to flash performance

[JVKran]

Hi there!

Logging specific log-messages to flash is key to our applications. On previous platforms, this was possible without any hassle. The nRF Connect however, has been a whole other experience. Logging to the SD-card is no option, as playing audio files is also a key-function for our applications, and Zephyr doesn't support simultaneously opened files being read/written (see previous Q&A). As a result, we have no other choice than to log to flash. 

For this, we're using Zephyr's Filesystem Logging Backend. In itself, it does what it says. We do however question the measured performance with SEGGER SystemViewer. The screenshots underneath were taken with the logging sample application.

The screenshot above showcases the real-time behaviour of the sample with the RTT-Shell enabled (and set as logging backend) while also having the Filesystem Logging Backend enabled and directed to the on-board (non-external) flash. As one can see, there is little to no time left for other threads to run. This was ran on an nRF52840. With our own applications (including Bluetooth, playing audio (SD-Card to I2S)), this is unusable; we don't have thousands of milliseconds available to let the logging thread run. Making our audio player non-pre-emptible is also no option, as we would have no logging for ten's of seconds.

Using an the nRF52832 on the nRF52DK with external flash chip, we see an improvement in performance, with still periods in which no idle time is present. This could be usable, but we see this as still not in the safe-zone.

Then there is the application with only the RTT-Shell enabled and selected as logging backend. While we understand that logging to flash takes time, we wonder if the difference (which is night and day) is right, as we have a gut-feeling the difference is too large.

If it is too large, do you have any tips on how to improve the performance? In the mean-time we're going to try and play with log buffer sizes, processing trigger thresholds and runtime filtering options to see wether this approach is feasible.

Kind regards,

Jochem

[JVKran]

And another update already. Logging a message with logging to flash enabled, takes around 128 milliseconds. Logging the same message twice, results in the logging thread running for a little more than double the amount of milliseconds; 259 milliseconds.

[JVKran]

And a new one, with minimal logging (shown below) the application behaves like the following. All threads interrupting the logger thread could cause such behaviour? By increasing scheduling-overhead? The sheer amount of log messages causing this seems questionable and makes me doubt about doing something wrong.

[00:00:00.005,249] <inf> BATTERY: Setup AIN4 got 0
[00:00:00.005,249] <inf> BATTERY: Battery setup: 0 1
[00:00:02.015,197] <inf> sd: Detected SD card
[00:00:02.359,924] <inf> sd: Maximum SD clock is under 25MHz, using clock of 24000000Hz
[00:00:02.513,092] <inf> app: Started playing '1803.wav'.
[00:00:04.906,188] <err> i2s_nrfx: Next buffers not supplied on time

[Susheel Nuguru]

Hi Jochem.

I do not have experience with filesystem as logging backend, so I cannot tell how much CPU overhead it has over every flash operation.

Having log regularly written to flash with another CPU intensive audio app does not seem to bode well in nRF52 based solutions. I am guessing that you might have already considered nRF53? 

Flash logging are CPU intensive on nRF52 and I am guessing your Audio processing also must be.

Have you done any benchmarks without any logging and how much percentage of CPU your audio application consumes in average?

As you already have measured that each flash operation takes about an average of 128ms, and hoping that you know the average flash operations, do you see that flash operations fitting in the idle slots?

What are the priorities of your threads here? I cannot know which operation is preempted by which operation without knowing the priorities of all contexts in your application. Having your audio application on higher priority than flash operation, you just need to benchmark the frequency of maximum flash operations allowed by your application. It is almost impossible for me to comment or suggest any optimization strategy without looking at your application.

You cannot have two extreme CPU intensive operations running with very frequent operations of each without the lower priority operation starving in the end in the resource limited chip.