High initial playback delay when using audiomixer
Ajit Warrier
ajit.warrier at gmail.com
Tue Nov 29 22:56:37 UTC 2016
I am using the following pipeline on an x86 PC, using v1.10.1:
gst-launch-1.0 -v udpsrc caps="application/x-rtp" port=1234
multicast-group=239.0.0.190 ! rtpg722depay ! avdec_g722 ! audiomixer !
alsasink
It receives g722 coded rtp audio and plays it out. When using the
audiomixer in this pipeline, if I perform the following operations:
- start pipeline
- wait for couple of minutes
- THEN send rtp audio
I experience a delay of 5-6 seconds before playback starts. This only
happens if I wait for couple of minutes, in fact the playback delay gets
worse the longer I wait. And it only happens with the audiomixer in the
pipeline. Without the audiomixer, there is no playback delay.
I ran GST_DEBUG=6 and got the following output that looks suspicious:
Multiple repeated instances of:
0:02:52.285149489 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3360:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:02:47.560000000, end: 0:02:47.570000000
0:02:52.285156228 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:1946:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:02:47.560000000, stop: 0:02:47.570000000, do_sync 0
0:02:52.285163242 5934 0x55dc774f8d40 LOG basesink
gstbasesink.c:2483:gst_base_sink_do_sync:<alsasink0> avg frame diff
0:00:00.010000000
0:02:52.285168838 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3468:gst_base_sink_chain_unlocked:<alsasink0> rendering
object 0x7f3934017af0
0:02:52.285173812 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:1899:gst_audio_base_sink_render:<alsasink0> Received GAP
or ignoring audio for trickplay. Dropping contents
0:02:52.285178641 5934 0x55dc774f8d40 DEBUG GST_EVENT
gstevent.c:305:gst_event_new_custom: creating new event 0x7f393c004a60 gap
40966
0:02:52.285184292 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:912:gst_audio_ring_buffer_start:<audiosinkringbuffer0>
starting ringbuffer
0:02:52.285188437 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:929:gst_audio_ring_buffer_start:<audiosinkringbuffer0>
was not stopped, try paused
0:02:52.285192343 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:937:gst_audio_ring_buffer_start:<audiosinkringbuffer0>
was not paused, must have been started
0:02:52.285199470 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:1911:gst_base_sink_get_sync_times:<alsasink0> Got Gap time
0:02:47.560000000 duration 0:00:00.010000000
0:02:52.285206383 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:1946:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:02:47.560000000, stop: 0:02:47.570000000, do_sync 1
0:02:52.285213779 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:2523:gst_base_sink_do_sync:<alsasink0> reset rc_time to time
0:02:47.780000000
0:02:52.285219206 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:2535:gst_base_sink_do_sync:<alsasink0> possibly waiting for
clock to reach 0:02:47.560000000, adjusted 0:02:47.780000000
0:02:52.285225617 5934 0x55dc774f8d40 LOG basesink
gstbasesink.c:2117:gst_base_sink_wait_clock:<alsasink0> time
0:02:47.780000000, base_time 1349:31:49.960166366
0:02:52.285232112 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:535:gst_clock_id_wait:<GstSystemClock> waiting on clock entry
0x7f393c0048a0
0:02:52.285236787 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:1045:gst_clock_get_internal_time:<GstSystemClock> internal time
1349:34:41.935386462
0:02:52.285242365 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:1090:gst_clock_get_time:<GstSystemClock> adjusted time
1349:34:41.935386462
0:02:52.285247488 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstsystemclock.c:717:gst_system_clock_id_wait_jitter_unlocked: entry
0x7f393c0048a0 time 1349:34:37.740166366 now 1349:34:41.935386462 diff
(time-now) -4195220096
0:02:52.285254637 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:545:gst_clock_id_wait:<GstSystemClock> done waiting entry
0x7f393c0048a0, res: 1 (early)
0:02:52.285259717 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:2542:gst_base_sink_do_sync:<alsasink0> clock returned 1,
jitter 0:00:04.195220096
0:02:52.285265829 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:2858:gst_base_sink_is_too_late:<alsasink0> frame dropping
disabled
0:02:52.285269802 5934 0x55dc774f8d40 LOG GST_EVENT
gstevent.c:222:_gst_event_free: freeing event 0x7f393c004a60 type gap
0:02:52.285275293 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3507:gst_base_sink_chain_unlocked:<alsasink0> object unref
after render 0x7f3934017af0
0:02:52.285279814 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:724:_gst_buffer_free: finalize 0x7f3934017af0
0:02:52.285284056 5934 0x55dc774f8d40 DEBUG GST_MEMORY
gstmemory.c:87:_gst_memory_free: free memory 0x7f393c012620
0:02:52.285289468 5934 0x55dc774f8d40 DEBUG GST_SCHEDULING
gstpad.c:4209:gst_pad_chain_data_unchecked:<alsasink0:sink> called
chainfunction &gst_base_sink_chain with buffer 0x7f3934017af0, returned ok
0:02:52.285295407 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1372:gst_audio_aggregator_aggregate:<audiomixer0>
pushed outbuf, result = ok
0:02:52.285300098 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:831:gst_aggregator_aggregate_func:<audiomixer0> flow return
is ok
0:02:52.285305893 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function 0x7f39559040f0 on pad
0:02:52.285311540 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:428:gst_aggregator_check_pads_ready:<audiomixer0> checking
pads
0:02:52.285315809 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:460:gst_aggregator_check_pads_ready:<audiomixer0> pads are
ready
0:02:52.285319732 5934 0x55dc774f8d40 DEBUG aggregator
gstaggregator.c:630:gst_aggregator_wait_and_check:<audiomixer0> all pads
have data
0:02:52.285324475 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function 0x7f39559040f0 on pad
0:02:52.285330484 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function sync_pad_values on pad
0:02:52.285338421 5934 0x55dc774f8d40 LOG default
gstobject.c:1120:gst_object_sync_values:<audiomixer0:sink_0> sync_values
0:02:52.285343028 5934 0x55dc774f8d40 DEBUG GST_MEMORY
gstmemory.c:138:gst_memory_init: new memory 0x7f393c012440, maxsize:327
offset:0 size:320
0:02:52.285348790 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:798:gst_buffer_new: new 0x7f3934017c00
0:02:52.285352988 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:413:_memory_add: buffer 0x7f3934017c00, idx -1, mem
0x7f393c012440
0:02:52.285357932 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:854:gst_buffer_new_allocate: new buffer 0x7f3934017c00 of size
320 from allocator (nil)
0:02:52.285362993 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:1720:gst_buffer_map_range: buffer 0x7f3934017c00, idx 0, length
-1, flags 0002
0:02:52.285368270 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:212:_get_merged_memory: buffer 0x7f3934017c00, idx 0, length 1
0:02:52.285373686 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1194:gst_audio_aggregator_aggregate:<audiomixer0>
Starting to mix 160 samples for offset 2681120 with timestamp
0:02:47.570000000
0:02:52.285380278 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1365:gst_audio_aggregator_aggregate:<audiomixer0>
pushing outbuf 0x7f3934017c00, timestamp 0:02:47.570000000 offset 2681120
0:02:52.285386988 5934 0x55dc774f8d40 DEBUG GST_SCHEDULING
gstpad.c:4203:gst_pad_chain_data_unchecked:<alsasink0:sink> calling
chainfunction &gst_base_sink_chain with buffer buffer: 0x7f3934017c00, pts
0:02:47.570000000, dts 99:
99:99.999999999, dur 0:00:00.010000000, size 320, offset 2681120,
offset_end 2681280, flags 0x800
Finally followed by the playback:
0:02:52.285535775 5934 0x55dc774f8d40 DEBUG GST_SCHEDULING
gstpad.c:4209:gst_pad_chain_data_unchecked:<alsasink0:sink> called
chainfunction &gst_base_sink_chain with buffer 0x7f3934017c00, returned ok
0:02:52.285541688 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1372:gst_audio_aggregator_aggregate:<audiomixer0>
pushed outbuf, result = ok
0:02:52.285546617 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:831:gst_aggregator_aggregate_func:<audiomixer0> flow return
is ok
0:02:52.285552504 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function 0x7f39559040f0 on pad
0:02:52.285558288 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:428:gst_aggregator_check_pads_ready:<audiomixer0> checking
pads
0:02:52.285562564 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:460:gst_aggregator_check_pads_ready:<audiomixer0> pads are
ready
0:02:52.285566505 5934 0x55dc774f8d40 DEBUG aggregator
gstaggregator.c:630:gst_aggregator_wait_and_check:<audiomixer0> all pads
have data
0:02:52.285571214 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function 0x7f39559040f0 on pad
0:02:52.285577286 5934 0x55dc774f8d40 LOG aggregator
gstaggregator.c:378:gst_aggregator_iterate_sinkpads:<audiomixer0:sink_0>
calling function sync_pad_values on pad
0:02:52.285582555 5934 0x55dc774f8d40 LOG default
gstobject.c:1120:gst_object_sync_values:<audiomixer0:sink_0> sync_values
0:02:52.285586893 5934 0x55dc774f8d40 DEBUG GST_MEMORY
gstmemory.c:138:gst_memory_init: new memory 0x7f393c012260, maxsize:327
offset:0 size:320
0:02:52.285592416 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:798:gst_buffer_new: new 0x7f3934017c00
0:02:52.285596623 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:413:_memory_add: buffer 0x7f3934017c00, idx -1, mem
0x7f393c012260
0:02:52.285604025 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:854:gst_buffer_new_allocate: new buffer 0x7f3934017c00 of size
320 from allocator (nil)
0:02:52.285609397 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:1720:gst_buffer_map_range: buffer 0x7f3934017c00, idx 0, length
-1, flags 0002
0:02:52.285614824 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:212:_get_merged_memory: buffer 0x7f3934017c00, idx 0, length 1
0:02:52.285620362 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1194:gst_audio_aggregator_aggregate:<audiomixer0>
Starting to mix 160 samples for offset 2681280 with timestamp
0:02:47.580000000
0:02:52.285627060 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1277:gst_audio_aggregator_aggregate:<audiomixer0:sink_0>
Mixing buffer for current offset
0:02:52.285631472 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:1720:gst_buffer_map_range: buffer 0x7f3934017c00, idx 0, length
-1, flags 0003
0:02:52.285636893 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:212:_get_merged_memory: buffer 0x7f3934017c00, idx 0, length 1
0:02:52.285641867 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:1720:gst_buffer_map_range: buffer 0x7f3934017270, idx 0, length
-1, flags 0001
0:02:52.285647069 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:212:_get_merged_memory: buffer 0x7f3934017270, idx 0, length 1
0:02:52.285652574 5934 0x55dc774f8d40 LOG audiomixer
gstaudiomixer.c:640:gst_audiomixer_aggregate_one_buffer:<audiomixer0:sink_0>
mixing 16 bytes at offset 304 from offset 0
0:02:52.285790505 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1283:gst_audio_aggregator_aggregate:<audiomixer0:sink_0>
Pad is at or after current offset: 2681440 >= 2681440
0:02:52.285798603 5934 0x55dc774f8d40 LOG audioaggregator
gstaudioaggregator.c:1365:gst_audio_aggregator_aggregate:<audiomixer0>
pushing outbuf 0x7f3934017c00, timestamp 0:02:47.580000000 offset 2681280
0:02:52.285806631 5934 0x55dc774f8d40 DEBUG GST_SCHEDULING
gstpad.c:4203:gst_pad_chain_data_unchecked:<alsasink0:sink> calling
chainfunction &gst_base_sink_chain with buffer buffer: 0x7f3934017c00, pts
0:02:47.580000000, dts 99:99:99.999999999, dur 0:00:00.010000000, size 320,
offset 2681280, offset_end 2681440, flags 0x0
0:02:52.285815505 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3360:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:02:47.580000000, end: 0:02:47.590000000
0:02:52.285823219 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:1946:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:02:47.580000000, stop: 0:02:47.590000000, do_sync 0
0:02:52.285831300 5934 0x55dc774f8d40 LOG basesink
gstbasesink.c:2483:gst_base_sink_do_sync:<alsasink0> avg frame diff
0:00:00.010000000
0:02:52.285837240 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3468:gst_base_sink_chain_unlocked:<alsasink0> rendering
object 0x7f3934017c00
0:02:52.285842645 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:1916:gst_audio_base_sink_render:<alsasink0> time
0:02:47.580000000, start 0:00:00.000000000, samples 160
0:02:52.285856423 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:1953:gst_audio_base_sink_render:<alsasink0> sync-offset
+0:00:00.220000000, render-delay 0:00:00.000000000, ts-offset
+0:00:00.000000000
0:02:52.285866566 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2015:gst_audio_base_sink_render:<alsasink0> running:
start 0:02:47.580000000 - stop 0:02:47.590000000
0:02:52.285873485 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2030:gst_audio_base_sink_render:<alsasink0> compensating
for sync-offset 0:00:00.220000000
0:02:52.285879252 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2037:gst_audio_base_sink_render:<alsasink0> adding
base_time 1349:31:49.960166366
0:02:52.285888650 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:1045:gst_clock_get_internal_time:<GstSystemClock> internal time
1349:34:41.936038218
0:02:52.285894620 5934 0x55dc774f8d40 DEBUG GST_CLOCK
gstclock.c:1090:gst_clock_get_time:<GstSystemClock> adjusted time
1349:34:41.936038218
0:02:52.285905690 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:568:gst_audio_base_sink_get_time:<alsasink0> processed
samples: raw 72960, delay 3100, real 69860, time 0:00:04.366250000
0:02:52.285913345 5934 0x55dc774f8d40 DEBUG audioclock
gstaudioclock.c:202:gst_audio_clock_get_time:<GstAudioSinkClock> result
0:00:04.366250000, last_time 0:00:00.000000000
0:02:52.285921064 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:1452:gst_audio_base_sink_skew_slaving:<alsasink0>
internal 0:00:04.366250000 external 1349:34:41.936038218 cinternal
0:00:00.000000000 cexternal 1349:34:37.567980323
0:02:52.285930548 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:1473:gst_audio_base_sink_skew_slaving:<alsasink0>
internal 0:00:04.366250000 external 0:00:04.368057895 skew
-0:00:00.001807895 avg -0:00:00.001807895
0:02:52.285940773 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2057:gst_audio_base_sink_render:<alsasink0> final
timestamps: start 0:00:00.192186043 - stop 0:00:00.202186043
0:02:52.285948429 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2126:gst_audio_base_sink_render:<alsasink0> no align
possible: no previous sample position known
0:02:52.285952614 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2155:gst_audio_base_sink_render:<alsasink0> rendering at
3074 160/160
0:02:52.285957857 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:1720:gst_buffer_map_range: buffer 0x7f3934017c00, idx 0, length
-1, flags 0001
0:02:52.285963384 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:212:_get_merged_memory: buffer 0x7f3934017c00, idx 0, length 1
0:02:52.285969094 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1503:default_commit:<audiosinkringbuffer0> write 160 :
160
0:02:52.285974366 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1523:default_commit:<audiosinkringbuffer0> pointer at
456, write to 19-68, diff -437, segtotal 20, segsize 320, base 0
0:02:52.285980927 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1553:default_commit:<audiosinkringbuffer0> write
@0x7f393c0078f0 seg 19, sps 160, off 68, avail 252
0:02:52.285986614 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1579:default_commit: copy 252 bytes
0:02:52.285991302 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1523:default_commit:<audiosinkringbuffer0> pointer at
456, write to 20-0, diff -436, segtotal 20, segsize 320, base 0
0:02:52.285997607 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1553:default_commit:<audiosinkringbuffer0> write
@0x7f393c006130 seg 0, sps 160, off 0, avail 68
0:02:52.286003049 5934 0x55dc774f8d40 DEBUG ringbuffer
gstaudioringbuffer.c:1579:default_commit: copy 68 bytes
0:02:52.286007709 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2166:gst_audio_base_sink_render:<alsasink0> wrote 160 of
160
0:02:52.286012918 5934 0x55dc774f8d40 DEBUG audiobasesink
gstaudiobasesink.c:2198:gst_audio_base_sink_render:<alsasink0> next sample
expected at 3234
0:02:52.286017810 5934 0x55dc774f8d40 DEBUG basesink
gstbasesink.c:3507:gst_base_sink_chain_unlocked:<alsasink0> object unref
after render 0x7f3934017c00
0:02:52.286022216 5934 0x55dc774f8d40 LOG GST_BUFFER
gstbuffer.c:724:_gst_buffer_free: finalize 0x7f3934017c00
0:02:52.286026444 5934 0x55dc774f8d40 DEBUG GST_MEMORY
gstmemory.c:87:_gst_memory_free: free memory 0x7f393c012260
Any ideas why this delay occurs ?
Ajit.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20161129/278fa29e/attachment-0001.html>
More information about the gstreamer-devel
mailing list