Ticket #195 (new defect)

Opened 9 months ago

Last modified 3 months ago

ARM: possible deadlocks when running pulseaudio with --high-priority=1

Reported by: kaivehmanen Assigned to: lennart
Priority: normal Milestone:
Component: core Severity: normal
Keywords: SCHED_FIFO Cc: kai.vehmanen@nokia.com

Description

Originally reported to pulse-audio discuss: https://tango.0pointer.de/pipermail/pulseaudio-discuss/2007-December/001001.html 

--cut--
This is probably a known issue, but I'm constantly hitting 
a deadlock when running Pulseaudio (0.9.7) with SCHED_FIFO
(--high-priority=1). 

I can reproduce it as follows:

- run pulseaudio (self-compiled, debian stable) with --high-priority=1
- first client: while [ 1 ] ; do aplay -D pulse foo.wav ; done
- second: while [ 1 ] ; do aplay -D pulse foo.wav ; done

At some point, pulseaudio gets stuck and backtrace shows its
stuck in memblock.c:pa_memblock_unref() -> memblock_free() 
-> pa_mutex_lock().
At some point, pulseaudio gets stuck and backtrace shows its
stuck in memblock.c:pa_memblock_unref() -> memblock_free() 
-> pa_mutex_lock().
--cut--

Change History

12/21/07 12:37:42 changed by kaivehmanen 

Some backtraces attached (sorry, debugging symbols lacking from many libraries):

chrt info
--cut--
pid 7280's current scheduling policy: SCHED_OTHER 
pid 7280's current scheduling priority: 0
pid 7287's current scheduling policy: SCHED_FIFO
pid 7287's current scheduling priority: 1
--cut--

thread 1
--cut--
Using host libthread_db library "/lib/libthread_db.so.1".
Attaching to program: /usr/bin/pulseaudio, process 7280 Reading symbols from /lib/libpthread.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /usr/lib/libpulsecore.so.4...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libpulsecore.so.4 Reading symbols from /usr/lib/libsndfile.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libsndfile.so.1 Reading symbols from /usr/lib/liboil-0.3.so.0...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/liboil-0.3.so.0 Reading symbols from /usr/lib/libdbus-1.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libdbus-1.so.3 Reading symbols from /lib/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libdl.so.2...
(no debugging symbols found)...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.3...
(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.3
Reading symbols from /lib/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libnss_files.so.2 Reading symbols from /usr/lib/pulse-0.9/modules/module-alsa-sink.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-alsa-sink.so
Reading symbols from /usr/lib/libasound.so.2...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libasound.so.2 Reading symbols from /usr/lib/pulse-0.9/modules/libalsa-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libalsa-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-native-protocol-unix.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-native-protocol-unix.so
Reading symbols from /usr/lib/pulse-0.9/modules/libprotocol-native.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libprotocol-native.so
Reading symbols from /usr/lib/pulse-0.9/modules/libsocket-server.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libsocket-server.so
Reading symbols from /usr/lib/pulse-0.9/modules/libsocket-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libsocket-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpstream.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpstream.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpstream-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpstream-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpdispatch.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpdispatch.so
Reading symbols from /usr/lib/pulse-0.9/modules/libtagstruct.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libtagstruct.so
Reading symbols from /usr/lib/pulse-0.9/modules/libauthkey.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libauthkey.so
Reading symbols from /usr/lib/pulse-0.9/modules/libauthkey-prop.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libauthkey-prop.so
Reading symbols from /usr/lib/pulse-0.9/modules/libstrlist.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libstrlist.so
Reading symbols from /usr/lib/pulse-0.9/modules/libiochannel.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libiochannel.so
Reading symbols from /usr/lib/pulse-0.9/modules/libipacl.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libipacl.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpacket.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpacket.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-rescue-streams.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-rescue-streams.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-suspend-on-idle.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-suspend-on-idle.so
0x4003042c in sem_wait
    () from /lib/libpthread.so.0
(gdb) bt
#0  0x4003042c in sem_wait () from /lib/libpthread.so.0
#1  0x40091058 in pa_semaphore_wait () from /usr/lib/libpulsecore.so.4
#2  0x4008b248 in pa_asyncmsgq_send () from /usr/lib/libpulsecore.so.4
#3  0x40e80a44 in ?? () from /usr/lib/pulse-0.9/modules/libprotocol-native.so

--cut--

thread 2 (SCHED_FIFO thread)
--cut--
warning: process 7287 is a cloned process Reading symbols from /lib/libpthread.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /usr/lib/libpulsecore.so.4...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libpulsecore.so.4 Reading symbols from /usr/lib/libsndfile.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libsndfile.so.1 Reading symbols from /usr/lib/liboil-0.3.so.0...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/liboil-0.3.so.0 Reading symbols from /usr/lib/libdbus-1.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libdbus-1.so.3 Reading symbols from /lib/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libdl.so.2...
(no debugging symbols found)...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.3...
(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.3
Reading symbols from /lib/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libnss_files.so.2 Reading symbols from /usr/lib/pulse-0.9/modules/module-alsa-sink.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-alsa-sink.so
Reading symbols from /usr/lib/libasound.so.2...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libasound.so.2 Reading symbols from /usr/lib/pulse-0.9/modules/libalsa-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libalsa-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-native-protocol-unix.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-native-protocol-unix.so
Reading symbols from /usr/lib/pulse-0.9/modules/libprotocol-native.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libprotocol-native.so
Reading symbols from /usr/lib/pulse-0.9/modules/libsocket-server.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libsocket-server.so
Reading symbols from /usr/lib/pulse-0.9/modules/libsocket-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libsocket-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpstream.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpstream.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpstream-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpstream-util.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpdispatch.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpdispatch.so
Reading symbols from /usr/lib/pulse-0.9/modules/libtagstruct.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libtagstruct.so
Reading symbols from /usr/lib/pulse-0.9/modules/libauthkey.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libauthkey.so
Reading symbols from /usr/lib/pulse-0.9/modules/libauthkey-prop.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libauthkey-prop.so
Reading symbols from /usr/lib/pulse-0.9/modules/libstrlist.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libstrlist.so
Reading symbols from /usr/lib/pulse-0.9/modules/libiochannel.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libiochannel.so
Reading symbols from /usr/lib/pulse-0.9/modules/libipacl.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libipacl.so
Reading symbols from /usr/lib/pulse-0.9/modules/libpacket.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/libpacket.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-rescue-streams.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-rescue-streams.so
Reading symbols from /usr/lib/pulse-0.9/modules/module-suspend-on-idle.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/pulse-0.9/modules/module-suspend-on-idle.so

0x4002b71c in pthread_mutex_lock () from /lib/libpthread.so.0
(gdb) bt
#0  0x4002b71c in pthread_mutex_lock () from /lib/libpthread.so.0
#1  0x40090428 in pa_mutex_lock () from /usr/lib/libpulsecore.so.4
#2  0x4006a0a8 in pa_memblock_unref () from /usr/lib/libpulsecore.so.4
#3  0x400803ec in pa_sink_input_peek () from /usr/lib/libpulsecore.so.4
#4  0x4007b114 in ?? () from /usr/lib/libpulsecore.so.4
--cut--

02/15/08 14:56:17 changed by lennart

Hmm, no this is not a known issue. So, someone else apparently has taken the mutex of the mempool that we try to acquire. Hmm, I know this is not easy, but could you find out which piece of code might be doing that?

What arch is this?

02/15/08 15:22:42 changed by lennart

If this is arm, then #178 is probably the same issue as this one.

Please comment!

02/19/08 17:13:14 changed by kaivehmanen

The traced run was on armv6. I remember reproducing this on x86 as well, but now when I tried it again, I couldn't trigger it anymore. :( And even on armv6, you have to create quite a bit of load (including constant addition/removals of clients) to trigger the freeze. Anyways, looking at the traces, this doesn't seem to be same as #178, but the two can still be related. Currently I've been able to workaround this bug by using trylock() variant in the real-time thread (i.e. don't take the lock if lower-priority bug is holding it). While this is not an acceptable solution, this does suggest that the bug is indeed in PRIO_INHERIT. On the other hand, the lower priority thread (in above trace) is blocked in sem_wait() and raising its priority doesn't really help so this could still be something else as well.

Oh well, more details are obviously needed. If/when I have a free time slot, I'll try to dig deeper and see who/where is actually taking the memblock mutex that ends up blocking the high-priority thread. I'm ok with closing the ticket for now as duplicate of 178 (I'll reopen if I can prove it's not PRIO_INHERIT).

06/21/08 17:30:42 changed by lennart

  • summary changed from possible deadlocks when running pulseaudio with --high-priority=1 to ARM: possible deadlocks when running pulseaudio with --high-priority=1.