PipeWire does not write properly to the wm8962
PipeWire has problems writing data to the wm8962 on the phone. This issue is created in the linux-next project because it is assumed the problem is in the kernel driver but that may not be the case. The following steps will reproduce the problem:
# Shut pulseaudio off
systemctl --user mask pulseaudio.socket pulseaudio.service
systemctl --user stop pulseaudio.socket pulseaudio.service
# Install dependencies
sudo apt build-dep pipewire
sudo apt install libjack-jackd2-dev
# Build pipewire
git clone -b 0.3.0 https://gitlab.freedesktop.org/pipewire/pipewire.git
meson -Dvulkan=false -Dbluez5=false pipewire-build pipewire
cd pipewire-build
ninja
# Run pipewire from the build directory
PIPEWIRE_DEBUG=5 make run
# In another terminal, run paplay
cd pipewire-build
make shell
paplay /usr/share/sounds/librem5/stereo/phone-incoming-call.oga
# If you hear sound, stop paplay and restart it
# Witness something like the following in the first terminal
[T][000007645.668921][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7645617422513 7645617356931 65582 1024 11236
[T][000007645.668961][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007645.882172][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7645830673176 7645830106931 566245 1024 11236
[T][000007645.882208][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007646.094417][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7646042917526 7646042856931 60595 1024 11236
[T][000007646.094454][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007646.307208][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7646255700432 7646255606931 93501 1024 11236
[T][000007646.307265][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007646.519941][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7646468438098 7646468356931 81167 1024 11236
[T][000007646.519978][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007646.733195][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7646681690321 7646681106931 583390 1024 11236
[T][000007646.733231][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007646.945942][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7646894436267 7646893856931 579336 1024 11236
[T][000007646.945978][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007647.158227][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7647106709656 7647106606931 102725 1024 11236
[T][000007647.158295][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007647.371496][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7647319977359 7647319356931 620428 1024 11236
[T][000007647.371596][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007647.583779][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7647532254108 7647532106931 147177 1024 11236
[T][000007647.583879][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007647.796482][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7647744961534 7647744856931 104603 1024 11236
[T][000007647.796549][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
[T][000007648.009253][alsa-pcm.c:1097 alsa_on_timeout_event()] alsa-pcm 0xaaab005558a8: timeout 11236 1024 7647957730160 7647957606931 123229 1024 11236
[T][000007648.009319][alsa-pcm.c:1013 handle_play()] alsa-pcm 0xaaab005558a8: early wakeup 11236 1024
Here are logs of the daemon both failing as above and a log of one instance of writing correctly:
This important grepped section of the non-working log shows the activity in alsa-pcm.c prior to failing:
[D][000000174.725632][alsa-pcm.c:1184 spa_alsa_start()] alsa-pcm 0xaaaaf31984c8: start 1024 duration:1024 rate:48000 slave:0 match:0
[T][000000174.726083][alsa-pcm.c:770 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: begin 0 131072 1024 2048
[T][000000174.726103][alsa-pcm.c:830 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: silence 2048
[T][000000174.726127][alsa-pcm.c:836 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: commit 0 2048 0
[T][000000174.726152][alsa-pcm.c:852 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: snd_pcm_start 2048
[T][000000174.726851][alsa-pcm.c:622 get_status()] alsa-pcm 0xaaaaf31984c8: avail: 129024, matching: 0
[T][000000174.726879][alsa-pcm.c:1101 alsa_on_timeout_event()] alsa-pcm 0xaaaaf31984c8: timeout 2048 1024 174693849576 174693223536 626040 1024 2048
[T][000000174.726915][alsa-pcm.c:716 update_time()] alsa-pcm 0xaaaaf31984c8: slave:0 174693223536 0.997804 2048 1024.000000 1021.751115 1024
[T][000000174.726934][alsa-pcm.c:1028 handle_play()] alsa-pcm 0xaaaaf31984c8: 0
[T][000000174.747828][alsa-pcm.c:622 get_status()] alsa-pcm 0xaaaaf31984c8: avail: 129024, matching: 0
[T][000000174.747853][alsa-pcm.c:1101 alsa_on_timeout_event()] alsa-pcm 0xaaaaf31984c8: timeout 2048 1024 174714823665 174714603824 219841 1024 2048
[T][000000174.747897][alsa-pcm.c:716 update_time()] alsa-pcm 0xaaaaf31984c8: slave:0 174714603824 0.994662 2048 1024.000000 1018.534358 1024
[T][000000174.747954][alsa-pcm.c:1028 handle_play()] alsa-pcm 0xaaaaf31984c8: 1
[T][000000174.749834][alsa-pcm.c:770 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: begin 2048 129024 1024 0
[T][000000174.749849][alsa-pcm.c:814 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: reuse buffer 0
[T][000000174.749876][alsa-pcm.c:836 spa_alsa_write()] alsa-pcm 0xaaaaf31984c8: commit 2048 996 2048
[T][000000174.769160][alsa-pcm.c:622 get_status()] alsa-pcm 0xaaaaf31984c8: avail: 128028, matching: 0
[T][000000174.769195][alsa-pcm.c:1101 alsa_on_timeout_event()] alsa-pcm 0xaaaaf31984c8: timeout 3044 1024 174736163754 174736051635 112119 1024 3044
[T][000000174.769219][alsa-pcm.c:1017 handle_play()] alsa-pcm 0xaaaaf31984c8: early wakeup 3044 1024
[T][000000174.811237][alsa-pcm.c:622 get_status()] alsa-pcm 0xaaaaf31984c8: avail: 128028, matching: 0
[T][000000174.811262][alsa-pcm.c:1101 alsa_on_timeout_event()] alsa-pcm 0xaaaaf31984c8: timeout 3044 1024 174778232653 174778134968 97685 1024 3044
[T][000000174.811323][alsa-pcm.c:1017 handle_play()] alsa-pcm 0xaaaaf31984c8: early wakeup 3044 1024
[T][000000174.853295][alsa-pcm.c:622 get_status()] alsa-pcm 0xaaaaf31984c8: avail: 128028, matching: 0
Here are some abridged logs of the #pipewire
IRC channel discussing the issue:
15:26 <@wtay> rah, aplay works differently
15:27 < rah> wtay: how so?
15:28 <@wtay> rah, pipewire uses a timer and precise timing info from the driver to write samples. aplay uses the device interrupt
15:28 < panto> it is very common for platforms to have busted dma/timer drivers
15:29 < panto> it's like 99% of the problems that people have with pulseaudio which defaults to using timer interrupts
...
14:19 < rah> I can see why there's a click: it seems to write one period and then gets lost
14:19 < rah> there's an xrun first, then it writes a period, then it gets lost
14:22 < gkiagia> I've digged into this early wakeup before... what happens with broken drivers is that pipewire wakes up by the system timer to write, but before writing it asks the alsa driver how much data it still has in the buffer.... the driver reports wrong data and pipewire thinks it needs to sleep again ("early wakeup")
14:23 < gkiagia> and later on, when it finally comes to writing, the driver reports an underrun
14:38 < rah> gkiagia: can I ask which hardware/driver you saw this on before?
15:10 < gkiagia> rah: not sure, I think it was an imx6 board
15:11 < gkiagia> rah: I've played with a couple of boards for AGL... most of them fortunately work
15:12 < rah> gkiagia: I see
...
15:26 < smurray> gkiagia: re imx6/imx8, I've got both here (been tinkering with imx8) if there's something you need tested
15:28 < gkiagia> smurray: wasn't it your imx6 board that had underruns that I wasn't able to fix (when we tested at all systems go)
15:29 < gkiagia> I don't fully remember anymore
15:36 < smurray> gkiagia: yeah, and I see the same thing on imx8
15:37 < smurray> gkiagia: and I believe one of the Indian devs trying AGL on the imx8 EVK opened a similar JIRA
15:41 * rah is using imx8 btw
15:54 < Ford_Prefect> rah: smurray: wtay: we disable timer based scheduling on devices that report snd_pcm_hw_params_is_batch() as true (except if they are USB devices)
15:56 < Ford_Prefect> The rationale being that these devices usually only update their hw pointer values in multiples of the period size, so when you sleep for ~the full buffer length and wake up and query the free buffer space, you will get an incorrect low value
15:56 < gkiagia> we = pulseaudio ?
15:56 < Ford_Prefect> "incorrect"
15:56 < Ford_Prefect> gkiagia: yes, sorry