BLE Throughput and Timing Issues

Hello, 

I am trying to create an application on the nRF5340 which samples data at 16kHz and packages + sends it over BLE. This requires a BLE throughput ~1Mbps, which I can get very easily when trying to throughput example application, but I can not achieve when communicating with my desktop application and a single nRF5340dk. My nRF53 chip is acting as the peripheral and sends  a notification using bt_gatt_notify() after a "sample_buf" is filled and packaged. I have ensured that my peripheral negotiates a connection interval of 7.5ms, the MTU size is increased, and I have increased the number of L2CAP buffers by settings the following configs:

# bluetooth 
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_PHY_UPDATE=y
CONFIG_BT=y
CONFIG_BT_RPMSG=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="LiteBEST" 
CONFIG_BT_P1_SECURITY_ENABLED=y
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_BUF_ACL_RX_SIZE=502
CONFIG_BT_L2CAP_TX_BUF_COUNT=20
CONFIG_BT_L2CAP_TX_MTU=498
CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_CONN_TX_MAX=20
CONFIG_BT_BUF_ACL_TX_COUNT=20
CONFIG_BT_BUF_ACL_TX_SIZE=502
CONFIG_BT_PERIPHERAL_PREF_MIN_INT=6
CONFIG_BT_PERIPHERAL_PREF_MAX_INT=6
#CONFIG_BT_PERIPHERAL_PREF_LATENCY=0
#CONFIG_BT_ATT_PREPARE_COUNT=4
#CONFIG_BT_PERIPHERAL_PREF_TIMEOUT=400
CONFIG_BT_GAP_AUTO_UPDATE_CONN_PARAMS=y
CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_AUTO_PHY_UPDATE=n

# adding addtional BLE things from random nordic dev form posts
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_SMP=y
CONFIG_BT_ATT_PREPARE_COUNT=5
CONFIG_BT_CTLR_RX_BUFFERS=18
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_HEAP_MEM_POOL_SIZE=2048
#CONFIG_BT_CONN_TX_MAX=20
#CONFIG_BT_L2CAP_TX_BUF_COUNT=20
#CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y

# ads131m04
CONFIG_SPI=y
CONFIG_ABC=y
CONFIG_ABC_TRIGGER=y
CONFIG_ABC_TRIGGER_THREAD_PRIO=0
CONFIG_NRFX_SPIM4=y
CONFIG_ABC_SENSOR_LOG_LEVEL=0
CONFIG_ABC_SAMPLE_COUNT=20
CONFIG_ABC_FRAME_SIZE_BYTES=3

# LED stuff
CONFIG_LED_STRIP=y
CONFIG_LED_STRIP_LOG_LEVEL_DBG=y
CONFIG_WS2812_STRIP=y

# fuel gauge stuff
CONFIG_FUEL_GAUGE=y

# remove SWO from J-TAG
CONFIG_NRF_TRACE_PORT=n

# log stuff
CONFIG_LOG=y
CONFIG_SENSOR=y

# over clocking stuff
CONFIG_NRFX_CLOCK=y

# optimization stuff
CONFIG_SPEED_OPTIMIZATIONS=y
CONFIG_SIZE_OPTIMIZATIONS=y
#CONFIG_NO_OPTIMIZATIONS=y
CONFIG_MAIN_STACK_SIZE=4096

# gpio stuff
CONFIG_GPIO_NRFX=y
CONFIG_NRFX_TIMER0=y
CONFIG_NRFX_GPIOTE=y

# prototype stuff
CONFIG_RTT_CONSOLE=y
CONFIG_PRINTK=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y 
CONFIG_STDOUT_CONSOLE=y
CONFIG_CLOCK_CONTROL=y
CONFIG_SOC_HFXO_CAP_INTERNAL=y
CONFIG_SOC_HFXO_CAP_INT_VALUE_X2=27
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_LOG_MODE_DEFERRED=y

The child image config is attached below:

#CONFIG_BT_LL_SOFTDEVICE=y
CONFIG_BT=y
CONFIG_BT_HCI_RAW=y
CONFIG_BT_HCI_RAW_RESERVE=1
CONFIG_BT_MAX_CONN=16
#CONFIG_BT_HCI=y
#CONFIG_BT_CTLR_ADVANCED_FEATURES=y

CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT=4000000
#CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
#CONFIG_BT_CTLR_TX_BUFFER_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=502
CONFIG_BT_BUF_ACL_TX_SIZE=502
#CONFIG_BT_CTLR_RX_BUFFERS=10
#CONFIG_BT_CTLR_TX_BUFFERS=10

CONFIG_IPC_SERVICE=y
CONFIG_MBOX=y
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_MAIN_STACK_SIZE=1024
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=1024


CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_SMP=y
CONFIG_BT_ATT_PREPARE_COUNT=5
CONFIG_BT_CTLR_RX_BUFFERS=18
#CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_DATA_LENGTH_MAX=502
CONFIG_HEAP_MEM_POOL_SIZE=2048


# Workaround: Unable to allocate command buffer when using K_NO_WAIT since
# Host number of completed commands does not follow normal flow control.
CONFIG_BT_BUF_CMD_TX_COUNT=10

# Enable and adjust the below value as necessary
CONFIG_BT_BUF_EVT_RX_COUNT=16
CONFIG_BT_L2CAP_TX_BUF_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=498

I know that some config changes need to be copied to the child but I'm not sure which ones exactly so I tried to copy most of them over. 

I begin the application by advertising on the 1M physical layer and then updating the connection parameters manually to 2M PHY after a connection is made. I know that this works because of the nRF BLE Sniffer logs (see below). 

The desktop application is receiving 2000 packets (each is 244 bytes) within 17 seconds (~200kbps) but it is expected to receive it under 4 seconds if we're actually able to get close to the expected throughput of ~1Mbps. 

litebest_blelog.pcapng

This is the BLE sniffer log I was able to collect which clearly shows the PHY layer getting updated but I am struggling to fully understand what I'm seeing. I know that the BLE link layer guarantees delivery and therefore the master must reply even though notify doesn't require a reply from the Host layer but I think there is a problem with the reply from Master (desktop app) as seen in the following snip of the above log:

Any help is greatly appreciated! 

Parents
  • Hey Susheel, 

    Attached is the minimum amount of code required to recreate the issue. This is the Lesson 3 exercise 2 nordic academy code and proj configs which can be found at this github link:
    https://github.com/NordicDeveloperAcademy/bt-fund/tree/main/lesson3/blefund_less3_exer2_solution

    and attached is my version of it with no changes from the github link above:

    min_example.zip

    This has been implemented on the nRF5340 dev kit and the logs are as follows when connecting from my phone using the nRF Connect mobile application:

    VCOM1:
    ```

    *** Booting Zephyr OS build v3.3.99-ncs1-1 ***
    [00:00:00.251,861] <inf> Lesson3_Exercise2: Starting Lesson 3 - Exercise 2

    [00:00:00.257,659] <inf> fs_nvs: 2 Sectors of 4096 bytes
    [00:00:00.257,659] <inf> fs_nvs: alloc wra: 0, fe8
    [00:00:00.257,690] <inf> fs_nvs: data wra: 0, 0
    [00:00:00.280,456] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:00.280,487] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
    [00:00:00.280,517] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 224.11902 Build 2231721665
    [00:00:00.281,341] <inf> bt_hci_core: No ID address. App must call settings_load()
    [00:00:00.282,318] <inf> bt_hci_core: Identity: EA:68:F4:23:65:77 (random)
    [00:00:00.282,348] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x2077, manufacturer 0x0059
    [00:00:00.282,379] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x2077
    [00:00:00.285,034] <inf> Lesson3_Exercise2: Bluetooth initialized
    [00:00:00.287,231] <inf> Lesson3_Exercise2: Advertising successfully started
    [00:11:32.408,050] <inf> Lesson3_Exercise2: Connected
    [00:11:32.408,081] <inf> Lesson3_Exercise2: Connection parameters: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    [00:11:32.556,610] <inf> Lesson3_Exercise2: MTU exchange successful
    [00:11:32.556,640] <inf> Lesson3_Exercise2: New MTU: 244 bytes
    [00:11:32.827,148] <inf> Lesson3_Exercise2: Data length updated. Length 27/27 bytes, time 2120/328 us
    [00:11:32.962,371] <inf> Lesson3_Exercise2: Connection parameters updated: interval 7.50 ms, latency 0 intervals, timeout 5000 ms
    [00:11:33.081,268] <inf> Lesson3_Exercise2: PHY updated. New PHY: 2M
    [00:11:33.224,304] <inf> Lesson3_Exercise2: Connection parameters updated: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    [00:11:44.751,922] <inf> Lesson3_Exercise2: Disconnected. Reason 19
    ```
    nRF Connect Mobile Application Log:
    ```
    nRF Connect, 2023-10-04 Nordic_Peripheral (EA:68:F4:23:65:77) V 22:07:08.299 Connecting to EA:68:F4:23:65:77... D 22:07:08.299 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M) D 22:07:08.467 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2) I 22:07:08.468 Connected to EA:68:F4:23:65:77 V 22:07:08.476 Discovering services... D 22:07:08.476 gatt.discoverServices() D 22:07:08.495 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED I 22:07:09.007 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms) I 22:07:09.077 PHY updated (TX: LE 2M, RX: LE 2M) D 22:07:09.162 [Callback] Services discovered with status: 0 I 22:07:09.163 Services discovered V 22:07:09.168 Generic Attribute (0x1801)

    • Service Changed [I] (0x2A05)

       Client Characteristic Configuration (0x2902)

    • Client Supported Features [R W] (0x2B29)
    • Database Hash [R] (0x2B2A)

    Generic Access (0x1800)

    • Device Name [R] (0x2A00)
    • Appearance [R] (0x2A01)
    • Peripheral Preferred Connection Parameters [R] (0x2A04)

    Nordic LED Button Service (00001523-1212-efde-1523-785feabcd123)

    • Button [N R] (00001524-1212-efde-1523-785feabcd123)

       Client Characteristic Configuration (0x2902)

    • LED [W] (00001525-1212-efde-1523-785feabcd123)

    D 22:07:09.169 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true) D 22:07:09.172 gatt.setCharacteristicNotification(00001524-1212-efde-1523-785feabcd123, true) I 22:07:09.266 Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms) V 22:07:19.672 Disconnecting... D 22:07:19.672 gatt.disconnect() D 22:07:19.683 [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0) I 22:07:19.683 Disconnected D 22:07:19.684 gatt.close() D 22:07:19.688 wait(200)
    ```

    Expected behavior is updated Data length to 251 as defined on line 74 of main.c. Actual behavior is seen in red text of VCOM1 output above of data length 27. Can you try to recreate this issue on your end? Thank you again for all of your help Susheel. 

    Respectfully,

    Brady 

Reply
  • Hey Susheel, 

    Attached is the minimum amount of code required to recreate the issue. This is the Lesson 3 exercise 2 nordic academy code and proj configs which can be found at this github link:
    https://github.com/NordicDeveloperAcademy/bt-fund/tree/main/lesson3/blefund_less3_exer2_solution

    and attached is my version of it with no changes from the github link above:

    min_example.zip

    This has been implemented on the nRF5340 dev kit and the logs are as follows when connecting from my phone using the nRF Connect mobile application:

    VCOM1:
    ```

    *** Booting Zephyr OS build v3.3.99-ncs1-1 ***
    [00:00:00.251,861] <inf> Lesson3_Exercise2: Starting Lesson 3 - Exercise 2

    [00:00:00.257,659] <inf> fs_nvs: 2 Sectors of 4096 bytes
    [00:00:00.257,659] <inf> fs_nvs: alloc wra: 0, fe8
    [00:00:00.257,690] <inf> fs_nvs: data wra: 0, 0
    [00:00:00.280,456] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:00.280,487] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
    [00:00:00.280,517] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 224.11902 Build 2231721665
    [00:00:00.281,341] <inf> bt_hci_core: No ID address. App must call settings_load()
    [00:00:00.282,318] <inf> bt_hci_core: Identity: EA:68:F4:23:65:77 (random)
    [00:00:00.282,348] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x2077, manufacturer 0x0059
    [00:00:00.282,379] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x2077
    [00:00:00.285,034] <inf> Lesson3_Exercise2: Bluetooth initialized
    [00:00:00.287,231] <inf> Lesson3_Exercise2: Advertising successfully started
    [00:11:32.408,050] <inf> Lesson3_Exercise2: Connected
    [00:11:32.408,081] <inf> Lesson3_Exercise2: Connection parameters: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    [00:11:32.556,610] <inf> Lesson3_Exercise2: MTU exchange successful
    [00:11:32.556,640] <inf> Lesson3_Exercise2: New MTU: 244 bytes
    [00:11:32.827,148] <inf> Lesson3_Exercise2: Data length updated. Length 27/27 bytes, time 2120/328 us
    [00:11:32.962,371] <inf> Lesson3_Exercise2: Connection parameters updated: interval 7.50 ms, latency 0 intervals, timeout 5000 ms
    [00:11:33.081,268] <inf> Lesson3_Exercise2: PHY updated. New PHY: 2M
    [00:11:33.224,304] <inf> Lesson3_Exercise2: Connection parameters updated: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    [00:11:44.751,922] <inf> Lesson3_Exercise2: Disconnected. Reason 19
    ```
    nRF Connect Mobile Application Log:
    ```
    nRF Connect, 2023-10-04 Nordic_Peripheral (EA:68:F4:23:65:77) V 22:07:08.299 Connecting to EA:68:F4:23:65:77... D 22:07:08.299 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M) D 22:07:08.467 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2) I 22:07:08.468 Connected to EA:68:F4:23:65:77 V 22:07:08.476 Discovering services... D 22:07:08.476 gatt.discoverServices() D 22:07:08.495 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED I 22:07:09.007 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms) I 22:07:09.077 PHY updated (TX: LE 2M, RX: LE 2M) D 22:07:09.162 [Callback] Services discovered with status: 0 I 22:07:09.163 Services discovered V 22:07:09.168 Generic Attribute (0x1801)

    • Service Changed [I] (0x2A05)

       Client Characteristic Configuration (0x2902)

    • Client Supported Features [R W] (0x2B29)
    • Database Hash [R] (0x2B2A)

    Generic Access (0x1800)

    • Device Name [R] (0x2A00)
    • Appearance [R] (0x2A01)
    • Peripheral Preferred Connection Parameters [R] (0x2A04)

    Nordic LED Button Service (00001523-1212-efde-1523-785feabcd123)

    • Button [N R] (00001524-1212-efde-1523-785feabcd123)

       Client Characteristic Configuration (0x2902)

    • LED [W] (00001525-1212-efde-1523-785feabcd123)

    D 22:07:09.169 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true) D 22:07:09.172 gatt.setCharacteristicNotification(00001524-1212-efde-1523-785feabcd123, true) I 22:07:09.266 Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms) V 22:07:19.672 Disconnecting... D 22:07:19.672 gatt.disconnect() D 22:07:19.683 [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0) I 22:07:19.683 Disconnected D 22:07:19.684 gatt.close() D 22:07:19.688 wait(200)
    ```

    Expected behavior is updated Data length to 251 as defined on line 74 of main.c. Actual behavior is seen in red text of VCOM1 output above of data length 27. Can you try to recreate this issue on your end? Thank you again for all of your help Susheel. 

    Respectfully,

    Brady 

Children
No Data
Related