alsasrc reports very large DISCONT after 7h20m

[Nicolas Dufresne]

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)

> 
> 
> Not sure about this, but my guess for where the 7h20m time (and number of samples) comes from is related to the ALSA 'boundary' parameter, which can be viewed with:
> 
> $ cat /proc/asound/card0/pcm1p/sub0/sw_params 
> tstamp_mode: NONE
> period_step: 1
> avail_min: 480
> start_threshold: 9600
> stop_threshold: 9600
> silence_threshold: 0
> silence_size: 0
> boundary: 1258291200
> 
> 'boundary' is calculated in the kernel, by multiplying buffer_size * 2 up to LONG_MAX (<https://elixir.bootlin.com/linux/v4.18/source/sound/core/pcm_native.c#L751>). This means 'boundary' is much larger on a 64-bit system, maybe the DISCONT wouldn't happen there.
> 
> Any ideas/help is much appreciated.
> 
> Brendan
> _______________________________________________
> gstreamer-devel mailing list
> gstreamer-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 195 bytes
Desc: This is a digitally signed message part
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20180817/6f18bfe9/attachment.sig>