Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jittery audio #60

Closed
georgefst opened this issue Sep 4, 2017 · 22 comments
Closed

Jittery audio #60

georgefst opened this issue Sep 4, 2017 · 22 comments
Labels

Comments

@georgefst
Copy link

Using this plugin to stream audio from Android to Raspberry Pi 3 (fresh install of Raspbian Stretch).

No real setup needed, and I haven't changed any settings, but when using bluealsa-aplay audio is unlistenable - cutting out every second or so - when using my phone or tablet. I've tried changing the buffer size but that only seems to make it worse.

I'm a bit of a linux noob and documentation here seems to be fairly minimal, so pointers on how to at least find relevant logs/debugging information would be greatly appreciated.

@arkq
Copy link
Owner

arkq commented Sep 4, 2017

Hi, please tell me which version of Android you are using. I've seen similar problem you're describing with Android 6.1.x. So, it might be the same issue.

I've got Android 6.0.1 and there is no problems with streaming. Unfortunately, I've got rather limited possibilities for testing with various devices. If you've got some other devices, please try to use them as well and post the results here.

Additional, you might try to see logs from the bluealsa server. However, I do not know where such a logs on Raspbian Stretch are stored.... In order to perform full debugging, try to compile bluez-alsa by yourself on Raspberry Pi (see the instruction in the readme) and run in. Beforehand, kill the bluealsa server which is already running. Try something like that:

pgrep -a bluealsa # this should show you how it was invoked natively
pkill bluealsa

And of course post logs here.

@arkq arkq added the bug label Sep 4, 2017
@ghost
Copy link

ghost commented Sep 4, 2017

I see this issue with a Moto G 4 Play device running Android 7.1.1 as well as an Intel TG701 tablet running Android 4.4.2. I'll try to get a hold of a device running 6.0.1 and report back.

Here's the bluealsa log from the Android 7.1.1 device:

pi@arachnos:~ $ sudo bluealsa
bluealsa: ../../src/ctl.c:489: Starting controller loop
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/1
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/Headset
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/AudioGateway
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/HandsFree
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/AudioGateway
bluealsa: ../../src/main.c:225: Starting main dispatching loop
bluealsa: ../../src/bluez.c:783: Profile method call: org.bluez.Profile1.NewConnection()
bluealsa: ../../src/transport.c:613: State transition: 0 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/io.c:997: Starting IO loop: HFP Hands-Free
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:723: HFP Hands-Free configured for device F0:D7:AA:C1:24:5C
bluealsa: ../../src/transport.c:613: State transition: 0 -> 2
bluealsa: ../../src/rfcomm.c:553: Starting RFCOMM loop: HFP Hands-Free
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+BRSF, value:244
bluealsa: ../../src/transport.c:96: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/at.c:156: AT message: RESP: command:+BRSF, value: 2919
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 0 -> 1
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 1 -> 2
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+BAC, value:1
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 2 -> 3
bluealsa: ../../src/rfcomm.c:95: Sending AT message: TEST: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: ("call",(0,1)),("callsetup",(0-3)),("service",(0-1)),("signal",(0-5)),("roam",(0,1)),("battchg",(0-5)),("callheld",(0-2))
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 3 -> 4
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 4 -> 5
bluealsa: ../../src/rfcomm.c:95: Sending AT message: GET: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: 0,0,1,3,0,1,0
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 5 -> 6
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 6 -> 7
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+CMER, value:3,0,0,1,0
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 7 -> 8
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 8 -> 9
bluealsa: ../../src/bluez.c:539: Endpoint method call: org.bluez.MediaEndpoint1.SetConfiguration()
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:471: A2DP Sink (SBC) configured for device F0:D7:AA:C1:24:5C
bluealsa: ../../src/bluez.c:473: Configuration: channels: 2, sampling: 44100
bluealsa: ../../src/transport.c:613: State transition: 0 -> 0
bluealsa: ../../src/bluez.c:593: Endpoint already registered: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/2
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 13 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 13
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIEV, value: 4,4
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIEV, value: 4,3
bluealsa: ../../src/ctl.c:550: New client accepted: 13
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:550: New client accepted: 14
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:326: PCM requested for F0:D7:AA:C1:24:5C type 1 stream 1
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:71: Opening FIFO for writing: /var/run/bluealsa/hci0-F0:D7:AA:C1:24:5C-1-1
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 211 != 210
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIEV, value: 4,4
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 1249 != 1246
bluealsa: SBC decoding error: No such file or directory
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 1304 != 1303
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 1308 != 1306
bluealsa: SBC decoding error: No such process
bluealsa: Missing RTP packet: 1997 != 1996
bluealsa: Missing RTP packet: 2186 != 2184
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 2194 != 2191
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 2447 != 2445
bluealsa: Missing RTP packet: 2531 != 2530
bluealsa: SBC decoding error: No such process
bluealsa: Missing RTP packet: 2678 != 2675
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIEV, value: 4,3
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/ctl.c:521: Client closed connection: 13
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:521: Client closed connection: 14
bluealsa: ../../src/transport.c:855: Cleaning PCM FIFO: /var/run/bluealsa/hci0-F0:D7:AA:C1:24:5C-1-1
bluealsa: ../../src/transport.c:862: Closing PCM: 16
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/main.c:229: Exiting main loop
bluealsa: ../../src/transport.c:333: Freeing transport: HFP Hands-Free
bluealsa: ../../src/transport.c:781: Closing RFCOMM: 10
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/transport.c:333: Freeing transport: HFP Hands-Free
bluealsa: ../../src/transport.c:333: Freeing transport: A2DP Sink (SBC)
pi@arachnos:~ $

Going to restart the pi before doing the same test with the Android 4.4.2 tablet in order to get a clean system state.

@ghost
Copy link

ghost commented Sep 4, 2017

The Android 4.4.2 device had much bigger issues, with long pauses where the bluealsa logs say it was "Closing BT".

pi@arachnos:~ $ sudo bluealsa
bluealsa: ../../src/ctl.c:489: Starting controller loop
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/1
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/Headset
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/AudioGateway
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/HandsFree
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/AudioGateway
bluealsa: ../../src/main.c:225: Starting main dispatching loop
bluealsa: ../../src/bluez.c:539: Endpoint method call: org.bluez.MediaEndpoint1.SetConfiguration()
bluealsa: ../../src/bluez.c:471: A2DP Sink (SBC) configured for device 80:69:AC:D0:79:B3
bluealsa: ../../src/bluez.c:473: Configuration: channels: 2, sampling: 44100
bluealsa: ../../src/transport.c:613: State transition: 0 -> 0
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:593: Endpoint already registered: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/2
bluealsa: ../../src/bluez.c:783: Profile method call: org.bluez.Profile1.NewConnection()
bluealsa: ../../src/transport.c:613: State transition: 0 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/bluez.c:723: HFP Hands-Free configured for device 80:69:AC:D0:79:B3
bluealsa: ../../src/io.c:997: Starting IO loop: HFP Hands-Free
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/transport.c:613: State transition: 0 -> 2
bluealsa: ../../src/rfcomm.c:553: Starting RFCOMM loop: HFP Hands-Free
bluealsa: ../../src/transport.c:96: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+BRSF, value:244
bluealsa: ../../src/at.c:156: AT message: RESP: command:+BRSF, value: 359
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 0 -> 1
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 1 -> 2
bluealsa: ../../src/rfcomm.c:95: Sending AT message: TEST: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: ("call",(0,1)),("callsetup",(0-3)),("service",(0-1)),("signal",(0-5)),("roam",(0,1)),("battchg",(0-5)),("callheld",(0-2))
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 2 -> 4
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 4 -> 5
bluealsa: ../../src/rfcomm.c:95: Sending AT message: GET: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: 0,0,0,5,0,2,0
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 5 -> 6
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 6 -> 7
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+CMER, value:3,0,0,1,0
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 7 -> 8
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 8 -> 9
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 9 -> 13
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:550: New client accepted: 10
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:550: New client accepted: 14
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:326: PCM requested for 80:69:AC:D0:79:B3 type 1 stream 1
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/io.c:71: Opening FIFO for writing: /var/run/bluealsa/hci0-80:69:AC:D0:79:B3-1-1
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: SBC decoding error: No such process
bluealsa: Missing RTP packet: 2437 != 2436
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 3181 != 3180
bluealsa: Missing RTP packet: 3189 != 3188
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 3514 != 3510
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: Missing RTP packet: 5028 != 5023
bluealsa: ../../src/ctl.c:521: Client closed connection: 10
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: SBC decoding error: No such file or directory
bluealsa: ../../src/io.c:167: FIFO endpoint has been closed: 16
bluealsa: ../../src/transport.c:855: Cleaning PCM FIFO: /var/run/bluealsa/hci0-80:69:AC:D0:79:B3-1-1
bluealsa: ../../src/transport.c:862: Closing PCM: 16
bluealsa: ../../src/ctl.c:521: Client closed connection: 14
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 2 -> 0
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 15
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 0 -> 1
bluealsa: ../../src/transport.c:703: New transport: 10 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:613: State transition: 1 -> 2
bluealsa: ../../src/transport.c:96: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:235: Starting IO loop: A2DP Sink (SBC)
bluealsa: ../../src/main.c:229: Exiting main loop
bluealsa: ../../src/transport.c:333: Freeing transport: HFP Hands-Free
bluealsa: ../../src/transport.c:333: Freeing transport: HFP Hands-Free
bluealsa: ../../src/transport.c:781: Closing RFCOMM: 11
bluealsa: ../../src/transport.c:884: Exiting IO thread
bluealsa: ../../src/transport.c:333: Freeing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:729: Releasing transport: A2DP Sink (SBC)
bluealsa: ../../src/transport.c:757: Closing BT: 10
bluealsa: ../../src/transport.c:884: Exiting IO thread
pi@arachnos:~ $

@arkq
Copy link
Owner

arkq commented Sep 4, 2017

Thank, for these logs.

So it seems, that the problem is with the "link quality" and bluealsa might be the cause of it. I'll make special branch for testing this issue (maybe tomorrow). Basically, what I'd like to see is if the missing RTP packages are caused by bluez or bluealsa. So, it is required to remove all decoding code within the bluealsa and allow the IO thread to just read data from the socket (without decoding and without sending it to the FIFO). If you like, you might try to do it by yourself (in this function), or wait till tomorrow.

EDIT
Just comment out lines from line 296 to 324 and see if "missing RTP" is still showing up.

@ghost
Copy link

ghost commented Sep 4, 2017

After commenting out the lines 296 to 324, the bluealsa output shows a lot less Missing RTP packets, though it still happens whenever I do anything at all on the system. If I only leave the console with bluealsa open and don't touch the computer at all, the messages go away completely. But even typing this message on a browser window causes missing RTP packets. If I move a window around the screen, I get a burst of Missing RTP packets per second. This with the system load between 10% and 20%.

@arkq
Copy link
Owner

arkq commented Sep 4, 2017

OK, so the problem seems to be load related after all. See this comment for some clues: #21 (comment)

@ghost
Copy link

ghost commented Sep 4, 2017

I'll see if I can get the configuration fix on that comment working on Raspbian Stretch, but this probably needs a FAQ/Wiki page on its own once a fix is identified, rather than being buried on a thread about compiling it. Raspbian Stretch uses bluealsa by default, so if their default configuration is useless because of system scheduling not giving enough CPU time to bluealsa, the fix should be very visible and easy to find for everybody migrating to Stretch.

@Captain-Coder
Copy link

@leandrotlz, perhaps you can report this to Raspbian. I see no mention of this on their strech launch (party) blog. And seemingly the only way to communicate this to them is to respond on the blogs or forums. That being said, they do explicitly exclude (nor test apparently) bluetooth audio input from support, see this post.

Seeing things from the other side, I would not use my "hack" as a proper solution for a distribution. As I said in the comment that @arkq mentions, it's a rather nuclear option that can make your system unresponsive if something misbehaves.

I've ammended the thread #21 with some further comment, that could be an explanation for what is happening here. Specifically, the Pi problem in reverse, bluez-alsa not preempting bleutoothd and thus missing packets from the pipe. So not exactly a CPU time issue, but a CPU timing issue.

@arkq
Copy link
Owner

arkq commented Sep 6, 2017

@Captain-Coder thanks a lot for this extensive explanations. I was thinking for a while, that maybe it could be resolved in the bluealsa itself, however my knowledge is rather short in the area of RT systems (especially running on a board with a single CPU thread). One possible solution is to put bluez and bluealsa in the FF scheduler (or maybe RR just like you've said), however who should decide about that? I think, that the correct answer is the user (in the case of this issue, the distribution - Raspbian - creators), who wants prioritize Bluetooth audio over other things.

Anyhow, there is one possibility to improve responsiveness of the IO thread in the bluealsa. My current approach is a single thread which do things as follows (in a pipeline fashion):

-> select for read
-> reads data from a socket/pipe
-> encode/decode
-> write data to pipe/socket
-> delay in order to maintain transfer rate

There is no select for writing and writing is non-blocking. So if there is no room for data it will fail. I could rearrange this logic to be governed by two threads, however this approach will require locks, which I'd like to avoid. Other approach is to multiplex reading and writing within a single thread. And that's what I will try to accomplish. However, I do not know if result will be worth the effort....

@Captain-Coder
Copy link

As far as I know only the first generation of PI is a single core, many if not most will now be true multi-core systems. So the single core Pi is really the worst case scenario.

First off, I am by no means an expert on real-time scheduling in linux. I know the basics from my Operating Systems course in university, and learned some of the linux implementation details while trying to figure out how to get glitch free audio on my pi. From what I understand there are two types of processes SCHED_NORMAL for non real time processes and either SCHED_FIFO or SCHED_RR for real time processes. The trick here is that a process which has any of the rt schedulings will preempt running processes. So for this situation it doesn't matter much if it is the FIFO or RR one. The only thing that matters is to get the process reading the pipe under the RT scheduler regime. As opposed to the "when the next slot comes around" scheduling when using SCHED_NORMAL. If both bluez-alsa and bluetoothd are set to rt scheduling, then it is something to look into.

On multi-core systems this prempring is real easy, there may well be a core available or linux can preempt one without to much overhead. But as we can see in this comment, on a single core Pi this generates a large overhead due to all the process preemption (for pretty much every write to a pipe).

Had a quick glance at io.c, both IO functions looks fine to me (or put another way: I don't know how to do it better). The only thing that strikes me is the delay. I would think that the rate of the source and sink should be matched so delay/synchronisation should happen naturally on the blocking read from PCM? Having said that I can't find the actual "delay" function, it seems to be only communicating the incurred delay, not actually waiting for it? If it is an actual wait, the type of wait could have a big impact. A sleep(..) style wait would yield the remaining timeslice to the scheduler and allow the other end of the pipe to start reading pretty much immediately without having to resort to RT scheduling. (This could fail under load though). A spin-wait/delay could be a problem here, but if the delay is small it might be the only option.

Splitting the IO thread into two opens up a whole can of worms. Not only will you require locking on your data structures as you say, but I can imagine synchronisation being a headache, and any (slight) missmatch between the rate of the source and sync will potentially buffer an ever increasing amount of data between the two threads. And oh, it causes even more context switches and latency. Like you, I'd try to steer clear of this route.

I'm unsure what you mean by multiplexing in this context, what would the io thread logic look like in that case?

@arkq
Copy link
Owner

arkq commented Sep 7, 2017

The only thing that strikes me is the delay. I would think that the rate of the source and sink should be matched so delay/synchronisation should happen naturally on the blocking read from PCM?

That's true. Sink IO actually relies on the reading-based synchronization. However, source (theoretically) does not. Source reads from the PCM FIFO, which in fact is synced with the audio rate by the PCM ALSA plugin. However, there should be no sync requirement - e.g. one could open bluealsa PCM FIFO and write to it some audio (omitting ALSA system) without worry about transfer rate (that was my idea). So, synchronization is done by the bluealsa itself (it could be optimized a little, because right now, timing is calculated by the PCM plugin and by the bluealsa...).

A spin-wait/delay could be a problem here.

Of course, for delay sleep is called (nanosleep actually). Spin-locks are mostly used by kernel (that what I've heard), using them in a userland might not be a good idea :D - generally speaking. I've been using spin-locks, but in microprocessors.

I'm unsure what you mean by multiplexing in this context, what would the io thread logic look like in that case?

That is so called "can of worms" minus unnecessary context switches. However, the "synchronisation being a headache" preserves. I will select on reading and writing. If read wakes up, I will fill in the internal buffer, then if the write wakes up, I will send this buffer through the socket/PIPE (writing will be prioritized - firstly checked). In the select I will incorporate timeout which will maintain transfer rate, however with some granularity. Right now, transfer is checked and corrected every read/write spin, which might be unnecessary. Single read/write processes about 2ms of audio. If transfer will be within 10ms, it will be still OK, but it might help socket communication - there will be some room for timing de-synchronization between threads (from the kernel point of view).

So, that's my basic idea. I will have to implement it anyway, because right now I'm trying to merge mSBC feature from the #37. It requires a little bit of freedom in the IO loop - aka internal buffer, because single mSBC packet is about 250 bytes, however, socket MTU is 24 bytes. And my communication template/example - Jabra headset - sends packets via the socket not with a constant rate, but with bursts when a single audio frame is encoded. So, I will try to implement something similar :).

@jason-a69
Copy link

I am having this same problem with a Samsung S8+ running Android 7.0. I managed to connect my Asus transformer laptop (running Windows 32 bit) and music streaming from the PC to the Pi worked just fine.

@MarvAmBass
Copy link

Hey guys, I also had this jittering on my rpi3. (I'm using the raspberry pi as bluetooth audio sink)

In my case it was because of the internal bluetooth chip of the raspberry. bluez-alsa didn't have a impact on the cpu so it needed to be something else.

after I tried an external bluetooth usb stick it was working without any problems in great quality

useful infos: http://youness.net/raspberry-pi/bluetooth-headset-raspberry-pi-3-ad2p-hsp

@asavah
Copy link

asavah commented Sep 28, 2017

Another tip for rpi3 owners using built-in BT - try disabling built-in wifi via overlay

dtoverlay=pi3-disable-wifi

@jason-a69
Copy link

I can confirm a Pi zero (not W) with a BT adaptor works fine

@jason-a69
Copy link

I can confirm a Pi zero W with inbuilt BT does not work fine

@jason-a69
Copy link

I downloaded and compiled the code like so
../configure --enable-aac --enable-debug --disable-payloadcheck

When I stream from my Android phone to the internal BT chip of the Pi3, I get the following debug messages from bluealsa (see below). Is there anything I can do to change the code or test that will help you?

bluealsa: ../../src/ctl.c:489: Starting controller loop
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/MPEG24/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/MPEG24/Sink/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/1
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/Headset
bluealsa: ../../src/bluez.c:836: Registering profile: /HSP/AudioGateway
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/HandsFree
bluealsa: ../../src/bluez.c:836: Registering profile: /HFP/AudioGateway
bluealsa: ../../src/main.c:225: Starting main dispatching loop
bluealsa: ../../src/bluez.c:539: Endpoint method call: org.bluez.MediaEndpoint1.SetConfiguration()
bluealsa: ../../src/bluez.c:471: A2DP Sink (SBC) configured for device
bluealsa: ../../src/bluez.c:473: Configuration: channels: 2, sampling: 44100
bluealsa: ../../src/transport.c:616: State transition: 0 -> 0
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/bluez.c:593: Endpoint already registered: /A2DP/MPEG24/Source/1
bluealsa: ../../src/bluez.c:593: Endpoint already registered: /A2DP/MPEG24/Sink/1
bluealsa: ../../src/bluez.c:593: Endpoint already registered: /A2DP/SBC/Source/1
bluealsa: ../../src/bluez.c:610: Registering endpoint: /A2DP/SBC/Sink/2
bluealsa: ../../src/bluez.c:783: Profile method call: org.bluez.Profile1.NewConnection()
bluealsa: ../../src/transport.c:616: State transition: 0 -> 2
bluealsa: ../../src/transport.c:99: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/io.c:1006: Starting IO loop: HFP Hands-Free
bluealsa: ../../src/bluez.c:723: HFP Hands-Free configured for device
bluealsa: ../../src/transport.c:616: State transition: 0 -> 2
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/rfcomm.c:553: Starting RFCOMM loop: HFP Hands-Free
bluealsa: ../../src/transport.c:99: Created new IO thread: HFP Hands-Free
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+BRSF, value:244
bluealsa: ../../src/at.c:156: AT message: RESP: command:+BRSF, value: 4079
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 0 -> 1
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 1 -> 2
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+BAC, value:1
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 2 -> 3
bluealsa: ../../src/rfcomm.c:95: Sending AT message: TEST: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: ("call",(0,1)),("callsetup",(0-3)),("service",(0-1)),("signal",(0-5)),("roam",(0,1)),("battchg",(0-5)),("callheld",(0-2))
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 3 -> 4
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 4 -> 5
bluealsa: ../../src/rfcomm.c:95: Sending AT message: GET: command:+CIND, value:(null)
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIND, value: 0,0,1,4,0,5,0
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 5 -> 6
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 6 -> 7
bluealsa: ../../src/rfcomm.c:95: Sending AT message: SET: command:+CMER, value:3,0,0,1,0
bluealsa: ../../src/at.c:156: AT message: RESP: command:, value:OK
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 7 -> 8
bluealsa: ../../src/rfcomm.c:113: HFP state transition: 8 -> 9
bluealsa: ../../src/ctl.c:550: New client accepted: 10
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:550: New client accepted: 14
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:326: PCM requested for type 1 stream 1
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/ctl.c:571: +-+-
bluealsa: ../../src/at.c:156: AT message: RESP: command:+CIEV, value: 4,3
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:616: State transition: 0 -> 1
bluealsa: ../../src/transport.c:715: New transport: 15 (MTU: R:672 W:1008)
bluealsa: ../../src/bluez.c:954: Signal: PropertiesChanged: org.bluez.MediaTransport1
bluealsa: ../../src/transport.c:616: State transition: 1 -> 2
bluealsa: ../../src/transport.c:99: Created new IO thread: A2DP Sink (SBC)
bluealsa: ../../src/io.c:236: Starting IO loop: A2DP Sink (SBC)

@jason-a69
Copy link

After lots of research, it looks like this is a problem with Raspberry Pi firmware. Wifi and BT do not coexist very well.

It is referenced here
raspberrypi/linux#1552

The easiest workaround is to use a USB BT adapter until new Pi firmware comes out.

@ssj71
Copy link

ssj71 commented Jan 18, 2018

I was able to do this on a rPi3 by setting up a UDEV rule to disable wifi when a BT device connects. I'm still getting a few xruns every minute and a faint chattering like when a CD is all scratched up but still playable. Separate issues I know.

@georgefst
Copy link
Author

Having come back to my project after a few months, I can confirm that my original problem was definitely the rPi bluetooth/wifi interference as mentioned above, not anything to do with bluez-alsa (which is now working impressively well!)

@pietercardoen
Copy link

I am currently using a raspberry pi 3 and I also notice the jittery audio. The music is barely understandable.

I am using bluealsa 1.2.0 and bluez 5.48.

I experimented by setting real-time priorities for the services bluealsa, bluetoothd and bluealsa-aplay but nothing helped.

Wifi is disabled using device tree overlay and the WiFi kernel modules are not loaded.

I'm getting lots of messages:
bluealsa: Missing RTP packet: 1234 != 1232
bluealsa: Missing RTP packet: 1237 != 1235
bluealsa: Missing RTP packet: 1241 != 1238
bluealsa: Missing RTP packet: 1249 != 1242
bluealsa: Missing RTP packet: 1252 != 1250
bluealsa: Missing RTP packet: 1257 != 1254
bluealsa: Missing RTP packet: 1263 != 1258

Can anyone advice me?

Thanks
Pieter

@pietercardoen
Copy link

To come back on my comment. I have been able to fix this by setting the serial speed to a higher value. I was using 115200 which was not sufficient at all. By configuring hciattach with speed 3000000, it worked almost perfectly. I only get sometimes an error (once at 20 minutes):

bluealsa: Missing RTP packet: 18440 != 18439
bluealsa: SBC decoding error: No such file or directory
bluealsa: Missing RTP packet: 18452 != 18451

Pieter

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

8 participants