Awkward increasing latency after reconnecting dynamic branches
marcin at saepia.net
marcin at saepia.net
Mon Mar 17 11:55:47 PDT 2014
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 <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.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/gstreamer-devel/attachments/20140317/512968a6/attachment-0001.html>
More information about the gstreamer-devel
mailing list