RFCOMM connection lag (slow)
Hi!
I recently found a strange behaviour...
I have a device which accepts an RFCOMM connection on channel 1. Creating the connection works just fine and I can basically communicate.
But as soon as larger chunks of data are sent (something like 128 bytes at a time) it starts to take a pretty long time to transfer it (in the range of about a second). The connection stays connected and data can be sent but at a very slow pace.
This is from a 2.6.39 kernel to the device, my PC has a Bluetooth3.0 USB device.
The interesting part is that if I try the same thing from an HTC G1 phone it works as expected, i.e. "fast". I tried to compare the HCI settings between the HTC G1 and my notebook and did the same on my notebook which did not help (the only obvious difference was disabled PARK mode and a slightly different ACL MTU).
It is pretty likely that the device also has an RFCOMM bug here but since it works with the HTC phone it must be possible to make it work with my notebook too.
Any hint would be very much appreciated ;)
Thanks!
Cheers
nils
Signature · 4 lines
kernel concepts GbR Tel: +49-271-771091-12 Sieghuetter Hauptweg 48 D-57072 Siegen Mob: +49-176-21024535 http://www.kernelconcepts.de
SGkgTmlscywNCg0KT24gU3VuLCAyMDExLTA3LTI0IGF0IDEyOjIyIC0wNDAwLCBOaWxzIEZhZXJi ZXIgd3JvdGU6DQo+IEhpIQ0KPiBJIHJlY2VudGx5IGZvdW5kIGEgc3RyYW5nZSBiZWhhdmlvdXIu Li4NCi4uLg0KPiBCdXQgYXMgc29vbiBhcyBsYXJnZXIgY2h1bmtzIG9mIGRhdGEgYXJlIHNlbnQg KHNvbWV0aGluZyBsaWtlIDEyOCBieXRlcw0KPiBhdCBhIHRpbWUpIGl0IHN0YXJ0cyB0byB0YWtl IGEgcHJldHR5IGxvbmcgdGltZSB0byB0cmFuc2ZlciBpdCAoaW4gdGhlDQo+IHJhbmdlIG9mIGFi b3V0IGEgc2Vjb25kKS4gVGhlIGNvbm5lY3Rpb24gc3RheXMgY29ubmVjdGVkIGFuZCBkYXRhIGNh biBiZQ0KPiBzZW50IGJ1dCBhdCBhIHZlcnkgc2xvdyBwYWNlLg0KPiBUaGlzIGlzIGZyb20gYSAy LjYuMzkga2VybmVsIHRvIHRoZSBkZXZpY2UsIG15IFBDIGhhcyBhIEJsdWV0b290aDMuMCBVU0IN Cj4gZGV2aWNlLg0KLi4uLg0KPiBJdCBpcyBwcmV0dHkgbGlrZWx5IHRoYXQgdGhlIGRldmljZSBh bHNvIGhhcyBhbiBSRkNPTU0gYnVnIGhlcmUgYnV0DQo+IHNpbmNlIGl0IHdvcmtzIHdpdGggdGhl IEhUQyBwaG9uZSBpdCBtdXN0IGJlIHBvc3NpYmxlIHRvIG1ha2UgaXQgd29yaw0KPiB3aXRoIG15 IG5vdGVib29rIHRvby4NCj4gDQo+IEFueSBoaW50IHdvdWxkIGJlIHZlcnkgbXVjaCBhcHByZWNp YXRlZCA7KQ0KDQoxLiBXaGF0IGRvZXMgYW4gaGNpZHVtcCAtdFggb2YgdGhlIHNlc3Npb24gc2F5 Pw0KMi4gV2hhdCBmbG93IGNvbnRyb2wgaXMgYmVpbmcgdXNlZD8NCjMuIFdoYXQgZG9lcyB0aGUg bG9nIHNheSB3aGVuIGJsdWV0b290aGQgaXMgaW4gZGVidWcgbW9kZT8NCg0KVGhhdCdzIHdoZXJl IEkgd291bGQgc3RhcnQuLi4NCg0KUmVnYXJkcywNClBldGVyDQo=
Am 24.07.2011 19:06, schrieb Peter Hurley:
Quoted 1 line
Hi Nils,
Hi Peter!
First, thanks for the fast reply!
Quoted 9 lines · Nils Faerber
Quoted 1 line
I recently found a strange behaviour...
...
Quoted 6 lines
But as soon as larger chunks of data are sent (something like 128 bytes at a time) it starts to take a pretty long time to transfer it (in the range of about a second). The connection stays connected and data can be sent but at a very slow pace.
This is from a 2.6.39 kernel to the device, my PC has a Bluetooth3.0 USB device.
Quoted 8 lines
....
Quoted 5 lines
It is pretty likely that the device also has an RFCOMM bug here but since it works with the HTC phone it must be possible to make it work with my notebook too.
Any hint would be very much appreciated ;)
1. What does an hcidump -tX of the session say?
The complete log would be a little longer. Is there something special that I could watch for?
Here an excerpt:
1311530163.994927 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530165.033926 > ACL data: handle 12 flags 0x02 dlen 9
L2CAP(d): cid 0x0040 len 5 [psm 0]
0000: 09 ff 01 02 5c ....\
1311530165.034148 < ACL data: handle 12 flags 0x00 dlen 40
0000: 24 00 43 00 0b ef 41 01 20 40 00 57 60 00 00 03 $.C...A. @.W`...
0010: fc 01 00 07 00 00 00 00 58 60 00 00 fe ff 01 80 ........X`......
0020: 03 00 00 00 00 d7 af 9a ........
1311530165.034254 < ACL data: handle 12 flags 0x00 dlen 39
0000: 23 00 43 00 0b ef 3f 01 20 40 00 59 60 00 00 fc #.C...?. @.Y`...
0010: ff 01 e0 01 00 00 00 00 5a c0 00 00 fc ff 01 38 ........Z......8
0020: 00 00 00 00 00 cc 9a .......1311530165.244924 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530166.494919 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530167.594936 > ACL data: handle 12 flags 0x02 dlen 9
L2CAP(d): cid 0x0040 len 5 [psm 0]
0000: 09 ff 01 02 5c ....\Quoted 1 line
2. What flow control is being used?
You mean the serial port flow control on the RFCOMM channel?
Quoted 1 line
From my Linux app I do not use any handshake. On the G1 I can not check
since the Android app seems to go through the socket interface instead of the /dev/rfcomm device.
Quoted 1 line
3. What does the log say when bluetoothd is in debug mode?
In how far is bluetooth involved in the rfcomm conection? The establishment is done manually using the rfcomm cmdline utility.
Quoted 4 lines
That's where I would start...
Regards,
Peter
Cheers
nils
Signature · 4 lines
kernel concepts GbR Tel: +49-271-771091-12 Sieghuetter Hauptweg 48 D-57072 Siegen Mob: +49-176-21024535 http://www.kernelconcepts.de
Am 24.07.2011 19:58, schrieb Nils Faerber:
Quoted 21 lines
Am 24.07.2011 19:06, schrieb Peter Hurley:
Quoted 1 line
1. What does an hcidump -tX of the session say?
The complete log would be a little longer. Is there something special that I could watch for?
Here an excerpt:
1311530163.994927 > HCI Event: Number of Completed Packets (
0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530165.033926 > ACL data: handle 12 flags0x02dlen 9L2CAP(d): cid 0x0040 len 5 [psm 0] 0000: 09 ff 01 02 5c ....\ 1311530165.034148 < ACL data: handle 12 flags 0x00 dlen 40 0000: 24 00 43 00 0b ef 41 01 20 40 00 57 60 00 00 03 $.C...A. @.W`... 0010: fc 01 00 07 00 00 00 00 58 60 00 00 fe ff 01 80 ........X`...... 0020: 03 00 00 00 00 d7 af 9a ........ 1311530165.034254 < ACL data: handle 12 flags 0x00 dlen 39 0000: 23 00 43 00 0b ef 3f 01 20 40 00 59 60 00 00 fc #.C...?. @.Y`... 0010: ff 01 e0 01 00 00 00 00 5a c0 00 00 fc ff 01 38 ........Z......8 0020: 00 00 00 00 00 cc 9a .......
Quoted 7 lines
1311530165.244924 > HCI Event: Number of Completed Packets (
0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530166.494919 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 0c 00 01 00 .....
1311530167.594936 > ACL data: handle 12 flags0x02dlen 9L2CAP(d): cid 0x0040 len 5 [psm 0] 0000: 09 ff 01 02 5c ....\
Strangely the dump from the Android G1 looks pretty different (and better):
1311284173.980396 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 01 00 01 00 .....
1311284174.009115 > ACL data: handle 1 flags 0x02 dlen 9
L2CAP(d): cid 0x0041 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 0 fcs 0x5c credits 2
1311284174.012621 < ACL data: handle 1 flags 0x02 dlen 40
L2CAP(d): cid 0x0043 len 36 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 32 fcs 0x9a
0000: 01 20 40 01 5a 00 00 00 00 00 00 00 00 00 00 00 .
@.Z...........
0010: 00 5b 00 00 00 00 00 00 00 00 00 00 00 00 dd a4.[..............
1311284174.016646 > HCI Event: Number of Completed Packets (0x13) plen 5
0000: 01 01 00 01 00 .....
1311284174.048780 < ACL data: handle 1 flags 0x02 dlen 40
L2CAP(d): cid 0x0043 len 36 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 32 fcs 0x9a
0000: 01 20 40 01 5c 00 00 00 00 00 00 00 00 00 00 00 .
@.\...........
0010: 00 5d 00 00 00 00 00 00 00 00 00 00 00 00 98 90.]..............
Why does the hcidump from Linux not show RFCOMM(d) parts like the G1 dump? Pretty strange...
Quoted 2 lines
Quoted 2 lines
Regards,
Peter
Cheers
nils
Signature · 4 lines
kernel concepts GbR Tel: +49-271-771091-12 Sieghuetter Hauptweg 48 D-57072 Siegen Mob: +49-176-21024535 http://www.kernelconcepts.de
T24gU3VuLCAyMDExLTA3LTI0IGF0IDE0OjQyIC0wNDAwLCBOaWxzIEZhZXJiZXIgd3JvdGU6DQo+ IEFtIDI0LjA3LjIwMTEgMTk6NTgsIHNjaHJpZWIgTmlscyBGYWVyYmVyOg0KPiA+IEFtIDI0LjA3 LjIwMTEgMTk6MDYsIHNjaHJpZWIgUGV0ZXIgSHVybGV5Og0KPiA+PiAxLiBXaGF0IGRvZXMgYW4g aGNpZHVtcCAtdFggb2YgdGhlIHNlc3Npb24gc2F5Pw0KPiA+IA0KPiA+IFRoZSBjb21wbGV0ZSBs b2cgd291bGQgYmUgYSBsaXR0bGUgbG9uZ2VyLg0KPiA+IElzIHRoZXJlIHNvbWV0aGluZyBzcGVj aWFsIHRoYXQgSSBjb3VsZCB3YXRjaCBmb3I/DQouLi4NCj4gDQo+IFdoeSBkb2VzIHRoZSBoY2lk dW1wIGZyb20gTGludXggbm90IHNob3cgUkZDT01NKGQpIHBhcnRzIGxpa2UgdGhlIEcxIGR1bXA/ DQoNClRoZSBuZXcgbDJjYXAgY29kZSBub3cgc2V0cyB0aGUgZmlyc3QgQUNMIGRhdGEgcGFja2V0 DQpQYWNrZXRfQm91bmRhcnlfRmxhZyB0byAnbm90IGF1dG9tYXRpY2FsbHkgZmx1c2hhYmxlJyBv biBsMmNhcCBjaGFubmVscw0Kbm90IG1hcmtlZCBmbHVzaGFibGUgKHRoZSBkZWZhdWx0IGlzIG5v dCBmbHVzaGFibGUpLg0KDQpUaGUgZGVjb2RlIG9mIHRoaXMgaW4gaGNpZHVtcCB3YXMgZml4ZWQg YmFjayBpbiBGZWJydWFyeS4gDQoNClJlZ2FyZHMsDQpQZXRlcg0K
Am 24.07.2011 21:20, schrieb Peter Hurley:
Quoted 9 lines · Nils Faerber
Quoted 6 lines
Am 24.07.2011 19:58, schrieb Nils Faerber:
Quoted 5 lines
Am 24.07.2011 19:06, schrieb Peter Hurley:
Quoted 1 line
1. What does an hcidump -tX of the session say?
The complete log would be a little longer. Is there something special that I could watch for?
...
Quoted 1 line
Quoted 7 lines
Quoted 1 line
Why does the hcidump from Linux not show RFCOMM(d) parts like the G1 dump?
The new l2cap code now sets the first ACL data packet
Packet_Boundary_Flagto 'not automatically flushable' on l2cap channels not marked flushable (the default is not flushable).The decode of this in hcidump was fixed back in February.
OK, great, with a new one I see the RFCOMM now, thanks!
I also found another hint towards the RFCOMM lag...
If I disable SNIFF on the Linux side it behaves normal again. Once it has entered SNIFF mode for the first time the connection starts to lag.
So I am almost suspecting not an RFCOMM but rather HCI/SNIFF issue and this is most likely caused by the Bluetooth device rather the Linux host. I just can not come up with an explanation why it work including SNIFF from the older HTC G1 - there the Linux kernel is for sure much older than on my notebook. Did something concerning SNIFF mode change more or less recently?
Quoted 2 lines
Regards,
Peter
Cheers
nils
Signature · 4 lines
kernel concepts GbR Tel: +49-271-771091-12 Sieghuetter Hauptweg 48 D-57072 Siegen Mob: +49-176-21024535 http://www.kernelconcepts.de