Inconsistent behavior UART_ASYNC_API callbacks

[WoutWG]

Hi,

I am working on an application with ncs 2.5.0 that is based on a combination of the central_uart example and the hci_lpuart as I'm trying to pass data around between the nRF52840 and the nRF9160 on the nRF9160DK. I'm running into some issues that don't really seem to consistent with the documentation of the UART_ASYNC_API, or I am interpreting it incorrectly.

It seems that my issues are related to this issue, however since I'm using v2.5.0, I would expect it's not the same bug.

When I keep the UART_RX_TIMEOUT at 50000 (same as in the central_uart example), it seems to work well, however, when I send messages quickly after another, I notice messages are grouped together. Therefore, I was thinking to reduce the UART_RX_TIMEOUT to a value that should ensure that UART_RX_RDY is triggered after every single message. Since the uart speed is set to 1000000, I thought having a UART_RX_TIMEOUT of a little over 1 (us) should be enough to ensure that UART_RX_RDY is triggered after a burst of characters. 

However, when I set the UART_RX_TIMEOUT to 5 (us), I notice that UART_RX_RDY does get triggered, but it doesn't lead to the uart_rx_disable because the \r \n (indicating the end of a single message) are not identified. When logging the length of the buffer, I see that indeed not the full message is received yet when UART_RX_RDY is called. I see that data only gets added to the FIFO when the buffer is full after receiving more messages, which results in calling UART_RX_BUF_RELEASED after UART_RX_BUF_REQUEST.

The strange thing is, when I increase the UART_RX_TIMEOUT, the length of the buffer in my repeated UART_RX_RDY logs increases, but UART_RX_RDY is not called when the full message is received for some reason unless I increase the UART_RX_TIMEOUT to a high value. For a message of length 14 (including the \r \n), these are my findings. With UART_RX_TIMEOUT set to 5us, I see UART_RX_RDY triggered at lengths 3 and 6, with the timeout set to 50us it is triggered at length 6 and 7, at 500 us timeout it is triggered at length 10, and at 5000us it is finally triggered at length 14 and the message is added to the FIFO since the last bytes match \r \n.

This raises 3 questions:

1. It makes sense that UART_RX_RDY is called multiple times if the UART_RX_TIMEOUT is close to the time it takes to send a byte and if there are other things happening on the sender  side that may slightly delay sending bytes. However I was under the impression that the Async API would result in a pretty consistent 'time between bytes' independent of activity in other threads. Am I misunderstanding that with a uart_speed set to 1000000, the average time between bytes should be around 1us?

2. When I do seem to get multiple calls of UART_RX_RDY after receiving some bytes, I don't seem to get UART_RX_RDY after getting the full 14 bytes unless I increase the timeout to ensure that I received the full message in one go. If UART_RX_RDY is triggered in between receiving full messages, shouldn't it also be triggered after receiving the full message since this will also result in a timeout when no new bytes are being transmitted?

3. The documentation indicates that the timeout is counted from the last byte received. With a relatively stable transmit speed, I would expect that UART_RX_RDY would be called either after every byte or after receiving a full burst of bytes (aka the full message), depending on the timeout selected. From my measurements, it seems however that the buffer length is increasing with increasing timeout. This seems to point towards the timeout not counting from the last byte received, but from the first byte received. What could be the reason for this behavior?

I can implement a work around to split up a buffer in multiple messages if this happens when the timeout is set to a large value, but I wanted to make sure I understand the operation of the UART Async API since it will play a critical role in the application ensuring data integrity. I hope you can help me understand why i'm seeing what I'm seeing.

Best,

Wout

[Einar Thorsrud]

Hi Wout,

Am I misunderstanding that with a uart_speed set to 1000000, the average time between bytes should be around 1us?

I think so. The baud rate indicate bit per second, not characters per second. So to get byte/characters per second you can divide by ten (8 bit +1 start bit + 1 stop bit).

PS: There was a bug (mixing milli/micro) in the peripheral UART sample that was fixed in by this PR, did you by any chance inherit this?

Einar

[WoutWG]

Hi Einar,

Thank you for your reply. I did indeed mistake baud rate for characters per second. But even if it is bps, then every character should take approx. 10us.

So I don't get why I see UART_RX_RDY getting triggered after receiving different amount of characters when setting the timeout to 50us vs 500us vs 5000us, and more importantly, why I don't get a UART_RX_RDY event when the transmission is completed and there should actually be a timeout triggered because no new data is coming in.

I did indeed notice that there was a change going from ms to us, I did make sure to use us.

[Einar Thorsrud]

Hi,

WoutWG said:

So I don't get why I see UART_RX_RDY getting triggered after receiving different amount of characters when setting the timeout to 50us vs 500us vs 5000us

I am not sure I understand why that is unexpected? If the timeout is so that you don't receive all data before it times out, the longer the time out the more data you receive with the UART_RX_RDY event (assuming the buffer is largr enough and data is still being received by the HW). Perhaps you can elaborate a bit on the problem?

WoutWG said:

why I don't get a UART_RX_RDY event when the transmission is completed and there should actually be a timeout triggered because no new data is coming in.

If no data was receevied, you wll not get the event.  See API doc for uart_event_type for details.

[WoutWG]

 Hi Einar,

The documentation indicates "RX timeout is counted from last byte received". To me this means that every time a byte is received, the timeout is reset until there are no more bytes coming in (i.e. transmission is completed), which will then in turn trigger the timeout and consequently the UART_RX_RDY event.

So if I send a message which contains multiple bytes (in this specific case 14 bytes), I would expect the timeout to either trigger for every byte if the timeout is set to a value smaller than the time it takes to transmit a single byte (in my case of 1000000 baud rate that would be approx. 10us as we established earlier) or only after receiving all 14 bytes in case the timeout is set to a value larger than the time it takes to transmit a single byte, since the timeout will be reset with every byte received.

With this understanding, it doesn't make sense that increasing the timeout value would mean that more data is received before triggering UART_RX_RDY. Am I misunderstanding how the timeout operates?

[Einar Thorsrud]

Hi,

That is a good point. The Zephyr API is generic and on this point it does not match perfectly with the UARTE peripheral on the nRF, which will only generate an event when the receive buffer is full. There is no way for the peripheral to signal to the "outside" that it has received a certain number of bytes before the buffer is full.

(For this reason and to avoid loosing data in cases with high baud rate etc you mayłant to enable hardware byte counting, which use a timer in counter mode and PPI to count incomming bytes. In that case you need to use something like CONFIG_UART_0_NRF_HW_ASYNC=y and CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2, but replace the UART instance in both configs with the one you use, and set the timer number in the last config to an available timer).

[ErnestVanHoecke]

I haven't gone through it all but just a short +1 from me to mention that we also had two similar sounding issues when starting from the UART examples:

* Byte counting without the aforementioned HW flags just completely misses bytes when raising the speed (I have seen this mentioned before on the forum, it might be good to document this more in the sample and use the hardware byte counting by default)

* We rewrote the logic surrounding when to process received UART buffers, the one in the sample completely relies on the "\r\n" bytes as mentioned, but then also frees both UART buffers when that happens, meaning you could miss bytes at that time. We now copy bytes into a buffer as they are received. Sorry for the poor explanation, this has been a while, I just wanted to mention that you cannot rely on the default `uart_cb` logic for high throughputs and when not using termination bytes, it's best to rethink the system there for your use case.

[WoutWG]

Hi Einar,

Sorry for the delayed reply. I finally got a breakthrough. I built out a sample application based on a combination of hci_lpuart, central_uart and lte_ble_gateway, stripping away pretty much all other functionality of the application to focus on the core. This worked as expected. Since my application is based on hci_lpuart and lte_ble_gateway,  CONFIG_UART_0_NRF_HW_ASYNC=y and CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2 were already in place.

Then I started adding functionality to see where it breaks, and to my surprise it didn't break. Then I did a detailed analysis of all the conf and overlay files to ensure that I did in fact do the same thing on both applications, only to find out that I missed adding the nrf9160dk_nrf52840.conf (exact copy of hci_lpuart sample) file in my original application in the build configuration. I assume this made it so that hardware byte counting as well as the lpuart driver were not actually enabled, which would explain why I wasn't getting my callbacks when I expected to get them.

Sorry for this mixup, but thank you for sticking with me.