DFU on iOS 17.3.1 nRF Connect app very slow.

[MortenK]

We have noted that in our project a DFU triggered by the iOS app is very slow, achieving 0.1 -0.2 kbps.

Whereas DFUs initiated by the Android app are achieving the expected ~5-7kbps

Running nRF Connect SDK v2.5.1 on a custom board with an nRF52832; utilizing external flash.

We have found:
1. The iOS app logs report an MTU exchange error.

However, Wireshark has shown that this is unrelated to an actual MTU exchange. The MTU exchange actually occurs on first connection in the iOS app. Starting the DFU reports this error into the log, while no MTU request is actually sent.

Initiating this via the slave, and allowing the app to initiate this both yield in the same log.

2. Wireshark shows there are large 10 second breaks in traffic when running the DFU.

1321    33.867180    Slave_0x50656d9b    Master_0x50656d9b    ATT    49    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1322    33.896985    Master_0x50656d9b    Slave_0x50656d9b    ATT    271    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1323    33.898160    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1324    33.926985    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1325    33.956985    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1326    33.958163    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1327    33.958453    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1328    33.959631    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1329    33.986985    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1330    33.988163    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1331    34.016986    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1332    34.018164    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1333    34.046986    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1334    34.047180    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1335    34.076985    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1336    34.078163    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1337    34.106985    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1338    34.107179    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1339    34.136985    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1340    34.138164    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1341    34.166986    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1342    34.167180    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1343    34.196984    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1344    34.197179    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1345    34.226985    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1346    34.227179    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)

...

10s break with just LE LL Empty packets.

...

1968    43.976931    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1969    43.977125    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1970    44.006931    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1971    44.008109    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1972    44.036930    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1973    44.037124    Slave_0x50656d9b    Master_0x50656d9b    L2CAP    42    Connection Parameter Update Request
1974    44.037382    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1975    44.037576    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1976    44.066929    Master_0x50656d9b    Slave_0x50656d9b    L2CAP    36    Connection Parameter Update Response (Rejected)
1977    44.067164    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1978    44.067358    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1979    44.068537    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1980    44.096930    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1981    44.097125    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1982    44.126930    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1983    44.128108    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1984    44.156930    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1985    44.186929    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1986    44.188107    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1987    44.188397    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1988    44.189575    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1989    44.216928    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1990    44.218107    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1991    44.246929    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1992    44.248108    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1993    44.276929    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1994    44.277124    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1995    44.306927    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
1996    44.308106    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
1997    44.336928    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1998    44.337122    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1999    44.366928    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
2000    44.396927    Master_0x50656d9b    Slave_0x50656d9b    ATT    272    Sent Write Command, Handle: 0x0033 (Unknown: Unknown)
2001    44.398105    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
2002    44.426928    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
2003    44.427122    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
2004    44.456927    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
2005    44.457121    Slave_0x50656d9b    Master_0x50656d9b    LE LL    26    Empty PDU
2006    44.486927    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
2007    44.487121    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
2008    44.516926    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU

...

10s break with just LE LL Empty packets.

...  etc....

3. Wireshark shows attempts at the slave device initiating a connection parameter update request.

1973    44.037124    Slave_0x50656d9b    Master_0x50656d9b    L2CAP    42    Connection Parameter Update Request
1974    44.037382    Master_0x50656d9b    Slave_0x50656d9b    LE LL    26    Empty PDU
1975    44.037576    Slave_0x50656d9b    Master_0x50656d9b    ATT    50    Rcvd Handle Value Notification, Handle: 0x0033 (Unknown: Unknown)
1976    44.066929    Master_0x50656d9b    Slave_0x50656d9b    L2CAP    36    Connection Parameter Update Response (Rejected)

The very first time this occurs in a DFU, the update response is successful. Subsequent ones (which always happen after every 10s break) report failures.

4. We have noted that a successful DFU on Android has different size packets than the iOS (277 size writes on Android, 272 as per logs above on iPhones)

Can anyone comment as to this behaviour and any possible workarounds?

We have validated that the MTU size of 247/249 (tested both) is successfully set on Android and PC apps. By the look of the size of the packets on the sniffer, it seems to us that the MTU size being used is indeed 249.

[Vidar Berg]

Hello,

Are you able to share the capture file from wireshark (*.pcapng)? 

10s break with just LE LL Empty packets.

This sounds similar to the issue seen in this thread:   RE: "Error: sending the request failed" trying to perform OTA DFU with nRF Connect app, where the mcumgr transport workqueue was blocked for longer periods of time.

Wireshark shows attempts at the slave device initiating a connection parameter update request.

Please try with the following configuration:

CONFIG_MCUMGR_TRANSPORT_BT_CONN_PARAM_CONTROL=y

CONFIG_MCUMGR_TRANSPORT_BT_CONN_PARAM_CONTROL_MIN_INT=12

CONFIG_MCUMGR_TRANSPORT_BT_CONN_PARAM_CONTROL_MAX_INT=12

Which is in line with Apple's recommondations here:

https://developer.apple.com/accessories/Accessory-Design-Guidelines.pdf

This should ensure that the connection update request is accepted.

Best regards,

Vidar

[MortenK]

Hi Vidar,

Unfortunately we believe that post to be unrelated as there is no actual response that triggers the re-transmit at the 10s mark. Logs for iOS, (and functional Android logs as a comparison):
ios dfu.pcapng

android dfu.pcapng
The change to Parameters did stop point 3 in the original post, thanks!

[Vidar Berg]

Hi

Thanks for providing the capture files. You're right, I see from your sniffer trace that the phone is not waiting on the notification in your case. Unfortunately, it is not clear from the trace what's slowing down the write requests. For DFU on iOS, I'd excepted the throughput to be > 7kB/s even without optimized buffer settings.

Could you please try the same test with the nRF Device Manager app and see if you get the same result?

MortenK said:

By default the external flash options introduced in later versions of the SDK seem to be reliant on QSPI, which isn't a peripheral on nRF52832. In order to get this to work with normal SPI on an nRF52832 we have the following configuration:

I inherited this case from Sigurd. I don't suspect that there is a problem with the SPI flash configuration, considering it works fine with Android phones.

[MortenK]

Hi Vidar,

The Device Manager app had the same issues.

However, we have managed to get the update to work quickly by reducing the number of buffers in the update from 4 to 2. This is a setting in the app itself on the DFU page. This results in an update that is plenty fast enough.

It's a bit unclear to us why the setting of 4 would have such long delays, as we would expect timeouts not to be a full 10s.

Nevertheless, the issue is solved. If you have any pointers as to how to get the default setting of 4 to work, or a reason as to why it wouldn't work please let us know.