[alsa-devel] [PATCH] Meter causes freeze when closing audio device

[Takashi Sakamoto]

Hi,

On Mar 6 2017 12:01, Alistair Buxton wrote:
> After adding assert(0); to snd_timer_stop I got the following backtrace:
>
> #0  0x00007ffff730d428 in __GI_raise (sig=sig at entry=6) at
> ../sysdeps/unix/sysv/linux/raise.c:54
> #1  0x00007ffff730f02a in __GI_abort () at abort.c:89
> #2  0x00007ffff7305bd7 in __assert_fail_base (fmt=<optimised out>,
> assertion=assertion at entry=0x7ffff7b9439e "0",
>     file=file at entry=0x7ffff7b9e8b9 "timer.c", line=line at entry=918,
>     function=function at entry=0x7ffff7b9e9c8 <__PRETTY_FUNCTION__.10913>
> "snd_timer_stop") at assert.c:92
> #3  0x00007ffff7305c82 in __GI___assert_fail
> (assertion=assertion at entry=0x7ffff7b9439e "0",
>     file=file at entry=0x7ffff7b9e8b9 "timer.c", line=line at entry=918,
>     function=function at entry=0x7ffff7b9e9c8 <__PRETTY_FUNCTION__.10913>
> "snd_timer_stop") at assert.c:101
> #4  0x00007ffff7b64503 in snd_timer_stop (timer=<optimised out>) at timer.c:918
> #5  0x00007ffff7b5158d in snd_pcm_dmix_sync_ptr0
> (pcm=pcm at entry=0x622de0, slave_hw_ptr=<optimised out>)
>     at pcm_dmix.c:421
> #6  0x00007ffff7b51aac in snd_pcm_dmix_status (pcm=0x622de0,
> status=0x7ffff6af1e80) at pcm_dmix.c:496
> #7  0x00007ffff7b18f11 in snd_pcm_status (pcm=pcm at entry=0x622de0,
> status=status at entry=0x7ffff6af1e80) at pcm.c:977
> #8  0x00007ffff7b48bc0 in snd_pcm_meter_thread (data=0x622940) at
> pcm_meter.c:200
> #9  0x00007ffff76a86ba in start_thread (arg=0x7ffff6af2700) at
> pthread_create.c:333
> #10 0x00007ffff73de82d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
>
> So the meter thread is indirectly stopping the timer while the main
> thread is trying to poll it.
>
> The following patch avoids this issue. Is it the right way to fix it?

I can reproduce this issue in below environment:
  - Ubuntu 17.10 (amd64)
  - Linux kernel 4.8.0-41-generic
  - alsa-lib 1.1.2-1
  - your .asoundrc
  - 'aplay -v -fS16_LE -r48000 -c2 -d1 -Dmymeter /dev/zero'
(http://mailman.alsa-project.org/pipermail/alsa-devel/2017-March/118459.html)

Although you catch the cause as mostly correct and your patch is one of 
solutions for your issue, it's just a workaround for your case, because 
this is a bug of PCM dmix plugin. We can also generate this issue in the 
other cases.

I wrote a rough program as a proof. This program runs two threads; main 
and for lister. In the lister, snd_pcm_status() is called frequently. In 
the main thread, PCM frames as much as 1 sec are written, then 
snd_pcm_drain() is called. I can see this program is sometimes blocked 
in a call of poll(2).
https://gist.github.com/takaswie/a498329f0a09b1f715b562cb1942638f

As I work with strace(1), when the process is blocked, 
ioctl(SNDRV_TIMER_IOCTL_STOP) is called after the process starts to be 
blocked with a call of poll(2). As you know, timer character device is 
stopped before elapsing scheduled ticks.

[pid  8655] 13:31:39.338252 poll([{fd=3, 
events=POLLIN|POLLERR|POLLNVAL}], 1, -1 <unfinished ...>
[pid  8656] 13:31:39.338359 futex(0x55a553c93ca0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  8656] 13:31:39.358459 ioctl(3, SNDRV_TIMER_IOCTL_STOP, 0x2000) = 0
[pid  8656] 13:31:39.358507 read(3, 
"\3\0\0\0\0\0\0\0\305\31\0\0\0\0\0\0$\f/3\0\0\0\0\0\0\0\0\0\0\0\0", 128) 
= 32

I need more time to propose thorough solution for this issue. Anyway, 
thank you to report this bug.


Takashi Sakamoto