alsa: snd_pcm_drain() sometimes takes longer than it should

This happens with the bcm2835 driver.

snd_pcm_drain() should normally wait until all buffered audio data buffered has been played. But sometimes, it seems to take much longer. It takes seconds, even though the amount of buffered audio is only milliseconds.

Here's a backtrace (with mpv):

#0  0x756c2dc8 in ioctl () at ../sysdeps/unix/syscall-template.S:82
#1  0x75b7fc1c in snd_pcm_hw_drain () from /usr/local/lib/libasound.so.2
#2  0x75b672dc in snd_pcm_drain () from /usr/local/lib/libasound.so.2
#3  0x0002a95c in drain (ao=0x83ea50) at ../audio/out/push.c:158

This seems to happen pretty randomly (and somehow timing related), so I'm really not sure how to provide a reproducible test case.

[popcornmix]

Anything appear in dmesg?

From what I remember no, but I can check for sure tomorrow.

[popcornmix]

Realistically it's not going to be possible to fix without a repeatable test case.
It might be worth creating a script to repeatedly play a one second file to try to provoke the failure in a reasonable timescale.
Also add start_debug=1 to config.txt and reboot.
After the failure try running:
sudo vcdbg log msg
to see if any GPU errors have been logged.

Nothing in any of these logs.

I managed to make a test case: http://sprunge.us/gZcH

// Compile with:  gcc -std=c99 test.c `pkg-config alsa --libs --cflags`

#define _XOPEN_SOURCE 500

#include <stdlib.h>
#include <unistd.h>

#include <alloca.h>
#include <alsa/asoundlib.h>

int main(int argc, char **argv)
{
    snd_pcm_t *alsa;

    if (snd_pcm_open(&alsa, "default", SND_PCM_STREAM_PLAYBACK, 0) < 0)
        abort();

    if (snd_pcm_nonblock(alsa, 0) < 0)
        abort();

    snd_pcm_hw_params_t *alsa_hwparams;
    snd_pcm_sw_params_t *alsa_swparams;

    snd_pcm_hw_params_alloca(&alsa_hwparams);
    snd_pcm_sw_params_alloca(&alsa_swparams);

    if (snd_pcm_hw_params_any(alsa, alsa_hwparams) < 0)
        abort();
    if (snd_pcm_hw_params_set_format(alsa, alsa_hwparams, SND_PCM_FORMAT_S16) < 0)
        abort();
    if (snd_pcm_hw_params_set_access(alsa, alsa_hwparams, SND_PCM_ACCESS_RW_INTERLEAVED) < 0)
        abort();

    int channels = 2;
    if (snd_pcm_hw_params_set_channels_near(alsa, alsa_hwparams, &channels) < 0 || channels != 2)
        abort();

    if (snd_pcm_hw_params_set_rate_resample(alsa, alsa_hwparams, 0) < 0)
        abort();

    int rate = 8000;
    if (snd_pcm_hw_params_set_rate_near(alsa, alsa_hwparams, &rate, NULL) < 0 || rate != 8000)
        abort();

    if (snd_pcm_hw_params_set_buffer_time_near(alsa, alsa_hwparams, &(unsigned int){250000}, NULL) < 0)
        abort();

    if (snd_pcm_hw_params_set_periods_near(alsa, alsa_hwparams, &(unsigned int){16}, NULL) < 0)
        abort();

    if (snd_pcm_hw_params(alsa, alsa_hwparams) < 0)
        abort();

    if (snd_pcm_sw_params_current(alsa, alsa_swparams) < 0)
        abort();

    snd_pcm_uframes_t boundary;
    if (snd_pcm_sw_params_get_boundary(alsa_swparams, &boundary) < 0)
        abort();

    snd_pcm_uframes_t chunk_size;
    if (snd_pcm_hw_params_get_period_size(alsa_hwparams, &chunk_size, NULL) < 0)
        abort();

    if (snd_pcm_sw_params_set_start_threshold(alsa, alsa_swparams, chunk_size) < 0)
        abort();

    if (snd_pcm_sw_params_set_stop_threshold(alsa, alsa_swparams, boundary) < 0)
        abort();

    if (snd_pcm_sw_params_set_silence_size(alsa, alsa_swparams, boundary) < 0)
        abort();

    if (snd_pcm_sw_params(alsa, alsa_swparams) < 0)
        abort();

    int samples = 32768;
    char *stuff = calloc(samples, 4);
    if (!stuff)
        abort();

    fprintf(stderr, "start playing\n");


    snd_pcm_prepare(alsa);
    int r = snd_pcm_writei(alsa, stuff, samples);
    fprintf(stderr, "r=%d\n", r);

    usleep(300000);

    fprintf(stderr, "start drain\n");
    snd_pcm_drain(alsa);
    fprintf(stderr, "end drain\n");

    return 0;
}

This takes about 14 seconds to complete, even though it's only about 4 seconds of audio. It basically hangs while draining. This is pretty reproducible here. So far every run took much longer than the at most 5 seconds it should take. The usleep() call is required - I think it provokes a buffer underflow.

[popcornmix]

I see the effect you describe. I've had a look on the firmware side and it seems happy:

MESS: 00:03:05.372960:0:  audioserv: AUDIOSERV: handle_vchi_callback command=VC_AUDIO_MSG_TYPE_WRITE, msg:1792:2131169884:-1849039744:262144000
MESS: 00:03:05.372984:0:  audioserv: AUDIOSERV: audioserv_write count=1792,silence=0
MESS: 00:03:05.382690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1640, count=1956+1244
MESS: 00:03:05.382729:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1244)
MESS: 00:03:05.382773:0:  audioserv: AUDIOSERV: audio_complete_task latency=1636, submitted=1956-80=409
MESS: 00:03:05.392688:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1320, count=1636+1244
MESS: 00:03:05.393542:0:  audioserv: AUDIOSERV: audio_complete_task: audio_write(1244) latency=2536
MESS: 00:03:05.393591:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2532, count=2880+1600
MESS: 00:03:05.393630:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1600)
MESS: 00:03:05.393674:0:  audioserv: AUDIOSERV: audio_complete_task latency=2532, submitted=2880-87=633
MESS: 00:03:05.402690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2244, count=2532+1600
MESS: 00:03:05.402727:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1600)
MESS: 00:03:05.402770:0:  audioserv: AUDIOSERV: audio_complete_task latency=2240, submitted=2532-73=560
MESS: 00:03:05.412689:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1924, count=2240+1600
MESS: 00:03:05.412728:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1600)
MESS: 00:03:05.412772:0:  audioserv: AUDIOSERV: audio_complete_task latency=1920, submitted=2240-80=480
MESS: 00:03:05.422690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1604, count=1920+1600
MESS: 00:03:05.422727:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1600)
MESS: 00:03:05.422769:0:  audioserv: AUDIOSERV: audio_complete_task latency=1600, submitted=1920-80=400
MESS: 00:03:05.432689:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1284, count=1600+1600
MESS: 00:03:05.433890:0:  audioserv: AUDIOSERV: audio_complete_task: audio_write(1600) latency=2848
MESS: 00:03:05.433942:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2848, count=3200+1280
MESS: 00:03:05.433979:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1280)
MESS: 00:03:05.434021:0:  audioserv: AUDIOSERV: audio_complete_task latency=2840, submitted=3200-90=710
MESS: 00:03:05.442690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2564, count=2840+1280
MESS: 00:03:05.442728:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1280)
MESS: 00:03:05.442773:0:  audioserv: AUDIOSERV: audio_complete_task latency=2560, submitted=2840-70=640
MESS: 00:03:05.452689:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2244, count=2560+1280
MESS: 00:03:05.452727:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1280)
MESS: 00:03:05.452769:0:  audioserv: AUDIOSERV: audio_complete_task latency=2240, submitted=2560-80=560
MESS: 00:03:05.462690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1924, count=2240+1280
MESS: 00:03:05.462728:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1280)
MESS: 00:03:05.462773:0:  audioserv: AUDIOSERV: audio_complete_task latency=1920, submitted=2240-80=480
MESS: 00:03:05.472688:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1604, count=1920+1280
MESS: 00:03:05.472725:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1280)
MESS: 00:03:05.472768:0:  audioserv: AUDIOSERV: audio_complete_task latency=1600, submitted=1920-80=400
MESS: 00:03:05.482690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1284, count=1600+1280
MESS: 00:03:05.483567:0:  audioserv: AUDIOSERV: audio_complete_task: audio_write(1280) latency=2536
MESS: 00:03:05.483619:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2532, count=2880+1792
MESS: 00:03:05.483656:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1792)
MESS: 00:03:05.483698:0:  audioserv: AUDIOSERV: audio_complete_task latency=2532, submitted=2880-87=633
MESS: 00:03:05.492689:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=2244, count=2532+1792
MESS: 00:03:05.492727:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1792)
MESS: 00:03:05.492772:0:  audioserv: AUDIOSERV: audio_complete_task latency=2240, submitted=2532-73=560
MESS: 00:03:05.502691:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1924, count=2240+1792
MESS: 00:03:05.502727:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1792)
MESS: 00:03:05.502770:0:  audioserv: AUDIOSERV: audio_complete_task latency=1920, submitted=2240-80=480
MESS: 00:03:05.512689:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1604, count=1920+1792
MESS: 00:03:05.512728:0:  audioserv: AUDIOSERV: audio_complete_task, sleeping for 1ms (remaining 1792)
MESS: 00:03:05.512772:0:  audioserv: AUDIOSERV: audio_complete_task latency=1600, submitted=1920-80=400
MESS: 00:03:05.522690:0:  audioserv: AUDIOSERV: audio_complete_task(1) latency=1284, count=1600+1792
MESS: 00:03:05.523911:0:  audioserv: AUDIOSERV: audio_complete_task: audio_write(1792) latency=3036
MESS: 00:03:05.523959:0:  audioserv: AUDIOSERV: audio_complete_task latency=3036, submitted=3392-89=759
MESS: 00:03:05.532687:0:  audioserv: AUDIOSERV: audio_complete_task latency=2756, submitted=3036-70=689
MESS: 00:03:05.542688:0:  audioserv: AUDIOSERV: audio_complete_task latency=2436, submitted=2756-80=609
MESS: 00:03:05.552687:0:  audioserv: AUDIOSERV: audio_complete_task latency=2116, submitted=2436-80=529
MESS: 00:03:05.562688:0:  audioserv: AUDIOSERV: audio_complete_task latency=1796, submitted=2116-80=449
MESS: 00:03:05.572686:0:  audioserv: AUDIOSERV: audio_complete_task latency=1476, submitted=1796-80=369
MESS: 00:03:05.582688:0:  audioserv: AUDIOSERV: audio_complete_task latency=1156, submitted=1476-80=289
MESS: 00:03:05.592686:0:  audioserv: AUDIOSERV: audio_complete_task latency=836, submitted=1156-80=209
MESS: 00:03:05.602687:0:  audioserv: AUDIOSERV: audio_complete_task latency=516, submitted=836-80=129
MESS: 00:03:05.612686:0:  audioserv: AUDIOSERV: audio_complete_task latency=196, submitted=516-80=49
MESS: 00:03:05.622686:0:  audioserv: AUDIOSERV: audio_complete_task latency=0, submitted=196-49=0
MESS: 00:03:15.667114:0:  audioserv: AUDIOSERV: handle_vchi_callback command=VC_AUDIO_MSG_TYPE_STOP, msg:1:-1823198464:-1847877600:-1835127232
MESS: 00:03:15.668151:0:  audioserv: AUDIOSERV: handle_vchi_callback command=VC_AUDIO_MSG_TYPE_CLOSE, msg:2131059792:2131056528:-1833108992:-1833108992

So we get the last WRITE comand from kernel driver. It takes another 25ms to play it out. Then a ten second pause before we are told to stop/close.

I'm guessing kernel side is not understanding that the firmware side has played out and there is a 10 second timeout in alsa before it closes anyway.

In general the firmware receives samples, and sends messages back to kernel as they are played out. Eventually played out samples == submitted samples and kernel knows stream has completely drained. I'm guessing the underrun that occurs before the drain is affecting the submitted vs played out numbers and kernel is still waiting for the "underrun" samples to be played out.

I'll need to try to understand what goes on In the kernel when the underrun occurs...

[pssc]

Ah i see this behaviour in my squeezplay Pi build also when using the default internal devices only, I see buffer underflows (large alsa buffers to some effect mitigated this).

[Ruffio]

@wm4 has your issue been resolved? If so, please close this issue. Thanks.

I'm not aware that this has been fixed, so probably not.

[Ruffio]

@popcornmix @wm4 I know that there hasn't been linked directly from any commit to this PR, but could it be that it has been fixed by some other commit and there it should be tested with latest firmware/code?

[JamesH65]

@popcornmix @wm4 Reiterating @Ruffio previous comment.

[zpon]

It looks like the usleep provokes an underrun as @wm4 and @popcornmix mentions. Without the usleep or if a second call to snd_pcm_writei is made after the usleep everything seems to work.
If the usleep time is lowered to around 200.000 us the drain is also fine. This is probably because the buffer time is only 250.000 us, thus a sleep of 300.000 us will exceed the time in the buffer and cause an underrun (even though more than 4 seconds is written to alsa. Most of the time seems to be spend in the snd_pcm_writei call - probably because the call waits for the buffer to be ready for more data).

Whether this is the right behavior in case of an underrun I don't know.

Here is the output of snd_pcm_hw_params_dump on my pi (please note that it is running a custom build):

ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 8000
PERIOD_TIME: 32000
PERIOD_SIZE: 256
PERIOD_BYTES: 1024
PERIODS: (7 8)
BUFFER_TIME: 250000
BUFFER_SIZE: 2000
BUFFER_BYTES: 8000
TICK_TIME: 0