zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.87k stars 6.62k forks source link

Bluetooth isochronous channels samples not working with nrf52840dk boards #58160

Closed whati001 closed 1 year ago

whati001 commented 1 year ago

Hi,

as mentioned in the discord thread, it seems like that the current samples of the iso_broadcast and iso_receive do not work for the nrf52840dk board. The boards are able to exchange the BIG information and the broadcast sample seems to announce the counter value. However, the receive sample never receives the actual value and always prints the value 0. We would expect to see the counter values, send by the broadcaster sample instead of 0.

The problem can be reproduced by placing two nrf52840dk boards next to each other and flash the unchanged samples from the current upstream (git commit: d9637673694419abcbbb04d8a012da9a8380866d) as following:

# pull upstream and update west modules
git pull origin master
west update 

# flash first board with broadcaster sample
west build -p -b nrf52840dk_nrf52840 samples/bluetooth/iso_broadcast -DOVERLAY_CONFIG=overlay-bt_ll_sw_split.conf
west flash

# flash second board with receiver sample
west build -p -b nrf52840dk_nrf52840 samples/bluetooth/iso_receive -DOVERLAY_CONFIG=overlay-bt_ll_sw_split.conf
west flash

Here are the logs of the two samples after the boot: broadcaster

*** Booting Zephyr OS build zephyr-v3.3.0-4221-gd96376736944 ***
Starting ISO Broadcast Demo
[00:00:00.259,307] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.259,368] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
[00:00:00.259,399] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.3 Build 99
[00:00:00.260,040] <inf> bt_hci_core: bt_dev_show_info: Identity: D9:F3:38:72:D9:3E (random)
[00:00:00.260,070] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.4 (0x0d) revision 0x0000, manufacturer 0x05f1
[00:00:00.260,101] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.4 (0x0d) subver 0xffff
Waiting for BIG complete chan 0...
ISO Channel 0x20000134 connected
ISO Channel 0x20000148 connected
BIG create complete chan 0.
Waiting for BIG complete chan 1...
BIG create complete chan 1.
Sending value 0
Sending value 1
Sending value 2
Sending value 3
Sending value 4
Sending value 5
Sending value 6
Sending value 7
Sending value 8
Sending value 9
Sending value 10
Sending value 11
Sending value 12
Sending value 13
Sending value 14
Sending value 15

receiver

*** Booting Zephyr OS build zephyr-v3.3.0-4221-gd96376736944 ***
Starting Synchronized Receiver Demo
Get reference to LED device...done.
Configure GPIO pin...done.
[00:00:00.252,838] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.252,899] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
[00:00:00.252,929] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.3 Build 99
[00:00:00.253,570] <inf> bt_hci_core: bt_dev_show_info: Identity: FC:89:B2:08:34:C4 (random)
[00:00:00.253,601] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.4 (0x0d) revision 0x0000, manufacturer 0x05f1
[00:00:00.253,662] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.4 (0x0d) subver 0xffff
Scan callbacks register...success.
Periodic Advertising callbacks register...Success.
Start scanning...success.
Start blinking LED...
Waiting for periodic advertising...
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -78  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[1;31m--- 1 messages dropped ---
[0m[DEVICE]: 7C:64:56:80:79:07 (public), AD evt type 3, Tx Pwr: 127, RSSI -85  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
--- 1 messages dropped ---
[DEVICE]: 4A:12:E0:C6:FC:EE (random), AD evt type 3, Tx Pwr: 127, RSSI -84  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 71:09:DA:C6:45:56 (random), AD evt type 0, Tx Pwr: 127, RSSI -88  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
--- 1 messages dropped ---
Waiting for periodic sync...
--- 5 messages dropped ---
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -78  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 18:AA:78:67:FB:1C (random), AD evt type 3, Tx Pwr: 127, RSSI -88  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -83  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 71:1C:E2:81:3A:F4 (random), AD evt type 0, Tx Pwr: 127, RSSI -88  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 54:44:A3:3E:0F:75 (public), AD evt type 3, Tx Pwr: 127, RSSI -86  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 1D:52:7E:91:89:DA (random), AD evt type 3, Tx Pwr: 127, RSSI -67  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 4A:12:E0:C6:FC:EE (random), AD evt type 3, Tx Pwr: 127, RSSI -84  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 62:9B:FD:AD:1A:21 (random), AD evt type 0, Tx Pwr: 127, RSSI -90  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 7C:64:56:80:79:07 (public), AD evt type 3, Tx Pwr: 127, RSSI -87  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -87  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 1D:52:7E:91:89:DA (random), AD evt type 3, Tx Pwr: 127, RSSI -78  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 4A:12:E0:C6:FC:EE (random), AD evt type 3, Tx Pwr: 127, RSSI -87  C:0 S:0 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -81  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: 73:80:25:CF:0F:0F (random), AD evt type 0, Tx Pwr: 127, RSSI -88  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
[DEVICE]: CC:55:33:1F:16:06 (random), AD evt type 0, Tx Pwr: 127, RSSI -86  C:1 S:1 D:0 SR:0 E:0 Prim: LE 1M, Secn: No packets, Interval: 0x0000 (0 us), SID: 255
PER_ADV_SYNC[0]: [DEVICE]: 31:F2:60:46:50:0B (random), tx_power 127, RSSI -35, CTE 0, data length 0, data: 
BIG INFO[0]: [DEVICE]: 31:F2:60:46:50:0B (random), sid 0x00, num_bis 2, nse 2, interval 0x0008 (10 ms), bn 1, pto 0, irc 2, max_pdu 4, sdu_interval 10000 us, max_sdu 4, phy LE 2M, without framing, not encrypted
ISO Channel 0x20000134 connected
ISO Channel 0x20000148 connected
BIG sync chan 0 successful.
Waiting for BIG sync chan 1...
BIG sync chan 1 successful.
BIG sync established.
Stop blinking LED.
Waiting for BIG sync lost chan 0...
Incoming data channel 0x20000134 flags 0xa seq_num 1 ts 2418962 len 0:  (counter value 0)
Incoming data channel 0x20000148 flags 0xa seq_num 1 ts 2418962 len 0:  (counter value 0)
Incoming data channel 0x20000134 flags 0xa seq_num 2 ts 2428963 len 0:  (counter value 0)
Incoming data channel 0x20000148 flags 0xa seq_num 2 ts 2428963 len 0:  (counter value 0)
Incoming data channel 0x20000134 flags 0xa seq_num 3 ts 2438962 len 0:  (counter value 0)
Incoming data channel 0x20000148 flags 0xa seq_num 3 ts 2438962 len 0:  (counter value 0)
Incoming data channel 0x20000134 flags 0xa seq_num 4 ts 2448962 len 0:  (counter value 0)
[1;31m--- 1 messages dropped ---
[0mIncoming data channel 0x20000134 flags 0xa seq_num 5 ts 2458962 len 0:  (counter value 0)
[1;31m--- 2 messages dropped ---
[0mIncoming data channel 0x20000148 flags 0xa seq_num 6 ts 2468962 len 0:  (counter value 0)
[1;31m--- 2 messages dropped ---
[0mIncoming data channel 0x20000134 flags 0xa seq_num 9 ts 2498962 len 0:  (counter value 0)
[1;31m--- 2 messages dropped ---
[0mIncoming data channel 0x20000134 flags 0xa seq_num 10 ts 2508961 len 0:  (counter value 0)
[1;31m--- 3 messages dropped ---
[0mIncoming data channel 0x20000148 flags 0xa seq_num 11 ts 2518961 len 0:  (counter value 0)
[1;31m--- 1 messages dropped ---
[0mIncoming data channel 0x20000148 flags 0xa seq_num 12 ts 2528961 len 0:  (counter value 0)

Compiled:

Possible issue: As @cvinayak mentioned in the discord message, the receive may drop the message data because it receives it out-of-sync.

cvinayak commented 1 year ago

Please check if the sample is able to transmit ISO data on making the below if clause false: https://github.com/zephyrproject-rtos/zephyr/blob/d9637673694419abcbbb04d8a012da9a8380866d/subsys/bluetooth/controller/ll_sw/isoal.c#L1584-L1586

i.e. have it as:

        /* Adjust payload number */
        if (session->sn && 0) {
            /* Not the first SDU in this session, so reference
whati001 commented 1 year ago

After adjusting the if clause and reflashing both boards (receive + broadcast), we sometimes receive the counter data. But it is really only sometimes, not always and reliably. Here are the logs from the iso_receive sample:

Incoming data channel 0x20000134 flags 0x9 seq_num 648 ts 8214653 len 4: 42040000 (counter value 1090)
--- 1 messages dropped ---
Incoming data channel 0x20000134 flags 0x9 seq_num 650 ts 8234654 len 4: 44040000 (counter value 1092)
--- 4 messages dropped ---
Incoming data channel 0x20000148 flags 0xa seq_num 651 ts 8244654 len 0:  (counter value 0)
--- 1 messages dropped ---
Incoming data channel 0x20000148 flags 0xa seq_num 652 ts 8254653 len 0:  (counter value 0)
--- 1 messages dropped ---
Incoming data channel 0x20000148 flags 0xa seq_num 653 ts 8264653 len 0:  (counter value 0)
--- 1 messages dropped ---
Incoming data channel 0x20000148 flags 0xa seq_num 655 ts 8284653 len 0:  (counter value 0)
--- 3 messages dropped ---
Incoming data channel 0x20000148 flags 0xa seq_num 656 ts 8294651 len 0:  (counter value 0)
Incoming data channel 0x20000134 flags 0x9 seq_num 657 ts 8304652 len 4: 4b040000 (counter value 1099)
--- 1 messages dropped ---
Incoming data channel 0x20000134 flags 0x9 seq_num 658 ts 8314652 len 4: 4c040000 (counter value 1100)
cvinayak commented 1 year ago

I am suspecting that the logging over UART can throttle the reception, starving available free buffers in the Controller due to slow processing in the application.

  1. Retain the if clause hack in the iso_broadcast
  2. Increase the logging buffer, CONFIG_LOG_BUFFER_SIZE=4096 in the iso_receive. Or make the logged message shorter so that UART transmission is short enough to process to received ISO data quick enough.
cvinayak commented 1 year ago

This is how I get, eventually logging starts dropping messages as it is not able to catch up: image

whati001 commented 1 year ago

Thank you very much for the hint. I will try to adjust the logging system.

But would not it be possible to simply send less data? Especially to cover my use case, a single channel send one message every 100ms would be sufficient. I am really not an ISO expert so please apologize this stupid question.

whati001 commented 1 year ago

Hi, unfortunately, I have to finish my master thesis quickly, therefore, I have to postpone this project for some time. Thank you very much for your help and.

cvinayak commented 1 year ago

This may be fix by use of CONFIG_BT_CTLR_ISOAL_SN_STRICT=n in the iso_broadcast sample introduced in https://github.com/zephyrproject-rtos/zephyr/pull/58717. Closing issue, reporter can re-open if issue persists.