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

[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

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, 

the event counter in the sniffer trace shows that the Write Response is sent from the peripheral 6-8 connection events, i.e. 180 msec(6*30) to 240 msec (8*30) after the Write Request is sent from the central.  As you have pointed out he peripheral timing should not change when additional peripherals are connected to the central as the central schedules the connection events for each connection so that all connections have communicate with the central every 30msec. However, the sniffer trace indicates that the Write response is sent after 6-8 connection events, so it is either the peripheral that takes longer to send the Write Response or it is missing 6-8 connection events. The latter should be visible in the sniffer trace, i.e. we should see multiple Write Response packets for each Write Request. 

From the first comment (Nov 1st) it seems that with one peripheral connected the Write Response is sent on the next connection event, i.e. 30msec after the Write Request is sent from the central. The connection event length (NRF_SDH_BLE_GAP_EVENT_LENGTH) defines the maximum length of a connection event in 1.25msec units, i.e. if its set to 320, then the maximum connection event length is 400msec. However, the connection event will close when the transmit buffer is empty, i.e if there is only one packet to be sent, then the connection event is ended and the central moves on to the next connection event for the next peripheral. 

The write request is a total of 49 bytes on-air, which at 1Mbps will take 390us, so sending 8 Write Requests will take 3.1360 msec , in addition you need to add the time it takes to change between TX and RX for each event (about 40us) and changing  frequency of the radio between the event( 140us ), So in total is should be somewhere in the 3.1360msec + 8*40us + 8*140us ~ 4.60 milliseconds area., which is leagues away from the max event length of 400msec. 

My suggestion would be to reduce the NRF_SDH_BLE_GAP_EVENT_LENGTH to  6, i.e. a connection event length of 7.5ms and see if that removes the delays. If not, is it possible to run the central and peripheral code on nRF52840 DKs? I could then reproduce the issue here and sniff the on-air packets with a Ellisys Bluetooth protocol analyzer to get the complete picture with no missing packets.

Best regards

Bjørn

[Tielman]

Hi Bjørn

Thanks for the detailed response.

From my side, I will change NRF_SDH_BLE_GAP_EVENT_LENGTH to 6 and see what happens to the timing. It will be great if the fix is that simple and I'll let you know what the result is.

bjorn-spockeli said:

However, the sniffer trace indicates that the Write response is sent after 6-8 connection events, so it is either the peripheral that takes longer to send the Write Response or it is missing 6-8 connection events

Forgive me, but I believe you are not interpreting the trace correctly. A WRITE_RESPONSE is never sent from a peripheral as the first comms on the connection event. It is always after the master sends an Data Channel PDU to start the communications. As per BLE spec Vol 6 Part B 4.5.1:

"The start of a connection event is called an anchor point. At the anchor point, a
master shall start to transmit a Data Channel PDU to the slave. ... The slave
listens for the packet sent by its master at the anchor point."

What you pointed out with no packets being sent between the master or slave for the 6-8 connection events points to the softdevice not sending the Data Channel PDU as per Spec:

"Each connection event contains at least one packet sent by the master."

Here is a breakdown per packet from 1302 in the trace

(Connection EVT 1)

1302 - Master send Write Request

1303 - Slave ack in same connection event

No data for 6-8 connection events

(Connection EVT x)

1304 - Master initiales comms after 300ms with the empty PDU

1305 - Slave send WR_RSP in same connection event

You can look through the entire trace, but it is always the master that initiates the communications on a new connection event. If the master does not, the peripheral does not respond. You can therefor see that it is the master that starts the comms (after skipping 6-8 connection events) only 300ms later for the peripheral to then send the WR_RSP.

Regards

Tielman

[bjorn-spockeli]

Yes, I think that you are absolutly correct. I just assumed that there were packets missing, i.e. that we didn't see the empty packets transmitted from the central in the trace.

So what I think is going on is that SoftDevice scheduler on the Central is allocating the maximum event length for each connection, i.e. connection event length == connection interval, since the NRF_SDH_BLE_GAP_EVENT_LENGTH is set to 320(400ms). If we take a look at Multilink scheduling with eight connections as a Central and minimum intervall, then we see that the minimum connection interval for C0( and other 7 connections) will be 8*connection event length, which in your case will be 8*30ms = 240ms

So setting the NRF_SDH_BLE_GAP_EVENT_LENGTH to  5, i.e. a connection event length of 6.25ms, the minimum connection interval is 5*1.25ms*8=50ms, should resolve the issue. 

Best regards 

Bjørn

[Tielman]

Hi

Great, thanks! Changing NRF_SDH_BLE_GAP_EVENT_LENGTH  to 5 does force tevent=6.25ms and the events are delivered in close succession.

Thanks! This marathon session left me with traces coming out of my ears, but I am glad it is resolved

Best Regards

Tielman

[bjorn-spockeli]

Happy to hear that you're not getting the events in close succession and I apologize that I didnt see the cause of the issue until now :)