DLE goes to 27 when using PHY_2M

[plippo]

Hello,

We're trying to optimize the data transfer rate from our nRF52832 based peripheral device to the mobile phone. Tested with two different BLE >= 5 Android phones we encountered a weird behavior and would like to get your help to resolve it.

Our device uses SoftDevice s132 v6.1.1 and SDK 15.3 and in the beginning of the connection we set

MTU: 161 (RAM limited)
DLE: rx: 165 , tx: 165

The phone that I use (OnePlus 8) approves the MTU and requests DLE rx: 251, tx: 27 so the final negotiation results 165 (periph->central), 27 (central->periph). The phone is typically content using PHY_1M and this results the throughput (measured with Ellisys sniffer) of about 60kB/s which is pretty much what I would hope for it.

As soon as I change the connection to PHY_2M (either with nRF Connect debug mode on the phone or requesting it from the device software) the speed drops by about 50% resulting around 30-35 kB/s. The sniffer revealed the reason to be that the data length was dropped to 27 resulting a lot of very small packets. Initially I thought that the reason for this was the nrf_ble_gatt -module which I had enabled to take care of DLE and MTU settings since the RTT logs revealed some GATT module printouts and there was this really weird comment in the code ("The SoftDevice only supports symmetric RX/TX data length settings."), so I removed the GATT module and replaced the funtionality with direct SD calls.

However even after specifically setting DLE to (165,165) the connection defaults to 27 byte packets and really slow connection as soon as I set PHY_2M. This is really weird since the 1M PHY works great and I didn't think there was any extra limitations on DLE because of different PHYs. I did try to search for help in SoftDevice specification but did not find anything that sounded relevant...

Thank you in advance,

Petri L.
ps. I have the Ellisys logs available (the PHY_2M case with GATT module) but would like to keep them confidential if possible. 

 

[Hung Bui]

Hi Petri, 

You can move this thread to Private if you want to provide confidential information. Please click on "Go Private" button. 

In the sniffer trace, please check for which side send the request to change the DLE size. 

It could be the issue on the phone that it doesn't support long DLE size on 2Mbps PHY. 

[plippo]

I'm away from the sniffer and managed to distill the case to the minimal change of calling or not calling the sd_ble_gap_phy_update()-function after receiving BLE_GAP_EVT_CONNECTED.  The code calls sd_ble_gap_data_length_update() after receiving BLE_GATTC_EVT_EXCHANGE_MTU_RSP as well as BLE_GAP_EVT_PHY_UPDATE (when status == 0). The row with DataLengthSet is the one where the call to sd_ble_gap_data_length_update happens.

With PHY 2M:

00:00:14 BLE GAP: onConnect to 7A:A7:A8:35:1E:5C (Random private resolvable)
00:00:15 BLE event: 0x3A - Exchange MTU Response event
00:00:15 BLE_GATTC_EVT_EXCHANGE_MTU_RSP server_rx_mtu: 161
00:00:15 BleGapService::DataLengthSet
00:00:15 BLE event: 0x22 - BLE_GAP_EVT_PHY_UPDATE
00:00:15 BLE_GAP_EVT_PHY_UPDATE (RX:2, TX:2, status:0)
00:00:15 BleGapService::DataLengthSet
00:00:15 BLE event: 0x24 - Data length update
00:00:15 BLE_GAP_EVT_DATA_LENGTH_UPDATE: max_tx_octets: 165, max_rx_octets: 27
00:00:15 BLE event: 0x12 - Connection Parameters updated
00:00:15 BLE_GAP_EVT_CONN_PARAM_UPDATE. min_conn_interval: 6, max_conn_interval: 6, slave_latency: 0, conn_sup_timeout: 500
00:00:16 BLE event: 0x12 - Connection Parameters updated
00:00:16 BLE_GAP_EVT_CONN_PARAM_UPDATE. min_conn_interval: 36, max_conn_interval: 36, slave_latency: 0, conn_sup_timeout: 500

Same code without requesting phy_update (so the speed stays PHY_1M):

00:00:05 BLE GAP: onConnect to 42:B6:5F:10:19:CC (Random private resolvable)
00:00:05 BLE event: 0x3A - Exchange MTU Response event
00:00:05 BLE_GATTC_EVT_EXCHANGE_MTU_RSP server_rx_mtu: 161
00:00:05 BleGapService::DataLengthSet
00:00:05 BLE event: 0x24 - Data length update
00:00:05 BLE_GAP_EVT_DATA_LENGTH_UPDATE: max_tx_octets: 165, max_rx_octets: 27
00:00:06 BLE event: 0x12 - Connection Parameters updated
00:00:06 BLE_GAP_EVT_CONN_PARAM_UPDATE. min_conn_interval: 6, max_conn_interval: 6, slave_latency: 0, conn_sup_timeout: 500
00:00:06 BLE event: 0x12 - Connection Parameters updated
00:00:06 BLE_GAP_EVT_CONN_PARAM_UPDATE. min_conn_interval: 36, max_conn_interval: 36, slave_latency: 0, conn_sup_timeout: 500

In both cases I receive the event BLE_GAP_EVT_DATA_LENGTH_UPDATE (max_tx_octets: 165, max_rx_octets: 27) indicating that the DLE is setup identically but the xfer speed is half of 1M case (I'm not with the sniffer right now so I can't confirm it with it).

EDIT: I confirmed same behavior with two different phones: OnePlus 8 (Android 11) and Sony XPeria XZ Premium (Android 9) so it does not feel like a phone quirk.

[Hung Bui]

Hi Petri, 

Could you also send the 1M sniffer for comparison ? 

From what I can find here in the last packet before the peers stopped transmission in a connection event is that the MD (More Data) bit is not set. This means the Peripheral doesn't want to send anything further. 

There could be 2 reasons for this: 

- There is no data queued. We need to take a look at how you queued your data, have you queued more data when you receive BLE_GATTS_EVT_HVN_TX_COMPLETE event ? 
- Your event length configuration was too short. Could you please check NRF_SDH_BLE_GAP_EVENT_LENGTH configuration in sdk_config.h and check if you used that number in nrf_sdh_ble_default_cfg_set()  ? 

[plippo]

My code reads next piece of data to send as soon as previous has been queued. The sending code calls in the loop with max 1ms delay until the packet goes thru (which trigger yet another send):

// Try to send until there is buffers available (with wait, so we don't consume CPU)

while (true)

{

    error = sd_ble_gatts_hvx(m_conn_handle, &hvx_params);

    if (error != NRF_ERROR_RESOURCES) break;

    threadSleepMs(1);

}

The debug logging over the while look indicates that the code handles about 7-8 sends on first try and then waits for 30-40 ms until it succeeds.


Event length should be ok (and indeed it works with PHY_1M):

#define NRF_SDH_BLE_GAP_EVENT_LENGTH 36

[Hung Bui]

Hi Petri, 

Please send the 1Mbps trace.

Could you try increasing the NRF_SDH_BLE_GAP_EVENT_LENGTH  ? 

If you test the throughput example in the NRF5 SDK you can find that at 2M PHY the throughput can be achieved is around 1.4Mbps. 

[plippo]

Hello,

Got back to office and did the following test runs (Ellisys files as attachment). Short result: No changes in behaviour from previous tests.



- 1M1M (request 1M on rx & tx) => fast

- 2M2M (request 2M on rx & tx) => slow

- 2MxM (request 2M on tx, 1M or 2M on rx) => slow

- RetAutoOnReq: Don't ask for PHY, just if requested set rx & tx to BLE_GAP_PHY_AUTO (phone chooses 1M) => fast

- 2M2M_EL400 (request 2M on rx & tx, set NRF_SDH_BLE_GAP_EVENT_LENGTH to 400) => slow

PHY2MTests.zip

[Hung Bui]

Hi Petri, 

In your code:

while (true)
{
    error = sd_ble_gatts_hvx(m_conn_handle, &hvx_params);
    if (error != NRF_ERROR_RESOURCES) break;
    threadSleepMs(1);
}

What happens when sd_ble_gatts_hvx returns NRF_SUCCESS  ? From what I can see it will just break out of the while loop. 
How do you queue the next packets when the first one is successfully queued ? 
Please try to test with just queueing more data right away when the previous packet is successfully queued. 

[plippo]

This loop resides in a "dlServiceSend" function which is part of our communication stack. There is a thread outside that calls that code in a loop until there is no more data to send. So the next call comes in as soon as the while loop (and the function) is exited.

In my debug printouts it is clearly visible that the waiting happens in the while loop above until the connection interval is over (usually around 35 ms). So in short there is data waiting to be sent which causes it to wait in that while loop because sd_ble_gatts_hvx returns NRF_ERROR_RESOURCES.

[Hung Bui]

Hi Petri, 

Could you try to reproduce the issue on a simple application so that we can have a test here ? 
I also attached here a small example that you can test. It's a modified version of ble_app_uart that send 100kB of data (500 packets of 200bytes each). At 7.5ms I can see the throughput of around 100kB/s when the phone is close. 
You can test by connect using the nRFToolbox app =>Uart Profile to connect, and then click button 0 on the nRF52DK. Or you can use NRF Connect, and enable CCCD before testing. 

The fundamental difference I can observe here is that the MD bit at the end of the connection event is set on the last packet from the slave, meaning the slave can send more data but the central didn't want to receive more. 

When in your case the slave didn't want to send more data. The example is from SDK v17.0.2 and for nRF52832 DK. Please use RTT logging when testing. 

ble_app_uart - Througput.zip

[plippo]

Hello,

I finally found the DK in our office and managed to run some tests. I did three runs with the following settings:

1. Your sample unmodified (I did have to give Softdevice 256 bytes more RAM)
2. sample with conn_interval min & max set to 45ms (to match what our settings default to when connecting to Android)
3. Conn interval of 45ms and DLE set to match ours (165)

In all cases the transfer speed was high and the packets are transferred over most of the connection interval.

I'm really running out of ideas on what could cause our weird behavior. Also a curious detail: in the 165 DLE test the DLE gets set to 165 / 165 on 3rd try or something. (initially 165 / 27 since phone wants 251 / 27).


UART_Test_45ms.bttUART_Test_45ms_DLE165.bttUART_Test_orig.btt


EDIT: An idea occurred to me. I'm using a separate thread for handling SD events which calls nrf_sdh_evts_poll()  in a loop when triggered in SD_EVT_IRQHandler. The event thread has the same priority as my sending thread, but it should get time to run during the sleep of the send thread. Assuming the event thread is not being run properly, is it possible that the softdevice stops sending data if the events are not delivered?

[Hung Bui]

Hi Petri, 
We would need to have a look at your code to see how you call nrf_sdh_evts_poll(). At which priority level do you have your sending thread running ? 

From what I know of, if you don't pull the event out from the stack event buffer, it will start NACKing the packets from the central. I suspect that there could be some share buffer here and when you don't pull the event out of the buffer, you have less buffer for the notification.

I would suggest to test on how many notification packets you can queue until you receive NRF_ERROR_RESOURCES in your case (you can use a long connection interval like 1s to make it easier to test). And compare that to what you have in my example. 

You can also think of implementing the same way of calling nrf_sdh_evts_poll() in my example and see if it has any effect on the throughput. 

[plippo]

I did some timing printouts in the event handling and the delay from IRQ to event handling was just a couple of ms, so nothing is hanging there.

I tried with 100ms connection interval and the amount per event seems to vary from 3 packets to 8 (2.5ms - 7ms, most packets were big, couple of small ones in the middle) which is the same as with interval 45 ms.

Next I set the conn interval to 7,5 (like your sample, negotiations resulted 11ms) and the situation was identical. 3-8 packets per interval but total speed was of course much faster since transmission continued much sooner (about 50% time spent waiting for next interval).

I'll continue studying this next week but it's really weird that PHY1M doesn't cause this issue...