nrf5340 is unable to trigger rpmsg(ipc) transfer

[Dumam]

Hi,

I have quite demanding SPI device which should send its data over BLE.
Thanks to throughput example i was able to achieve maximum transfer speeds for synthetic tests (without SPI).
Sadly after adding real data input, I noticed that no transfer is executed until I finish my commands. 

Thanks to SystemView I was able to narrow this problem to one part of configuration -> rpmsg.

Colors:

Green -> spi thread
Yellow -> bt_hci thread
Orange -> ble host TX
Red (small squere in top) - IRQ 58 from probably ipc, but i wasnt able to find it in manual (not listed)
Blue - probably openAmp mailing work queue thread
purple - systemwork queue

SystemView Data Log
4010.BleProblem.dat

Here is repo with configs etc.
https://github.com/DuMaM/bitly_nrf5x

[Edvin]

Hello,

I am not sure I understand the question? What are you seeing, and how do you expect it to work?

I noticed that no transfer is executed until I finish my commands. 

What sort of commands are you talking about here?

BR,
Edvin

[Dumam]

 Edvin Thanks for response, and sorry to not be clear enough. 

This is what i'm doing here:
-> I have ads129x communication over SPI. It's set to work in continuous mode, so every n seconds it sends data packet (24bytes). To notify that we should get them it pulls up DATA_READY pin. I detect this in ISR callback and via semaphore i'm notifying SPI thread to read data. (GREEN part in picture)
-> after SPI read this it send that data via pipe to other thread which is packing up data for BLE transfer, every time i get 251 bytes in this thread I'm sending this with `bt_gatt_write_without_response`. (YELLOW part in picture)

The question is:
why it takes so long rpmsg to start transmit data and why there are so big delays between each frame. (BLUE part in picture)

[Dumam]

 Edvin I'm soo grateful for this. I'm trying to figure it out for 2 months without any luck. :(

[Edvin]

Ok, I am trying to navigate your project. I am struggling to see exactly how it relates to the throughput sample. Where exactly are you sending the BLE packets. Can you please point to it? Where it sends, and how long are the packets that you are sending? There should be a call to bt_gatt_notify_cb() or bt_gatt_write() or something like that.

You say that your throughput is much higher when you disable the SPI and just use dummy data. So the MTU and connection interval and everything else is the same, just that you wait for the SPI to finish? 

What is it that triggers send_test_ecg_data()? 

ads129x_get_data() only triggers a read from a buffer? No actual peripheral transferring data? When will it continue; and when will it send data (which I assume it does inside bt_performance_test_write(). And when bt_performance_test_write() is called, what is the length of the data that is being sent?

Sorry, a lot of unstructured questions, but I was reading more and more into your project. So the question is, how often is send_test_ecg_data() called, and how often is bt_performance_test_write() called? Is bt_performance_test_write() called every time send_test_ecg_data() is called, or does it often skip it because of continue; ?

[Dumam]

> Ok, I am trying to navigate your project. I am struggling to see exactly how it relates to the throughput sample. 

I renamed it to performance_tests
I wanted to extract this form nrf sdk, mostly because in feature I'm going to modify it.
This also helped me to have a stable code base.

> Where exactly are you sending the BLE packets. Can you please point to it?

Sure. I'm using writes here, as it was in example. I'm sending packages here: 
https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/cmd_run_adc.c#L61

> Where it sends, and how long are the packets that you are sending? There should be a call to bt_gatt_notify_cb() or bt_gatt_write() or something like that.

I'm trying to fill package as much as possible. Until there are data in buffer I'm sending `data_len->tx_max_len`, otherwise when there will be some leftovers I placing them as a whole.

> You say that your throughput is much higher when you disable the SPI and just use dummy data. So the MTU and connection interval and everything else is the same, just that you wait for the SPI to finish? 

I think yes.  
SPI is driven by GPIO called DRDY. This pin is used by hooked up device to notify master that it should fetch data. Maximum speed here is 32000 samples/s, but with current BLE capabilities the maximum reasonable value is 4000k samples/s (1400kbps), for tests i'm using 2000k samples/s.

> What is it that triggers send_test_ecg_data()? 

This semaphore and GPIO callback:
https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/spi_adc.c#L442
github.com/.../spi_adc.c

> ads129x_get_data() only triggers a read from a buffer? No actual peripheral transferring data? > When will it continue; and when will it send data (which I assume it does inside bt_performance_test_write()

It triggers only on when there is a timeout on pipe k_polling or requested number of data was delivered from SPI pipe. I'm not sure what you mean by `No actual peripheral transferring data?`
Anyway when it fetch data from pipe it will transfer them to `bt_performance_test_write` which is wrapper for `bt_gatt_write_without_response`
It's a bit stupid but thats how it was designed in example. I didnt have time to change it too much.
github.com/.../performance_test.c


> And when bt_performance_test_write() is called, what is the length of the data that is being sent?

As I said before it's max len set for single connection event - mostly 251 bytes.
If SPI finish it's data transfer and it's not aligned to 251 bytes I send this remainder.

> Sorry, a lot of unstructured questions? I was reading more and more into your project.

No problem, I really appreciate it.

> So the question is, how often is send_test_ecg_data() called, and how often is bt_performance_test_write() called? Is bt_performance_test_write() called every time send_test_ecg_data() is called, or does it often skip it because of continue; ?

It will be hard to answer for this, because it's constantly changing. Depending on priories I set for threads and ISR. What I can tell for sure is that it's able to pull data from pipe without issue.
I started to suspect that bt_gatt_write_without_response waits for something. I'm not sure what, but when I interrupt it with SPI ISR, this event is lost.
This behavior would explain why synthetic dummy tests are ok. 

[Edvin]

Dumam said:

I'm not sure what you mean by `No actual peripheral transferring data?`

I mean that you are not doing any SPI transactions inside that function, which means that you need to wait for the transaction to finish inside this callback? If so, that will introduce a delay. 

Ok, we have a more similar understanding of what your project does now, which is a good thing

My claim is that bt_performance_test_write() does not care whether the data comes from a buffer of all 0's or a buffer consisting of SPI data. So the lower throughput has to come from elsewhere. 

For debugging purposes, what if you instead of calling bt_performance_test_write(), just add up the length of what you were going to send, and look at what sort of total length/throughput you would have got without actually sending the data? Is it still lower than only sending dummy data without the SPI?

BR,

Edvin

[Dumam]

Edvin said:

For debugging purposes, what if you instead of calling bt_performance_test_write(), just add up the length of what you were going to send, and look at what sort of total length/throughput you would have got without actually sending the data? Is it still lower than only sending dummy data without the SPI?

I checked this. I'm always sending 251 bytes. 

You gave me other idea how I can debug this. I will try to use dummy data with SPI in background and see if this is a problem on thread sync level or maybe some ISR/MCU components. 
This way I separate SPI thread from BLE one.

Did you manage to find something on your side? 

[Dumam]

Hi Edvin,

You were right. There was problem with connection interval.
Zephyr needs a constant feed of data at the beginning of a connection event.
If this steam is not delivered, then the connection is instantly terminated.
I was planning to just retransmit my SPI data without any additional buffering, but this will not work in that case.

So, I increased SPI buffer, and now it provides space for data from 35ms long SPI stream.
At the end, I was able to reach 0.5Mbits/s of throughput 

That's so big step forward  thanks for this help.


Sadly, I still require some help.
I noticed that SPI is now a blocking factor. 
Do you have nice example how to work with EasyDMA SPI in zephyr, so I can fetch data only on interrupt from it? Additional GPIO, takes too many CPU cycles in ISR, and it duplicates SPI work.

Please do not close this ticket yet.

[Edvin]

Dumam said:

Please do not close this ticket yet.

No problem. We can go on for a while more. Just please note that I will be out of office tomorrow, but I'll be back on Monday.

I am glad you figured it out! That makes sense. The data needs to be queued up before the connection event. Obviously, all individual packets needs to be queued before they go on air. And in each packet, there is a bit that says whether or not it has more data. So the Bluetooth stack (SoftDevice Controller) needs to at least be aware of the second packet before it starts transmitting the initial packet. Whether or not that is recursive, I am not sure. That is, if you have queued packet #1 and #2 when packet #1 goes on air. Then you queue packet #3 before packet #2 has started airing, I am not sure whether it will change the "more data" bit in packet #2 or not. If not, then all packets needs to be queued before the connection event starts. 

As for the SPI. I am not aware of any SPI with EasyDMA samples in Zephyr, but you can set up a ppi approach. On how to use PPI, please see the sample found in NCS\zephyr\samples\boards\nrf\nrfx. What you can do here is to chain the transfer end event with a transfer start, so that it runs in the background, if that is what you are looking for. Then you would typically use a timer in counter mode to also count up, and then set an interrupt when the timer (counter) reaches a certain value, to then trigger a "timeout" interrupt in your application.

Best regards,

Edvin

[Dumam]

Edvin said:

Whether or not that is recursive, I am not sure. That is, if you have queued packet #1 and #2 when packet #1 goes on air. Then you queue packet #3 before packet #2 has started airing, I am not sure whether it will change the "more data" bit in packet #2 or not. If not, then all packets needs to be queued before the connection event starts. 

As far as I can tell, write request is locked since there will be a free space in rpmsg buffer.
I don't understand why I see only 2 work queue execution per, connection event, even thought I have more data prepared for transmission. I think this is a one of settings from RPMSG. 

I'm not sure about PPI. My guess is that SPI is taking too long, and I'm unable to provide next packet for BT_TX thread.

[Dumam]

I also increased systick speed and this didnt helped.

# clock settings
# https://github.com/zephyrproject-rtos/zephyr/issues/28469#issuecomment-704164283
# https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/zephyr/kernel/services/timing/clocks.html
# https://devzone.nordicsemi.com/f/nordic-q-a/92297/increasing-cpu-clock-frequency-for-bl653
CONFIG_NRF_RTC_TIMER=n
CONFIG_CORTEX_M_SYSTICK=y
CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC=64000000
CONFIG_SYS_CLOCK_TICKS_PER_SEC=6400000

[Edvin]

I believe it is rather the work queue holding you back than the BLE stack. You can try to either skip the work queue, and call the bt_gatt_notify_cb() directly from your spi callback handler.