Why are notifications slower than indications with SoftDevice s130 on nRF51822?

[brianreinhold]

This question stems from this discussion

 https://devzone.nordicsemi.com/f/nordic-q-a/71044/notifications-how-to-know-who-is-consuming-tx-buffers-most-efficient-way-of-sending-a-sequence-what-error-conditions-are-received

but is so important as a new standard is being based upon behaviors exhibited in actual implementations.

The test situation is a sequence of 87 bytes being indicated/notified as fast as possible with an MTU size of 23. So that means 4 20-bytes chunks followed by one 7-byte chunk are indicated/notified.

• In the main loop the app is waiting on sd_app_evt_wait()
• The central peer writes a command to send data
• sd_app_evt_wait() wakes up
• App calls sd_ble_evt_get() in a loop
• If there is an event app calls ble_evt_dispatch(evt) to handle event
• There is a command to write data so flag to send data is set
• All events handled app checks send data flag. It is set, app calls sd_ble_gatts_hvx() to send first chunk and clears flag
• App waits on sd_app_evt_wait() (expecting BLE_GATTS_EVT_HVC [indications] or BLE_EVT_TX_COMPLETE [notifications]
• Event occurs app wakes up
• Usual get events, handle event, flag set to send data, next chunk sent, wait for event, etc.

The only thing that changes in the code between the two cases is whether the ble_gatts_hvx_params_t parameter in sd_ble_gatts_hvx() is set for indications versus notifications.

Results with indications: (Times are elapsed time since application start in milliseconds)

APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 0 on attribute handle 0x000E at time 53966
APP:DEBUG:=====> Indication of hunk complete at time 54069, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 20 on attribute handle 0x000E at time 54070
APP:DEBUG:=====> Indication of hunk complete at time 54167, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 40 on attribute handle 0x000E at time 54167
APP:DEBUG:=====> Indication of hunk complete at time 54264, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 60 on attribute handle 0x000E at time 54265
APP:DEBUG:=====> Indication of hunk complete at time 54362, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 7 bytes of 87 total from offset 80 on attribute handle 0x000E at time 54362
APP:DEBUG:=====> Indications complete at time 54459, connection handle 0x0000

Results with notifications:

APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 0 on attribute handle 0x000E at time 29278
APP:DEBUG:Notification TX done event sent
APP:DEBUG:=====> Notification of hunk complete at time 29406, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 20 on attribute handle 0x000E at time 29406
APP:DEBUG:Notification TX done event sent
APP:DEBUG:=====> Notification of hunk complete at time 29503, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 40 on attribute handle 0x000E at time 29503
APP:DEBUG:Notification TX done event sent
APP:DEBUG:=====> Notification of hunk complete at time 29601, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 60 on attribute handle 0x000E at time 29601
APP:DEBUG:Notification TX done event sent
APP:DEBUG:=====> Notification of hunk complete at time 29698, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 7 bytes of 87 total from offset 80 on attribute handle 0x000E at time 29698
APP:DEBUG:Notification TX done event sent
APP:DEBUG:=====> Notification complete at time 29796, connection handle 0x0000

Result without the extra print statement

APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 0 on attribute handle 0x000E at time 10218
APP:DEBUG:=====> Notification of hunk complete at time 10358, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 20 on attribute handle 0x000E at time 10358
APP:DEBUG:=====> Notification of hunk complete at time 10455, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 40 on attribute handle 0x000E at time 10455
APP:DEBUG:=====> Notification of hunk complete at time 10553, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 20 bytes of 87 total from offset 60 on attribute handle 0x000E at time 10553
APP:DEBUG:=====> Notification of hunk complete at time 10650, connection handle 0x0000
APP:DEBUG:=====> Send # 1: Sending 7 bytes of 87 total from offset 80 on attribute handle 0x000E at time 10650
APP:DEBUG:=====> Notification complete at time 10748, connection handle 0x0000

Note that in all cases, the use of indications results in a faster transfer than notifications. That result is clearly unexpected. I have been asked why I chose to use indications versus notifications in our BT SIG meetings where this standard is being developed. The only reason I did it was to assure that the peer got the data. However, in the field, missing packets has seldom been the problem with health devices. So it was reasonable to use notifications to speed up the transfer since once did not have to wait for the next connection interval. 

So I changed the indications to notifications expecting that transfers would speed up. But they slowed down! Is there something I am doing wrong to get this result or is there some quirk with the SoftDevice TX buffer implementation? I do not think I can justify using indications versus notifications in this standard unless this is a generic result and would be true on all platforms.

Any insight?

[Dmitry]

Hi,

what I can see from debug log - the time is exactly the same for notifications and indications (97-98 ms), except for the first packet that's not in sync with connection timeline.

brianreinhold said:

All events handled app checks send data flag. It is set, app calls sd_ble_gatts_hvx() to send first chunk and clears flag

Then you have exactly one packet per connection interval, no matter whether it's a notification or indication. Try to change your algorithm to call sd_ble_gatts_hvx() until it returns BLE_ERROR_NO_TX_PACKETS, to fill notification queue and allow SoftDevice to send as many packets in a connection event as it can.

[brianreinhold]

Okay, didn't know that was how it worked. I assumed that was just a queue and under the hood it would send and generate a response event for each packet in the queue. But if one can stuff 6 packets in a connection interval and that generates only one event, then its an entirely different story! I guess I'll find out! Thanks for the suggestion.

I did that and it sure made a difference! Thanks for pointing that out for me. Had no idea it worked like that!

There is NOT a one to one correspondence between packets and events as I assumed. There are far fewer events than packets! However, I did note that the event has a parameter indicating how many packets were sent so you still know if everything you queued at least went out the door. This statement in the documentation led me astray

It is important to note that a notification will consume an application buffer, and will therefore generate a BLE_EVT_TX_COMPLETE event when the packet has been transmitted. 

I still have some questions:

1. Can I get an NRF_ERROR_BUSY when doing notifications?

2. If I get a BLE_ERROR_NO_TX_PACKETS response do I have to resend the packet after I wait for the event?

[run_ar]

For reference: sd_ble_gatts_hvx

1. Most likely you would only see this for indications.

2. Yes, if you get this error it means there was no available buffers, so you need to resend that particular packet.

[brianreinhold]

Thanks. I am well aware of the documentation. But it is not always clear on these critical points. My understanding is now that the NRF_ERROR_BUSY' is ONLY for indications. What was not clear when the BLE_ERROR_NO_TX_PACKETS error came was if the packet was internally queued but before you send another you have to wait for the event. I have noted that the 'count' returned with the event is most frequently one. So I guess there is an attempt to make a one-to-one correspondence between the sd_ble_gatts_hvx call and the event but that is not always possible.

It would help if there was more in the documentation about how indications and notifications work in SoftDevice as that does influence code design. Its also pretty central in data transfer. I understand its impossible to clarify everything, but in my case I came away with more questions than answers after reading the documentation. I can also understand that sd_* documentation has lower priority as most are probably using the SDK and they are hidden from this stuff.

But by far and away, the best thing about Nordic is the responsiveness they have on this forum! 

[run_ar]

Yes, it's always hard to document these things in a good way. I usually look at the message sequence charts for the SD to see what is going on. For the S130 this is a bit limited: GATTS Handle Value Notification. But we have more details for newer softdevices: GATTS Handle Value Notification (Newer message sequence charts are not necessarily valid for older SD versions)

[brianreinhold]

At the moment I am stuck on the nRF51822 as that is what is being used on the production device and s130 is the best we got (they used to use s110 but I was able to upgrade that). s110 had issues with the flash writes (it didn't write) that simply moving to s130 solved without code changes.

[run_ar]

I understand. Let us know if you have any further questions.