Audio dropouts that disappear when queue2 logging is enabled

Fri Sep 2 15:05:23 UTC 2016

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"<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  for important notices.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20160902/b637eb86/attachment-0001.html>