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

[Dumam]

Ok, I confirmed that this interrupt comes from ipc.

And blue thread is a workthread for rpmsg mbox.

Anyway this didnt helped with tracing down the problem

[Dumam]

[00:01:23.903,991] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
                                      02 00 20 07 00                                   |.. ..
[00:01:23.999,847] <inf> main: === Reseting data buffer ===
[00:01:24.001,159] <inf> ads129x_log: Data transfer enabled
[00:01:24.001,220] <inf> main: === Start analog data transfer ===
[00:01:24.001,220] <inf> main: Sending 126 bytes (value after rounding to max packet size)
[00:01:24.003,784] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20019a88 type 2 len 137
[00:01:24.003,906] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
                                        02 00 00 85 00 81 00 04  00 52 12 00 00 00 01 c0 |........ .R......
                                        00 00 01 a6 f7 f5 c3 eb  ff fd 22 ff f6 bf ff f6 |........ ..".....
                                        de ff f7 54 ff f6 cd ff  fa ff f5 c6 c9 05 1f 79 |...T.... .......y
                                        05 1c 9b 05 1c 9b 00 00  01 c0 00 00 01 a6 ac f5 |........ ........
                                        d0 59 ff fd 2b ff f6 cf  ff f6 d4 ff f7 41 ff f6 |.Y..+... .....A..
                                        c5 ff fb 1f f5 d3 2e 05  19 3e 05 16 69 05 16 69 |........ .>..i..i
                                        00 00 02 c0 00 00 01 a5  e6 f5 d2 54 ff fd 1f ff |........ ...T....
                                        f6 e1 ff f6 c4 ff f7 31  ff f6 ae ff fb 22 f5 d5 |.......1 ....."..
                                        35 05 18 46 05 15 65 05  15 65                   |5..F..e. .e
[00:01:24.004,119] <inf> main: [local] sent 126 bytes (0 KB) in 3 ms at 336 kbps
[00:01:24.005,676] <inf> ads129x_log: Data transfer disabled
[00:01:24.005,889] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20019a88 type 2 len 11
[00:01:24.005,920] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
                                        02 00 00 07 00 03 00 04  00 0a 12 00             |........ ....
[00:01:24.011,444] <dbg> bt_hci_driver: bt_rpmsg_rx: RPMsg data:
                                        04 13 05 01 00 00 01 00                          |........
[00:01:24.011,474] <dbg> bt_hci_driver: bt_rpmsg_evt_recv: len 5
[00:01:24.011,505] <dbg> bt_hci_driver: bt_rpmsg_rx: Calling bt_recv(0x20019758)
[00:01:24.011,810] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
                                        04 00 00 00 e1                                   |.....
[00:01:24.011,993] <dbg> bt_hci_driver: bt_rpmsg_rx: RPMsg data:
                                        04 13 05 01 00 00 01 00                          |........
[00:01:24.012,084] <dbg> bt_hci_driver: bt_rpmsg_evt_recv: len 5
[00:01:24.012,115] <dbg> bt_hci_driver: bt_rpmsg_rx: Calling bt_recv(0x20019758)
[00:01:24.012,451] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
                                        42 00 00 00 ac                                   |B....
[00:01:24.043,762] <dbg> bt_hci_driver: bt_rpmsg_rx: RPMsg data:
                                        02 00 20 15 00 11 00 04  00 0b 01 00 00 00 7e 00 |.. ..... ......~.
                                        00 00 87 24 00 00 ff ff  ff ff                   |...$.... ..
[00:01:24.043,792] <dbg> bt_hci_driver: bt_rpmsg_acl_recv: len 21
[00:01:24.043,823] <dbg> bt_hci_driver: bt_rpmsg_rx: Calling bt_recv(0x200197c8)
[00:01:24.043,914] <inf> main: [peer] received 126 bytes (0 KB) in 1 GATT writes at 9 kbps
[00:01:24.044,006] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20019970 type 0 len 8
[00:01:24.044,036] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
                                        01 35 0c 05 01 00 00 01  00                      |.5...... .
[00:01:24.044,250] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
                                        e2 ae 03 00 88 9a 01 20  02 00 00 00 0f 00 00 00 |.......  ........
[00:01:24.044,372] <inf> main:

Here is a debug log from rpmsg. 

I send 100 bytes with write ble command. The final hci buffer was ok 137 bytes.
Sadly there is quite long response from NETWORK, which makes it unusable

[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

[Edvin]

Perhaps I was a bit short, but I suspect that you expect to be able to create some sort of stream to send one byte at the time. That is not the case, according to the Bluetooth specification. You need to construct complete packets, and send them to the receiving device.

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)