Audio dropouts that disappear when queue2 logging is enabled

Carlos Rafael Giani dv at pseudoterminal.org
Mon Sep 5 08:36:59 UTC 2016 

Yes, it is. This was just a test to confirm my suspicions.

The fundamental problem here is that uridecodebin tries to calculate a 
buffer size based on the bitrate, but does this only once. Also, I guess 
the initial buffer size here of 352827 bytes might be a tad too low as 
well. And keep in mind that downstream's behavior also influences the 
buffering progress. If you see buffering percentage reverting back to 
somewhere around 0-5% sometimes, then this is because downstream just 
consumed data and emptied the queue. In some extreme cases, this can 
lead to pipelines that reach the PLAYING state, only for their queue2 
element to suddenly get emptied again, dropping back to PAUSED state.

I posted a proof-of-concept patch here: 
https://bugzilla.gnome.org/show_bug.cgi?id=762125 though it is somewhat 
outdated now (I have ideas for better solutions for the documented 
problems).

On 2016-09-04 20:13, Jonathan Miles wrote:
>
> That stops the rebuffering, and souphttpsrc is getting a change to 
> refill the buffer before queue2 is drained.
>
>
> Once the pipeline is into its stride:
>
>
> 0:03:09.196031856 12635   0x284d50 INFO  queue2 
> gstqueue2.c:2447:gst_queue2_locked_dequeue:<queue2-0> 
> cur_level.bytes=3892256
> 0:03:09.198157856 12635   0x3f58c0 INFO  queue2 
> gstqueue2.c:2328:gst_queue2_locked_enqueue:<queue2-0> 
> cur_level.bytes=4840136
> 0:03:09.244743939 12635   0x3f58c0 DEBUG  souphttpsrc 
> gstsouphttpsrc.c:1640:gst_soup_http_src_read_buffer:<source> Read 
> 977352 bytes from http input
> 0:03:09.246352481 12635   0x3f58c0 DEBUG  souphttpsrc 
> gstsouphttpsrc.c:1744:gst_soup_http_src_create:<source> Returning 0 ok
>
> Isn't 4MB a bit over the top for a 16/44.1 FLAC file?
>
> ------------------------------------------------------------------------
> *From:* gstreamer-devel 
> <gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos 
> Rafael Giani <dv at pseudoterminal.org>
> *Sent:* 03 September 2016 16:17:43
> *To:* gstreamer-devel at lists.freedesktop.org
> *Subject:* Re: Audio dropouts that disappear when queue2 logging is 
> enabled
> 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
>
>
>
> 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/20160905/de8ffad2/attachment-0001.html>

More information about the gstreamer-devel mailing list