ASYNC uart and UART_RX_RDY timeout

[mmm]

I saw some similar question, but none is what I am experiencing.

I notice some weird behavior while testing DMA mode, so I made a simple setup:

I set the DMA buffer to be 100 bytes, and a timeout of 100ms, and a custom callback:

uart_callback_set(dev_uart, app_uart_async_callback, NULL);

uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);

Then on PC side, i send message of 10 bytes, this is to make sure there is no buffer switch, only timeout from UART_RX_RDY, to avoid any possible mistake with buffer management.

Baudrate is 921600

WHAT DO I EXPECT:

100ms after i sent the message, the callback app_uart_async_callback() get called with event data rx.buf containing my 10 byte message, rx.offset to be 0, and rx.len of 10

If i send another message, the same as above, only difference is the rx.offset is now 10.

And so on until the buffer is full and all the required callback to change buffer get called

WHAT IS HAPPENING:

while sending the message from pc, the callback app_uart_async_callback() get called with event data rx.buf containing ONLY X bytes, rx.offset to be 0, and rx.len of X, where X is between 1 and 10; the TIMEOUT is not respected at all!

What is worse is that i do NOT get a second callback with the remaining data!

Now, at this point, if i send an extra message lets say 1 bytes, the callback is called and all, with rx.len = 1, but as result i see the OLD data that was not served!

MY CONCLUSION:

- according to docs, the TIMEOUT should start at the END of the last bytes, as it is inactivity, this is NOT happening

- even if timeout is counting since the first message is received, ad 921600 baud i should be able to receive 9216 bytes before timeout

- clearly something is wrong in the way the timeout for UART_RX_RDY or the event rx.len is calculated!

- this lead to possibility where data is received, and my application has NO WAY to know it has been

- UART_RX_BUF_REQUEST and RELEASED seems to work properly and get called at the right time, with the correct amount of data in rx.len. SEEMS because due to the delay output, is a bit difficult to notice if data is missing without a proper automated test.

[Edvin]

Hello,

What NCS version are you using? The reason I ask is that we have a bug in some of the previous ncs versions (fixed in v2.4.0) where the uart_rx_enable() expects a timeout in microseconds, but we provided it in milliseconds. So depending on what your UART_RX_TIMEOUT_MS is set to, it may only receive 1/1000 of what you expect it to be. 

If that is the issue, the fix is easy. Just increase the UART_RX_TIMEOUT_MS by a factor of 1000, and you should be fine. 

Let me know if that doesn't help.

Best regards,

Edvin

[mmm]

Hi,

it does not fix the issue but I did indeed used a wrong example.
I am using 2.4.0, the example is bluetooth/peripherical_uart.

I changed this timeout to be 1 second and I still get timeout with partial received data:

I am sending, all together, 0123456789ABCDF, then wait for timeout, then send again the string 0123456789ABCDF

here what i see

[16:08:38:190] Hello world through the UART async driver␍␊

[16:08:47:780] UART_RX_RDY 15 536881776 0!␍␊

[16:08:47:780] RX 15: 0123456789ABCDE␍␊

[16:08:53:182] UART_RX_RDY 15 536881776 15!␍␊

[16:08:53:182] RX 15: F0123456789ABCD␍␊

at about 16:08:46 i send 0123456789ABCDF␍␊,

one second later we see

[16:08:47:780] UART_RX_RDY 15 536881776 0!␍␊

means the event has been called, with len 15 (wrong, should be 16), dma buffer at memory 536881776 (ok) and offset 0 (ok)

[16:08:47:780] RX 15: 0123456789ABCDE␍␊

is the main loop that send our data back, we see it send back the first 15 bytes, we are missing 'F'

Then we can see i dont do nothing for more than 5 seconds, and no timeout for the remaining data.

then at about 16:08:52 i send again 0123456789ABCDF

and we see

[16:08:53:182] UART_RX_RDY 15 536881776 15!␍␊

len 15 (wrong, should be 16 of the new message plus the 1 of the old message), dma buffer at memory 536881776 (ok) and offset 15 (ok, at least is aligned with what happen before)

[16:08:53:182] RX 15: F0123456789ABCD␍␊

we see that we finally obtained the last F, and the first 14 bytes, but now E and F are missing.. but the event UART_RX_RDY is never called...
My application has no way to know that there are 2 more bytes waiting.

full test up until buffer swap:

[16:08:38:190] UART Async example started␍␊

[16:08:38:190] UART_RX_BUF_REQUEST␍␊

[16:08:38:190] Hello world through the UART async driver␍␊

>>> 0123456789ABCDEF

[16:08:47:780] UART_RX_RDY 15 536881776 0!␍␊

[16:08:47:780] RX 15: 0123456789ABCDE␍␊

>>> 0123456789ABCDEF

[16:08:53:182] UART_RX_RDY 15 536881776 15!␍␊

[16:08:53:182] RX 15: F0123456789ABCD␍␊

>>> 0000000000

[16:12:37:011] UART_RX_RDY 9 536881776 30!␍␊

[16:12:37:011] RX 9: EF0000000␍␊

>>> 1111111111

[16:12:49:414] UART_RX_RDY 9 536881776 39!␍␊

[16:12:49:414] RX 9: 000111111␍␊

>>> 3333333333

[16:12:55:008] UART_RX_RDY 9 536881776 48!␍␊

[16:12:55:008] RX 9: 111133333␍␊

>>> 4444444444

[16:12:57:806] UART_RX_RDY 10 536881776 57!␍␊

[16:12:57:806] RX 10: 3333344444␍␊

>>> 5555555555

[16:12:59:803] UART_RX_RDY 9 536881776 67!␍␊

[16:12:59:819] RX 9: 444444555␍␊

>>> 6666666666

[16:13:02:616] UART_RX_RDY 9 536881776 76!␍␊

[16:13:02:616] RX 9: 555555566␍␊

>>> 7777777777

[16:13:03:545] UART_RX_RDY 15 536881776 85!␍␊

[16:13:03:545] UART_RX_BUF_RELEASED␍␊

[16:13:03:545] UART_RX_BUF_REQUEST␍␊

[16:13:03:545] RX 15: 666666667777777␍␊

>>> 0123456789ABCDEF
[16:14:08:549] UART_RX_RDY 14 536881876 0!␍␊

[16:14:08:549] RX 14: 7770123456789A␍␊

we see the buffer swap happen correctly at len 100 and no data is lost and the second buffer is used, but we always have few byes lost, and the amount of lost byte is not constant.
It can become so bad, sometimes i can be more than 10 bytes late!

[Edvin]

I can't say that I have seen this before. Is it possible to zip the application that you are using to replicate this, so that I can give it a go? Are you running it on a DK, or are you using custom HW?

Best regards,

Edvin

[mmm]

of course,here it is!
The board I am using is a FANSTEL BT480E
I started from a standard example and did a couple of configuration changes.

Note i am using

CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC=y

2480.peripheral_uart.zip

[Edvin]

Hello,

I see that your implementation differs quite a bit from the peripheral_uart sample. Is that on purpose? I played around with the sleep in your main() loops, and I see that it queues only parts of the message on every sleep cycle. Also, your UART_TX_DONE event (inside app_uart_async_callback()) is not successfully triggering the next byte, so this will continue to fill up the buffer, as you write to it. 

I think you need to look into the UART_TX_DONE implementation that you are using. Especially the bytes_claimed handling. Is this working as you expect? Or are you freeing up the buffer faster than you are processing it? I also suggest adding logging via RTT, so that you can use LOG_INF() to see what's going on. (It is difficult to use printk, which is using the UART, when the UART is not working as you expect it to). 

I see that when I remove all the printk() it is working closer to what I expect it to, but then again, as it says in the comments, these functions are not thread safe, so interrupting it with printk() may not be very fortunate.

Best regards,

Edvin

[mmm]

Hi,

yes, those differences are desired.

This is a minimal example to reproduce and debug the issue, i did not want to add anything more than necessary.

I need to be able to saturate the 921600 baudrate, so i had to get rid of the interrupt implementation and switch to a DMA based. I managed to reach full write speed, but when i started to test the input speed, i notice the test failing and the issue was the weird timing.

Then i started to remove stuff, thinking it may be some issue with timing or concurrency..

Until i notice the issue is coming from the callback.

Note that the data is missing already in the callback event, so even if TX would misbehave, the issue is present; the TX output is just a nice to have

[Edvin]

I understand. I am sorry for the late reply. I have been trying to clear up my backlog, because I will be out of office for a while. 

Try adding RTT logging to your project, so that you can look into what the functions in the UART_TX_DONE event returns, and whether they work as you expected. I didn't manage to understand the logic flow during my last take on this ticket. 

Check whether bytes_claimed have the correct value when UART_TX_DONE triggers, and whether k_sem_give(&tx_done) is called when it shouldn't be (if bytes_claimed != 0). 

Since I will be out of office, I suggest you create a new ticket for follow up questions. You can refer to this one for background, but please upload your application there, if you changed anything at this point, and try to give a summary of your current status.

Best regards,

Edvin