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! 

  • Hi Brady,

    Fine tuning throughput is no easy business. But it looks like you have been on the right track all along. You seems to understand the need to calibrate connection interval, parameters and buffer sizes. 

    In terms of child image, the below config should be enough with the rest set to defaults

    CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT=4000000
    
    CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
    CONFIG_BT_BUF_ACL_RX_SIZE=502
    CONFIG_BT_BUF_ACL_TX_SIZE=502
    
    CONFIG_BT_MAX_CONN=2

    I strongly recommend you to take sniffer log of the throughput sample as well and compare that with the sniffer log you got. If the connection interval, 

    There can also be bottlenecks in pre and post processing of the data/buffer you are trying to transfer on your peripheral side. I use SystemView to get a visual understanding of timings of each thread/ISR running. It can be possible that you have all the configs set correctly but your peripheral pre/post packet processing is the bottle neck. you can compare the timings of threads by running Throughput example in systemview and also your application to see if you have introduced any processing bottlenecks in some contexts.

  • Hey Susheel,

    Thank you for the quick reply. I've learned a few new things by following the nordic dev academy lesson 3 exercise 2: 
    https://academy.nordicsemi.com/courses/bluetooth-low-energy-fundamentals/lessons/lesson-3-bluetooth-le-connections/topic/blefund-lesson-3-exercise-2/

    I linked my wireshark capture in the original post by using the nRF BLE sniffer I created from an nRF52840 dev kit. The capture starts with some malformed packets, but that is because I didn't have the sniffer close enough to both devices. If you scroll down, you can see the advertising restarts, and then a good connection is made. You can see in packet no. 845 that my PC (ble client, master) requests data length extension but the embedded system, nRF5340 w/ the above configs shown in the original post, replies in packet no. 856 with a max TX & RX octet of 27. 

    By following the nordic dev academy lesson 3 exercise 2 I was able to initiate another data length extension request from the server side and the call to bt_conn_le_data_len_update() doesn't return an error but my own server doesn't honor its own request because when I debug and set a break point in  le_data_len_change() in the hci_core.c file the net_buf param doesn't contain the expected values for length and time which are set correctly in the bt_conn_le_data_len_update(). Its just reverting back to the default len and timing values of 27 bytes as seen in the attached wireshark capture. If you could help me understand this problem first I think I might be able to get more throughput regardless of the master repsonse times I first highlighted in the original post. 

    Greatly apprciated,
    Brady
    ---

    Functions from the academy lesson 3 exercise 2 used to request and monitor data length extension requests/updates:

    static void update_data_length(struct bt_conn *conn)
    {
    	int err;
    	struct bt_conn_le_data_len_param data_len = {
    		.tx_max_len = BT_GAP_DATA_LEN_MAX,
    		.tx_max_time = BT_GAP_DATA_TIME_MAX,
    	};
    	err = bt_conn_le_data_len_update(conn, &data_len);
    	if (err) {
    		LOG_ERR("data_len_update failed (err %d)", err);
    		return;
    	}
    	LOG_INF("Data length update successful");
    }

    void on_le_data_len_updated(struct bt_conn *conn, struct bt_conn_le_data_len_info *info)
    {
        uint16_t tx_len     = info->tx_max_len;
        uint16_t tx_time    = info->tx_max_time;
        uint16_t rx_len     = info->rx_max_len;
        uint16_t rx_time    = info->rx_max_time;
        LOG_INF("Data length updated. Length %d/%d bytes, time %d/%d us", tx_len, rx_len, tx_time, rx_time);
    }

    BT_CONN_CB_DEFINE(conn_callbacks) = {
    	.connected = connected,
    	.disconnected = disconnected,
    	.le_phy_updated = le_phy_updated,
    	.le_param_updated = on_le_param_updated,
    	.le_data_len_updated = on_le_data_len_updated,
    };

    ---

    Console output:

    ```
    Connected
    TX power level: 0
    [00:00:21.158,142] <inf> app: PHY update successful
    Connected as peripheral
    Conn. interval is 6 units
    [00:00:22.158,905] <inf> app: MTU exchange successful
    [00:00:22.158,905] <inf> app: New MTU: 244 bytes
    LE PHY updated: TX PHY LE 1M, RX PHY LE 1M
    [00:00:22.158,996] <inf> app: Data length updated. Length 27/27 bytes, time 2120/2120 us
    [00:00:22.376,495] <inf> app: Connection parameters updated: interval 15.00 ms, latency 0 intervals, timeout 9600 ms
    [00:00:24.176,300] <inf> app: Connection parameters updated: interval 7.50 ms, latency 0 intervals, timeout 420 ms
    ```

  • 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 

  • Brady,

    I compiled your project and flashed it to nRF53 DK. I had a throughput central example flashed to another nRF DK and I can see that the data length is updated as normal to 251

    I also tried to run it against the central which is nrf Connect for mobile app and I still get the data length updated to 251

    So I am not sure why you are seeing those results. Which central are you testing it with when you see the data length is negotiated and set to 27 bytes. Are you use that this central supports DLE?

  • I am using the nRF5340 dev kit, PCA10095, as the server, and my phone is a Google Pixel 7 Pro which supports DLE. As stated earlier, the server is the one who is refusing to update the link layer's data length according to the ble sniffer logs from Wireshark. Are you sure you're running the code from the zip file I linked earlier? Our logs do not look the same. 

    Current SDK: 2.4.2
    Current Toolchain: v2.4.1

    My log from dev kit:
    ```

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

    [00:00:00.269,104] <inf> fs_nvs: 2 Sectors of 4096 bytes
    [00:00:00.269,104] <inf> fs_nvs: alloc wra: 0, fd0
    [00:00:00.269,134] <inf> fs_nvs: data wra: 0, 1c
    [00:00:00.291,870] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    [00:00:00.291,870] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
    [00:00:00.291,900] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 224.11902 Build 2231721665
    [00:00:00.292,724] <inf> bt_hci_core: No ID address. App must call settings_load()
    [00:00:00.293,762] <inf> bt_hci_core: Identity: EA:68:F4:23:65:77 (random)
    [00:00:00.293,792] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x2077, manufacturer 0x0059
    [00:00:00.293,823] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x2077
    [00:00:00.295,745] <inf> Lesson3_Exercise2: Bluetooth initialized
    [00:00:00.297,912] <inf> Lesson3_Exercise2: Advertising successfully started
    [00:02:32.456,878] <inf> Lesson3_Exercise2: Connected
    [00:02:32.456,909] <inf> Lesson3_Exercise2: Connection parameters: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    [00:02:32.614,135] <inf> Lesson3_Exercise2: MTU exchange successful
    [00:02:32.614,166] <inf> Lesson3_Exercise2: New MTU: 244 bytes
    [00:02:32.884,735] <inf> Lesson3_Exercise2: Data length updated. Length 27/27 bytes, time 2120/328 us
    [00:02:33.019,470] <inf> Lesson3_Exercise2: Connection parameters updated: interval 7.50 ms, latency 0 intervals, timeout 5000 ms
    [00:02:33.146,392] <inf> Lesson3_Exercise2: PHY updated. New PHY: 2M
    [00:02:33.311,828] <inf> Lesson3_Exercise2: Connection parameters updated: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
    ```

    Everything in green is something from my log which is not present in your log. The timeout in orange is also different between our logs.  Thanks again for your help. 

Related