Open tlvince opened 8 months ago
btmon --analyze dump.btsnoop:
Found LE-ISO connection with handle 2305
Address: 00:00:00:00:00:00 (OUI 00-00-00)
RX packets: 3050/3050
RX Latency: 0-22 msec (~9 msec)
RX size: 4-124 octets (~105 octets)
RX speed: ~84 Kb/s
1000 +-+-----------------------------------------------------------------+
+| + | |
+| | | RX +-----+ |
+| | | |
+| + | | + |
100 +-| | + + | | | + + |
+| + | | | | | | + | | + |
+| + | | | | | | | | | | | |
+| | | | | + + | | | | + | | | | |
+| | | | | | | | | | | | | | | | + |
| | | | | | + | | | | | | + | | | | | + |
10 +-| | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | + |
+| | | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | | |
1 +-| | | | | | | | | | | | | | | | | | | | | + |
+| | | | | | | | | | | | | | | | | | | | | | |
++-----------------------------------------------------------------+
+ + + + + +
0 5 10 15 20 25
Latency (ms)
TX packets: 2087/2086
TX Latency: 4-62 msec (~7 msec)
TX size: 124-124 octets (~124 octets)
TX speed: ~53 Kb/s
10000 +-+----------------------------------------------------------------+
+| |
+| TX +-----+ |
+| |
1000 +-| + |
+| | |
+| | + |
+| | | |
100 +-| | | |
+| + | | |
+| |++ + + + + + |+ |
+| ||| | | | | | || |
| ||| | | | | | || |
10 +-| ||| | | | | | || |
+| +||| | | | | | +|| |
+| |||| +|+ ++ | + | + +| + | |||++ |
| |||| ||| || | | | | || | | ||||| |
1 +-| |||| ||| || + +|+ | + + ++ + | || | |+ ||||| |
++----------------------------------------------------------------+
+ + + + + + + +
0 10 20 30 40 50 60 70
Latency (ms)
Found LE-ISO connection with handle 2304
Address: 00:00:00:00:00:00 (OUI 00-00-00)
RX packets: 3008/3008
RX Latency: 0-22 msec (~9 msec)
RX size: 4-124 octets (~105 octets)
RX speed: ~84 Kb/s
1000 +-+-----------------------------------------------------------------+
+| + | |
+| | | RX +-----+ |
+| | | |
+| + | | + |
100 +-| + | + | | + | + |
+| | | + | | | | + | | |
+| + | | | | | | | | | | |
+| | | | | + | | | | + | | | |
+| | | | | + | + | | | | + + | | | | + |
| | | | | | | | | | | | | | | | | | | + |
10 +-| | | | | | | | | | | | | | | | | | | | + |
+| | | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | | |
+| | | | | | | | | | | | | | | | | | | | | |
1 +-| | | | | | | | | | | | | | | | | | | | | + |
+| | | | | | | | | | | | | | | | | | | | | | |
++-----------------------------------------------------------------+
+ + + + + +
0 5 10 15 20 25
Latency (ms)
TX packets: 2087/2086
TX Latency: 4-89 msec (~7 msec)
TX size: 124-124 octets (~124 octets)
TX speed: ~53 Kb/s
10000 +-+----------------------------------------------------------------+
+| |
+| TX +-----+ |
+| |
1000 +-| + |
+| | |
+| | + |
+| | | |
100 +-| | | |
+| +| | |
+| +|+ + + + + + + |
+| ||| | | | | | | |
| ||| | | | | | | |
10 +-| ||| | | | | | | |
+| +||| | | | | | | |
+| |||| +|+++ | + | | | +|++ |
| |||| ||||| | | | | | |||| |
1 +-| |||| ||||| |+| ++ + + + +| + + |||| + + +|
++----------------------------------------------------------------+
+ + + + + + + + + +
0 10 20 30 40 50 60 70 80 90
Latency (ms)
The RX is pretty much the same but the TX of the second connection is falling behind (@pv not sure how you plot them together though, might be a good addition to btmon --analyze), also there seems to be a considerable about of packets failing to be delivered before the presentation delay (which I assume is 40ms?).
Thanks for having a look @Vudentz. What'd be your suggestion here? Presumably, this'd need addressing at the controller (AX210) level?
Thanks for having a look @Vudentz. What'd be your suggestion here? Presumably, this'd need addressing at the controller (AX210) level?
Yes, something at link-layer is not quite right it seems.
Where'd be the best place to report this?
Where'd be the best place to report this?
I talking to our (Intel) firmware folks, looks like it is not a good idea to have the ISO interval at 10ms if the HID is at 7.5ms since their intervals would eventually collide, now where we put such a policy may be the problem, because it is pipewire that is selecting 10ms interval perhaps it should check if there is anything else already connected, like HID, that said when it is the opposite we would have to adjust the HID to 10ms if there is already an ISO at 10ms.
Where'd be the best place to report this?
I talking to our (Intel) firmware folks, looks like it is not a good idea to have the ISO interval at 10ms if the HID is at 7.5ms since their intervals would eventually collide, now where we put such a policy may be the problem, because it is pipewire that is selecting 10ms interval perhaps it should check if there is anything else already connected, like HID, that said when it is the opposite we would have to adjust the HID to 10ms if there is already an ISO at 10ms.
According to some folks we shall prefer 7.5ms whenever possible since its better for coexisting scenarious and it does have the added benefit of being lower latency as well.
Well pipewire can choose 7.5ms as well, https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 and maybe @tlvince can try to see if that helps.
If the sound server has to choose 10ms in some cases and 7.5ms in other cases depending on what else is connected, then it sounds like BlueZ should decide or at least suggest the right value to the sound server. Maybe PreferredFrameDuration
in SelectProperties or something like that.
Well pipewire can choose 7.5ms as well, gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 and maybe @tlvince can try to see if that helps.
If the sound server has to choose 10ms in some cases and 7.5ms in other cases depending on what else is connected, then it sounds like BlueZ should decide or at least suggest the right value to the sound server. Maybe
PreferredFrameDuration
in SelectProperties or something like that.
Yeah, we can do something like that, the tricky part is if the peripheral asks to change the ACL interval later, well perhaps we should reject that.
The immediate issue (of playback breaking up) has certainly improved with https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90. I can't reliably trigger it by moving the mouse as I could before.
However, the general usability is flakey. My initial experience was the ear buds often would fail to connect and/or be listed as a playback device/sink. Restarting bluetooth.service
helped, but then the microphone/source wasn't listed. Playback would work for a few minutes until one or both buds disconnected/reconnected. I managed to capture dump.btsnoop when it dropped off after around 2 mins / somewhere around event 70000+ in case it's of use.
I'd have to do more testing to isolate different factors - I'm unsure how much of this would have been introduced by https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 if at all.
linux-firmware just got new FW for Intel AX chips, maybe these work better?
With linux-firmware 4f3022dc1f90e29705d892996b89a9cec3e183c4 (which includes the AX210 update), I experience similar behavior. Playback works for a few minutes until the ear buds disconnect/reconnect. (A secondary issue - the microphone does not show up in GNOME sound settings, but does in pavucontrol
as "Bluetooth (unplugged)").
Some logs (I'll get capture some debug logs later):
Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:19 framework wireplumber[2729]: Failed to release transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd35: Operation Not Authorized
Jan 10 12:34:28 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:28 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:29 framework boltd[1267]: probing: started [1000]
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:35:33 framework wireplumber[2729]: 0x1762628: error 24
Jan 10 12:35:33 framework .gsd-media-keys[2436]: Unable to get default sink
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:40 framework boltd[1267]: probing: started [1000]
Jan 10 12:35:40 framework bluetoothd[1309]: profiles/battery/battery.c:foreach_batt_service() More than one BATT service exists for this device
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_F0/pac_sink0/fd39: fd(41) ready
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd35: fd(39) ready
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_F0/pac_source0/fd38: fd(41) ready
Jan 10 12:35:43 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd34: fd(39) ready
Jan 10 12:35:45 framework boltd[1267]: probing: timeout, done: [2974255] (2000000)
Jan 10 12:35:49 framework wireplumber[2729]: 0x114f358: error 24
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework wireplumber[2729]: error id:4 seq:65 res:-2 (No such file or directory): target not found
Jan 10 12:35:49 framework wireplumber[2729]: error id:4 seq:88 res:-2 (No such file or directory): target not found
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:69 res:-2 (No such file or directory): unknown resource 4 op:2
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:70 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:71 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:72 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:73 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:74 res:-2 (No such file or directory): unknown resource 4 op:4
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:75 res:-2 (No such file or directory): unknown resource 4 op:7
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:92 res:-2 (No such file or directory): unknown resource 4 op:2
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:93 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:94 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:95 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:96 res:-2 (No such file or directory): unknown resource 4 op:4
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:97 res:-2 (No such file or directory): unknown resource 4 op:7
Jan 10 12:35:51 framework bluetoothd[1309]: profiles/battery/battery.c:foreach_batt_service() More than one BATT service exists for this device
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework .gsd-media-keys[2436]: Unable to get default sink
Jan 10 12:35:53 framework pipewire[2723]: mod.client-node: 0x557053a08b70: unknown peer 0x557053e26170 fd:73
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:53 framework wireplumber[2729]: 0xe44eb0: out of playback buffers: Broken pipe
Jan 10 12:35:53 framework wireplumber[2729]: 0xe44eb0: out of playback buffers: Broken pipe
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:54 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:54 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
slightly off topic @pv are you planning implementing HFP 1.9, the specification enables superwideband via LC3 without LE Audio. In the specification it is Appendix E: Technical Specification of LC3-SWB. As I understand Google implemented it for Pixel Buds Pro, they're Bluetooth 5.0 and can't into real LE Audio. https://android.googlesource.com/platform/packages/modules/Bluetooth/+/refs/heads/main/system/stack/btm/btm_sco.h
Yes, we can add support for SWB in Pipewire, afaics it uses same esco modes as msbc so might not require changes on kernel side. I'll need to get a test device though to make it easier.
EDIT: done https://gitlab.freedesktop.org/pipewire/pipewire/-/merge_requests/1856
Gave it another test. Same overall behaviour as before - playback's fine for a minute or two, intermittently with stutters, until one or both of the ear buds eventually disconnects.
Debug logs:
Versions:
< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6 #728 [hci0] 7.898382
Extended scan: Enabled (0x01)
Filter duplicates: Enabled (0x01)
Duration: 0 msec (0x0000)
Period: 0.00 sec (0x0000)
< ISO Data TX: Handle 2304 flags 0x02 dlen 124 #729 [hci0] 7.898898
< ISO Data TX: Handle 2305 flags 0x02 dlen 124 #730 [hci0] 7.898905
> HCI Event: Command Complete (0x0e) plen 4 #731 [hci0] 7.904357
LE Set Extended Scan Enable (0x08|0x0042) ncmd 2
Status: Success (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 9 #732 [hci0] 7.907357
Num handles: 2
Handle: 2304 Address: 75:2F:34:49:80:21 (Resolvable)
Count: 1
#723: len 124 (62 Kb/s)
Latency: 16 msec (6-16 msec ~11 msec)
Handle: 2305 Address: 75:6A:23:8B:75:B6 (Resolvable)
Count: 1
#724: len 124 (62 Kb/s)
Latency: 16 msec (6-16 msec ~11 msec)
Looks like things starts to go wrong when scan is enabled after connecting the mouse, they it goes into a pretty bad latency over time:
> HCI Event: Number of Completed Packets (0x13) plen 9 #1765 [hci0] 9.954397
Num handles: 2
Handle: 2304 Address: 75:2F:34:49:80:21 (Resolvable)
Count: 1
#1746: len 124 (16 Kb/s)
Latency: 60 msec (5-60 msec ~59 msec)
Handle: 2305 Address: 75:6A:23:8B:75:B6 (Resolvable)
Count: 1
#1747: len 124 (16 Kb/s)
Latency: 60 msec (5-60 msec ~59 msec)
They do seem to be in sync, it just the TX latency is way too big.
< HCI Command: LE Set Connected Isochronous Group Parameters (0x08|0x0062) plen 24 #58678 [hci0] 87.974437
CIG ID: 0x00
Central to Peripheral SDU Interval: 7500 us (0x001d4c)
Peripheral to Central SDU Interval: 7500 us (0x001d4c)
SCA: 201 - 500 ppm (0x00)
Packing: Sequential (0x00)
Framing: Unframed (0x00)
Central to Peripheral Maximum Latency: 75 ms (0x004b)
Peripheral to Central Maximum Latency: 75 ms (0x004b)
Number of CIS: 1
CIS ID: 0x00
Central to Peripheral Maximum SDU Size: 117
Peripheral to Central Maximum SDU Size: 117
Central to Peripheral PHY: LE 2M (0x02)
Peripheral to Central PHY: LE 2M (0x02)
Central to Peripheral Retransmission attempts: 0x0d
Peripheral to Central Retransmission attempts: 0x0d
Retransmission and Maximum Latency are rather big though, @pv how do you choose these parameters? This is sort of high reliability territory which I don't think it is recommended for the general use cases, we should probably go for balanced for general use which is more inline with the testing presets e.g. 48_1_1 latency 15 ms rtn 5.
We set RTN and latency to the preferred values the device suggests in its ASE. I think this device produced at least in its first firmware revision broken sound if the small latency values from BAP were used.
(This happens when BlueZ fails to report the preferred QoS values due to the API issue in SelectProperties; as a workaround I changed also the fallback values to the high-reliability ones, but I think in the case here the values come from the device.)
Here:
> ACL Data RX: Handle 2049 flags 0x02 dlen 51 #564 [hci0] 23.629854
ATT: Handle Value Notification (0x1b) len 46
Handle: 0x0046 Type: Sink ASE (0x2bc4)
Data: 010100020d4b00409c00409c00409c00409c0006000000001302010802020005030100000003047500020501
ASE ID: 1
State: Codec Configured (0x01)
Framing: Unframed PDUs supported (0x00)
PHY: 0x02
LE 2M PHY preffered (0x02)
RTN: 13
Max Transport Latency: 75
Presentation Delay Min: 40000 us
Presentation Delay Max: 40000 us
Preferred Presentation Delay Min: 40000 us
Preferred Presentation Delay Max: 40000 us
Codec: LC3 (0x06)
Codec Specific Configuration: #0: len 0x02 type 0x01
Sampling Frequency: 48 Khz (0x08)
Codec Specific Configuration: #1: len 0x02 type 0x02
Frame Duration: 7.5 ms (0x00)
Codec Specific Configuration: #2: len 0x05 type 0x03
Location: 0x00000001
Front Left (0x00000001)
Codec Specific Configuration: #3: len 0x03 type 0x04
Frame Length: 117 (0x0075)
Codec Specific Configuration: #4: len 0x02 type 0x05
Frame Blocks per SDU: 1 (0x01)
We set RTN and latency to the preferred values the device suggests in its ASE. I think this device produced at least in its first firmware revision broken sound if the small latency values from BAP were used.
(This happens when BlueZ fails to report the preferred QoS values due to the API issue in SelectProperties; as a workaround I changed also the fallback values to the high-reliability ones, but I think in the case here the values come from the device.)
You meant the values from https://github.com/bluez/bluez/blob/master/doc/org.bluez.MediaEndpoint.rst#dict-qos-readonly-optional-iso-only-experimental? Are they reporting PreferredRetransmissions as 13?
They do seem to be in sync, it just the TX latency is way too big.
TX latency can grow if there is clock drift between controller and host, and controller clock runs a bit slower. Or (which looks like occurred here) if the controller leaves packets in the queue without sending them.
If the TX latency / packet queue depth is made visible to userspace (without monitor), Pipewire can rate match to compensate for clock drift and dropouts like this. (This would be useful to have also for A2DP in principle.) This sort of matching is also made with ALSA and is necessary as sound card clocks are not necessarily in sync with host or with each other, or with machines over network etc.
EDIT: actually, not sure they help in this case since latency growth here appears fast enough for Pipewire to get EAGAIN from the socket, in which case we stop sending for a while (500ms) to avoid losing sync between the earbud CIS.
In principle Core spec has the TX Sync command but I don't see how it can be used for TX synchronization without direct access to controller clock --- and AFAIK we can only communicate with it over HCI...
On the disconnections: I have not seen disconnections in my tests (over long times), but I don't have other devices connected than these earbuds.
In the above dumps, the disconnections are as
> ISO Data RX: Handle 2305 flags 0x02 dlen 4 #54466 [hci0] 77.480574 (last RX for the ISO handle)
...
< ISO Data TX: Handle 2305 flags 0x02 dlen 121 #54481 [hci0] 77.496099 (last TX for the ISO handle)
...
> HCI Event: Disconnect Complete (0x05) plen 4 #54484 [hci0] 77.501807
Status: Success (0x00)
Handle: 2305 Address: 00:00:00:00:00:00 (OUI 00-00-00)
Reason: Connection Timeout (0x08)
> HCI Event: Disconnect Complete (0x05) plen 4 #54485 [hci0] 77.503816
Status: Success (0x00)
Handle: 2048
Reason: Connection Timeout (0x08)
@ MGMT Event: Device Disconnected (0x000c) plen 8 {0x0001} [hci0] 77.531699
LE Address: 18:26:54:C7:6C:9C (Samsung Electronics Co.,Ltd)
Reason: Connection timeout (0x01)/2
They come from controller (don't know why they occur).
You meant the values from https://github.com/bluez/bluez/blob/master/doc/org.bluez.MediaEndpoint.rst#dict-qos-readonly-optional-iso-only-experimental? Are they reporting PreferredRetransmissions as 13?
Yes, see https://github.com/bluez/bluez/issues/713#issuecomment-1894273211 where I added now the values the ASE reports
Tried it here:
< ACL Data TX: Handle 2049 flags 0x00 dlen 59 #1601 [hci3] 15:40:20.012757
ATT: Write Command (0x52) len 54
Handle: 0x0043 Type: ASE Control Point (0x2bc6)
Data: 01020302020600000000100201030202010304280005030100000001020206000000001002010302020103042800050301000000
Opcode: Codec Configuration (0x01)
Number of ASE(s): 2
ASE: #0
ASE ID: 0x03
Target Latency: Balance Latency/Reliability (0x02)
PHY: 0x02
LE 2M PHY (0x02)
Codec: LC3 (0x06)
Codec Specific Configuration: #0: len 0x02 type 0x01
Sampling Frequency: 16 Khz (0x03)
Codec Specific Configuration: #1: len 0x02 type 0x02
Frame Duration: 10 ms (0x01)
Codec Specific Configuration: #2: len 0x03 type 0x04
Frame Length: 40 (0x0028)
Codec Specific Configuration: #3: len 0x05 type 0x03
Location: 0x00000001
Front Left (0x00000001)
ASE: #1
ASE ID: 0x01
Target Latency: Balance Latency/Reliability (0x02)
PHY: 0x02
LE 2M PHY (0x02)
Codec: LC3 (0x06)
Codec Specific Configuration: #0: len 0x02 type 0x01
Sampling Frequency: 16 Khz (0x03)
Codec Specific Configuration: #1: len 0x02 type 0x02
Frame Duration: 10 ms (0x01)
Codec Specific Configuration: #2: len 0x03 type 0x04
Frame Length: 40 (0x0028)
Codec Specific Configuration: #3: len 0x05 type 0x03
Location: 0x00000001
Front Left (0x00000001)
> HCI Event: Number of Completed Packets (0x13) plen 5 #1602 [hci3] 15:40:20.022346
Num handles: 1
Handle: 2049 Address: 75:B9:7A:EF:D4:4A (Resolvable)
Identity type: Public (0x00)
Identity: F0:CD:31:8F:CC:4E (Samsung Electronics Co.,Ltd)
Count: 1
#1601: len 59 (52 Kb/s)
Latency: 9 msec (5-86 msec ~12 msec)
> ACL Data RX: Handle 2049 flags 0x02 dlen 15 #1603 [hci3] 15:40:20.052542
ATT: Handle Value Notification (0x1b) len 10
Handle: 0x0043 Type: ASE Control Point (0x2bc6)
Data: 0102030000010000
Opcode: Codec Configuration (0x01)
Number of ASE(s): 2
ASE: #0
ASE ID: 0x03
ASE Response Code: Success (0x00)
ASE Response Reason: None (0x00)
ASE: #1
ASE ID: 0x01
ASE Response Code: Success (0x00)
ASE Response Reason: None (0x00)
> ACL Data RX: Handle 2049 flags 0x02 dlen 51 #1604 [hci3] 15:40:20.052544
ATT: Handle Value Notification (0x1b) len 46
Handle: 0x004c Type: Source ASE (0x2bc5)
Data: 030100020d5f00409c00409c00409c00409c0006000000001302010302020105030100000003042800020501
ASE ID: 3
State: Codec Configured (0x01)
Framing: Unframed PDUs supported (0x00)
PHY: 0x02
LE 2M PHY preffered (0x02)
RTN: 13
Max Transport Latency: 95
Presentation Delay Min: 40000 us
Presentation Delay Max: 40000 us
Preferred Presentation Delay Min: 40000 us
Preferred Presentation Delay Max: 40000 us
Codec: LC3 (0x06)
Codec Specific Configuration: #0: len 0x02 type 0x01
Sampling Frequency: 16 Khz (0x03)
Codec Specific Configuration: #1: len 0x02 type 0x02
Frame Duration: 10 ms (0x01)
Codec Specific Configuration: #2: len 0x05 type 0x03
Location: 0x00000001
Front Left (0x00000001)
Codec Specific Configuration: #3: len 0x03 type 0x04
Frame Length: 40 (0x0028)
Codec Specific Configuration: #4: len 0x02 type 0x05
Frame Blocks per SDU: 1 (0x01)
It indeed does return RTN as 13 and latency as 95?? Even though I requested Balance Latency/Reliability (0x02), now the problem seems to be that we have no means to communicate this back to the endpoint without triggering another round of QoS settings, and to be honest this is sort of bogus because they are not a range but a specific value and at this point I don't think the headset can possible tell what the source is going to transmit, so I think it is actually best to ignore these and try to come up with the best settings per context/target latency.
For me, 48_5_1 on this device produces broken audio while 48_5_2 works (as do the "preferred" QoS values). The smaller SDU, 48_1_1 and 48_3_1 both work.
Earfun is even worse in picking up preferred settings:
> ACL Data RX: Handle 2048 flags 0x02 dlen 48 #450 [hci3] 16:04:33.328529
ATT: Handle Value Notification (0x1b) len 43
Handle: 0x0092 Type: Source ASE (0x2bc5)
Data: 050100020fa00f409c00409c0000000000000006000000001002010302020103042800050301000000
ASE ID: 5
State: Codec Configured (0x01)
Framing: Unframed PDUs supported (0x00)
PHY: 0x02
LE 2M PHY preffered (0x02)
RTN: 15
Max Transport Latency: 4000
Presentation Delay Min: 40000 us
Presentation Delay Max: 40000 us
Preferred Presentation Delay Min: 0 us
Preferred Presentation Delay Max: 0 us
Codec: LC3 (0x06)
Codec Specific Configuration: #0: len 0x02 type 0x01
Sampling Frequency: 16 Khz (0x03)
Codec Specific Configuration: #1: len 0x02 type 0x02
Frame Duration: 10 ms (0x01)
Codec Specific Configuration: #2: len 0x03 type 0x04
Frame Length: 40 (0x0028)
Codec Specific Configuration: #3: len 0x05 type 0x03
Location: 0x00000001
Front Left (0x00000001)
RTN 15 and Latency 400ms, I think they are just hardcoding the values for the worse case, instead of given their best guess for the target latency, the spec is also pretty vague in how these values should be interpreted, but so far these don't give me high hopes they are going to be useful.
I guess this means it has to be done exactly like what Android does, as the manufacturers probably are going to test with that, and anything else is crapshoot.
@tlvince you can try the smaller SDU/RTN/latency values in case it changes something https://gitlab.freedesktop.org/pvir/pipewire/-/commit/f95bbce59a62b29887b335f669bcfae6a32ac20e
Also try if changing input stream from 48kHz to 16kHz helps: https://gitlab.freedesktop.org/pvir/pipewire/-/commits/lc3-workaround-3 (for me, this makes a faint buzzing sound that comes from the left earbud during playback to go away)
... or maybe both: https://gitlab.freedesktop.org/pvir/pipewire/-/commits/lc3-workaround-4
I guess this means it has to be done exactly like what Android does, as the manufacturers probably are going to test with that, and anything else is crapshoot.
Ive been thinking on contact the peripheral companies because it makes sense to expose their stack to more implementation making it more robust in the process, perhaps we could create a database of devices and then describe their status since at some point that shall reach the manufactorer.
Unfortunately the same symptoms (playback until one ear bud drops) persisted with all three options:
Could you verify my system's using the correct pipewire builds from those?
These (and all earlier tests) we done with buds firmware R510XXU0AWI2. I've just noticed there's an update R510XXU0AXA2, which I'll try.
Same with R510XXU0AXA2 and smaller latency + 16khz: smaller-latency-16khz-xa2-firmware.btsnoop
Here's another sample dump without the keyboard and mouse connected in case it shows anything useful. Playback's fine with these disconnected (and was before any of the previous changes).
@tlvince: those btsnoop seem to all use the larger latency. You can check the transport configuration in bluetoothctl with transport.list
, transport.show /org/...
. You should see 16khz, QoS.Retransmissions = 2
, QoS.Latency = 8
for pac_sources, and for pac_sinks they are 48khz, 5, and 15. This works for me when building Pipewire from c720ed38fb0d74e6778541896aa1b53f69f40b7b
In btmon you should see
< HCI Command: LE Set Connected Isochronous Group Parameters (0x08|0x0062) plen 33 #1524 [hci0] 88.378109
CIG ID: 0x00
Central to Peripheral SDU Interval: 7500 us (0x001d4c)
Peripheral to Central SDU Interval: 7500 us (0x001d4c)
SCA: 201 - 500 ppm (0x00)
Packing: Sequential (0x00)
Framing: Unframed (0x00)
Central to Peripheral Maximum Latency: 15 ms (0x000f)
Peripheral to Central Maximum Latency: 8 ms (0x0008)
Number of CIS: 2
CIS ID: 0x00
Central to Peripheral Maximum SDU Size: 117
Peripheral to Central Maximum SDU Size: 30
Central to Peripheral PHY: LE 2M (0x02)
Peripheral to Central PHY: LE 2M (0x02)
Central to Peripheral Retransmission attempts: 0x05
Peripheral to Central Retransmission attempts: 0x02
CIS ID: 0x01
Central to Peripheral Maximum SDU Size: 117
Peripheral to Central Maximum SDU Size: 30
Central to Peripheral PHY: LE 2M (0x02)
Peripheral to Central PHY: LE 2M (0x02)
Central to Peripheral Retransmission attempts: 0x05
Peripheral to Central Retransmission attempts: 0x02
Thanks. An old build was still use in my last test.
All 3 fared better this time.
f95bbce59a62b29887b335f669bcfae6a32ac20e: smaller-latency.btsnoop
2nd attempt, I got a disconnection soon after restarting bluetoothd
with bluetoothd: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:F0: Function not implemented (38)
3rd attempt was mostly stable until a bit of break up around event ~80000, smaller-latency-3.btsnoop
Hit another disconnect with the combined 48_1_1 + 16KHz branch after ~1 hour of playback. Unfortunately don't have a btsnoop dump, but repeated profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
errors from bluetoothd and
Cannot allocate memory (12)
That means there is still some race where tearing down the old CIG does not complete before bluez tries to set it up again. If you have the bluetoothd logs from before that error it might tell something.
Unfortunately no logs for that one. Will re-test next week.
Per pipewire #3762, I experience frequent jitters/short breaks in playback using the Samsung Galaxy Buds2 Pro over LE Audio/bap. I can reproduce this reliably when a LE mouse (MX Master) is connected at the same time and is moved.
Thanks to analysis from @pv:
I've tried a few different buffer sizes on the pipewire side to no avail.
intel/ibt-0041-0041.sfi
151-42.23