Bad HCI Event : Number of Completed Packets
I am trying to run a BLE server that transmits around 35-40KBytes/sec through notifications. I have the server and notifications up and running with BlueZ-5.54 interfacing over HCI with BT860 Laird bluetooth module that leverages CYW20704 A2 Chipset.
The problem is with HCI Event: Number of Completed Packets. From what I understand the bluetooth controller will send this event once it has transmitted buffered packets to indicate available capacity. Also it is manufacture specific and cannot be controlled. The chipset can buffer up to 15 packets of length 251 each. I confirmed that by sending raw command using hcitool.
All good so far, here is the problem description:
- The applications sends 15 packets to the controller
- After 2 x connection_interval_ms Controller replies with HCI Event: Number of Completed Packets = 2
- This continues until all packets are sent. At the end, controller sends 8 HCI Event: Number of Completed Packets = 2/1, all 2 x connection_interval_ms apart
I am pasting output from "btmon" here for a better understanding of the situation(the important sections are separated by /******** break-lines ******/).
From the output it is clear that the controller only transmits 2 ACL packet at a time and then waits 2xconnection_interval_ms. This really is the bottleneck of my BLE server, please let me know how I can improve it!
I have tried different connection intervals, mtu sizes and even different client apps(nRF connect and RaspberryPi gatt client) all give me the same results. As well as gone through documentation for BT860 and CYW20704.
Can someone please help me understand how I can fix this? Essentially,
Why are the packets buffered and not transmitted?
If they are being transmitted, why is it not reported by the controller? How do I know if this is a bug in the controller?
Why are "Number of Completed Packets" HCI event always 2 x connection intervals apart? How can I control its frequency?
/********************************************Initiate Connection and GATT Service discovery*****************************************/
> HCI Event: LE Meta Event (0x3e) plen 19 #289 [hci0] 1767.983447
LE Connection Complete (0x01)
Status: Success (0x00)
Handle: 64
Role: Slave (0x01)
Peer address type: Random (0x01)
Peer address: F5:2F:BD:4D:B4:A1 (Static)
Connection interval: 7.50 msec (0x0006)
Connection latency: 0 (0x0000)
Supervision timeout: 4000 msec (0x0190)
Master clock accuracy: 0x07
@ MGMT Event: Device Connected (0x000b) plen 13 {0x0002} [hci0] 1767.983514
LE Address: F5:2F:BD:4D:B4:A1 (Static)
Flags: 0x00000000
Data length: 0
@ MGMT Event: Device Connected (0x000b) plen 13 {0x0001} [hci0] 1767.983514
LE Address: F5:2F:BD:4D:B4:A1 (Static)
Flags: 0x00000000
Data length: 0
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2 #290 [hci0] 1767.983782
Handle: 64
> HCI Event: Command Status (0x0f) plen 4 #291 [hci0] 1767.985754
LE Read Remote Used Features (0x08|0x0016) ncmd 1
Status: Success (0x00)
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #292 [hci0] 1768.003893
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0001-0xffff
Attribute group type: Primary Service (0x2800)
> HCI Event: LE Meta Event (0x3e) plen 12 #293 [hci0] 1768.020620
LE Read Remote Used Features (0x04)
Status: Unsupported Remote Feature / Unsupported LMP Feature (0x1a)
Handle: 64
Features: 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00
LE Encryption
Connection Parameter Request Procedure
Extended Reject Indication
Slave-initiated Features Exchange
LE Ping
LE Data Packet Length Extension
LL Privacy
Extended Scanner Filter Policies
< ACL Data TX: Handle 64 flags 0x00 dlen 16 #294 [hci0] 1768.020769
LE L2CAP: Connection Parameter Update Request (0x12) ident 1 len 8
Min interval: 24
Max interval: 40
Slave latency: 0
Timeout multiplier: 400
< ACL Data TX: Handle 64 flags 0x00 dlen 18 #295 [hci0] 1768.034943
ATT: Read By Group Type Response (0x11) len 13
Attribute data length: 6
Attribute group list: 2 entries
Handle range: 0x0001-0x0006
UUID: Generic Access Profile (0x1800)
Handle range: 0x0007-0x000a
UUID: Generic Attribute Profile (0x1801)
> HCI Event: LE Meta Event (0x3e) plen 11 #296 [hci0] 1768.043019
LE Data Length Change (0x07)
Handle: 64
Max TX octets: 251
Max TX time: 2120
Max RX octets: 251
Max RX time: 2120
> ACL Data RX: Handle 64 flags 0x02 dlen 10 #297 [hci0] 1768.050522
LE L2CAP: Connection Parameter Update Response (0x13) ident 1 len 2
Result: Connection Parameters accepted (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5 #298 [hci0] 1768.058490
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #299 [hci0] 1768.065527
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x000b-0xffff
Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 64 flags 0x00 dlen 26 #300 [hci0] 1768.065867
ATT: Read By Group Type Response (0x11) len 21
Attribute data length: 20
Attribute group list: 1 entry
Handle range: 0x000b-0x0012
UUID: Vendor specific (a79ef145-bde1-4bbd-8fbd-28d5dad70a97)
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #301 [hci0] 1768.081234
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0013-0xffff
Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 64 flags 0x00 dlen 9 #302 [hci0] 1768.081687
ATT: Error Response (0x01) len 4
Read By Group Type Request (0x10)
Handle: 0x0013
Error: Attribute Not Found (0x0a)
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #303 [hci0] 1768.095555
ATT: Read Request (0x0a) len 2
Handle: 0x000b
< ACL Data TX: Handle 64 flags 0x00 dlen 21 #304 [hci0] 1768.095684
ATT: Read Response (0x0b) len 16
Value: 970ad7dad528bd8fbd4be1bd45f19ea7
> HCI Event: Number of Completed Packets (0x13) plen 5 #305 [hci0] 1768.096516
Num handles: 1
Handle: 64
Count: 2
> HCI Event: LE Meta Event (0x3e) plen 10 #306 [hci0] 1768.103986
LE Connection Update Complete (0x03)
Status: Success (0x00)
Handle: 64
Connection interval: 30.00 msec (0x0018)
Connection latency: 0 (0x0000)
Supervision timeout: 4000 msec (0x0190)
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #307 [hci0] 1768.163413
ATT: Read By Type Request (0x08) len 6
Handle range: 0x0001-0x0006
Attribute type: Characteristic (0x2803)
< ACL Data TX: Handle 64 flags 0x00 dlen 20 #308 [hci0] 1768.163731
ATT: Read By Type Response (0x09) len 15
Attribute data length: 7
Attribute data list: 2 entries
Handle: 0x0002
Value: 820300002a
Handle: 0x0005
Value: 020600012a
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #309 [hci0] 1768.223048
ATT: Read Request (0x0a) len 2
Handle: 0x0003
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #310 [hci0] 1768.223324
ATT: Read Response (0x0b) len 22
Value: 427261696e436f205261737062657272795069205374
> HCI Event: Number of Completed Packets (0x13) plen 5 #311 [hci0] 1768.223995
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #312 [hci0] 1768.313032
ATT: Read Request (0x0a) len 2
Handle: 0x0006
< ACL Data TX: Handle 64 flags 0x00 dlen 7 #313 [hci0] 1768.313294
ATT: Read Response (0x0b) len 2
Value: 8000
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #314 [hci0] 1768.373681
ATT: Find Information Request (0x04) len 4
Handle range: 0x0004-0x0006
< ACL Data TX: Handle 64 flags 0x00 dlen 18 #315 [hci0] 1768.373818
ATT: Find Information Response (0x05) len 13
Format: UUID-16 (0x01)
Handle: 0x0004
UUID: Characteristic Extended Properties (0x2900)
Handle: 0x0005
UUID: Characteristic (0x2803)
Handle: 0x0006
UUID: Appearance (0x2a01)
> HCI Event: Number of Completed Packets (0x13) plen 5 #316 [hci0] 1768.373932
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #317 [hci0] 1768.433025
ATT: Read Request (0x0a) len 2
Handle: 0x0004
< ACL Data TX: Handle 64 flags 0x00 dlen 7 #318 [hci0] 1768.433350
ATT: Read Response (0x0b) len 2
Value: 0100
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #319 [hci0] 1768.493683
ATT: Find Information Request (0x04) len 4
Handle range: 0x0007-0x0006
< ACL Data TX: Handle 64 flags 0x00 dlen 9 #320 [hci0] 1768.493961
ATT: Error Response (0x01) len 4
Find Information Request (0x04)
Handle: 0x0007
Error: Invalid Handle (0x01)
> HCI Event: Number of Completed Packets (0x13) plen 5 #321 [hci0] 1768.493965
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #322 [hci0] 1768.553023
ATT: Read Request (0x0a) len 2
Handle: 0x0003
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #323 [hci0] 1768.553275
ATT: Read Response (0x0b) len 22
Value: 427261696e436f205261737062657272795069205374
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #324 [hci0] 1768.613688
ATT: Read Blob Request (0x0c) len 4
Handle: 0x0003
Offset: 0x0016
< ACL Data TX: Handle 64 flags 0x00 dlen 21 #325 [hci0] 1768.614021
ATT: Read Blob Response (0x0d) len 16
61 72 6b 20 47 41 54 54 20 53 65 72 76 65 72 00 ark GATT Server.
> HCI Event: Number of Completed Packets (0x13) plen 5 #326 [hci0] 1768.614029
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #327 [hci0] 1768.904932
Num handles: 1
Handle: 64
Count: 1
> HCI Event: LE Meta Event (0x3e) plen 10 #328 [hci0] 1776.593921
LE Connection Update Complete (0x03)
Status: Success (0x00)
Handle: 64
Connection interval: 7.50 msec (0x0006)
Connection latency: 0 (0x0000)
Supervision timeout: 4000 msec (0x0190)
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #329 [hci0] 1788.592219
ATT: Read By Type Request (0x08) len 6
Handle range: 0x000b-0x0012
Attribute type: Characteristic (0x2803)
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #330 [hci0] 1788.592438
ATT: Read By Type Response (0x09) len 22
Attribute data length: 21
Attribute data list: 1 entry
Handle: 0x000c
Value: 100d00072c6b8a1e1aeda86b47cec24ebcd4e8
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #331 [hci0] 1788.607574
ATT: Read By Type Request (0x08) len 6
Handle range: 0x000d-0x0012
Attribute type: Characteristic (0x2803)
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #332 [hci0] 1788.607721
ATT: Read By Type Response (0x09) len 22
Attribute data length: 21
Attribute data list: 1 entry
Handle: 0x0010
Value: 0c110008c6a6034ef06baf8549343533924732
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #333 [hci0] 1788.622590
ATT: Read By Type Request (0x08) len 6
Handle range: 0x0011-0x0012
Attribute type: Characteristic (0x2803)
< ACL Data TX: Handle 64 flags 0x00 dlen 9 #334 [hci0] 1788.622708
ATT: Error Response (0x01) len 4
Read By Type Request (0x08)
Handle: 0x0011
Error: Attribute Not Found (0x0a)
> HCI Event: Number of Completed Packets (0x13) plen 5 #335 [hci0] 1788.623156
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #336 [hci0] 1788.637230
ATT: Read Request (0x0a) len 2
Handle: 0x000c
< ACL Data TX: Handle 64 flags 0x00 dlen 24 #337 [hci0] 1788.637352
ATT: Read Response (0x0b) len 19
Value: 100d00072c6b8a1e1aeda86b47cec24ebcd4e8
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #338 [hci0] 1788.652248
ATT: Read Request (0x0a) len 2
Handle: 0x0010
< ACL Data TX: Handle 64 flags 0x00 dlen 24 #339 [hci0] 1788.652361
ATT: Read Response (0x0b) len 19
Value: 0c110008c6a6034ef06baf8549343533924732
> HCI Event: Number of Completed Packets (0x13) plen 5 #340 [hci0] 1788.653195
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #341 [hci0] 1788.697157
ATT: Find Information Request (0x04) len 4
Handle range: 0x000e-0x0012
< ACL Data TX: Handle 64 flags 0x00 dlen 18 #342 [hci0] 1788.697287
ATT: Find Information Response (0x05) len 13
Format: UUID-16 (0x01)
Handle: 0x000e
UUID: Characteristic User Description (0x2901)
Handle: 0x000f
UUID: Client Characteristic Configuration (0x2902)
Handle: 0x0010
UUID: Characteristic (0x2803)
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #343 [hci0] 1788.712242
ATT: Read Request (0x0a) len 2
Handle: 0x000e
< ACL Data TX: Handle 64 flags 0x00 dlen 18 #344 [hci0] 1788.712447
ATT: Read Response (0x0b) len 13
Value: 4545472052656164696e677300
> HCI Event: Number of Completed Packets (0x13) plen 5 #345 [hci0] 1788.712787
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #346 [hci0] 1788.727224
ATT: Read Request (0x0a) len 2
Handle: 0x000f
< ACL Data TX: Handle 64 flags 0x00 dlen 5 #347 [hci0] 1788.727405
ATT: Read Response (0x0b) len 0
Value:
> HCI Event: Number of Completed Packets (0x13) plen 5 #348 [hci0] 1788.749650
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #349 [hci0] 1788.764653
ATT: Find Information Request (0x04) len 4
Handle range: 0x0012-0x0012
< ACL Data TX: Handle 64 flags 0x00 dlen 10 #350 [hci0] 1788.764773
ATT: Find Information Response (0x05) len 5
Format: UUID-16 (0x01)
Handle: 0x0012
UUID: Characteristic User Description (0x2901)
> ACL Data RX: Handle 64 flags 0x02 dlen 7 #351 [hci0] 1788.779703
ATT: Read Request (0x0a) len 2
Handle: 0x0012
< ACL Data TX: Handle 64 flags 0x00 dlen 18 #352 [hci0] 1788.779898
ATT: Read Response (0x0b) len 13
Value: 4545472052656164696e677300
> HCI Event: Number of Completed Packets (0x13) plen 5 #353 [hci0] 1788.794650
Num handles: 1
Handle: 64
Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #354 [hci0] 1790.062100
ATT: Write Request (0x12) len 4
Handle: 0x000f
Data: 0100
/************************************************** START THE NOTIFICATIONS **********************************************************/
> ACL Data RX: Handle 64 flags 0x02 dlen 9 #354 [hci0] 1790.062100
ATT: Write Request (0x12) len 4
Handle: 0x000f
Data: 0100
< ACL Data TX: Handle 64 flags 0x00 dlen 5 #355 [hci0] 1790.062426
ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #356 [hci0] 1790.063602
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 54f003008bce915f8bce915f8bce915f5483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #357 [hci0] 1790.064609
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #358 [hci0] 1790.065696
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #359 [hci0] 1790.066768
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #360 [hci0] 1790.067887
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #361 [hci0] 1790.068955
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #362 [hci0] 1790.070077
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #363 [hci0] 1790.071196
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #364 [hci0] 1790.072277
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #365 [hci0] 1790.073346
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #366 [hci0] 1790.074458
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #367 [hci0] 1790.075560
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #368 [hci0] 1790.076665
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #369 [hci0] 1790.077775
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
> HCI Event: Number of Completed Packets (0x13) plen 5 #370 [hci0] 1790.084497
Num handles: 1
Handle: 64
Count: 2
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #371 [hci0] 1790.084532
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #372 [hci0] 1790.084546
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
> HCI Event: Number of Completed Packets (0x13) plen 5 #373 [hci0] 1790.099497
Num handles: 1
Handle: 64
Count: 2
/*******************************************BREAK: SKIP TO END OF TRANSFER ************************************************/
> HCI Event: Number of Completed Packets (0x13) plen 5 #493 [hci0] 1790.736984
Num handles: 1
Handle: 64
Count: 2
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #494 [hci0] 1790.737022
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #495 [hci0] 1790.737037
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
> HCI Event: Number of Completed Packets (0x13) plen 5 #496 [hci0] 1790.751975
Num handles: 1
Handle: 64
Count: 2
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #497 [hci0] 1790.752012
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
< ACL Data TX: Handle 64 flags 0x00 dlen 27 #498 [hci0] 1790.752027
ATT: Handle Value Notification (0x1b) len 22
Handle: 0x000d
Data: 0000000030b6510100000000e8b651015483ac7e
> HCI Event: Number of Completed Packets (0x13) plen 5 #499 [hci0] 1790.766970
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #500 [hci0] 1790.782000
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #501 [hci0] 1790.796968
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #502 [hci0] 1790.811970
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #503 [hci0] 1790.826973
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #504 [hci0] 1790.841972
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #505 [hci0] 1790.856964
Num handles: 1
Handle: 64
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #506 [hci0] 1791.031954
Num handles: 1
Handle: 64
Count: 1 asked on Stack Overflow Dec 23, 2020 by 
aamirholdings
aamirholdings1 Answer
To get better throughput you should make use of the data length extension by setting a longer mtu and use longer notifications.
Anyway, this side runs as the "slave" role. But it's the master that controls how long the connection interval should stay open in the first place, so better check out the master setup and make sure it uses a long "connection event length". When this is equal to the connection interval you get maximum throughput.
A slave can abort a connection event earlier by stopping to listen to packets from the master. This is generally only done if the radio scheduler decides a more important radio event needs the radio right now.
answered on Stack Overflow Dec 23, 2020 by 
Emil
EmilUser contributions licensed under CC BY-SA 3.0