Bug#828190: [pulseaudio] sometimes locks up with emu10k1 sink

[Michał Mirosław]

Package: pulseaudio
Version: 8.0-2+b2
Severity: important

--- Please enter the report below this line. ---

There is some weird interaction of pulseaudio with emu10k1 ALSA driver.
Sometimes it can't start playback, but just eats 100% CPU and spams
system logs (if allowed) with "Resume failed, couldn't restore original
sample settings."

I managed to catch in a debugging session that at
modules/alsa/alsa-sink.c:1099:

(gdb) p u->sink->sample_spec
$9 = {format = PA_SAMPLE_S16LE, rate = 44100, channels = 2 '\002'}
(gdb) p ss
$11 = {format = PA_SAMPLE_S16LE, rate = 48000, channels = 2 '\002'}

This stopped (resulting in working sound) after I changed
/etc/pulse/daemon.conf's default-sample-rate from 48000 to 44100,
commented alternate-sample-rate 44100 line and killed pulseaudio. The
problem didn't reappear after reverting the changes and killing
pulseaudio again, though.

--- System information. ---
Architecture: amd64
Kernel: Linux 4.6.3mq

Debian Release: stretch/sid
900 testing ftp.icm.edu.pl
800 jessie-backports ftp.icm.edu.pl
750 stable www.deb-multimedia.org
750 stable security.debian.org
750 stable repos.fds-team.de
750 stable ftp.icm.edu.pl
700 unstable ftp.icm.edu.pl
600 experimental ftp.icm.edu.pl
500 unstable-debug debug.mirrors.debian.org
500 testing-debug debug.mirrors.debian.org
500 stable deb.opera.com
500 proposed-updates ftp.icm.edu.pl
1 experimental-debug debug.mirrors.debian.org

--- Package information. ---
Depends (Version) | Installed
=======================================================-+-=======================
libasound2 (>= 1.0.24.1) |
libc6 (>= 2.15) |
libcap2 (>= 1:2.10) |
libdbus-1-3 (>= 1.9.14) |
libfftw3-single3 |
libgcc1 (>= 1:3.0) |
libice6 (>= 1:1.0.0) |
libltdl7 (>= 2.4.6) |
liborc-0.4-0 (>= 1:0.4.25) |
libpulse0 (= 8.0-2+b2) |
libsm6 |
libsndfile1 (>= 1.0.20) |
libsoxr0 (>= 0.1.0) |
libspeexdsp1 (>= 1.2~beta3.2-1) |
libstdc++6 (>= 4.1.1) |
libsystemd0 |
libtdb1 (>= 1.2.7+git20101214) |
libudev1 (>= 183) |
libwebrtc-audio-processing-0 |
libx11-6 |
libx11-xcb1 |
libxcb1 |
libxtst6 |
adduser |
lsb-base (>= 3.2-13) |
udev (>= 143) |
libasound2-plugins |
pulseaudio-utils |


Recommends (Version) | Installed
====================================-+-===========
pulseaudio-module-x11 | 8.0-2+b2
rtkit | 0.11-4


Suggests (Version) | Installed
==========================-+-===========
pavumeter |
pavucontrol | 3.0-3+b2
paman |
paprefs |

[Michał Mirosław]

Post by Michał Mirosław
This stopped (resulting in working sound) after I changed
/etc/pulse/daemon.conf's default-sample-rate from 48000 to 44100,
commented alternate-sample-rate 44100 line and killed pulseaudio.
The problem didn't reappear after reverting the changes and killing
pulseaudio again, though.

It locked up again. Commenting out alternate-sample-rate works
as a workaround.

[Felipe Sateler]

Control: tags -1 moreinfo

Post by Michał Mirosław

Post by Michał Mirosław
This stopped (resulting in working sound) after I changed
/etc/pulse/daemon.conf's default-sample-rate from 48000 to 44100,
commented alternate-sample-rate 44100 line and killed pulseaudio.
The problem didn't reappear after reverting the changes and killing
pulseaudio again, though.

It locked up again. Commenting out alternate-sample-rate works
as a workaround.

Could you attach a verbose log of the problem appearing? Instructions
to do so are here: https://wiki.ubuntu.com/PulseAudio/Log

[Michał Mirosław]

Post by Felipe Sateler

Post by Michał Mirosław

Post by Michał Mirosław
This stopped (resulting in working sound) after I changed
/etc/pulse/daemon.conf's default-sample-rate from 48000 to 44100,
commented alternate-sample-rate 44100 line and killed pulseaudio.
The problem didn't reappear after reverting the changes and killing
pulseaudio again, though.

It locked up again. Commenting out alternate-sample-rate works
as a workaround.

Could you attach a verbose log of the problem appearing? Instructions
to do so are here: https://wiki.ubuntu.com/PulseAudio/Log

Logs attached: first buggy, then working.

[Felipe Sateler]

Hi,

Post by Michał Mirosław

Post by Felipe Sateler

Post by Michał Mirosław

Post by Michał Mirosław
This stopped (resulting in working sound) after I changed
/etc/pulse/daemon.conf's default-sample-rate from 48000 to 44100,
commented alternate-sample-rate 44100 line and killed pulseaudio.
The problem didn't reappear after reverting the changes and killing
pulseaudio again, though.

It locked up again. Commenting out alternate-sample-rate works
as a workaround.

Could you attach a verbose log of the problem appearing? Instructions
to do so are here: https://wiki.ubuntu.com/PulseAudio/Log

Logs attached: first buggy, then working.

Did this ever work? Could you try with a different kernel (in
particular, with the stock ones debian provides)? Looks like a driver
bug to me, as the driver for some reason can be successfully changed
one time, but not after suspend-resume:

( 27.938| 0.000) D: [pulseaudio] sink-input.c: Negotiated format:
pcm, format.sample_format = "\"s16le\"" format.rate = "44100"
format.channels = "2" format.channel_map =
"\"front-left,front-right\""
( 27.938| 0.000) I: [pulseaudio] sink-input.c: Trying to change sample rate
( 27.938| 0.000) D: [pulseaudio] sink.c: Suspending sink
alsa_output.pci-0000_07_01.0.analog-stereo due to changing the sample
rate.
( 27.938| 0.000) I: [pulseaudio] alsa-sink.c: Updating rate for
device front:1, new rate is 44100
( 27.938| 0.000) D: [pulseaudio] source.c: Suspending source
alsa_output.pci-0000_07_01.0.analog-stereo.monitor due to changing the
sample rate.
( 27.938| 0.000) I: [pulseaudio] source.c: Changed sampling rate successfully
( 27.938| 0.000) I: [pulseaudio] sink.c: Changed sampling rate successfully
( 27.938| 0.000) I: [pulseaudio] sink-input.c: Rate changed to 44100 Hz
( 27.938| 0.000) I: [pulseaudio] module-stream-restore.c: Restoring
volume for sink input sink-input-by-application-name:MPlayer.
( 27.938| 0.000) I: [pulseaudio] module-stream-restore.c: Restoring
mute state for sink input sink-input-by-application-name:MPlayer.
( 27.938| 0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink
alsa_output.pci-0000_07_01.0.analog-stereo becomes busy, resuming.
( 27.938| 0.000) D: [pulseaudio] sink.c: Suspend cause of sink
alsa_output.pci-0000_07_01.0.analog-stereo is 0x0000, resuming
( 27.938| 0.000) D: [pulseaudio] reserve-wrap.c: Successfully
acquired reservation lock on device 'Audio1'
( 27.938| 0.000) I: [alsa-sink-emu10k1] alsa-sink.c: Trying resume...
( 27.939| 0.000) I: [alsa-sink-emu10k1] alsa-util.c: Cannot disable
ALSA period wakeups
( 27.939| 0.000) D: [alsa-sink-emu10k1] alsa-util.c: Maximum hw
buffer size is 341 ms
( 27.939| 0.000) D: [alsa-sink-emu10k1] alsa-util.c: Set buffer
size first (to 17832 samples), period size second (to 17832 samples).
( 27.939| 0.000) I: [alsa-sink-emu10k1] alsa-util.c: Device front:1
doesn't support 44100 Hz, changed to 48000 Hz.


Also, please give a try to the pulseaudio version in experimental, to
see if that improves the issue.

There may still be a pulseaudio bug, in that it should probably not
keep getting stuck in the suspend-resume loop...

[Harald Geyer]

retitle 828190 [pulseaudio] sometimes locks up
tag 828190 - moreinfo
stop

Dear Maintainer,

this report is tagged "moreinfo", but I don't see which info is
missing. AFAICS the original submitter provided everything he was
asked. Please add the tag again and clarify, if indeed some information
is missing.

Also I want to refute the theory, that this problem is mostly a bug
in the kernel driver: Everything works for me, if I use ALSA directly
instead of via pulseaudio and duckduckgo finds variants of this problem
reported on the internet related to many different drivers.

Here are my observations:

On my system audio mostly works fine for trivial things like beeps
or playing .wav files. However advanced uses (mostly VoIP software
like empathy, pidgin and baresip) cause pulseaudio to run at
100% CPU (one thread) and spam syslog with this message

Mar 31 00:19:02 teres pulseaudio[9099]: W: [alsa-source-1c22c00.dai-sun8i sun8i-0] alsa-source.c: Resume failed, couldn't restore original sample settings.

about 315 times per second.

The really fun part: After executing
pulseaudio -k; pulseaudio --log-level=4 --log-target=stderr

I can't reproduce the issue. Must be some race involved somewhere.

The system is set up with pulse as the default ALSA device. Interaction
with pulseaudio typically happens via the ALSA API.

From the difficulty in reproducing the behaviour and the content of the
message I gather, that the trigger depends on the state of the
audio HW/alsa and the properties of the audio data to be played.
Eg. Simply playing an audio file from baresip usually works fine from
a pristine state, but might fail if earlier activity caused the messages
to appear. Using "aplay" to play a .wav file might restore a working
state.

From reading [1] and [2] I understand, that mismatched sample rates
might cause such a problem. But pulseaudio should resample as needed
to avoid this. Upstream bug [3] might be related somewhat.

I focused my efforts for analyzing this problem with baresip, because it
has the most straight forward and easy to understand code. I can reproduce
this without any other audio applications running, so it really seems like
pulseaudio is stepping on its own toes. The versions in unstable and
experimental are both affected.

The code in baresip, responsible for handling audio is at:
https://github.com/alfredh/baresip/blob/be4448a54117cfd2cda69d4fc88e1c2802e8a5b6/modules/alsa/alsa_play.c#L53

If the ALSA API immediatly returns an error without blocking at all, this
code turns into a tight loop. Neatly explaining why the system hangs with
100% CPU.

I guess this code should be smarter about handling errors. OTOH I don't
see anything illegal happening there and pulseaudio should resample instead
of throwing errors, so the main problem must be with pulseaudio.

--- begin ---
static void *write_thread(void *arg)
{
struct auplay_st *st = arg;
int n;
int num_frames;

num_frames = st->prm.srate * st->prm.ptime / 1000;

while (st->run) {
const int samples = num_frames;
void *sampv;

st->wh(st->sampv, st->sampc, st->arg);

sampv = st->sampv;

n = snd_pcm_writei(st->write, sampv, samples);

if (-EPIPE == n) {
snd_pcm_prepare(st->write);

n = snd_pcm_writei(st->write, sampv, samples);
if (n != samples) {
warning("alsa: write error: %s\n",
snd_strerror(n));
}
}
else if (n < 0) {
warning("alsa: write error: %s\n", snd_strerror(n));
}
else if (n != samples) {
warning("alsa: write: wrote %d of %d samples\n",
n, samples);
}
}

snd_pcm_drain(st->write);

return NULL;
}
--- end ---

I might dig into this further in the coming days, but since I'm very much
not familiar with ALSA, pulseaudio and debugging threaded applications,
some help would be much appreciated.

I'm mostly writing this to tell you, that I can reproduce this issue at
will (mostly, considering I couln't get debug level logs) and can run
any tests you might need. But figuring out how to make pulseaudio
smarter about switching sample rates or how to make the debian package
detect, that alternate sample rates might not be a good idea on any given
system, is probably above my paygrade.

[1] https://pulseaudio-discuss.freedesktop.narkive.com/KCt6OOkP/testing-echo-cancellation-on-an-armhf-omap-phone

[2] https://arunraghavan.net/2011/10/alternate-sample-rates/

[3] https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/issues/374

[Harald Geyer]

Hi,

I have been wrong in at least one part of my previous update to this
bug. Even if I stop all threads in the sound application (in my case
baresip) in the debugger, pulseaudio still run's at 100% CPU spamming
syslog. Only killing baresip (probably the closing of file descriptors)
makes pulseaudio recover.

I got confused, because somehow this situation causes an other thread
of baresip consume lot's of CPU, which made me believe that there is
a rather tight loop between baresip and pulseaudio. Actually the calls
to the sound API never return while pulseaudio is busy, thus the
application never get's an error and can't actually close its ALSA
handles.

So at this point I'm convinced the entire problem is within pulseaudio.
Since baresip is not a pulseaudio but an ALSA application, works fine
without pulseaudio installed and only uses pulseaudio because
pulseaudio makes itself the default ALSA device on installation, I think
it is fair to say that pulseaudio is breaking unrelated software here.

I'm tempted to raise the severity of this bug to release critical, but
I guess this should be at the discretion of the maintainers.

This is clearly a (probably rather old) upstream bug. It seems to mostly
manifest itself with SoC devices, which might explain why it is more
often seen recently and with debian: Debian arm ports are quite popular
with users of SoC based laptops.

From the debian packaging PoV I can see two possible workarounds:
* Disable sample rate switching by setting defaut-sample-rate and
alternate-sample-rate to the same value by default for the ARM based
ports and prominently document the problem for everybody else.
* Don't enable pulseaudio at all on ARM based ports without some kind
of manual intervention by the local admin.

HTH,
Harald

[Michał Mirosław]

Looking at perf and strace output, the case looks similar to what was
described in an upstream commit [1] and its backing bug report [2].
(Haven't tried the workarounds nor testing or newer version, yet.)

[1]
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/commit/37358e42c49abe3d83b344452749461b70fdc80f
[2] https://bugzilla.kernel.org/show_bug.cgi?id=199365#c6

-- strace log:

22:59:37.624592 ppoll([{fd=4, events=POLLIN}, ...], 34, NULL, NULL, 8) = 1 ([{fd=18, revents=POLLIN}])

/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_poll+0x171) [0x26151]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_iterate+0x2f) [0x2674f]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_run+0x20) [0x26800]

22:59:37.628232 read(18, "\1\0\0\0\10\0\0\0\0\0\0\0\20\0\0\0controlC1\0\0\0\0\0\0\0"..., 272) = 64

/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-14.2.so(pa_read+0x21) [0x28441]
/usr/lib/pulse-14.2/modules/module-udev-detect.so() [0x3892]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_dispatch+0x1b3) [0x26433]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_iterate+0x3e) [0x2675e]

22:59:37.632976 read(18, 0x7ffcd669eb60, 272) = -1 EAGAIN (Zasoby chwilowo niedostępne)
22:59:37.637756 access("/dev/snd/controlC1", R_OK|W_OK) = 0

/usr/lib/pulse-14.2/modules/module-udev-detect.so() [0x281f]
/usr/lib/pulse-14.2/modules/module-udev-detect.so() [0x3c25]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_dispatch+0x1b3) [0x26433]

22:59:37.642327 write(38, "\1\0\0\0\0\0\0\0", 8) = 8

/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-14.2.so(pa_write+0x62) [0x284d2]
/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-14.2.so(pa_fdsem_post+0xa6) [0x2fa36]
/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecore-14.2.so(pa_asyncmsgq_dispatching+0xc1) [0x1a071]
/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecore-14.2.so(pa_asyncmsgq_send+0xb3) [0x19493]
/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecore-14.2.so(pa_sink_state_to_string+0x361) [0x53e61]
/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecore-14.2.so(pa_card_suspend+0x8a) [0x2920a]
/usr/lib/pulse-14.2/modules/module-udev-detect.so() [0x3c25]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_dispatch+0x1b3) [0x26433]

22:59:37.651251 read(4, 0x7ffcd669ecee, 10) = -1 EAGAIN (Zasoby chwilowo niedostępne)

/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-14.2.so(pa_read+0x21) [0x28441]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_prepare+0x5e) [0x25cae]
/usr/lib/x86_64-linux-gnu/libpulse.so.0.23.0(pa_mainloop_iterate+0x20) [0x26740]

[start over from ppoll()]

-- Package-specific info:
File '/etc/default/pulseaudio' does not exist


-- System Information:
Debian Release: 11.6
APT prefers stable-security
APT policy: (900, 'stable-security'), (900, 'stable-debug'), (900, 'proposed-updates'), (900, 'stable'), (800, 'oldstable-proposed-updates'), (800, 'oldstable-debug'), (800, 'oldstable'), (700, 'unstable'), (600, 'experimental'), (500, 'unstable-debug'), (500, 'stable-updates'), (500, 'proposed-updates-debug'), (1, 'experimental-debug')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 6.1.3+ (SMP w/8 CPU threads; PREEMPT)
Kernel taint flags: TAINT_OOT_MODULE
Locale: LANG=pl_PL.UTF-8, LC_CTYPE=pl_PL.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages pulseaudio depends on:
ii adduser 3.118
ii init-system-helpers 1.60
ii libasound2 1.2.4-1.1
ii libasound2-plugins 1.2.2-2
ii libc6 2.31-13+deb11u5
ii libcap2 1:2.44-1
ii libdbus-1-3 1.12.24-0+deb11u1
ii libgcc-s1 10.2.1-6
ii libice6 2:1.0.10-1
ii libltdl7 2.4.6-15
ii liborc-0.4-0 1:0.4.32-1
ii libpulse0 14.2-3
ii libsm6 2:1.2.3-1
ii libsndfile1 1.0.31-2
ii libsoxr0 0.1.3-4
ii libspeexdsp1 1.2~rc1.2-1.1
ii libstdc++6 10.2.1-6
ii libsystemd0 247.3-7+deb11u1
ii libtdb1 1.4.3-1+b1
ii libudev1 247.3-7+deb11u1
ii libwebrtc-audio-processing1 0.3-1+b1
ii libx11-6 2:1.7.2-1
ii libx11-xcb1 2:1.7.2-1
ii libxcb1 1.14-3
ii libxtst6 2:1.2.3-1
ii lsb-base 11.1.0
ii pulseaudio-utils 14.2-3

Versions of packages pulseaudio recommends:
ii dbus-user-session 1.12.24-0+deb11u1
ii libpam-systemd [logind] 247.3-7+deb11u1
ii rtkit 0.13-4

Versions of packages pulseaudio suggests:
ii paprefs 1.1-2
ii pavucontrol 4.0-2
ii pavumeter 0.9.3-4+b3
ii udev 247.3-7+deb11u1

[Michał Mirosław]

Post by Michał Mirosław
Looking at perf and strace output, the case looks similar to what was
described in an upstream commit [1] and its backing bug report [2].
(Haven't tried the workarounds nor testing or newer version, yet.)
[1]
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/commit/37358e42c49abe3d83b344452749461b70fdc80f
[2] https://bugzilla.kernel.org/show_bug.cgi?id=199365#c6

[...]

Disabling `load-module module-suspend-on-idle` in `default.pa` seems to
also work around the problem.