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]

Hi Bjørn

I will wait for the softdevice team's response, thanks.

However, the 30ms mentioned above is not between events for 1 peripheral, it is between the consecutive connections. In other words,

Connection 1 receives EVT, 30ms later connection 2 receives EVT, 30ms later connection 3 receives EVT, etc...Also, the 30ms stays the same for 2 connections or for 8 so the 7.5ms x 4 does not seem relevant at all. Also, it does not appear that the connection event length is 7.5ms unless there is another delay that pushes event scheduling to 30ms instead of servicing each connection every 7.5ms.

From what I see each connection is serviced (Connection_count x 30ms) and not (Connection_count x 7.5ms)

But I will await the response from the team

Regards

Tielman

[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