alsasrc reports very large DISCONT after 7h20m

[Brendan Shanks]

> On Aug 17, 2018, at 8:13 AM, Nicolas Dufresne <nicolas at ndufresne.ca> wrote:
> 
> Le jeudi 16 août 2018 à 18:17 -0700, Brendan Shanks a écrit :
>> My application is capturing and streaming audio/video, but I've reproduced this problem with a simple test app that's essentially implementing 'alsasrc ! tee name=t ! queue ! fakesink t. ! queue ! alsasink'. Note that the alsasrc is capturing from a dsnoop device, and alsasink is playing to a dshare device.
>> 
>> Consistently, after 7 hours 20 minutes, the alsasrc reports a large DISCONT. It's capturing at 48 kHz, so the number of samples "dropped" is always around 3-4 minutes worth.
>> 
>> 7:20:37.871464957  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:842:gst_audio_base_src_create:<alsasrc1> create DISCONT of 10501920 samples at sample 1268840640
>> 7:20:37.871751552  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:847:gst_audio_base_src_create:<alsasrc1> warning: Can't record audio fast enough
>> 7:20:37.871819092  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:847:gst_audio_base_src_create:<alsasrc1> warning: Dropped 10501920 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
>> 7:20:37.871974254  1919   0xda0180 INFO        GST_ERROR_SYSTEM gstelement.c:1938:gst_element_message_full_with_details:<alsasrc1> posting message: Can't record audio fast enough
>> 7:20:37.872104000  1919   0xda0180 INFO        GST_ERROR_SYSTEM gstelement.c:1965:gst_element_message_full_with_details:<alsasrc1> posted warning message: Can't record audio fast enough
>> 7:20:37.874166283  1919   0xecb380 WARN                    alsa gstalsasink.c:983:xrun_recovery:<alsasink1> xrun recovery -32: Broken pipe
>> 7:20:38.691488200  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:842:gst_audio_base_src_create:<alsasrc1> create DISCONT of 38400 samples at sample 1268880000
>> 7:20:38.691657779  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:847:gst_audio_base_src_create:<alsasrc1> warning: Can't record audio fast enough
>> 7:20:38.691715319  1919   0xda0180 WARN            audiobasesrc gstaudiobasesrc.c:847:gst_audio_base_src_create:<alsasrc1> warning: Dropped 38400 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
>> 7:20:38.691853783  1919   0xda0180 INFO        GST_ERROR_SYSTEM gstelement.c:1938:gst_element_message_full_with_details:<alsasrc1> posting message: Can't record audio fast enough
>> 7:20:38.691966738  1919   0xda0180 INFO        GST_ERROR_SYSTEM gstelement.c:1965:gst_element_message_full_with_details:<alsasrc1> posted warning message: Can't record audio fast enough
>> 
>> 
>> There's no sign that this is due to an actual xrun when capturing from the ALSA device, it seems to be some kind of clock/timing problem. (The alsasink does xrun though.) The pipeline clock is GstSystemClock. Hardware is an Ambarella SoC, it's very possible there's problems in hardware/drivers. ntpd is running on the system, and time seems to be accurate.
> 
> The skew handling in AudioSrc base class is not so nice. What happens
> is that it will only skew when buffer-size is reached, and then it will
> bring reset back to the current sample. This size can be very large on
> some system.
> 
> If you do more testing, you'll notice that due to drift, you're latency
> is growing up, which is a sign that samples are piling in the driver.
> You also seems to have some overrun, which usually means your ring
> buffer thread is not scheduled often enough. So, things to improve
> this:
> 
>  - Ensure the alsasrc provided clock is used across your pipeline
>  - Reduce as much as possible buffer-time
>  - Increase the ring buffer thread priority (remember
>    pulseaudio/pipewire uses high priority to do that same)


Bumping an old thread:
Thanks for the suggestions, I implemented them but it turned out to be a pointer rollover bug in alsa-lib/dshare that would block the streaming thread for 3+ minutes. Bug was already fixed in dmix.

More details:
http://mailman.alsa-project.org/pipermail/alsa-devel/2018-October/140911.html <http://mailman.alsa-project.org/pipermail/alsa-devel/2018-October/140911.html>

Patch now upstream:
http://git.alsa-project.org/?p=alsa-lib.git;a=commitdiff;h=7cea8c156204ebae7c0dc60801dde5ddfa5bb7d0 <http://git.alsa-project.org/?p=alsa-lib.git;a=commitdiff;h=7cea8c156204ebae7c0dc60801dde5ddfa5bb7d0>

Brendan


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190212/4f3df996/attachment-0001.html>