Reponse time of WRITE WITH RESPONSE command

[Tielman]

Hi

I'm using a NRF52840 as multi central with 8 connections

SDK: 15.0; SD: 6.1 S140

My central connects to a peripheral with a connection interval of 50ms and latency of 0

When connected to 1 peripheral, from the time of issuing the sd_ble_gattc_write() command to the time I receive the BLE_GATTC_EVT_WRITE_RSP event is on average +-100ms.

As soon as I receive the response, I immediately send the next command and keep doing this.

With 2 peripherals connected, the turnaround time from command to the event is +-200ms. I tested it up to 6 connections the led to a 600ms turnaround time form sending the message to receiving the BLE_GATTC_EVT_WRITE_RSP. 

Is there an internal delay/queue/timer in the softdevice for sending messages? What else could be causing this?

Thanks

[Tielman]

To add more details to this...

I am using FreeRTOS to start with.

Then, I have done some more controlled test in the following way:

1) Connections: 1; Send 1 message and resend the message on every WRITE_RSP event

Result: WRITE_RSP event arrival times after sending message: 210ms, 60ms, 120ms, 150ms, 60ms ... (perfect 30ms windows)

(IMAGE: Looking at the bottom two rows where there are 'i' in: First row is calling sd_ble_gattc_write(); 2nd row is getting BLE_GATTC_EVT_WRITE_RSP)

2) Connections: 2; Send only 1 message on each connection at the same time, not to be repeated on EVT

Result: First connection's WR_RSP arrives 130ms after send, 2nd connection's WR_RSP arrives another 30ms later

3) Same test as in (2) but with 4 connections

Result: First connection's WR_RSP arrives 300ms later, followed by each of the other connections' WR_RSP an extra 30ms later

4) Same test as (2) & (3) but with 8 connections

Result: Interestingly the first WR_RSP arrives 250ms later followed by the WR_RSP for of the other connections 30ms appart (so a total of 450ms to receive all WR_RSP events)

5) Connections: 8; Send 1 message per connection at the same time and reply to each WR_RSP event with another message as it arrives

Result: First WR_RSP event arrives 250ms after sending WRITE with 30ms spacing between each connection's WR_RSP event, however, the next set of events arrive 250ms after the last WR_RSP event was received. This means that for the second set of sending of WRITE_WITH_RESPONSE commands sent, their corresponding event arrives 470ms later

6) Connections: 8; Send only 1 message on only one connection and reply to the WR_RSP event (So only 1 connection is talking)

Result: Almost xact same timing as per (5), however, only one connection is talking. Time to event from first write is 300ms. Time to every other event after a write is 470ms

So with 8 connections and only one device talking, it takes 470ms just to send one WRITE_WITH_REPONSE and get the corresponding WR_RSP event.

1) What is the softdevice design that explains this?

2) Does each connection receive a 30ms (or something) timeslot in which data is sent and received?

3) Is there a SDK setting or something that will allow me to change this to not have such a slow turnaround time for WRITE_WITH_RESPONSE issues when having multiple connections? We are planning on supporting 20 connections so this might be a painful experience if it cannot be changed.

Thanks

[bjorn-spockeli]

Hi Tielman, 

Are you able to capture a sniffer trace of the on-air packets using a BLE protocol sniffer e.g. Ellisys or using the nRF Sniffer v2 ? It would be very useful in debugging the issue. 

Also have you altered the NRF_SDH_BLE_GAP_EVENT_LENGTH, NRF_SDH_BLE_GATT_MAX_MTU_SIZE or NRF_SDH_BLE_GAP_DATA_LENGTH values in sdk_config.h?

The S140 in a central role will schedule the connections as described in the Connection timing as a Central section in the S140 SoftDevice Specification. In addition to the scheduling the connection events, the central will also add the scanner event after all the connection events, see Figure 3. Scanner timing - one or more connections as a Central in the Primary channel scanner timing section.  

In short, if all the write request are send at the same time then the last connection that is scheduled be sent after N*Connection Event Length, where N is the number of connections. So with 50ms and a connection event length off 6*1.25ms = 7.5ms, then the last Write request will be sent 8*7.5ms = >60 milliseconds after the first connection event. If you're scanning at the same time, then the scan window will have to be added to the N*Connection Event Length value. 

Best regard 

Bjørn

[Tielman]

Hi Bjørn

I have not changed those parameters in the config file, but here is what they are configured as:

#define NRF_SDH_BLE_GAP_EVENT_LENGTH 320

#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 247

#define NRF_SDH_BLE_GAP_DATA_LENGTH 27

My scan window is 50ms and interval is 100ms, though when I have 8 connections, scanning is stopped so this will only apply to the connection graphs above with less than 8 connections.

Thanks for the links. I see there is some optimization I need to do in terms of my connection intervals and scanning windows and intervals. Regardless, and to understand the timing better:

1) You gave an example Connection Event Length of 7.5ms

bjorn-spockeli said:

connection event length off 6*1.25ms = 7.5ms

, however, from my graphs, it looks like my Tevent-Cx = 30ms since the events arrive 30ms apart? Why so slow and is there a way to reduce this?

2) I honestly don't understand what NRF_SDH_BLE_GAP_EVENT_LENGTH  is for. Infocentre gives the following description

"The time set aside for this connection on every connection interval in 1.25 ms units"

Does this have a part to play in the connection event length?

I will try and get my packet sniffer working and let you know what I find.

[Tielman]

Hi Bjørn

Attached is a sniffer trace between the master and one of the peripherals using Sniffer V2 and Wireshark.

• From packet 0 to 400 is peripheral advertising
• From packet 400 to 1050 (roughly) they are connected by not talking (only one connection)
• From packet 1050 five more peripherals connected, but with peripheral 1 still not talking
• From packet 1300 (roughly), the monitored peripheral and central communicate

Pico intervals 2.pcapng

From what I could see, the timing corresponded exactly to my previous findings, except that it looks like the peripheral sends the WRITE_RSP in the same connection interval as when it received the write command from the central and also appears tp respond with a notification in the same event (all 150us apart). So is the softdevice receiving the WRITE_RSP event and possibly also a notification from the peripheral in the same 1ms, but only giving that back to the application layer >200ms later?

Let me know your thoughts

Thanks

[bjorn-spockeli]

Hi Tielman, 

I would expect the SoftDevice to issue the BLE_GATTC_EVT_WRITE_RSP to the application as soon as connection event has passed, i.e. after Connection Event Length ms after the connection event started and before the next connection interval.  200ms between the reception of the ATT Write Response and the SoftDevice issuing the BLE_GATTC_EVT_WRITE_RSP to the application does not sound reasonable, when you have a connection interval of 50ms. I have raised this question with the SoftDevice team and will come back to you with their comments. 

As for the questions in your previous comment

1) Well, in the sniffer trace you are only monitoring the traffic between one peripheral and the central. Keep in mind that you also have 4 other peripherals connected at the same time, so if the  Connection Event Length is 7.5ms then the Central will schedule 7.5ms for each connection. This means that the central will use 4*7.5ms = 30ms to talk to the 4 other peripherals before talking to the monitored peripheral again. 

2) NRF_SDH_BLE_GAP_EVENT_LENGTH  ==  Connection Event Length. It's the same thing. 

Best regards

Bjørn