Audio dropouts that disappear when queue2 logging is enabled

Carlos Rafael Giani dv at pseudoterminal.org
Sat Sep 3 15:17:43 UTC 2016


How is the pipeline behavior with this? gst-launch-1.0 uridecodebin 
uri="http://10.0.1.120:50002/m/NDLNA/396487.flac" buffer-size=4000000 
buffer-duration=0 ! audioconvert ! audioresample ! autoaudiosink

On 2016-09-03 11:53, Jonathan Miles wrote:
>
> Thanks for your help.
>
>
> Here's the pipeline image: http://imgur.com/a/WV5DF
>
> For the sake of completeness, here's the the drop-out 
> (PLAYING->PAUSED): http://imgur.com/a/dBnhq
>
> And restart (PAUSED->PLAYING): http://imgur.com/a/IqMoU
>
>
> Assuming I'm looking at the right part of uridecodebin, here's the 
> queue size set-up:
>
>
> 0:00:03.801279251   786   0x28af50 DEBUG uridecodebin 
> gsturidecodebin.c:1110:decoded_pad_event_probe:<decodebin0:src_0> 
> found bitrate 0
> 0:00:03.892754459   786   0x28af50 DEBUG uridecodebin 
> gsturidecodebin.c:1110:decoded_pad_event_probe:<decodebin0:src_0> 
> found bitrate 1411429
> 0:00:03.899845626   786   0x28af50 DEBUG uridecodebin 
> gsturidecodebin.c:1065:configure_stream_buffering:<uridecodebin0> 
> overall bitrate 1411429
> 0:00:03.915355626   786   0x28af50 DEBUG uridecodebin 
> gsturidecodebin.c:1077:configure_stream_buffering:<uridecodebin0> 
> queue buffering time 0:00:02.000000000
> 0:00:03.917613084   786   0x28af50 DEBUG uridecodebin 
> gsturidecodebin.c:1080:configure_stream_buffering:<uridecodebin0> 
> corresponds to buffer size 352857
> ------------------------------------------------------------------------
> *From:* gstreamer-devel 
> <gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos 
> Rafael Giani <dv at pseudoterminal.org>
> *Sent:* 02 September 2016 19:29:58
> *To:* gstreamer-devel at lists.freedesktop.org
> *Subject:* Re: Audio dropouts that disappear when queue2 logging is 
> enabled
> 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
>
>
>
> 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/20160903/5b7bca83/attachment-0001.html>


More information about the gstreamer-devel mailing list