Using LIBUARTE during flash operations

[oguzcan oguz]

Hi, 

We are using a NRF52840 chip (SDK 15.3) in an application where we use the softdevice (S140) in combination with 2 UARTS: one for sending out debug output (UART0 - nrfx_uart), and another one for communication with another MCU.

During (internal) flash writes when doing bonding or garbage collection, the CPU stalls for quite a long time (~85 ms during flash erase). In order to make sure we do not lose data from the other CPU we have been looking into the 'nrf_libuarte_async' functionality.

It is constructed by using:

NRF_LIBUARTE_ASYNC_DEFINE(libuarte, 1, 1, NRF_LIBUARTE_PERIPHERAL_NOT_USED, 2, 512, 3);

(UARTE1, TIMER1 for byte counting, TIMER2 for timeout, buffer size of 512).

During normal operation it works fine, but after the CPU stall, we ofter end it in an error in 'nrf_libuarte_async_rx_free', stating "Unexpected RX free input parameter.". In this case the 'rx_free_cnt' is bigger than the 'chunck_size'. We are following the example of examples\peripheral\experimental_libuarte and free the buffer in the NRF_LIBUARTE_ASYNC_EVT_RX_DATA event.

Could you give any indication what can be the issue here? We couldn't find much documentation wrt to this driver. 

Thank you.

[ovrebekk]

Hi

What baudrate is the UART1 running at?

How large is the UART utilization from the connected MCU? Do you think there is a risk that the UART RX buffer could fill up during those ~85 milliseconds?

Are you using hardware flow control or not?

Best regards
Torbjørn

[RoyCreemers]

Response on behalf of my collegue: The baudrate is 115200. There is no risk that the UART Rx buffer could fill up. The connected MCU can only send one single message (which is less <400 bytes),then it waits for a response. Unfortunately there is no possibility that to use hardware flow control

[ovrebekk]

No problem, I am happy to hear you got it working

[RoyCreemers]

After testing some more, it seems that there are still issues. The device logs:

<error> app: Fatal error
<warning> app: System reset

... and reboots.

I tried to build for debug, but then it looks like more issues are popping up (UART data loss/corruption). When I repeat this several time and ignore the UART error, it looks like an issue in the softdevice:

<error> app: SOFTDEVICE: ASSERTION FAILED

Some more info:

-  I got none of there errors when using the nrfx_uart driver

- When increasing the timeout of the UART (e.g. 5000us to 15000us) the problem of the UART data corruption seems to be reduced/dissapeared

- The assertion of the softdevice is not related to flash operations. In case I toggle between advertising & standby, I also get the assertion.

[ovrebekk]

Hi Roy

How often do you get these asserts, and do they appear to be connected to any particular event or state in your application?

You mention that they occur when you toggle between advertising and standby, but I get the impression they also occur at other times?

Are you able to share the code you use for toggling between advertising and standby?

Best regards
Torbjørn

[RoyCreemers]

Sharing the code is possible, but I'm not sure this will help a lot (of course I will share if you think is has benefits). It is part of quite a big C++ application, involving multiple MCUs.

Our "application core" has a button which triggers an event to toggle advertising. This is communicated by UART to the Nordic BLE MCU. In his turn, this sends back a response over UART, and toggles advertising (so in this case there is a high change that there is some UART activity during softdevice activity).

The start of the advertisement is done by:

sd_ble_gap_adv_start(advertisementHandle, APP_BLE_CONN_CFG_TAG);

the stop is done by:

sd_ble_gap_adv_stop(advertisementHandle);

The scenario above can easily be reproduced here, the assertion occurs at least one out of 10 times. I share your oppinion that they can also occur at other times (I also saw some softdevice assertions during our automated testing, not related to advertisement... just during normal BLE transmittions)

[ovrebekk]

Hi Roy

Are you able to log these asserts, or use the debugger to trace from where they occur in the Nordic device?

Do you know if the sd_ble_gap_adv_start or sd_ble_gap_adv_stop functions return an error, or if the assert are exclusively generated by the SoftDevice?

I agree receiving your whole code base is unlikely to be helpful, but it might be interesting if you can isolate and send the parts of the code running on the nRF52 side that controls the SoftDevice (including starting and stopping advertising). 

Best regards
Torbjørn

[RoyCreemers]

The asserts seem to be exclusively from the softdevice. Return values of advertising start & stop are always ok (NRF_SUCCESS). Don't know if there is much relevant information in the fault itself.

'id' is always '1' (NRF_FAULT_ID_SD_ASSERT)

pc = 0x16e5a (or close)

info = 0;

)

[ovrebekk]

Hi Roy

When you say 0x16e5a or close, do you mean this changes from time to time, or you're not sure the exact address?

The exact address can be important when reporting this to the stack developers. 

To summarize, you confirm that this can happen with or without flash erase running?

You confirm that this will only happen when using the libuarte_async library?

How do you process UART events in the application? 
Are you running a lot of event processing in the events directly, or do you process it later in main/thread context?

Do you know what interrupt priority the UART events are returned in?

Best regards
Torbjørn

[RoyCreemers]

Hi Torbjørn,

I was preparing all your questions with answers, till I reached the final question about the interrupt priority. When searching through our code, I realized that we did not specificy the 'int_prio' field (it was added in the patch we received). It was undefined and pointed out to '112' (or some other high value). Once I changed it to  irq priority 5, the issue is gone!! Thanks!

Unfortunately I still see that data gets corrupted some times. I will dive into this first to see if I can get a reproducable scenario. For now, it reproduces more often in case I reduce the timeout.

[ovrebekk]

Hi Roy

That is good to hear

One of the SoftDevice developers confirmed that the assert was related to a delayed interrupt in the SoftDevice, which happens if you configure interrupts to run at the highest priorities (should be reserved for the SoftDevice only). 

As soon as you have more information on the corruption issue just let me know. 

I assume you are talking about UART corruption?

Does it happen both on RX and TX?

Does it happen with or without flash access enabled?

And any more details you think might be relevant. 

Best regards
Torbjørn

[RoyCreemers]

Let me start with answering some of your previous questions:

Q:To summarize, you confirm that this can happen with or without flash erase running?
A:This happens without flash erase.

Q:You confirm that this will only happen when using the libuarte_async library?
A: Yes. When using the nrfx_uarte driver directly, we did not have this issue.

Q:How do you process UART events in the application? Are you running a lot of event processing in the events directly, or do you process it later in main/thread context?
A: Data is put in a buffer, and processed in the main thread. No processing is handled in IRQ context. Same for BLE events: everything is queued for processing outside of interrupt context.

Q: Do you know what interrupt priority the UART events are returned in
A: The "irq_prio" is filled in with 5

The corruption only happens on the receive action. I looks like the problem occurs in case I receive new data during the timeout. What I see only the logic analyzer is that we often have a UART sequence looking llike the following

<~200 bytes on UART Rx>  <no communication for ~5 ms>  <~200 bytes on UART Rx> <no communication for ~X ms)

Initialily, I had the timeout set to 5 ms. I noticed the error very often. It looked like the data from the first and second burst where mixed.

Once I set the timeout to 15 ms, I see it very rarely: actually only when my "no communication" window is equal to X.

Now I reduced it to 2 ms, it works without issues (in the 15 minutes I tried this), probably because this "no communication" window is very unlikely to happen.