Audio dropouts that disappear when queue2 logging is enabled

Tue Sep 27 10:30:45 UTC 2016

After doing some investigating I've discovered that, as well as the poor estimate of the buffer size, souphttpsrc can make matters worse.

souphttpsrc increases its blocksize to receive as much data as possible from the server in a single transfer (see gstsouphttpsrc.c::gst_soup_http_src_check_update_blocksize()). This sets the size of the buffers souphttpsrc sends to queue2. As blocksize approaches the queue2 buffer size, you have fewer buffers in the queue. In the worst case there is only one large buffer in the queue so it toggles between empty and full.

Should uridecodebin be coordinating soupthttpsrc's maximum blocksize to match queue2's buffer size?

________________________________
From: gstreamer-devel <gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos Rafael Giani <dv at pseudoterminal.org>
Sent: 05 September 2016 09:36:59
To: gstreamer-devel at lists.freedesktop.org
Subject: Re: Audio dropouts that disappear when queue2 logging is enabled

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><mailto:gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos Rafael Giani <dv at pseudoterminal.org><mailto:dv at pseudoterminal.org>
Sent: 03 September 2016 16:17:43
To: gstreamer-devel at lists.freedesktop.org<mailto: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"<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><mailto:gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos Rafael Giani <dv at pseudoterminal.org><mailto:dv at pseudoterminal.org>
Sent: 02 September 2016 19:29:58
To: gstreamer-devel at lists.freedesktop.org<mailto: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><mailto:gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Carlos Rafael Giani <dv at pseudoterminal.org><mailto:dv at pseudoterminal.org>
Sent: 02 September 2016 15:55:25
To: gstreamer-devel at lists.freedesktop.org<mailto: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"<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><mailto:gstreamer-devel-bounces at lists.freedesktop.org> on behalf of Jonathan Miles <jonathan.miles at cambridgeaudio.com><mailto:jonathan.miles at cambridgeaudio.com>
Sent: 02 September 2016 11:57:55
To: gstreamer-devel at lists.freedesktop.org<mailto: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"<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.

_______________________________________________
gstreamer-devel mailing list
gstreamer-devel at lists.freedesktop.org<mailto: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<mailto: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<mailto: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<mailto: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  for important notices.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20160927/49eb7c28/attachment-0001.html>