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, 

I apologize for the late reply, the SoftDevice needed some time to get back to me. 

Ok, so from connection request in the trace we see that the connection interval is set to 30msec, the transmit window is set to 6.5msec and slave latency to 0. The Connection Request is followed up by a MTU Request, where the central asks for it to be set to 247 and the Peripheral replies with 23, i.e. the MTU size for the connection is set to 23. 

The first thing they suspected was that the messages were fragmented, e.g. the data sent with the write response did not fit within the MTU of 23. However, this appears to not be the case for the packets after packet no 1301. As far as I can see the value is a 16 byte number, i.e. 19byte in total with the ATT header, which is well within the 23 byte MTU. 

Taking a closer look at the trace you attached and the packets sent after packet 1301. From the event counter it seems that the peripheral is sending the Write Response 6-8 connection events after the Write request is sent from the central, but there are packets missing from the trace as the event counter states that there has been 6-8 connection events between the Write Request and Write Response, but in the trace we only see one or two Master-Slave message exchanges(i.e. one or two connection events). This is a known issue with the current version of the sniffer

So that the delay is at the Link Layer, i.e. the packet is not sent from the peripheral before 6-8 connection events have passed, and not between the reception of the Write Response and signaling of the BLE_GATTC_EVT_WRITE_RSP event in the S140 on the central side. Rather its the peripheral that takes its time to send the Write response. 

I think an idea would be to look at the timing on the peripheral side, for instance that you toogle a GPIO when you get the BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST on the peripheral and then toogle the same GPIO prior to calling sd_ble_gatts_rw_authorize_reply() which sends the Write Response? That way we could find out if the delay is added in the peripheral application or by the SD.

It would also be interesting to get a complete trace, so I was wondering if you have access to a commercial Bluetooth Protocol sniffer (e.g. Ellisys, Frontline or similar)? 

BEst regards

Bjørn 

[Tielman]

Hi Bjørn

1) 30ms connection interval - You are correct, thanks for pointing this out. My peripherals were configured to use 50ms, but I found the the BLE_CONN_INT_MAX_MS on the master side is set to 30 so the connections are created at 30ms and never updated. (I will get back to this)

2) Your assumption that the peripheral is responsible for the delay in response does not make sense since the peripheral cannot be aware of other peripherals connecting to the master and can therefore not "decide" to wait longer before sending a response when there are more peripherals connected to the master.

I reiterate the issue: The peripheral response DOES arrive in a timely manner when only one peripheral is connected. As soon as a second is connected, the time from transmitting the WR to receiving the first connections EVT increases, but also that there is a 30ms space between receiving the EVT from each of the other connections. In other words, when sending a WR to 8 different connections at the same time, the first event arrives roughly 300ms later, but all events from the other connections take an extra 30ms to arrive making the total time to wait for receiving the events from all 8 connections to 8x30ms=240ms.

Since you pointed out the my connection interval is 30ms (which matches the connection event length seen as 30ms), I changed my connection interval to 50ms and then to 100ms just to see that the connection event length also increases to 50ms and then 100ms. Now it takes even longer to receive all the events.

The softdevice appears to use the connection interval for the connection event length.

Regards

Tielman

[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 :)