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, 

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

[plippo]

Finally got forward with this. Looks like the issue is related to FreeRTOS thread timings in relation to SD event handling. I've simplified our protocol code as much as possible and took into use semaphore protected sending (producer-consumer pattern) with event handler triggered resend (a bit like in your sample code). This refactoring resulted a worsening of transfer speed from 50kB/s to 10kB/s.

As far as I understand the situation is as follows:

1. Data is sent from datasource to the protocol handler for sending over BLE notification
2. The protocol code pushes the notification to the SD (sd_ble_gatts_hvx). The SD receives max 4 updates until it responds with NRF_ERROR_RESOURCES. Setting semaphore count to 4 protects from this happening so the sender just waits until the event comes.
3. SD sends BLE events (BLE_GATTS_EVT_HVN_TX_COMPLETE) via IRQ which triggers calls to nrf_sdh_evts_poll in a high priority event thread.
4. Event handler releases the semaphore allowing next notification to be pushed to SD.

When the PHY_2M is in use the transmission of the 4 packets of  up-to 165 B takes about 3.0-4.2 ms depending on the size of the packets. By the time the HVN_TX_COMPLETE-event is handled and semaphore is triggered and the sending thread awoken to push the update into SD, the SD has already "gotten tired of waiting". SD then decides that there is no more data to send until next interval which results anything from 3-7 packets sent per interval. During the waiting the sending thread of course fills the buffer in SD so that when the new interval starts, there is again 4 ready to send. 

When PHY_1M is used the 4 packet memory lasts for 5-6 ms which gives the rest of the system enough time to handle sending the new data to SD resulting more packets per interval.


I tried to add more memory to the softdevice (linker RAM start address) as well as larger ATTR_TABLE in sdk_config.h, but neither changed the situation. No matter what I did the SD only accepts 4 notifications. Is there a way to increase the buffer on the SD?

I also tried to call "nrf_sdh_evts_poll" directly in the IRQ handler, but that didn't work with FreeRTOS threads for some reason (got stuck. maybe thats why your nrf_sdh_freertos.c also uses the event thread).

Now that I know what causes the slowdown I can try to design the protocol code to respond as fast as possible, but I'm not too optimistic...