alsasrc reports very large DISCONT after 7h20m

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

alsasrc reports very large DISCONT after 7h20m

Brendan Shanks
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.


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
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
Reply | Threaded
Open this post in threaded view
|

Re: alsasrc reports very large DISCONT after 7h20m

Nicolas Dufresne-5
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
> [hidden email]
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

signature.asc (201 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: alsasrc reports very large DISCONT after 7h20m

Brendan Shanks

On Aug 17, 2018, at 8:13 AM, Nicolas Dufresne <[hidden email]> 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:

Patch now upstream:

Brendan



_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel