Awkward increasing latency after reconnecting dynamic branches
Stefan Sauer
ensonic at hora-obscura.de
Mon Mar 17 13:09:55 PDT 2014
Hi,
we just debugged dynamic linking issues during the hackfest. Do you have
a standalone (minimal) repro?
Stefan
On 03/17/2014 07:55 PM, marcin at saepia.net wrote:
> I have found out two things that may be helpful:
>
> 1. that removing audiorate fixes the problem (although the audio
> starts to contain drops), and just after RTP branch reaches PLAYING,
> audiorate starts to insert a lot of samples
>
> 2. that delay is close to difference between running times of
> different branches of the adder. I've created test branch with
> audiotestsrc, and then added RTP branch. This is what happens in the
> logs in such case:
>
> 0:04:53.002670391 4078 0x1c18a80 LOG audiorate
> gstaudiorate.c:496:gst_audio_rate_chain:<test_audiorater>
> in_time:0:04:53.894965986, in_duration:0:00:00.023219955,
> in_size:4096, in_offset:12960768, in_offset_end:12961792,
> ->next_offset:12960768, ->next_ts:0:04:53.894965986
> 0:04:53.002735134 4078 0x1c18a80 LOG audiorate
> gstaudiorate.c:505:gst_audio_rate_chain:<test_audiorater> within
> tolerance 0:00:00.040000000
> 0:04:53.002916372 4078 0x1c7b320 LOG audiorate
> gstaudiorate.c:496:gst_audio_rate_chain:<livertp_audiorater>
> in_time:0:04:31.490257990, in_duration:0:00:00.020000000,
> in_size:3840, in_offset:13031532, in_offset_end:13032492,
> ->next_offset:13032481, ->next_ts:0:04:31.510020833
> 0:04:53.002952270 4078 0x1c7b320 LOG audiorate
> gstaudiorate.c:505:gst_audio_rate_chain:<livertp_audiorater> within
> tolerance 0:00:00.040000000
>
> During the delay, audiorate inserts multiple empty frames:
>
> <livertp_audiorater> inserting 48000 samples
>
>
> I would be glad if anyone could help me in resolving this odd case...
>
> m.
>
>
> 2014-03-17 17:47 GMT+01:00 marcin at saepia.net
> <mailto:marcin at saepia.net> <marcin at saepia.net <mailto:marcin at saepia.net>>:
>
> Hi,
>
> I have a pipeline that is basically
>
> adder ! pulsesink
>
> then I create dynamically a new branch. It is RTP source:
>
> rtpsrc ! rtpjitterbuffer do-lost=true ! rtpvorbisdepay ! vorbisdec
> ! queue2 max-size-bytes=16384 ! audiorate ! audioconvert !
> audioresample ! tee ! queue2 max-size-buffers=64 ! fakesink
>
> I put this branch to the separate bin, set state as PLAYING and
> wait for user input.
>
> When user wants to enable it, I request new pad in adder, request
> new pad in branch's tee, create appropriate ghost pads and link it.
>
> I am able to hear data coming through RTP.
>
> But I've found out that the latency increases each time I
> disconnect and reconnect new branch. I hear that the sound is
> delayed. It is almost not delayed if I add RTP source branch
> immediately at the initialization of the app, but it gets delayed
> if I reconnect it or just add a bit later. The latency is up to a
> few seconds.
>
> I've run the app with GST_DEBUG parameter and the only suspiciable
> thing I've found out is related to the pulse sink. In between
> linking the branch and moment in which I actually hear the sound
> such messages appear
>
> 0:00:07.917924339 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:07.917953114 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 158, out 158
> 0:00:07.918454156 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:07.918490613 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 43940, out 43940
> 0:00:07.920271008 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:07.920310888 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 44099, out 44099
> 2014-03-17 17:35:48.978 [APP APPTHREAD DEBG] [Source "livertp"
> PREPARED] Buffer levels (read_buffer): 5/0 buffers, 19200/16384
> bytes, 00:00:00.098/00:00:00.000
> 0:00:08.132638374 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:08.132677764 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 44099, out 44099
> 2014-03-17 17:35:49.980 [APP APPTHREAD DEBG] [Source "livertp"
> PREPARED] Buffer levels (read_buffer): 5/0 buffers, 19200/16384
> bytes, 00:00:00.098/00:00:00.000
> 0:00:09.106877139 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:09.106908428 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 44099, out 44099
> 2014-03-17 17:35:50.981 [APP APPTHREAD DEBG] [Source "livertp"
> PREPARED] Buffer levels (read_buffer): 5/0 buffers, 19200/16384
> bytes, 00:00:00.098/00:00:00.000
> 0:00:10.145079271 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:10.145115239 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 44099, out 44099
> 2014-03-17 17:35:51.982 [APP APPTHREAD DEBG] [Source "livertp"
> PREPARED] Buffer levels (read_buffer): 5/0 buffers, 19200/16384
> bytes, 00:00:00.098/00:00:00.000
> 0:00:11.099619090 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.099658900 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 25990, out 25990
> 0:00:11.733816986 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.733851977 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.734504784 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.734524758 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.735202987 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.735222752 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.735860753 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.735880239 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.802681891 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.802717371 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.803579910 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.803597929 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.804552798 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
> 0:00:11.804574659 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1458:gst_pulseringbuffer_commit:<tmpsink> in
> 881, out 881
> 0:00:11.875740692 20423 0xe22d40 DEBUG
> pulse pulsesink.c:1440:gst_pulseringbuffer_commit:<tmpsink>
> entering commit
>
>
> I've noticed that numbers in lines such as " in 44099, out 44099"
> are higher when this scenario occurs. When everything works ok
> they are equal to 881.
>
> How to interpret that or what else can I do in order to find what
> is causing the delay?
>
> Thanks,
>
> m.
>
>
>
>
> _______________________________________________
> gstreamer-devel mailing list
> gstreamer-devel at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/gstreamer-devel/attachments/20140317/afcc77ce/attachment.html>
More information about the gstreamer-devel
mailing list