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
  • 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. 

  • To reiterate, the issue I'm observing is within the zephyr hci code because the call to create the hci command is correct and the created net buf is correct but the network core is not honoring the parameters passed. I see tons of messages dropped when I enable CONFIG_BT_HCI_CORE_LOG_LEVEL_DBG. This issue does not happen for me when I use the nRF52840 even though my code and configs are the exact same. It is just a problem going from the application core to the network core on the nRF5340. Could this be a memory issue? Attached are the info and dbg logs from the hci on the application core. 

    [00:00:00.263,366] <dbg> bt_hci_core: bt_hci_driver_register: Registered RPMsg
    *** Booting Zephyr OS build v3.3.99-ncs1-1 ***
    --- 98 messages dropped ---
    [00:00:00.301,849] <inf> Lesson3_Exercise2: Bluetooth initialized
    --- 306 messages dropped ---
    [00:00:00.304,138] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    [00:00:00.304,138] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    [00:00:00.304,168] <dbg> bt_hci_core: send_cmd: Sending command 0x2009 (buf 0x200105fc) to driver
    --- 3 messages dropped ---
    [00:00:00.304,534] <dbg> bt_hci_core: bt_recv: buf 0x200105fc len 6
    [00:00:00.304,565] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2009
    [00:00:00.304,595] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2009 status 0x00 buf 0x200105fc
    [00:00:00.304,656] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200105fc opcode 0x2009 len 1
    [00:00:00.304,687] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
    [00:00:00.304,718] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:00.304,748] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200105fc opcode 0x200a len 4
    [00:00:00.304,779] <dbg> bt_hci_core: process_events: count 2
    [00:00:00.304,779] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:00.304,809] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    [00:00:00.304,840] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    [00:00:00.304,840] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x200105fc) to driver
    [00:00:00.304,870] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 4 type 0
    [00:00:00.304,901] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:00.304,931] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    [00:00:00.305,358] <dbg> bt_hci_core: bt_recv: buf 0x200105fc len 6
    [00:00:00.305,389] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
    [00:00:00.305,419] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x200105fc
    [00:00:00.305,480] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200105fc opcode 0x200a len 1
    [00:00:00.305,511] <inf> Lesson3_Exercise2: Advertising successfully started
    [00:00:00.335,296] <dbg> bt_hci_core: bt_recv: buf 0x2000eab0 len 68
    [00:00:00.335,327] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:00.335,327] <dbg> bt_hci_core: rx_work_handler: buf 0x2000eab0 type 1 len 68
    [00:00:00.335,357] <dbg> bt_hci_core: hci_event: event 0x3e
    [00:00:00.335,388] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x08
    [00:00:00.335,388] <dbg> bt_ecc: bt_hci_evt_le_pkey_complete: status: 0x00
    [00:00:08.565,673] <dbg> bt_hci_core: bt_recv: buf 0x2000eab0 len 33
    --- 30 messages dropped ---
    [00:00:08.567,047] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    [00:00:08.567,108] <dbg> bt_hci_core: send_cmd: Sending command 0x2022 (buf 0x2001061c) to driver
    [00:00:08.567,108] <dbg> bt_hci_core: bt_send: buf 0x2001061c len 9 type 0
    [00:00:08.567,169] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:08.567,169] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:08.567,199] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    [00:00:08.567,443] <dbg> bt_hci_core: bt_recv: buf 0x2001061c len 8
    [00:00:08.567,474] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2022
    [00:00:08.567,504] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2022 status 0x00 buf 0x2001061c
    [00:00:08.567,535] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2001061c opcode 0x2022 len 3
    [00:00:08.567,596] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
    [00:00:08.567,626] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:08.567,657] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200105fc opcode 0x2016 len 5
    [00:00:08.567,687] <dbg> bt_hci_core: process_events: count 3
    [00:00:08.567,718] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:08.567,718] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    [00:00:08.567,749] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    [00:00:08.567,779] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x200105fc) to driver
    [00:00:08.567,810] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 5 type 0
    [00:00:08.567,840] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:08.567,871] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:08.567,901] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 11 type 2
    [00:00:08.567,962] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    [00:00:08.568,237] <dbg> bt_hci_core: bt_recv: buf 0x200105fc len 6
    [00:00:08.568,267] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
    [00:00:08.568,298] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x200105fc
    [00:00:08.568,328] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200105fc opcode 0x2016 len 0
    [00:00:08.652,557] <dbg> bt_hci_core: bt_recv: buf 0x20010314 len 7
    --- 3 messages dropped ---
    [00:00:08.742,095] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:08.742,095] <dbg> bt_hci_core: rx_work_handler: buf 0x2000fff0 type 3 len 11
    [00:00:08.742,126] <dbg> bt_hci_core: hci_acl: buf 0x2000fff0
    [00:00:08.742,126] <dbg> bt_hci_core: hci_acl: handle 15 len 7 flags 2
    [00:00:08.742,187] <inf> Lesson3_Exercise2: MTU exchange successful
    [00:00:08.742,218] <inf> Lesson3_Exercise2: New MTU: 244 bytes
    [00:00:08.742,218] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15
    [00:00:08.742,248] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
    [00:00:08.742,248] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:08.742,279] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    [00:00:08.742,279] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    [00:00:08.787,292] <dbg> bt_hci_core: bt_recv: buf 0x2000fff0 len 15
    [00:00:08.787,322] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:08.787,322] <dbg> bt_hci_core: rx_work_handler: buf 0x2000fff0 type 3 len 15
    [00:00:08.787,353] <dbg> bt_hci_core: hci_acl: buf 0x2000fff0
    [00:00:08.787,353] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2
    [00:00:08.787,506] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15
    [00:00:08.787,536] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
    [00:00:08.787,536] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:08.787,567] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    [00:00:08.787,567] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    [00:00:08.787,628] <dbg> bt_hci_core: process_events: count 3
    [00:00:08.787,658] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:08.787,658] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:08.787,689] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:08.787,719] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 22 type 2
    [00:00:08.787,780] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    [00:00:08.922,454] <dbg> bt_hci_core: bt_recv: buf 0x20010314 len 7
    [00:00:08.922,454] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    [00:00:08.922,485] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1
    --- 3 messages dropped ---
    [00:00:08.922,668] <dbg> bt_hci_core: hci_event: event 0x3e
    [00:00:08.922,668] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04
    [00:00:08.967,102] <dbg> bt_hci_core: bt_recv: buf 0x2000fff0 len 15
    [00:00:08.967,132] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:08.967,132] <dbg> bt_hci_core: rx_work_handler: buf 0x2000fff0 type 3 len 15
    [00:00:08.967,163] <dbg> bt_hci_core: hci_acl: buf 0x2000fff0
    --- 13 messages dropped ---
    [00:00:09.012,664] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:09.012,664] <dbg> bt_hci_core: rx_work_handler: buf 0x2000eab0 type 1 len 13
    [00:00:09.012,695] <dbg> bt_hci_core: hci_event: event 0x3e
    [00:00:09.012,695] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x07
    [00:00:09.012,725] <dbg> bt_hci_core: le_data_len_change: max. tx: 27 (2120us), max. rx: 27 (328us)
    [00:00:09.012,756] <inf> Lesson3_Exercise2: Data length updated. Length 27/27 bytes, time 2120/328 us
    [00:00:09.057,434] <dbg> bt_hci_core: bt_recv: buf 0x20010314 len 7
    [00:00:09.057,434] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    [00:00:09.057,464] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1
    [00:00:09.057,556] <dbg> bt_hci_core: bt_recv: buf 0x2000fff0 len 15
    [00:00:09.057,586] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:09.057,617] <dbg> bt_hci_core: rx_work_handler: buf 0x2000fff0 type 3 len 15
    [00:00:09.057,647] <dbg> bt_hci_core: hci_acl: buf 0x2000fff0
    [00:00:09.057,647] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2
    [00:00:09.057,769] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15
    [00:00:09.057,800] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
    [00:00:09.057,800] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:09.057,830] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    --- 7 messages dropped ---
    [00:00:09.147,186] <dbg> bt_hci_core: bt_recv: buf 0x2000eab0 len 12
    [00:00:09.147,247] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:09.147,247] <dbg> bt_hci_core: rx_work_handler: buf 0x2000eab0 type 1 len 12
    --- 2 messages dropped ---
    [00:00:09.200,286] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    --- 14 messages dropped ---
    [00:00:09.200,347] <dbg> bt_hci_core: process_events: count 3
    --- 16 messages dropped ---
    [00:00:09.230,072] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    --- 18 messages dropped ---
    [00:00:09.245,300] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    [00:00:09.245,300] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    --- 24 messages dropped ---
    [00:00:09.260,498] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    --- 18 messages dropped ---
    [00:00:09.275,238] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    --- 18 messages dropped ---
    [00:00:09.290,222] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    [00:00:09.290,252] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    --- 17 messages dropped ---
    [00:00:09.305,206] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    --- 19 messages dropped ---
    [00:00:09.320,251] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    --- 4 messages dropped ---
    [00:00:09.320,404] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 13 type 2
    --- 18 messages dropped ---
    [00:00:09.335,418] <dbg> bt_hci_core: bt_send: buf 0x2001093c len 31 type 2
    [00:00:09.335,479] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 25 type 2
    --- 15 messages dropped ---
    [00:00:09.357,727] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    --- 4 messages dropped ---
    [00:00:09.357,849] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:09.357,879] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 13 type 2
    [00:00:09.357,940] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    [00:00:09.372,283] <dbg> bt_hci_core: bt_recv: buf 0x20010314 len 7
    [00:00:09.372,314] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    [00:00:09.372,314] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1
    [00:00:09.372,436] <dbg> bt_hci_core: bt_recv: buf 0x2000fff0 len 13
    [00:00:09.372,467] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:09.372,497] <dbg> bt_hci_core: rx_work_handler: buf 0x2000fff0 type 3 len 13
    [00:00:09.372,497] <dbg> bt_hci_core: hci_acl: buf 0x2000fff0
    [00:00:09.372,528] <dbg> bt_hci_core: hci_acl: handle 15 len 9 flags 2
    [00:00:09.372,619] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15
    [00:00:09.372,619] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
    [00:00:09.372,650] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200105fc
    [00:00:09.372,680] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
    [00:00:09.372,680] <dbg> bt_hci_core: bt_send: buf 0x200105fc len 8 type 0
    [00:00:09.372,772] <dbg> bt_hci_core: process_events: count 3
    [00:00:09.372,772] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:09.372,802] <dbg> bt_hci_core: process_events: ev->state 0
    [00:00:09.372,802] <dbg> bt_hci_core: process_events: ev->state 4
    [00:00:09.372,833] <dbg> bt_hci_core: bt_send: buf 0x20011d7c len 14 type 2
    [00:00:09.372,894] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    [00:00:09.387,268] <dbg> bt_hci_core: bt_recv: buf 0x20010314 len 7
    [00:00:09.387,298] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    [00:00:09.387,329] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1
    [00:00:09.432,312] <dbg> bt_hci_core: bt_recv: buf 0x2000eab0 len 12
    [00:00:09.432,342] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    [00:00:09.432,373] <dbg> bt_hci_core: rx_work_handler: buf 0x2000eab0 type 1 len 12
    [00:00:09.432,373] <dbg> bt_hci_core: hci_event: event 0x3e
    [00:00:09.432,403] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
    [00:00:09.432,403] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 15
    [00:00:09.432,434] <inf> Lesson3_Exercise2: Connection parameters updated: interval 45.00 ms, latency 0 intervals, timeout 5000 ms

    The above screenshot is showing that the slave is requesting the wrong data length. This is clearly a problem with the nRF5340's hci command not being honored when it is parsed by the network core. 

    I've tried this with the ncs v2.4.1 and v2.3.0 and the issue is present in both versions for me. If you could get this working with ncs v2.4.1 that would be preferable for me. If you get this working please send your working code over in a zip. 

    Further proof that my phone is able to do DLE below. This is an issue with the nRF5340. 

    Thank you,

    Brady

  • Another update! This one is great news. I get the expected behavior from the nRF5340 when I flash the application core and THEN flash the net core with the hci_rpmsg image manually. I did this in order to try and debug the hci_rpmsg tx_thread and I realized that we get the expected behavior!!! YAY! Here are the attached screenshots to show the actual/expected behavior:

    ^ slave, nRF5340 requesting the correct TX data length of 251 octets. 

    ^ the application core updating the ble host connection object with the negotiated 251 LL data length!!! 

    Because flashing the app then net core images one at a time fixed the issue I am inclined to believe this is a build/linking issue. This is something I can work around for now so I will mark this as resolved if you would like.

    ---
    Tools Used: 

    tool chain and SDK are both v2.4.1
    Windows 11, Version 10.0.22621 Build 22621
    nRF5340-DK, PCA10095
    nRF Connect for VS Code v2023.9.336
    Pixel 7 Pro, android version 13, build #TQ3A.230901.001.C2
    Entire Project zip w/ build: please_work_this_time.zip

  • I retried your please_work_this_time.zip, removed the build folder and prestine built it (clean build) with a configuration of the merge flash to both APP and NET core. The usual way and it still works at my end 

    Not sure why you see the difference but atleast you have a working setup for now. So yes, please mark your previous reply as verified so other forum members can see the alternative build configuration when needed.

  • This was actually very interesting! I can see an asymmetric link here!
    [00:00:09.012,756] <inf> Lesson3_Exercise2: Data length updated. Length 27/27 bytes, time 2120/328 us

    Somehow I can't reproduce it but I really want to for maximizing TX time.

Reply Children
No Data
Related