Bug#1022119: Wakes up every 1.5s even with no work to do

[Josh Triplett]

On Thu, Oct 20, 2022 at 03:24:48PM +0200, Samuel Thibault wrote:
> Control: reassign -1 pulseaudio
> 
> Samuel Thibault, le jeu. 20 oct. 2022 15:02:09 +0200, a ecrit:
> > Josh Triplett, le jeu. 20 oct. 2022 13:45:45 +0100, a ecrit:
> > > sd_dummy seems to be waking up every 1.5s even when it has no work to
> > > do.
> > 
> > I don't see that happening on my system. Could you run strace on it so
> > we get to know what happens in your case? E.g.
> > 
> > strace -p $(pgrep sd_dummy)
> 
> Ah, -f is needed to see the thread started by pulseaudio.
> 
> (gdb) bt
> #0  0x00007fb4fdefe32f in __GI___poll (fds=fds at entry=0x7fb4f40071a0, nfds=nfds at entry=2, timeout=timeout at entry=1500) at ../sysdeps/unix/sysv/linux/poll.c:29
> #1  0x00007fb4fe0652e1 in poll (__timeout=1500, __nfds=2, __fds=0x7fb4f40071a0) at /usr/include/x86_64-linux-gnu/bits/poll2.h:39
> #2  poll_func (ufds=0x7fb4f40071a0, nfds=2, timeout=1500, userdata=0x56184db546b0) at ../src/pulse/thread-mainloop.c:70
> #3  0x00007fb4fe056fa4 in pa_mainloop_poll (m=m at entry=0x56184db545b0) at ../src/pulse/mainloop.c:863
> #4  0x00007fb4fe057606 in pa_mainloop_iterate (m=m at entry=0x56184db545b0, block=block at entry=1, retval=retval at entry=0x0) at ../src/pulse/mainloop.c:945
> #5  0x00007fb4fe0576b0 in pa_mainloop_run (m=0x56184db545b0, retval=retval at entry=0x0) at ../src/pulse/mainloop.c:963
> #6  0x00007fb4fe0653b9 in thread (userdata=0x56184db54560) at ../src/pulse/thread-mainloop.c:101
> #7  0x00007fb4fd5d433f in internal_thread_func (userdata=0x56184db5ad20) at ../src/pulsecore/thread-posix.c:81
> #8  0x00007fb4fde8784a in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
> #9  0x00007fb4fdf0b2cc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
> 
> so that's coming from pulseaudio. The 1500 delay is most probably
> coming from
> 
> ./src/pulse/stream.c:#define AUTO_TIMING_INTERVAL_END_USEC (1500*PA_USEC_PER_MSEC)
> 
> I don't know why pulseaudio would be waking up every 1.5s even if the
> speech module doesn't submit any audio.

In case it matters, I'm using pipewire, not pulseaudio.

An strace looks something like this (note: had to manually start
speech-dispatcher to get this, as I've since disabled autospawn because
of this issue):

[pid 14399] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 14398] futex(0x560856cef080, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 14399] <... restart_syscall resumed>) = 0
[pid 14399] getpid()                    = 14397
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WWW", 10)          = 3
[pid 14399] sendto(12, "\0\0\0\30\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0L\0\0\0\16L\0\0\0\rL\0"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
[pid 14399] read(9, 0x7f6ef0069c0e, 10) = -1 EAGAIN (Resource temporarily unavailable)
[pid 14399] poll([{fd=9, events=POLLIN}, {fd=12, events=POLLIN}], 2, 1500) = 1 ([{fd=12, revents=POLLIN}])
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] recvmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0\0\0S\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=20}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=746, uid=1000, gid=1000}}], msg_controllen=32, msg_flags=0}, 0) = 20
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WW", 10)           = 2
[pid 14399] poll([{fd=9, events=POLLIN}, {fd=12, events=POLLIN}], 2, 1499) = 1 ([{fd=12, revents=POLLIN}])
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] recvmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="L\0\0\0\2L\0\0\0\rU\0\0\0\0\0\0V*U\0\0\0\0\0\0\0\0000TcQ"..., iov_len=83}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=746, uid=1000, gid=1000}}], msg_controllen=32, msg_flags=0}, 0) = 83
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WW", 10)           = 2
[pid 14399] poll([{fd=9, events=POLLIN}, {fd=12, events=POLLIN}], 2, 1499) = 0 (Timeout)
[pid 14399] getpid()                    = 14397
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WWW", 10)          = 3
[pid 14399] sendto(12, "\0\0\0\30\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0L\0\0\0\16L\0\0\0\16L\0"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
[pid 14399] read(9, 0x7f6ef0069c0e, 10) = -1 EAGAIN (Resource temporarily unavailable)
[pid 14399] poll([{fd=9, events=POLLIN}, {fd=12, events=POLLIN}], 2, 1500) = 1 ([{fd=12, revents=POLLIN}])
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] recvmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0\0\0S\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=20}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=746, uid=1000, gid=1000}}], msg_controllen=32, msg_flags=0}, 0) = 20
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WW", 10)           = 2
[pid 14399] poll([{fd=9, events=POLLIN}, {fd=12, events=POLLIN}], 2, 1500) = 1 ([{fd=12, revents=POLLIN}])
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] recvmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="L\0\0\0\2L\0\0\0\16U\0\0\0\0\0\0V*U\0\0\0\0\0\0\0\0000TcQ"..., iov_len=83}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=746, uid=1000, gid=1000}}], msg_controllen=32, msg_flags=0}, 0) = 83
[pid 14399] write(10, "W", 1)           = 1
[pid 14399] read(9, "WW", 10)           = 2