Audio dropouts that disappear when queue2 logging is enabled
Carlos Rafael Giani
dv at pseudoterminal.org
Fri Sep 2 18:29:58 UTC 2016
Can you also produce a dot dump? Just run the gst-launch line with the
GST_DEBUG_DUMP_DOT_DIR environment variable set to "." or "/tmp/". In
that directory, GStreamer will then generate a bunch of .dot files. Pick
the one with "PAUSED_PLAYING" in its filename, convert it to PNG with
the dot tool (dot -Tpng -o dot-dump.png <filename.dot>), and put it on
Imgur.
It is possible that the maximum internal queue2 size is too small. I've
had this problem with FLAC before. The two most common reasons for this
(which I've observed) were: (1) queue2 figured out a size that is too
low because it looked at the incoming data rate, which just happened to
be low at this moment (2) uridecodebin got a bogus bitrate from the FLAC
parser that is way too low (can happen with FLACs that start with
silence), so it calculates a small size based on that.
On 2016-09-02 17:05, Jonathan Miles wrote:
> Here's the info from the identity element:
>
> /GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain
> ******* (identity0:sink) (18432 bytes, dts: none, pts:
> 0:00:51.408979591, duration: 0:00:00.104489796, offset: -1,
> offset_end: -1, flags: 00000000 ) 0xb4180df8
> /GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain
> ******* (identity0:sink) (18432 bytes, dts: none, pts:
> 0:00:51.513469387, duration: 0:00:00.104489796, offset: -1,
> offset_end: -1, flags: 00000000 ) 0xb4f2ec10
> Buffering, setting pipeline to PAUSED ...
> Done buffering, setting pipeline to PLAYING ...
> /GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain
> ******* (identity0:sink) (18432 bytes, dts: none, pts:
> 0:00:51.617959183, duration: 0:00:00.104489796, offset: -1,
> offset_end: -1, flags: 00000000 ) 0xb4f12200
> /GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain
> ******* (identity0:sink) (18432 bytes, dts: none, pts:
> 0:00:51.722448979, duration: 0:00:00.104489796, offset: -1,
> offset_end: -1, flags: 00000000 ) 0xb4f2e990
> /GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain
> ******* (identity0:sink) (18432 bytes, dts: none, pts:
> 0:00:51.826938775, duration: 0:00:00.104489796, offset: -1,
> offset_end: -1, flags: 00000000 ) 0xb43d18f0
>
> ------------------------------------------------------------------------
> *From:* gstreamer-devel
> <gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos
> Rafael Giani <dv at pseudoterminal.org>
> *Sent:* 02 September 2016 15:55:25
> *To:* gstreamer-devel at lists.freedesktop.org
> *Subject:* Re: Audio dropouts that disappear when queue2 logging is
> enabled
>
> It is possible that downstream consumes the entire buffered data in
> one go. Try this:
>
>
> gst-launch-1.0 -v uridecodebin
> uri="http://10.0.1.120:50002/m/NDLNA/396487.flac" ! identity
> silent=false ! audioconvert ! audioresample ! autoaudiosink
>
>
> Then you'll get lines from the identity element which tell you about
> the size of the passing buffers. Paste a few of those lines here.
>
>
>
> On 2016-09-02 16:39, Jonathan Miles wrote:
>>
>> Tweaking the logging, I'm seeing the following dance between queue2
>> and souphttpsrc:
>>
>>
>> Done buffering, setting pipeline to PLAYING ...
>> 0:00:20.721441002 3095 0x286150 INFO queue2
>> gstqueue2.c:2447:gst_queue2_locked_dequeue:<queue2-0> cur_level.bytes=0
>> 0:00:20.721910210 3095 0x286150 INFO queue2
>> gstqueue2.c:1070:gst_queue2_get_buffering_message:<queue2-0> Going to
>> post buffering: 0%
>> 0:00:20.723109877 3095 0x3f6ac0 INFO queue2
>> gstqueue2.c:2328:gst_queue2_locked_enqueue:<queue2-0>
>> cur_level.bytes=886192
>> buffering... 0%
>> Buffering, setting pipeline to PAUSED ...
>> 0:00:20.731298335 3095 0x3f6ac0 INFO queue2
>> gstqueue2.c:1070:gst_queue2_get_buffering_message:<queue2-0> Going to
>> post buffering: 100%
>> 0:00:20.795157794 3095 0x3f6ac0 DEBUG souphttpsrc
>> gstsouphttpsrc.c:1640:gst_soup_http_src_read_buffer:<source> Read
>> 947616 bytes from http input
>> 0:00:20.797286460 3095 0x3f6ac0 DEBUG souphttpsrc
>> gstsouphttpsrc.c:1744:gst_soup_http_src_create:<source> Returning 0 ok
>> buffering... 100%
>> Done buffering, setting pipeline to PLAYING ...
>> 0:00:26.157894003 3095 0x286150 INFO queue2
>> gstqueue2.c:2447:gst_queue2_locked_dequeue:<queue2-0> cur_level.bytes=0
>> 0:00:26.158368253 3095 0x286150 INFO queue2
>> gstqueue2.c:1070:gst_queue2_get_buffering_message:<queue2-0> Going to
>> post buffering: 0%
>> 0:00:26.159438128 3095 0x3f6ac0 INFO queue2
>> gstqueue2.c:2328:gst_queue2_locked_enqueue:<queue2-0>
>> cur_level.bytes=947616
>> buffering... 0%
>> Buffering, setting pipeline to PAUSED ...
>> 0:00:26.165946669 3095 0x3f6ac0 INFO queue2
>> gstqueue2.c:1070:gst_queue2_get_buffering_message:<queue2-0> Going to
>> post buffering: 100%
>> 0:00:26.230684461 3095 0x3f6ac0 DEBUG souphttpsrc
>> gstsouphttpsrc.c:1640:gst_soup_http_src_read_buffer:<source> Read
>> 947896 bytes from http input
>> 0:00:26.232809503 3095 0x3f6ac0 DEBUG souphttpsrc
>> gstsouphttpsrc.c:1744:gst_soup_http_src_create:<source> Returning 0 ok
>> buffering... 100%
>> Done buffering, setting pipeline to PLAYING ...
>>
>>
>> It looks like queue2 is sending the "buffering 0%" message before
>> souphttpsrc has had a chance to re-fill the queue.
>>
>>
>> Some more info on my set-up
>>
>>
>> - Building from git master
>>
>> - Crossed compiled for ARM
>>
>> - Running on an ARM AM335x (like a Beagle Bone)
>>
>> - Linux 3.8.11 - no kernel pre-emption enabled
>>
>> ------------------------------------------------------------------------
>> *From:* gstreamer-devel
>> <gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Jonathan
>> Miles <jonathan.miles at cambridgeaudio.com>
>> *Sent:* 02 September 2016 11:57:55
>> *To:* gstreamer-devel at lists.freedesktop.org
>> *Subject:* Audio dropouts that disappear when queue2 logging is enabled
>> While playing a FLAC file from a Synology NAS, I'm getting audio
>> dropouts as a result of re-buffering:
>>
>> ~ # gst-launch-1.0 playbin
>> uri="http://10.0.1.120:50002/m/NDLNA/396487.flac"
>> Setting pipeline to PAUSED ...
>> Pipeline is PREROLLING ...
>> WARNING: from element /GstPlayBin:playbin0/GstPlaySink:playsink: No
>> volume control found
>> Additional debug info:
>> /home/jonathanm/build/v010-a/build-glibc-glibc/work/armv7a-vfp-neon-oe-linux-gnueabi/gstreamer1.0-plugins-base/git-r0/git/gst/playback/gstplaysink.c(2857):
>> gen_audio_chain (): /GstPlayBin:playbin0/GstPlaySink:playsink:
>> Volume/mute is not available
>> Redistribute latency...
>> Pipeline is PREROLLED ...
>> Setting pipeline to PLAYING ...
>> New clock: GstAudioSinkClock
>> Buffering, setting pipeline to PAUSED ...
>> Done buffering, setting pipeline to PLAYING ...
>> Buffering, setting pipeline to PAUSED ...
>> Done buffering, setting pipeline to PLAYING ...
>>
>> If I enable queue2 debugging (GST_DEBUG="queue2:5"), the audio
>> drop-outs disappear, as the pipeline doesn't get set to PAUSED,
>> although it looks like the rebuffering is still happening:
>>
>> 0:00:32.967181462 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:842:apply_buffer:<queue2-0> position updated to
>> 0:00:00.000000000
>> 0:00:32.967705879 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:740:update_time_level:<queue2-0> sink 0:00:00.000000000,
>> src 0:00:00.000000000
>> 0:00:32.968154921 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:1221:update_out_rates:<queue2-0> rates: period 5.950074,
>> out 1048576
>> 0:00:32.968559296 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:1239:update_out_rates:<queue2-0> rates: out
>> 266973.567011, time 0:00:00.000000000
>> 0:00:32.969009754 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:1199:update_in_rates:<queue2-0> rates: in 1361330.412743,
>> time 0:00:00.000000000
>> 0:00:32.969451212 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:1004:get_buffering_level:<queue2-0> buffering 0, level 0
>> 0:00:32.969777004 1648 0x2cfb50 DEBUG queue2
>> gstqueue2.c:1122:update_buffering:<queue2-0> buffering 0 percent
>> 0:00:32.972558504 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:842:apply_buffer:<queue2-0> position updated to
>> 0:00:00.000000000
>> 0:00:32.973054296 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:740:update_time_level:<queue2-0> sink 0:00:00.000000000,
>> src 0:00:00.000000000
>> 0:00:32.973499504 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:1199:update_in_rates:<queue2-0> rates: in 1361330.412743,
>> time 0:00:00.779502162
>> 0:00:32.973981379 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:1199:update_in_rates:<queue2-0> rates: in 1361330.412743,
>> time 0:00:00.779502162
>> 0:00:32.974428254 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:1004:get_buffering_level:<queue2-0> buffering 1, level
>> 1000000
>> 0:00:32.974764921 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:1116:update_buffering:<queue2-0> buffering 100 percent
>> 0:00:32.975315546 1648 0x4408c0 DEBUG queue2
>> gstqueue2.c:1070:gst_queue2_get_buffering_message:<queue2-0> Going to
>> post buffering: 100%
>> Done buffering, setting pipeline to PLAYING ...
>>
>> Anyone got any ideas as to what might be going here?
>>
>> Thanks,
>>
>> Jonathan
>>
>>
>> Audio Partnership PLC, Gallery Court, Hankey Place, London SE1 4BB,
>> UK Reg No. 2953313 This e-mail is confidential and for the addressee
>> only. Please refer to Disclaimer
>> <https://www.cambridgeaudio.com/disclaimer> for important notices.
>>
>>
>> Audio Partnership PLC, Gallery Court, Hankey Place, London SE1 4BB,
>> UK Reg No. 2953313 This e-mail is confidential and for the addressee
>> only. Please refer to Disclaimer
>> <https://www.cambridgeaudio.com/disclaimer> for important notices.
>>
>>
>> _______________________________________________
>> gstreamer-devel mailing list
>> gstreamer-devel at lists.freedesktop.org
>> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
>
>
>
> Audio Partnership PLC, Gallery Court, Hankey Place, London SE1 4BB, UK
> Reg No. 2953313 This e-mail is confidential and for the addressee
> only. Please refer to Disclaimer
> <https://www.cambridgeaudio.com/disclaimer> for important notices.
>
>
> _______________________________________________
> gstreamer-devel mailing list
> gstreamer-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20160902/4e1519d1/attachment-0001.html>
More information about the gstreamer-devel
mailing list