[pulseaudio-discuss] Pulseaudio is deadlocked when using module-echo-cancel to Bluetooth input audio

Tanu Kaskinen tanuk at iki.fi
Sun Sep 27 07:30:50 UTC 2020 

On Fri, 2020-09-25 at 14:00 +0800, Chengyi Zhao wrote:
> Hi guys,
> 
> Pulseaudio is deadlocked when Bluetooth(HSP) is selected as the input 
> audio and module-echo-cancel is loaded.
> 
> I don't know why  Thread 1 and Thread 5 are all blocked in the function 
> futex_abstimed_wait_cancelable.
> 
> Please help analyze the following call stack information, thanks!
> 
> (gdb) info thread
>    Id   Target Id                                          Frame
> * 1    Thread 0x7f7f23817e00 (LWP 4366) "pulseaudio" 
> futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x7f7f0c0013e0) at 
> ../sysdeps/unix/sysv/linux/futex-internal.h:205
>    2    Thread 0x7f7f18818700 (LWP 4601) "alsa-sink-ALC89" 
> 0x00007f7f23feb926 in __GI_ppoll (fds=0x5cc130, nfds=4, 
> timeout=<optimized out>, sigmask=sigmask at entry=0x0) at 
> ../sysdeps/unix/sysv/linux/ppoll.c:39
>    3    Thread 0x7f7f13fa8700 (LWP 4604) "alsa-source-ALC" 
> 0x00007f7f23feb926 in __GI_ppoll (fds=0x7940c0, nfds=4, 
> timeout=<optimized out>, sigmask=sigmask at entry=0x0) at 
> ../sysdeps/unix/sysv/linux/ppoll.c:39
>    5    Thread 0x7f7f13227700 (LWP 6227) "bluetooth" 
> futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x667650) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
> (gdb) bt
> #0  0x00007f7f24260896 in futex_abstimed_wait_cancelable (private=0, 
> abstime=0x0, expected=0, futex_word=0x7f7f0c0013e0) at 
> ../sysdeps/unix/sysv/linux/futex-internal.h:205
> #1  0x00007f7f24260896 in do_futex_wait (sem=sem at entry=0x7f7f0c0013e0, 
> abstime=0x0) at sem_waitcommon.c:111
> #2  0x00007f7f24260988 in __new_sem_wait_slow 
> (sem=sem at entry=0x7f7f0c0013e0, abstime=0x0) at sem_waitcommon.c:181
> #3  0x00007f7f242609f9 in __new_sem_wait (sem=sem at entry=0x7f7f0c0013e0) 
> at sem_wait.c:42
> #4  0x00007f7f243846d2 in pa_semaphore_wait (s=0x7f7f0c0013e0) at 
> pulsecore/semaphore-posix.c:61
> #5  0x00007f7f243cc224 in pa_asyncmsgq_send (a=0x717130, 
> object=<optimized out>, code=code at entry=13, 
> userdata=userdata at entry=0x697810, offset=offset at entry=0, 
> chunk=chunk at entry=0x0) at pulsecore/asyncmsgq.c:168
> #6  0x00007f7f1f1f5dfe in command_get_playback_latency (pd=<optimized 
> out>, command=<optimized out>, tag=9, t=<optimized out>, 
> userdata=<optimized out>) at pulsecore/protocol-native.c:2873
> #7  0x00007f7f2436df7f in pa_pdispatch_run (pd=0x5c9650, 
> packet=packet at entry=0x6f84c0, ancil_data=ancil_data at entry=0x6e0158, 
> userdata=userdata at entry=0x6f4600) at pulsecore/pdispatch.c:346
> #8  0x00007f7f1f1f95e5 in pstream_packet_callback (p=0x6dfec0, 
> packet=0x6f84c0, ancil_data=0x6e0158, userdata=0x6f4600) at 
> pulsecore/protocol-native.c:4951
> #9  0x00007f7f2437098d in do_read (p=p at entry=0x6dfec0, 
> re=re at entry=0x6e0088) at pulsecore/pstream.c:1020
> #10 0x00007f7f24373758 in do_pstream_read_write (p=0x6dfec0) at 
> pulsecore/pstream.c:253
> #11 0x00007f7f24373af9 in srb_callback (srb=0x756d90, userdata=0x6dfec0) 
> at pulsecore/pstream.c:295
> #12 0x00007f7f2437434a in srbchannel_rwloop (sr=0x756d90) at 
> pulsecore/srbchannel.c:190
> #13 0x00007f7f242fed28 in dispatch_pollfds (m=0x5cc840) at 
> pulse/mainloop.c:140
> #14 0x00007f7f242fed28 in pa_mainloop_dispatch (m=m at entry=0x5cc840) at 
> pulse/mainloop.c:898
> #15 0x00007f7f242feffc in pa_mainloop_iterate (m=0x5cc840, 
> block=<optimized out>, retval=0x7ffceef8cde8) at pulse/mainloop.c:929
> #16 0x00007f7f242ff0a0 in pa_mainloop_run (m=m at entry=0x5cc840, 
> retval=retval at entry=0x7ffceef8cde8) at pulse/mainloop.c:945
> #17 0x0000000000407306 in main (argc=<optimized out>, argv=<optimized 
> out>) at daemon/main.c:1144
> (gdb) c
> Continuing.
> ^C
> Thread 1 "pulseaudio" received signal SIGINT, Interrupt.
> futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x7f7f0c0013e0) at 
> ../sysdeps/unix/sysv/linux/futex-internal.h:205
> 205    in ../sysdeps/unix/sysv/linux/futex-internal.h
> (gdb) info thread
>    Id   Target Id                                          Frame
> * 1    Thread 0x7f7f23817e00 (LWP 4366) "pulseaudio" 
> futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x7f7f0c0013e0) at 
> ../sysdeps/unix/sysv/linux/futex-internal.h:205
>    2    Thread 0x7f7f18818700 (LWP 4601) "alsa-sink-ALC89" 
> 0x00007f7f23feb926 in __GI_ppoll (fds=0x5cc130, nfds=4, 
> timeout=<optimized out>, sigmask=sigmask at entry=0x0) at 
> ../sysdeps/unix/sysv/linux/ppoll.c:39
>    3    Thread 0x7f7f13fa8700 (LWP 4604) "alsa-source-ALC" 
> 0x00007f7f23feb926 in __GI_ppoll (fds=0x7940c0, nfds=4, 
> timeout=<optimized out>, sigmask=sigmask at entry=0x0) at 
> ../sysdeps/unix/sysv/linux/ppoll.c:39
>    5    Thread 0x7f7f13227700 (LWP 6227) "bluetooth" 
> futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x667650) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
> (gdb) thread 5
> [Switching to thread 5 (Thread 0x7f7f13227700 (LWP 6227))]
> #0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, 
> futex_word=0x667650) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
> 205    in ../sysdeps/unix/sysv/linux/futex-internal.h
> (gdb) bt
> #0  0x00007f7f24260896 in futex_abstimed_wait_cancelable (private=0, 
> abstime=0x0, expected=0, futex_word=0x667650) at 
> ../sysdeps/unix/sysv/linux/futex-internal.h:205
> #1  0x00007f7f24260896 in do_futex_wait (sem=sem at entry=0x667650, 
> abstime=0x0) at sem_waitcommon.c:111
> #2  0x00007f7f24260988 in __new_sem_wait_slow (sem=sem at entry=0x667650, 
> abstime=0x0) at sem_waitcommon.c:181
> #3  0x00007f7f242609f9 in __new_sem_wait (sem=sem at entry=0x667650) at 
> sem_wait.c:42
> #4  0x00007f7f243846d2 in pa_semaphore_wait (s=0x667650) at 
> pulsecore/semaphore-posix.c:61
> #5  0x00007f7f243cc224 in pa_asyncmsgq_send (a=0x717130, 
> object=object at entry=0x73ce10, code=code at entry=0, 
> userdata=userdata at entry=0x7f7f132265e0, offset=offset at entry=0, 
> chunk=chunk at entry=0x0)
>      at pulsecore/asyncmsgq.c:168
> #6  0x00007f7f1334c123 in do_resync (u=0x756b30) at 
> ./pulsecore/msgobject.h:44
> #7  0x00007f7f1334c123 in source_output_push_cb (o=<optimized out>, 
> chunk=<optimized out>) at modules/echo-cancel/module-echo-cancel.c:925
> #8  0x00007f7f244112b7 in pa_source_output_push (o=o at entry=0x6fbee0, 
> chunk=chunk at entry=0x7f7f13226830) at pulsecore/source-output.c:833
> #9  0x00007f7f24419bca in pa_source_post (s=0x75f840, 
> chunk=chunk at entry=0x7f7f13226830) at pulsecore/source.c:989
> #10 0x00007f7f13260339 in sco_process_push (u=u at entry=0x76d990) at 
> modules/bluetooth/module-bluez5-device.c:408
> #11 0x00007f7f13261a56 in thread_func (userdata=<optimized out>) at 
> modules/bluetooth/module-bluez5-device.c:1556
> #12 0x00007f7f24384478 in internal_thread_func (userdata=0x686460) at 
> pulsecore/thread-posix.c:81
> #13 0x00007f7f24257fa3 in start_thread (arg=<optimized out>) at 
> pthread_create.c:486
> #14 0x00007f7f23ff64df in clone () at 
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
> (gdb)

It seems that do_resync() in module-echo-cancel.c assumes that the
source and sink run in separate threads, but the HSP sink and source
run in the same thread. do_resync() sends a message from the source
thread to the sink thread with pa_asyncmsgq_send(), which blocks until
the message is processed, but the sink thread never processes the
message, because it's the same thread as the source thread, which is
currently blocked in pa_asyncmsgq_send().

-- 
Tanu

https://www.patreon.com/tanuk
https://liberapay.com/tanuk

More information about the pulseaudio-discuss mailing list