SCO record quality is not great

[hrc-amilcar]

Hello,

I'm testing recording from two BT headsets. Zebra HS3100 and Plantronics Voyager Legend.

Playback quality is great, but recording is quiet, crackling, and slightly sped up.

I'm using the latest master (24b7300) with and without --enable-debug. Launched as:
/usr/bin/bluealsa --syslog -p a2dp-sink -p a2dp-source -p hfp-hf -p hfp-ag -p hsp-hs -p hsp-ag

Any hints would be a appreciated to improve record quality.

If it helps, here are the logs from arecord:

# arecord -v -fS16_LE -r 8000 -Dbluealsa:DEV=00:1B:41:B2:86:9A,PROFILE=sco test.wav
D: src/asound/bluealsa-pcm.c:1312: Getting BlueALSA PCM: CAPTURE 00:1B:41:B2:86:9A sco
D: src/asound/bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Setting constraints
Recording WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
D: src/asound/bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Initializing HW
D: src/asound/bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: FIFO buffer size: 32768 frames
D: src/asound/bluealsa-pcm.c:573: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Selected HW buffer: 4 periods x 2000 bytes == 8000 bytes
D: src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Initializing SW
D: src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Initializing SW
D: src/asound/bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Prepared
D: src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Initializing SW
Plug PCM: BlueALSA PCM: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source
BlueALSA BlueZ device: /org/bluez/hci0/dev_00_1B_41_B2_86_9A
BlueALSA Bluetooth codec: CVSD
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 1
  rate         : 8000
  exact rate   : 8000 (8000/1)
  msbits       : 16
  buffer_size  : 4000
  period_size  : 1000
  period_time  : 125000
  tstamp_mode  : NONE
  tstamp_type  : GETTIMEOFDAY
  period_step  : 1
  avail_min    : 1000
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 4000
  silence_threshold: 0
  silence_size : 0
  boundary     : 2097152000
D: src/asound/bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Starting
D: src/asound/bluealsa-pcm.c:226: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Starting IO loop: 7

-- a few seconds later I press Ctrl-C --
^CAborted by signal Interrupt...
arecord: pcm_read:2151: read error: Interrupted system call
D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Stopping
D: src/asound/bluealsa-pcm.c:161: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: IO thread cleanup
D: src/asound/bluealsa-pcm.c:592: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Freeing HW
D: src/asound/bluealsa-pcm.c:443: /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source: Closing

And here are the logs from BlueAlsa daemon:

user.debug /usr/bin/bluealsa: src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_00_1B_41_B2_86_9A/hfpag/source
user.debug /usr/bin/bluealsa: src/ba-transport.c:710: New SCO link: 00:1B:41:B2:86:9A: 24
user.debug /usr/bin/bluealsa: src/hci.c:132: SCO link socket MTU: 24: 180
user.debug /usr/bin/bluealsa: src/ba-transport.c:1145: Starting transport: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/ba-transport.c:293: Created BT socket duplicate: [24]: 25
user.debug /usr/bin/bluealsa: src/ba-transport.c:1462: Created new IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/ba-transport.c:293: Created BT socket duplicate: [24]: 26
user.debug /usr/bin/bluealsa: src/ba-transport.c:1462: Created new IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/sco.c:229: IO loop: START: sco_cvsd_enc_thread: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/sco.c:297: IO loop: START: sco_cvsd_dec_thread: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/ba-transport.c:1377: PCM resumed: 21
user.debug /usr/bin/bluealsa: src/ba-transport.c:1424: Closing PCM: 21
user.debug /usr/bin/bluealsa: src/ba-transport.c:437: PCM clients check keep-alive: 0 ms
user.debug /usr/bin/bluealsa: src/ba-transport.c:386: Stopping transport: No PCM clients
user.debug /usr/bin/bluealsa: src/ba-transport.c:305: Closing BT socket duplicate [24]: 25
user.debug /usr/bin/bluealsa: src/ba-transport.c:725: Releasing SCO link: 24
user.debug /usr/bin/bluealsa: src/ba-transport.c:1487: Exiting IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/ba-transport.c:305: Closing BT socket duplicate [-1]: 26
user.debug /usr/bin/bluealsa: src/sco.c:319: IO loop: EXIT: sco_cvsd_dec_thread: HFP Audio Gateway (CVSD)
user.debug /usr/bin/bluealsa: src/ba-transport.c:1487: Exiting IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)

[arkq]

Please check whether you will have the same results with bluez-alsa 3.1.0. If the result is the same, than you might try to record low level Bluetooth communication e.g.: hcidump or tcpdump and post it here (few seconds, so after manual audio reconstruction from raw packets you will be able to tell whether audio is OK or not).

Does you headset support mSBC? It might be easier with mSBC because there are control bits in the stream, so it will be possible to tell right away whether there are some missing packets.

[borine]

crackling, and slightly sped up

One possible cause of this effect is dropped samples. Are you using an RPi with on-board BT adapter by any chance? That is notorious for dropping incoming SCO samples, especially when 2.4GHz Wifi is in use at the same time,

[hrc-amilcar]

@arkq, I've attached test-01.zip containing:

• test-01.wav: Wave file captured with arecord -fS16_LE -r8000 -Dbluealsa:DEV=...
  This file sounds sped-up and crackly.
• test-01.raw: Audio file captured with hcidump -A test-01.raw at the same time.
  This file sounds loud and clear when I replay it with aplay -fS16_LE -r8000 -c1 test.raw on my laptop or back to the headset.

Next, I will try going back to 3.1.0 (b09f373).

@borine the device is a custom SOM with an onboard wl18xx Ti chip. Not currently using the WiFi capabilities of the chip.

[arkq]

@hrc-amilcar as for hcidump I thought about all data, not audio only (-A), so, we could examine SCO packet timings. Packets should arrive at even time periods, so if there are missing packets we should have some gaps. Then we can try to infer what might be the cause of that.

EDIT:
Scratch what I wrote before :D I haven't read carefully your previous message.

So the hcidump sounds OK, but the audio recorded with arecord is not OK.... hmmm. We will have to go dipper with that.

[arkq]

You might also try to record audio data without involving ALSA library (one less element which might cause issues). Please use bluealsa-cli open <PCM_PATH> > dump.raw to record audio to a file. If this will produce audio without any issues, something has to be not right with ALSA setup then....

[hrc-amilcar]

I updated to 3.1.0 (b09f373) and the arecord WAV now sounds identical to the hcidump RAW. i.e. good quality.

It would be nice to use the latest since I'm interfacing with DBus in my app. But I can go back to PCMAdded/PCMRemoved and stick to 3.1.0 if necessary.

Let me know if you need any other captures! Thank you.

EDIT: Will try bluealsa-cli next.

[arkq]

OK. It might be a long way to run, but could you try to pinpoint with git bisect the commit which breaks things? Now we know that it is some kind of regression....

[hrc-amilcar]

Will try to bisect. It's only log2(75) tries. :)

Also, I believe this affects playback as well. I was getting underruns from my app but not from aplay. The underruns went away with 3.1.0.

[hrc-amilcar]

It seems 1f82111 causes the speed-up in arecording as well as the underruns in my app playback.

Everything is good again if I take sco.c from b70aa72 and apply it on top of master 24b7300.

[arkq]

I was afraid that this commit might cause troubles... I'll try to figure out how to fix that. Many thanks for bisect.

[borine]

@hrc-amilcar if you have time, please could you try my branch here: https://github.com/borine/bluez-alsa/tree/sco-mtu-bus-check

This is actually a work-in-progress implementing changes discussed in #400, but I think that the change in CVSD mtu handlng for UART adapters may also possibly help with the issue reported here.

[hrc-amilcar]

@borine, I tried your branch. It sounds good again for both capture (no speed-up) and playback (no underruns).

The MTU is now 180 instead of 48, as reported by hci_sco_get_mtu. It seems good to honor the SCO_OPTIONS for these headsets.

[borine]

for these headsets.

Actually, it is the local adapter which matters when choosing the SCO socket read and write sizes. My patch distinguishes USB adapters (for which the Linux driver, btusb, is, IMHO, badly broken) from other types (for which the drivers are generally in good shape) and applies workarounds only for USB. The current BlueALSA source applies the workaround for all adapter types which turns out to be detrimental to UART adapters.

[hrc-amilcar]

Makes sense.

It's interesting that the current single-threaded SCO implementation for both Read/Write allows the audio to flow correctly with a small size MTU of 48. I would have thought there would be missed packets regardless. Or that the two thread implementation would be able to feed 48-byte packets more quickly than single-threaded. But maybe there's some inherent delay in the latter implementation for which 180 byte packets hides the issue?

[borine]

The critical change in commit 1f82111 that introduced the capture issue is the size of the read buffer in BlueALSA. The read() calls actually ignore the MTU and read all available data into the buffer, limited by the size of the buffer. Before commit 1f82111 the buffer was 128 bytes, but was reduced to MTU size (48 bytes) by that commit. So a simple fix for capture would be to increase the read buffer size - I would suggest 180 bytes or even 256.

I admit I cannot immediately explain the change in playback behaviour, nor why my patch would fix it.

[hrc-amilcar]

I tried with a read buffer of 256 in sco_cvsd_dec_thread and it fixed the issue for both playback and capture. But not sure where else the MTU values are used. I would think using the adapter MTU would be preferred?

[borine]

For reading from a socket the MTU is irrelevant - the read() call just returns whatever data is available at that time, or blocks if no data is available. For write() MTU is important - and for SCO sockets exceeding it can cause failure - certainly for USB, not sure about UART.

[arkq]

The critical change in commit 1f82111 that introduced the capture issue is the size of the read buffer in BlueALSA. The read() calls actually ignore the MTU and read all available data into the buffer, limited by the size of the buffer. Before commit 1f82111 the buffer was 128 bytes, but was reduced to MTU size (48 bytes) by that commit.

Yes, it seems that this "enhancement" in fact has broken something... However, right now I'm not sure why I have used only a single MTU for read buffer. Maybe unification with write thread, or maybe I've got some issue with other (bigger) value (I do remember that I've got some troubles with CVSD thread separation). Anyway, I think that this read buffer indeed can be bigger than MTU, especially in case when the MTU value is not guaranteed to be correct.

[borine]

especially in case when the MTU value is not guaranteed to be correct

Yes, and that is precisely the point of my branch referenced above. I am trying to identify where the MTU reported by the socket is correct, and where it is (dangerously) wrong. But as I said, that is most definitely a work in progress. I have a lot more research to do and do not expect to have it ready for at least another year.

However, it already seems clear that it is the btusb module where the problems originate, so possibly the part of my commit that factors out the USB adapter handling from other types (but ignoring the BT_VOICE_TRANSPARENT changes) is worth considering as a PR in it own right?

[arkq]

Yes, I think that it will be worth merging into the master. However, I've got a question. Merging your MTU fix will require kernel with patch applied (I'm not up to date what is the final kernel patch and how it maintains backward compatibility)?

[arkq]

@hrc-amilcar could you please check how #511 will work for you?

[borine]

@arkq PR #512 includes only the USB adapter check from my SCO work. It does not include any mSBC changes, so is independent of any kernel changes - I do not expect any backwards compatibility issues with this.

@hrc-amilcar - I believe my PR #512 is a direct fix for the issue you report here - both capture and playback - could I impose upon you to test this one also please ?.

I think #511 and #512 are compatible with each other and are possibly both worth considering for merging

[arkq]

I think #511 and #512 are compatible with each other and are possibly both worth considering for merging

Yes, I thought about merging your patch which should fix read/write for most cases and my patch which is a safety just for reading but should work for all cases.

[hrc-amilcar]

@arkq, @borine Both #511 and #512 correct the issue independently. Looking forward to the merges.

#511: I see the sco.c:310: Resizing CVSD read buffer: 96 -> 192 in the debug logs.
#512: One observation in hci_sco_get_mtu. It seems possible for getsockopt(SCO_OPTIONS) to fail and return a zero MTU now that the MTU will no longer be fixed at 48/24 for non-USB adapters.

[arkq]

One observation in hci_sco_get_mtu. It seems possible for getsockopt(SCO_OPTIONS) to fail and return a zero MTU now that the MTU will no longer be fixed at 48/24 for non-USB adapters.

Yes, that might happen, but in such a case it will be a fatal error later (there is a check in https://github.com/Arkq/bluez-alsa/blob/master/src/ba-transport.c#L282).