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

Audio playback garbled with mSBC codec #268

Closed
killerkalamari opened this issue Nov 18, 2019 · 31 comments
Closed

Audio playback garbled with mSBC codec #268

killerkalamari opened this issue Nov 18, 2019 · 31 comments

Comments

@killerkalamari
Copy link

Audio playback using mSBC is garbled when playing to HF devices supporting HFP_HF_FEAT_CODEC and +BAC 2 (2 is mSBC, per HFP spec Table 3.3). I tried two completely different devices to make sure it wasn't a HF problem. I have not yet tried bluealsa to bluealsa. aplay correctly recognized the sample rate as 16000, so that's good.

The bluealsa source is at commit 740886b with the patch from #266 (comment) applied. Configure options: --enable-debug --enable-msbc.

@kuikka Tagging for awareness.

$ sudo bluealsa -p hfp-ag
bluealsa: D: ba-adapter.c:151: Freeing adapter: hci0
bluealsa: D: bluez.c:1105: Creating hands-free profile object: /org/bluez/HFP/AudioGateway
bluealsa: D: bluez.c:1135: Registering hands-free profile: /org/bluez/HFP/AudioGateway
bluealsa: D: main.c:363: Acquiring D-Bus service name: org.bluealsa
bluealsa: D: main.c:368: Starting main dispatching loop

bluealsa: D: bluez.c:1073: Called: org.bluez.Profile1.NewConnection()
bluealsa: D: sco.c:167: Checking Broadcom internal SCO routing
bluealsa: D: sco.c:173: Current SCO interface setup: 1 2 0 1 1
bluealsa: D: sco.c:77: Starting SCO dispatcher loop: hci0
bluealsa: D: sco.c:201: Created SCO dispatcher [ba-sco-dispatch]: hci0
bluealsa: D: bluez.c:997: RFCOMM: HFP Audio Gateway configured for device E0:EE:1B:EA:1B:2D
bluealsa: D: ba-transport.c:635: State transition: 0 -> 2
bluealsa: D: rfcomm.c:732: Starting loop: RFCOMM: HFP Audio Gateway
bluealsa: D: ba-transport.c:948: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
bluealsa: D: ba-transport.c:635: State transition: 0 -> 2
bluealsa: D: sco.c:242: Starting SCO loop: HFP Audio Gateway
bluealsa: D: ba-transport.c:948: Created new thread [ba-sco]: HFP Audio Gateway
bluealsa: D: at.c:161: AT message: SET: command:+BRSF, value:943
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BRSF, value:2784
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
bluealsa: D: at.c:161: AT message: SET: command:+BAC, value:1,2
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 2 -> 3
bluealsa: D: at.c:161: AT message: TEST: command:+CIND, value:(null)
bluealsa: D: rfcomm.c:106: Sending 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: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 3 -> 5
bluealsa: D: at.c:161: AT message: GET: command:+CIND, value:(null)
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIND, value:0,0,1,5,0,5,0
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
bluealsa: D: at.c:161: AT message: SET: command:+CMER, value:3,0,0,1
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
bluealsa: D: rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
bluealsa: D: at.c:161: AT message: TEST: command:+CHLD, value:(null)
bluealsa: W: Unsupported AT message: TEST: command:+CHLD, value:(null)
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+CMEE, value:1
bluealsa: W: Unsupported AT message: SET: command:+CMEE, value:1
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+NREC, value:0
bluealsa: W: Unsupported AT message: SET: command:+NREC, value:0
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+CLIP, value:1
bluealsa: W: Unsupported AT message: SET: command:+CLIP, value:1
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+CCWA, value:1
bluealsa: W: Unsupported AT message: SET: command:+CCWA, value:1
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: CMD: command:+CNUM, value:(null)
bluealsa: W: Unsupported AT message: CMD: command:+CNUM, value:(null)
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+CSCS, value:"8859-1"
bluealsa: W: Unsupported AT message: SET: command:+CSCS, value:"8859-1"
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+COPS, value:3,0
bluealsa: W: Unsupported AT message: SET: command:+COPS, value:3,0
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: CMD: command:+CLCC, value:(null)
bluealsa: W: Unsupported AT message: CMD: command:+CLCC, value:(null)
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+BCS, value:2
bluealsa: D: at.c:161: AT message: SET: command:+BCS, value:2
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: at.c:161: AT message: SET: command:+XAPL, value:7108-0003-0103,8
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,0
bluealsa: D: at.c:161: AT message: SET: command:+BCS, value:2
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK

bluealsa: D: bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
bluealsa: D: bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIEV, value:2,2
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIEV, value:2,3
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIEV, value:1,1
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIEV, value:2,0
bluealsa: D: ba-transport.c:635: State transition: 2 -> 2
bluealsa: D: ba-transport.c:878: New SCO link: E0:EE:1B:EA:1B:2D: 18
bluealsa: D: hci.c:126: SCO link socket MTU: 18: 64
bluealsa: D: at.c:161: AT message: CMD: command:+CLCC, value:(null)
bluealsa: W: Unsupported AT message: CMD: command:+CLCC, value:(null)
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: D: msbc.c:66: Initializing mSBC encoder/decoder
bluealsa: D: ba-transport.c:718: PCM drained
bluealsa: D: a2dp.c:122: PCM read buffer flushed: 0
bluealsa: D: a2dp.c:122: PCM read buffer flushed: 0
bluealsa: D: ba-transport.c:921: Closing PCM: 8
bluealsa: D: sco.c:339: Releasing SCO due to PCM inactivity
bluealsa: D: ba-transport.c:897: Closing SCO: 18
bluealsa: D: rfcomm.c:106: Sending AT message: RESP: command:+CIEV, value:1,0
Connection to 192.168.42.1 closed.
$ aplay -v -D bluealsa:DEV=E0:EE:1B:EA:1B:2D,PROFILE=sco test.wav  
D: bluealsa-pcm.c:625: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Setting constraints
Playing WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
D: bluealsa-pcm.c:344: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing HW
D: bluealsa-pcm.c:371: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: FIFO buffer size: 4096
D: bluealsa-pcm.c:377: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Selected HW buffer: 4 periods x 4000 bytes == 16000 bytes
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
D: bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Prepared
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
Plug PCM: Rate conversion PCM (16000, sformat=S16_LE)
Converter: libspeex (builtin)
Protocol version: 10002
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 1
  rate         : 22050
  exact rate   : 22050 (22050/1)
  msbits       : 16
  buffer_size  : 11025
  period_size  : 2756
  period_time  : 125000
  tstamp_mode  : NONE
  tstamp_type  : GETTIMEOFDAY
  period_step  : 1
  avail_min    : 2756
  period_event : 0
  start_threshold  : 11025
  stop_threshold   : 11025
  silence_threshold: 0
  silence_size : 0
  boundary     : 6206523236469964800
Slave: BlueALSA PCM: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco
BlueALSA BlueZ device: /org/bluez/hci0/dev_E0_EE_1B_EA_1B_2D
BlueALSA Bluetooth codec: 0x2
D: bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Starting
D: bluealsa-pcm.c:137: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Starting IO loop: 8
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Initializing SW
D: bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: IO thread paused: 4
^[[AD: bluealsa-pcm.c:305: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Stopping
D: bluealsa-pcm.c:105: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: IO thread cleanup
D: bluealsa-pcm.c:305: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Stopping
D: bluealsa-pcm.c:384: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Freeing HW
D: bluealsa-pcm.c:334: /org/bluealsa/hci0/dev_E0_EE_1B_EA_1B_2D/sco: Closing
@arkq
Copy link
Owner

arkq commented Nov 18, 2019

Yes, I was not able to "force" mSBC to work since the beginning of this feature. I suspect that is has something to do with a type of a chip or a type of connection, because I'm able to play mSBC audio only on a chip connected via UART. In all other case I can only receive mSBC audio. Recently I've discovered this: https://marc.info/?l=linux-bluetooth&m=157404481613978&w=2 maybe it is related....

@killerkalamari
Copy link
Author

I looked at the patch, thanks. But, my Broadcom device is UART, not USB.

Are you able to hear any mSBC audio output when played to UART? I'm currently hearing mSBC playback, even though it's garbled. I think it must be very close to working. When I am playing a song, I can definitely make it out, it just has a lot of distortion.

I played around with switching endianness and signed/unsigned, but the original S16_LE is definitely correct here. I also tried with MTU's of 48 and 64, but it made no difference.

@arkq
Copy link
Owner

arkq commented Nov 18, 2019

So you can hear audio. That's OK. Maybe UART baudrate is too low. Because via my USB chip, there is no sound and when tested with other device I can see missing a lot of mSBC packets (so it is impossible to decode it, hence, silence). With UART chip everything is OK. I haven't tested long playback but some test sound (10-20s) works without a glitch. And I'm using MTU 24.

@killerkalamari
Copy link
Author

I tried MTU 24 and it sounded the same. Could my baudrate be too low for mSBC, even though I can play A2DP SBC audio just fine? Interesting that yours plays correctly.

@arkq
Copy link
Owner

arkq commented Nov 18, 2019

Interesting that yours plays correctly.

I was surprised too :) when I've checked it. If you have two devices try bluealsa-bluealsa with debug enabled. If you will see a lot of "mSBC decoding errors", then it means that some packets were dropped.

EDIT:
It might be even reasonable to modify msbc loop and send/receive "marked packets" - overwrite first bytes with counter and check whether some packets are missing.

@killerkalamari
Copy link
Author

I don't have my Pi 3 today, so I'm only using bluealsa as the AG. Not seeing any mSBC errors in the log, although I see where they'd be emitted in the source. I'll report back once I can try out bluealsa-bluealsa.

@killerkalamari
Copy link
Author

killerkalamari commented Nov 20, 2019

@arkq Gave it a try bluealsa to bluealsa. It plays better, but it plays slightly too fast, and starts to get garbled, then pauses for a second and seems to recover slightly, then the process repeats.

EDIT: Tried without any patches just to be sure, and it sounded the same.

@borine
Copy link
Collaborator

borine commented Nov 20, 2019

@killerkalamari re playing slightly too fast then stalling etc : I've seen that before with RPi; I was testing a2dp not sco at the time, but the solution turned out to be fixing the UART setup. It may be worth just double checking. Are you using hciattach to configure the UART? if so, what is the command line for it? Also, BT must have exclusive access to the high-speed UART - in particular make sure the kernel is not using it as a serial console.

For reference, I'm using Raspbian Lite: my hciattach command line is:
/usr/bin/hciattach /dev/serial1 bcm43xx 3000000 flow - xx:xx:xx:xx:xx:xx

and my kernel command line is:

cat /proc/cmdline
size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=f6ba7452-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet

The high-speed UART for BT is ttyAMA0, so be sure you do not have console=ttyAMA0 on the kernel command line.

@arkq
Copy link
Owner

arkq commented Nov 28, 2019

I think I've hit the same issue. @killerkalamari could you check whether playback with mpg123 produces "better" audio experience? Because what I've observed is that mSBC frames are not delivered to the remote device (tested with two bluealsa: AG and HF). On the HF side I've got dropped whole SBC frames (with mSBC 2 bytes header), which is really strange. With aplay the issue is more severe, hence audio experience is terrible (in my case). I will investigate this more thoroughly in the next few days.

@borine
Copy link
Collaborator

borine commented Nov 29, 2019

One alsa setup difference between mpg123 and aplay is that mpg123 uses a default hw buffer size of 200ms, whereas aplay uses 500ms. Does
aplay --buffer-time=200000
make any difference?

Also mpg123 requests period time of 1/3 buffer time, whereas aplay requests 1/4 buffer time, so maybe try something like:
aplay --buffer-time=200000 --period-time=66666

@arkq
Copy link
Owner

arkq commented Nov 29, 2019

@borine wow, when specifying buffer time the playback experience is same as with mpg123. So that seems to be remedium, however, I still will have to look for the root cause of this issue.... My first guess was the problem with timing during writing data to transparent link. I don't know how it's implemented in kernel, but I guess that the problem might be with underruns on the sco socket, so there is no enough data to be sent during specified timeslot. Or worse, I have to write data on specified timeslot, otherwise it will be discarded. @borine do you have some knowledge in this area?

@borine
Copy link
Collaborator

borine commented Nov 30, 2019

My reading of the kernel code is that transparent sco sockets are handled in the same way as cvsd sockets. So I would first look at differences in the application code. To me, the sco mtu of 24 looks suspicious. Unfortunately I'm not able to test this myself atm, but hopefully next week I will have time to set up 2 RPis and see what results I get.

If your adapter is USB, I would try an mtu of 48; if it's UART I would try the value got from the kernel.

If that makes no difference, then it is time to study the kernel code more carefully.

@killerkalamari
Copy link
Author

@borine Thanks a lot for the workaround! On my device, --buffer-time=100000 sounds even better than 200000. And I think 10000 sounds even better than 100000, but that could be placebo.

@borine
Copy link
Collaborator

borine commented Dec 2, 2019

Actually its the period time that is the critical factor. Try a period time of 10000 us - it does not matter what buffer size you use then,
The MTU setting has no effect on this issue, it seems to be due to delays in writing out the hci sco packets when pcm data arrives too fast from the alsa plugin.
I'll look into it more later in the week.

@killerkalamari
Copy link
Author

@borine When I replaced portaudio with plain ALSA what I found that worked for me was that first I called snd_pcm_hw_params_set_buffer_time_near and then snd_pcm_hw_params_set_period_time_near. What I noticed was that the choice I made for buffer time greatly affected the period time as well, so that's probably why adjusting buffer time works.

Probably directly related to that, I noticed that if I drop buffer time to even 200000, I start getting XRUNs. I'll experiment with leaving buffer time at 500000 and see if I can fix mSBC with period time alone.

@borine
Copy link
Collaborator

borine commented Dec 3, 2019

So the root cause of this issue is the "bursty" nature of the way that libasound passes data to the bluealsa plugin.

When I set a period time of 10 ms, libasound translates this to a "period_size" of 320 bytes in the bluealsa plugin. The blusealsa plugin then writes to the pcm fifo in "chunks" of 320 bytes which gives a reasonably smooth flow of data to the daemon.

However, when I set a period time of 125 ms (the default used by aplay), the bluealsa plugin is given a period size of 4000 bytes by libasound, When data is written to the fifo in chunks of 4000 bytes, the daemon is faced with a burst of data followed by a drought until the next cycle. The current sco thread code cannot handle this, and ends up missing the tough deadlines for the sco packet writes.

The usual solution to "smooth out" bursty data flows is to provide an extra layer of buffering, combined with a delay to the start of output from the buffer until a suitable "threshold" of input is stored in the buffer. This would inevitably increase latency which is very bad for most HFP use cases!

I will try to implement a change to the bluealsa plugin that ignores the period size given by libasound and instead writes smaller chunks for sco streams. I don't know if that will have any undesirable side effects, but I'll report back here when I've made some progress.

@borine
Copy link
Collaborator

borine commented Dec 4, 2019

What I noticed was that the choice I made for buffer time greatly affected the period time as well, so that's probably why adjusting buffer time works.
Probably directly related to that, I noticed that if I drop buffer time to even 200000, I start getting XRUNs

The alsa buffer needs to be a minimum of 2 periods - one for the application to be writing to, one for the sound card to be reading from (or vice-versa for a capture device). In practice, at least 3 periods are usually needed to avoid xruns so that there is always one on "standby" so that the timing of i/o is not absolutely critical.

When I said:

It does not matter what buffer size you use

I was referring to aplay parameters. When programming to the libasound API you should always set an explicit buffer size and period size. For playback streams you should probably also set a start threshold in the sw_params so that the stream will start automatically after the buffer has been "primed" with sufficient data to avoid underruns. The choices you make here are a compromise between the latency / processing requirements of your application and the constraints of the sound card (ie bluealsa in this case). Bluealsa sets a minimum period size of 10 ms and a minimum buffer size of 200 ms.

That is why I am recommending a period time of 10 ms for SCO streams - it is the smallest value permissible. The buffer size just needs to hold enough periods so that your application can prevent it running empty. That depends entirely on your application. If not told otherwise, aplay will set the buffer to 4 x period size, which is sufficient for simple playback of wav files. Your application may require a larger buffer if if has more time-consuming decoding to do.

The question here is whether the application should be responsible for knowing that SCO streams require very a small period size, or whether bluealsa should take care of it internally.

I prefer that bluealsa should deal with it - the necessary change in the plugin code is trivial and so far I have seen no side effects.

If it is decided that the application is responsible, then I think bluealsa should at least set an upper bound to the permitted period size in its constraints.

Even with the smaller period size, I still get occasional underruns (roughly one every 200 seconds or so), so there may still be some other change required. Also I have not yet tested two-way streams to simulate a HFP dialogue, so there is still lots more work to do.

@arkq
Copy link
Owner

arkq commented Dec 4, 2019

Hmm, thanks for such an analysis. I'm also in the middle of investigating this issue. What I've checked is the data transfer from one device to other. And it seems that when data is not transferred properly (e.g. missed time-slot for writing data), the receiving side sees all zeros... I will try to visualize data flow from the writing and reading perspective in the function of time. Maybe is will help...

Regarding the burst of data. The SCO IO thread has time synchronization which should prevent writing more data to the socket than it should be written at a given time point. So, I'm not quite convinced that SCO data is written in bursts to socket (but maybe I'm wrong, the visualization will show).

@borine
Copy link
Collaborator

borine commented Dec 4, 2019

The data bursts are on the pcm fifo from the plugin. Writing to the SCO socket looks fine, so long as it happens within the required time slots. If the thread spends too long waiting for the next burst of data on the fifo, or perhaps also too much time spent encoding too many frames in the same iiteration, then the sco write will be too late for the baseband "slot" and the controller is forced to write a frame with empty content just to satisfy the SCO link requirement. I'm convinced that the choice is between small chunks on the fifo, or a bigger input buffer in the sco thread. So far I have tried only reducing the chunk size and this dramatically improves the performance of msbc streams; but unfortunately is not sufficient to eliminate all underruns on the remote device.
I may play around with different buffer sizes later.

@borine
Copy link
Collaborator

borine commented Dec 5, 2019

With this simple patch to the plugin I get perfect playback with msbc using arecord/aplay on the remote end using MSBC; CVSD also works perfectly:

diff --git a/src/asound/bluealsa-pcm.c b/src/asound/bluealsa-pcm.c
index ec0acc5..19b45da 100644
--- a/src/asound/bluealsa-pcm.c
+++ b/src/asound/bluealsa-pcm.c
@@ -38,6 +38,7 @@
 #include "shared/log.h"
 #include "shared/rt.h"
 
+#define BA_PCM_SCO_CHUNK_FRAMES 120
 
 struct bluealsa_pcm {
        snd_pcm_ioplug_t io;
@@ -177,6 +178,11 @@ static void *io_thread(snd_pcm_ioplug_t *io) {
                snd_pcm_uframes_t io_hw_ptr = pcm->io_hw_ptr;
                snd_pcm_uframes_t io_hw_boundary = pcm->io_hw_boundary;
                snd_pcm_uframes_t frames = io->period_size;
+
+               if (io->stream == SND_PCM_STREAM_PLAYBACK &&
+                                          pcm->ba_pcm.flags & BA_PCM_FLAG_PROFILE_SCO)
+                               frames = BA_PCM_SCO_CHUNK_FRAMES;
+
                const snd_pcm_channel_area_t *areas = snd_pcm_ioplug_mmap_areas(io);
                char *buffer = (char *)areas->addr + (areas->first + areas->step * io_ptr) / 8;
                char *head = buffer;

However, bluealsa-aplay gives very occasional underruns (typically 4 times playing a 10 minute sound file) when using MSBC. I'm going to concentrate on the bluealsa-aplay code now to understand the difference from arecord when using MSBC. I think the above patch to the plugin fixes the underlying issue with the main bluealsa code, and I'm hoping some small tweak to bluealsa-aplay will fix that also.
@killerkalamari : could you test the above patch to see if it works also for you? I have no MSBC hardware devices so all my testing is with rpi + bluealsa to rpi + bluealsa. [There is no need to set any special buffer/period times in the application with the above bluealsa patch].

@killerkalamari
Copy link
Author

killerkalamari commented Dec 5, 2019

@borine Tested against my TaoTronics mSBC device, with aplay -v -D bluealsa:DEV=E9:08:EF:2D:40:33,PROFILE=sco and your patch works! I played a short song (1:49) a few times and didn't get any XRUNs. I then started playing a longer song to see if I could hit the XRUN and I noticed that the beginning of the song seemed to play too fast, then the speed returned to normal after a few seconds. So then I tested with some very short (~3 second) vocal clips and discovered that it plays the entire clip as if being fast-forwarded. I reverted your patch and tested using buffer_time and period_time, but it played identically (too fast at the beginning). I apologize for not noticing this before! The song I'd been testing with has a crowd cheering at the beginning and at the 16kHz rate I couldn't tell it was sped up.

@borine
Copy link
Collaborator

borine commented Dec 5, 2019

hmm, "speeded up" usually means audio frames are being dropped. So, this is still only part of the problem. More work required 😞

@arkq
Copy link
Owner

arkq commented Dec 7, 2019

@killerkalamari, @borine please test new master, I think I've "fixed" this issue :) The problem was with the sampling rate synchronization, which causes data to be written to the SCO link too fast. For now I've changed encoding part, but it might be required to fix decoding as well in order to smooth out data flow even more.

@borine
Copy link
Collaborator

borine commented Dec 8, 2019

@arkq msbc playback is now much improved using 2 RPis, I'm seeing no underruns (hurrah!). The new code now also shows missing frames and I'm seeing approximately 0.08% of frames are missing; so I think you are right about the decoding needing more work. I think when an incoming packet arrives the daemon needs to read it as soon as possible - otherwise there is a risk the next packet will overwrite it in the controller's buffer and data is lost.

@hrc-amilcar
Copy link

I've been watching this thread attentively. Even with master at 9eb717f, I get garbled mSBC audio with a Zebra HS3100 headset. I've had to disable mSBC for now. The output looks like this:

Dec  8 19:35:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:371: Called: org.bluealsa.PCM1.Open()
Dec  8 19:35:00 user.crit ./bluealsa: D: src/ba-transport.c:715: State transition: 2 -> 2
Dec  8 19:35:00 user.crit ./bluealsa: D: src/ba-transport.c:715: State transition: 2 -> 2
Dec  8 19:35:00 user.crit ./bluealsa: D: src/ba-transport.c:958: New SCO link: 00:1B:41:B2:86:9B: 27
Dec  8 19:35:00 user.crit ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 27: 180
Dec  8 19:35:00 user.crit ./bluealsa: D: src/msbc.c:73: Initializing mSBC encoder/decoder
Dec  8 19:35:00 user.crit ./bluealsa: D: src/ba-transport.c:943: Reusing SCO: 27
Dec  8 19:35:00 user.crit ./bluealsa: W: Missing mSBC packet: 2 != 3
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such file or directory
Dec  8 19:35:00 user.crit ./bluealsa: W: Missing mSBC packet: 0 != 3
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such file or directory
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such file or directory
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such file or directory
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such process
Dec  8 19:35:00 user.crit ./bluealsa: W: Missing mSBC packet: 1 != 0
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such process
Dec  8 19:35:00 user.crit ./bluealsa: W: mSBC decoding error: No such process
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 1 != 3
Dec  8 19:35:01 user.crit ./bluealsa: W: mSBC decoding error: No such process
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 0 != 2
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 3 != 1
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 1 != 0
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 3 != 2
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 1 != 0
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 3 != 2
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 1 != 0
Dec  8 19:35:01 user.crit ./bluealsa: W: Missing mSBC packet: 3 != 2
Dec  8 19:35:02 user.crit ./bluealsa: W: Missing mSBC packet: 2 != 1
Dec  8 19:35:02 user.crit ./bluealsa: W: Missing mSBC packet: 2 != 3
Dec  8 19:35:02 user.crit ./bluealsa: W: Missing mSBC packet: 2 != 3

@borine
Copy link
Collaborator

borine commented Dec 9, 2019

libsbc returns error code ENOENT (No such file or directory) when the sbc syncword (1st 3 bytes) is invalid, and ESRCH (No such process) when the crc check fails. So it looks like sbc_decode() is being called with invalid data.

@arkq
Copy link
Owner

arkq commented Dec 9, 2019

@borine, the issue might be with the reading side being to slow, like you've said, the buffer is overwritten by incoming data. I've refactored decoding part as well (it's not yet on github), but I'm also working on mtu part (so the buffer can be read faster). My approach will be to get mtu from read() call with big buffer. Is seems that read() returns correct mtu for usb and uart chips. It will have some caveat, though. Before correct mtu usage, there will have to be capture connection for given chip for given voice type. What do you think about such approach?

@borine
Copy link
Collaborator

borine commented Dec 9, 2019

I'm not certain that the mtu depends on voice type. Have you seen that documented anywhere? My thought was that read() returns whatever data is available - the smallest of:

  • the real mtu of the hci bus,
  • a full packet (typically for HFP that is a 2-EV3 packet, size 60 bytes),
  • the balance of the last packet if a partial read was done previously.

So I agree that bluealsa should always read as much data as is available by providing a "large" read buffer, and bluealsa needs to be careful not to let the write timing delay also delay a pending read.
As for detecting the real mtu with a read() - how would that work for a speaker with no microphone - it would never provide any data for the test read() ?
BTW bluez still clearly has issues with SCO data over USB HCI - see for example https://www.spinics.net/lists/linux-bluetooth/msg82230.html

@arkq
Copy link
Owner

arkq commented Dec 9, 2019

I'm not certain that the mtu depends on voice type. Have you seen that documented anywhere?

No. But my test app returns (on my USB Intel chip) 48 bytes for CVSD and 24 bytes for transparent during read() call with "big" buffer. And I'm sure that there is more than 48 bytes of data in the kernel/chip buffer, because after establishing connection with my headset I'm waiting 1s (but tcpdump shows hci incoming data all the time). So, I've seen such thing empirically.

Anyway, I think that you are right, relying on read() is not the best idea... So, I think I will drop that "feature" :)

@borine
Copy link
Collaborator

borine commented Dec 10, 2019

No. But my test app returns (on my USB Intel chip) 48 bytes for CVSD and 24 bytes for transparent during read() call with "big" buffer.

I've just tried a test application, and I see the same packet sizes as you with USB - I have a very old CSR adapter . So that's a difference between USB and UART then, I guess. The kernel reports mtu of 64 bytes.

With Broadcom UART I always see reads of 60 bytes with CVSD or mSBC. The mtu of that adapter is 64 bytes.

Some other interesting results from this test:

  • With the UART adapter, the only data read returns is the data written by the remote device. With the USB adapter, poll() returns POLLIN even when no data has been written by the remote end. I can't tell if this is on a timer or just always ready, but as a result I get many thousands of reads every second with just 48 (CVSD) or 24 (transparent) zeros in the payload.

  • Using transparent voice with UART adapter, the transmitted data stream arrives intact with no embedded zeros or other unexpected values. Using transparent voice with USB adapter, and ignoring all the "zero" packets, the data stream contains some bytes with unexpected values (2 of the 540 bytes sent in the test are corrupted).
    [EDIT] repeating the test some more times, the data corruption is not always there, and I can't see any pattern to it when it does occur.

@borine
Copy link
Collaborator

borine commented Jun 22, 2021

I believe that mSBC should now work with both UART and USB adapters provided the you use the latest bluez-alsa code and kernels 5.12 and later, 5.10.18 and later, or 5.11.1 and later. See #400 for details. Closing, as much of the info here is now outdated.

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

No branches or pull requests

4 participants