[pulseaudio-tickets] [PulseAudio] #755: Pulseaudio randomly starts taking 100% cpu in mainloop polling

PulseAudio trac-noreply at tango.0pointer.de
Sat Dec 26 04:51:21 PST 2009 

#755: Pulseaudio randomly starts taking 100% cpu in mainloop polling
------------------------+---------------------------------------------------
  Reporter:  lukehutch  |       Owner:  lennart
      Type:  defect     |      Status:  new    
 Milestone:             |   Component:  daemon 
Resolution:             |    Keywords:         
------------------------+---------------------------------------------------
Description changed by coling:

Old description:

> pulseaudio-0.9.21-3.fc13.x86_64 in F13 randomly starts taking 100% CPU on
> semi-frequent occasions, while not even playing sounds.  Here is the gdb
> trace of where it is looping:
>
> --------------------------------------
>
> ^C
> Program received signal SIGINT, Interrupt.
> 0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
> (gdb) thread apply all bt
>
> Thread 3 (Thread 0x7f59f3cfa710 (LWP 1752)):
> #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
> #1  0x0000003a730325fe in pa_rtpoll_run (p=0x13f4be0,
>     wait_op=<value optimized out>) at pulsecore/rtpoll.c:304
> #2  0x00007f59f2299f5e in thread_func (userdata=0x13f4290)
>     at modules/alsa/alsa-sink.c:1430
> #3  0x0000003a83c38660 in internal_thread_func (userdata=0x140ef00)
>     at pulsecore/thread-posix.c:72
> #4  0x0000003a72806aea in start_thread () from /lib64/libpthread.so.0
> #5  0x0000003a71ce234d in clone () from /lib64/libc.so.6
>
> Thread 2 (Thread 0x7f59f21ce710 (LWP 1753)):
> #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
> #1  0x0000003a730325fe in pa_rtpoll_run (p=0x1410150,
>     wait_op=<value optimized out>) at pulsecore/rtpoll.c:304
> #2  0x00007f59f229f200 in thread_func (userdata=0x1413f90)
>     at modules/alsa/alsa-source.c:1274
> #3  0x0000003a83c38660 in internal_thread_func (userdata=0x1410230)
>     at pulsecore/thread-posix.c:72
> #4  0x0000003a72806aea in start_thread () from /lib64/libpthread.so.0
> #5  0x0000003a71ce234d in clone () from /lib64/libc.so.6
>
> Thread 1 (Thread 0x7f59f9b2c780 (LWP 1751)):
> #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
> #1  0x0000003a8301cc07 in pa_mainloop_poll (m=0x13daeb0)
>     at pulse/mainloop.c:887
> #2  0x0000003a8301df29 in pa_mainloop_iterate (m=0x13daeb0,
>     block=<value optimized out>, retval=0x7fffa22a89ec) at
> pulse/mainloop.c:961
> #3  0x0000003a8301dfe0 in pa_mainloop_run (m=0x13daeb0,
> retval=0x7fffa22a89ec)
>     at pulse/mainloop.c:979
> #4  0x000000000040a4b8 in main (argc=<value optimized out>,
>     argv=<value optimized out>) at daemon/main.c:971
>
> ------------------------------------------
>
> Here is what it's doing MOST of the time, over and over again:
>
> ------------------------------------------
>
> ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
> {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
> {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
> events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
> events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
> events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
> events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL,
> NULL, 8) = 1 ([{fd=29, revents=POLLHUP}])
>
> ------------------------------------------------------
>
> Here is what it does OCCASIONALLY, among many, many syscalls of the above
> form:
>
> ------------------------------------------------------
>
> ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
> {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
> {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
> events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
> events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
> events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
> events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL,
> NULL, 8) = 2 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLIN}])
> recvmsg(22, {msg_name(0)=NULL,
> msg_iov(1)=[{"\0\0\0\30\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20}],
> msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
> cmsg_type=SCM_CREDENTIALS{pid=2761, uid=500, gid=500}}, msg_flags=0}, 0)
> = 20
> ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
> {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
> {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
> events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
> events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
> events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
> events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL,
> NULL, 8) = 2 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLIN}])
> recvmsg(22, {msg_name(0)=NULL,
> msg_iov(1)=[{"L\0\0\0\16L\0\1\22\212L\0\0\0\0TK3\371\35\0\5\376\272",
> 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
> cmsg_type=SCM_CREDENTIALS{pid=2761, uid=500, gid=500}}, msg_flags=0}, 0)
> = 24
> write(18, "\1\0\0\0\0\0\0\0", 8)        = 8
> sendto(22, "\0\0\0S\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20,
> MSG_NOSIGNAL, NULL, 0) = 20
> ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22,
> events=POLLIN|POLLOUT}, {fd=21, events=POLLIN}, {fd=10, events=POLLIN},
> {fd=7, events=POLLIN}, {fd=23, events=POLLIN}, {fd=30, events=POLLIN},
> {fd=33, events=POLLIN}, {fd=32, events=POLLIN}, {fd=31,
> events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=24,
> events=POLLIN}, {fd=27, events=POLLIN}, {fd=17, events=POLLIN}, {fd=20,
> events=POLLIN}, {fd=16, events=POLLIN|POLLERR|POLLHUP}, {fd=16,
> events=0}, {fd=15, events=POLLIN}, {fd=14, events=POLLIN}, {fd=8,
> events=POLLIN}], 21, NULL, NULL, 8) = 2 ([{fd=29, revents=POLLHUP},
> {fd=22, revents=POLLOUT}])
> sendto(22,
> "L\0\0\0\2L\0\1\22\212U\0\0\0\0\0\0\0\0U\0\0\0\0\0\0\0\0000TK3"..., 83,
> MSG_NOSIGNAL, NULL, 0) = 83
> ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22,
> events=POLLIN|POLLOUT}, {fd=21, events=POLLIN}, {fd=10, events=POLLIN},
> {fd=7, events=POLLIN}, {fd=23, events=POLLIN}, {fd=30, events=POLLIN},
> {fd=33, events=POLLIN}, {fd=32, events=POLLIN}, {fd=31,
> events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=24,
> events=POLLIN}, {fd=27, events=POLLIN}, {fd=17, events=POLLIN}, {fd=20,
> events=POLLIN}, {fd=16, events=POLLIN|POLLERR|POLLHUP}, {fd=16,
> events=0}, {fd=15, events=POLLIN}, {fd=14, events=POLLIN}, {fd=8,
> events=POLLIN}], 21, NULL, NULL, 8) = 2 ([{fd=29, revents=POLLHUP},
> {fd=22, revents=POLLOUT}])

New description:

 pulseaudio-0.9.21-3.fc13.x86_64 in F13 randomly starts taking 100% CPU on
 semi-frequent occasions, while not even playing sounds.  Here is the gdb
 trace of where it is looping:

 {{{
 Program received signal SIGINT, Interrupt.
 0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
 (gdb) thread apply all bt

 Thread 3 (Thread 0x7f59f3cfa710 (LWP 1752)):
 #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
 #1  0x0000003a730325fe in pa_rtpoll_run (p=0x13f4be0,
     wait_op=<value optimized out>) at pulsecore/rtpoll.c:304
 #2  0x00007f59f2299f5e in thread_func (userdata=0x13f4290)
     at modules/alsa/alsa-sink.c:1430
 #3  0x0000003a83c38660 in internal_thread_func (userdata=0x140ef00)
     at pulsecore/thread-posix.c:72
 #4  0x0000003a72806aea in start_thread () from /lib64/libpthread.so.0
 #5  0x0000003a71ce234d in clone () from /lib64/libc.so.6

 Thread 2 (Thread 0x7f59f21ce710 (LWP 1753)):
 #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
 #1  0x0000003a730325fe in pa_rtpoll_run (p=0x1410150,
     wait_op=<value optimized out>) at pulsecore/rtpoll.c:304
 #2  0x00007f59f229f200 in thread_func (userdata=0x1413f90)
     at modules/alsa/alsa-source.c:1274
 #3  0x0000003a83c38660 in internal_thread_func (userdata=0x1410230)
     at pulsecore/thread-posix.c:72
 #4  0x0000003a72806aea in start_thread () from /lib64/libpthread.so.0
 #5  0x0000003a71ce234d in clone () from /lib64/libc.so.6

 Thread 1 (Thread 0x7f59f9b2c780 (LWP 1751)):
 #0  0x0000003a71cd90c7 in ppoll () from /lib64/libc.so.6
 #1  0x0000003a8301cc07 in pa_mainloop_poll (m=0x13daeb0)
     at pulse/mainloop.c:887
 #2  0x0000003a8301df29 in pa_mainloop_iterate (m=0x13daeb0,
     block=<value optimized out>, retval=0x7fffa22a89ec) at
 pulse/mainloop.c:961
 #3  0x0000003a8301dfe0 in pa_mainloop_run (m=0x13daeb0,
 retval=0x7fffa22a89ec)
     at pulse/mainloop.c:979
 #4  0x000000000040a4b8 in main (argc=<value optimized out>,
     argv=<value optimized out>) at daemon/main.c:971
 }}}

 ----

 Here is what it's doing MOST of the time, over and over again:

 {{{
 ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
 {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
 {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
 {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
 events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
 events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
 events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15, events=POLLIN},
 {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL, NULL, 8) = 1
 ([{fd=29, revents=POLLHUP}])
 }}}

 ----

 Here is what it does OCCASIONALLY, among many, many syscalls of the above
 form:

 {{{
 ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
 {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
 {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
 {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
 events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
 events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
 events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15, events=POLLIN},
 {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL, NULL, 8) = 2
 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLIN}])
 recvmsg(22, {msg_name(0)=NULL,
 msg_iov(1)=[{"\0\0\0\30\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20}],
 msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
 cmsg_type=SCM_CREDENTIALS{pid=2761, uid=500, gid=500}}, msg_flags=0}, 0) =
 20
 ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22, events=POLLIN},
 {fd=21, events=POLLIN}, {fd=10, events=POLLIN}, {fd=7, events=POLLIN},
 {fd=23, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN},
 {fd=32, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31,
 events=0}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=17,
 events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
 events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15, events=POLLIN},
 {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL, NULL, 8) = 2
 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLIN}])
 recvmsg(22, {msg_name(0)=NULL,
 msg_iov(1)=[{"L\0\0\0\16L\0\1\22\212L\0\0\0\0TK3\371\35\0\5\376\272",
 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
 cmsg_type=SCM_CREDENTIALS{pid=2761, uid=500, gid=500}}, msg_flags=0}, 0) =
 24
 write(18, "\1\0\0\0\0\0\0\0", 8)        = 8
 sendto(22, "\0\0\0S\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20,
 MSG_NOSIGNAL, NULL, 0) = 20
 ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22,
 events=POLLIN|POLLOUT}, {fd=21, events=POLLIN}, {fd=10, events=POLLIN},
 {fd=7, events=POLLIN}, {fd=23, events=POLLIN}, {fd=30, events=POLLIN},
 {fd=33, events=POLLIN}, {fd=32, events=POLLIN}, {fd=31,
 events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=24, events=POLLIN},
 {fd=27, events=POLLIN}, {fd=17, events=POLLIN}, {fd=20, events=POLLIN},
 {fd=16, events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
 events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL,
 NULL, 8) = 2 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLOUT}])
 sendto(22,
 "L\0\0\0\2L\0\1\22\212U\0\0\0\0\0\0\0\0U\0\0\0\0\0\0\0\0000TK3"..., 83,
 MSG_NOSIGNAL, NULL, 0) = 83
 ppoll([{fd=4, events=POLLIN}, {fd=29, events=0}, {fd=22,
 events=POLLIN|POLLOUT}, {fd=21, events=POLLIN}, {fd=10, events=POLLIN},
 {fd=7, events=POLLIN}, {fd=23, events=POLLIN}, {fd=30, events=POLLIN},
 {fd=33, events=POLLIN}, {fd=32, events=POLLIN}, {fd=31,
 events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=24, events=POLLIN},
 {fd=27, events=POLLIN}, {fd=17, events=POLLIN}, {fd=20, events=POLLIN},
 {fd=16, events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
 events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 21, NULL,
 NULL, 8) = 2 ([{fd=29, revents=POLLHUP}, {fd=22, revents=POLLOUT}])
 }}}

--

-- 
Ticket URL: <http://pulseaudio.org/ticket/755#comment:1>
PulseAudio <http://pulseaudio.org/>
The PulseAudio Sound Server

More information about the pulseaudio-bugs mailing list