[gst-devel] Latency

Sat Sep 15 01:22:04 CEST 2007

I finally have my triggered audio clip element working, more or less,
and I'm running into an unexpected problem: latency. I don't know how
to read all of the GST_DEBUG output, so I can't give exact numbers,
but from the time I press Enter to the time I hear the sound, I have
time to hit about two other keys. I'd guess around 0.2 seconds of
latency, not that I'm any good at estimating time. (I was just telling
me wife "remember a couple of years back when we went to Costa Rica?"
She said, "you mean, in 1997? Our one and only trip, which was a
decade ago?")

In comparison, if I do a simple "aplay ping.wav", I hear the sound
coming out before I can release the Enter key. So there's no silent
padding at the beginning of the sound file or anything.

Even odder, my debugging printouts show that my element is stuffing
buffers down the pipeline pretty much immediately -- and in fact, it
stuffs 7-8 4KB buffers (at 22Khz) before I hear anything. The output
is going through an 'adder' element, which seems to undo any
synchronization you have, so I don't *think* it's because my
timestamps are wrong. What output can I look for to determine whether
that is the case?

Why is it able to return from gst_pad_push() (several times) without
anything showing up on the output? How can I track this down?

Here's my pipeline:

filesrc location=ping.wav ! wavparse ! clipcache name=cc ! adder
name=add ! alsasink cc.clip1 ! add.

(clipcache dynamically creates src pads named clip%d; in my tests, it
only ever needs to create clip1)

Below is a slightly cleaned-up portion of the debugging output. To
explain: I print out "Pushing buffer 0" just before I start pushing
buffers. "Buffer 0" is actually a single incoming 4096-byte buffer
that I chop up into 256-byte subbuffers, then push each down the
pipeline in turn. (This is so that I can respond to signals to start
additional clips faster; if I push whole buffers instead, the latency
isn't any better but it takes longer to start trying to push buffers.)

The output looks good, from what I can tell -- I think it claims to be
rendering out a bunch of different buffers. But I sure don't hear them
for a while.

Help?

0:00:10.220633000          clip_cache
gstcc.c:226:gst_clip_cache_clip_loop:<cc> Starting play in clip_loop
Pushing buffer 0
0:00:10.220695000       baseaudiosink
gstbaseaudiosink.c:339:gst_base_audio_sink_get_time:<alsasink0>
processed samples: raw 226800, delay 4402, real 222398, time
0:00:10.086077097
0:00:10.220762000            basesink
gstbasesink.c:2323:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:00:10.486349206, end: 0:00:10.486666666
0:00:10.220795000            basesink
gstbasesink.c:1244:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:00:10.486349206, stop: 0:00:10.486666666, do_sync 0
0:00:10.220827000            basesink
gstbasesink.c:1867:gst_base_sink_render_object:<alsasink0> rendering
buffer 0x9722bc0
0:00:10.220856000       baseaudiosink
gstbaseaudiosink.c:669:gst_base_audio_sink_render:<alsasink0> time
0:00:10.486349206, offset 231224, start 0:00:00.000000000, samples 7
0:00:10.220887000       baseaudiosink
gstbaseaudiosink.c:738:gst_base_audio_sink_render:<alsasink0> running:
start 0:00:10.486349206 - stop 0:00:10.486666666
0:00:10.220916000       baseaudiosink
gstbaseaudiosink.c:743:gst_base_audio_sink_render:<alsasink0>
base_time 0:00:00.000000000
0:00:10.220944000       baseaudiosink
gstbaseaudiosink.c:752:gst_base_audio_sink_render:<alsasink0>
compensating for latency 0:00:00.000000000
0:00:10.220973000       baseaudiosink
gstbaseaudiosink.c:808:gst_base_audio_sink_render:<alsasink0> after
latency: start 0:00:10.486349206 - stop 0:00:10.486666666
0:00:10.221001000       baseaudiosink
gstbaseaudiosink.c:848:gst_base_audio_sink_render:<alsasink0> align
with prev sample, 11 < 11025
0:00:10.221029000       baseaudiosink
gstbaseaudiosink.c:880:gst_base_audio_sink_render:<alsasink0>
rendering at 231212 7/7
0:00:10.221058000       baseaudiosink
gstbaseaudiosink.c:895:gst_base_audio_sink_render:<alsasink0> wrote 7
of 7
0:00:10.221086000       baseaudiosink
gstbaseaudiosink.c:911:gst_base_audio_sink_render:<alsasink0> next
sample expected at 231219
0:00:10.221114000            basesink
gstbasesink.c:1924:gst_base_sink_render_object:<alsasink0> object
unref after render 0x9722bc0
0:00:10.221185000             basesink
gstbasesink.c:2323:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:00:10.486666666, end: 0:00:10.489251700
0:00:10.221220000             basesink
gstbasesink.c:1244:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:00:10.486666666, stop: 0:00:10.489251700, do_sync 0
0:00:10.221253000             basesink
gstbasesink.c:1867:gst_base_sink_render_object:<alsasink0> rendering
buffer 0xb72eadb0
0:00:10.221315000        baseaudiosink
gstbaseaudiosink.c:669:gst_base_audio_sink_render:<alsasink0> time
0:00:10.486666666, offset 231231, start 0:00:00.000000000, samples 57
0:00:10.221347000        baseaudiosink
gstbaseaudiosink.c:738:gst_base_audio_sink_render:<alsasink0> running:
start 0:00:10.486666666 - stop 0:00:10.489251700
0:00:10.221376000        baseaudiosink
gstbaseaudiosink.c:743:gst_base_audio_sink_render:<alsasink0>
base_time 0:00:00.000000000
0:00:10.221404000        baseaudiosink
gstbaseaudiosink.c:752:gst_base_audio_sink_render:<alsasink0>
compensating for latency 0:00:00.000000000
0:00:10.221433000        baseaudiosink
gstbaseaudiosink.c:808:gst_base_audio_sink_render:<alsasink0> after
latency: start 0:00:10.486666666 - stop 0:00:10.489251700
0:00:10.221462000        baseaudiosink
gstbaseaudiosink.c:848:gst_base_audio_sink_render:<alsasink0> align
with prev sample, 11 < 11025
0:00:10.221490000        baseaudiosink
gstbaseaudiosink.c:880:gst_base_audio_sink_render:<alsasink0>
rendering at 231219 57/57
0:00:10.221519000        baseaudiosink
gstbaseaudiosink.c:895:gst_base_audio_sink_render:<alsasink0> wrote 57
of 57
0:00:10.221546000        baseaudiosink
gstbaseaudiosink.c:911:gst_base_audio_sink_render:<alsasink0> next
sample expected at 231276
0:00:10.221574000             basesink
gstbasesink.c:1924:gst_base_sink_render_object:<alsasink0> object
unref after render 0xb72eadb0
0:00:10.221634000            basesink
gstbasesink.c:2323:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:00:10.489251700, end: 0:00:10.489569160
0:00:10.221667000            basesink
gstbasesink.c:1244:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:00:10.489251700, stop: 0:00:10.489569160, do_sync 0
0:00:10.221697000            basesink
gstbasesink.c:1867:gst_base_sink_render_object:<alsasink0> rendering
buffer 0x9722c70
0:00:10.221726000       baseaudiosink
gstbaseaudiosink.c:669:gst_base_audio_sink_render:<alsasink0> time
0:00:10.489251700, offset 231288, start 0:00:00.000000000, samples 7
0:00:10.221756000       baseaudiosink
gstbaseaudiosink.c:738:gst_base_audio_sink_render:<alsasink0> running:
start 0:00:10.489251700 - stop 0:00:10.489569160
0:00:10.221784000       baseaudiosink
gstbaseaudiosink.c:743:gst_base_audio_sink_render:<alsasink0>
base_time 0:00:00.000000000
0:00:10.221812000       baseaudiosink
gstbaseaudiosink.c:752:gst_base_audio_sink_render:<alsasink0>
compensating for latency 0:00:00.000000000
0:00:10.221840000       baseaudiosink
gstbaseaudiosink.c:808:gst_base_audio_sink_render:<alsasink0> after
latency: start 0:00:10.489251700 - stop 0:00:10.489569160
0:00:10.221868000       baseaudiosink
gstbaseaudiosink.c:848:gst_base_audio_sink_render:<alsasink0> align
with prev sample, 11 < 11025
0:00:10.221895000       baseaudiosink
gstbaseaudiosink.c:880:gst_base_audio_sink_render:<alsasink0>
rendering at 231276 7/7
0:00:10.221924000       baseaudiosink
gstbaseaudiosink.c:895:gst_base_audio_sink_render:<alsasink0> wrote 7
of 7
0:00:10.221951000       baseaudiosink
gstbaseaudiosink.c:911:gst_base_audio_sink_render:<alsasink0> next
sample expected at 231283
0:00:10.221978000            basesink
gstbasesink.c:1924:gst_base_sink_render_object:<alsasink0> object
unref after render 0x9722c70
0:00:10.222038000             basesink
gstbasesink.c:2323:gst_base_sink_chain_unlocked:<alsasink0> got times
start: 0:00:10.489569160, end: 0:00:10.492154195
0:00:10.222093000             basesink
gstbasesink.c:1244:gst_base_sink_get_sync_times:<alsasink0> got times
start: 0:00:10.489569160, stop: 0:00:10.492154195, do_sync 0
0:00:10.222124000             basesink
gstbasesink.c:1867:gst_base_sink_render_object:<alsasink0> rendering
buffer 0xb72eae60
0:00:10.222152000        baseaudiosink
gstbaseaudiosink.c:669:gst_base_audio_sink_render:<alsasink0> time
0:00:10.489569160, offset 231295, start 0:00:00.000000000, samples 57
0:00:10.222182000        baseaudiosink
gstbaseaudiosink.c:738:gst_base_audio_sink_render:<alsasink0> running:
start 0:00:10.489569160 - stop 0:00:10.492154194
0:00:10.222211000        baseaudiosink
gstbaseaudiosink.c:743:gst_base_audio_sink_render:<alsasink0>
base_time 0:00:00.000000000
0:00:10.222239000        baseaudiosink
gstbaseaudiosink.c:752:gst_base_audio_sink_render:<alsasink0>
compensating for latency 0:00:00.000000000
0:00:10.222268000        baseaudiosink
gstbaseaudiosink.c:808:gst_base_audio_sink_render:<alsasink0> after
latency: start 0:00:10.489569160 - stop 0:00:10.492154194
0:00:10.222315000        baseaudiosink
gstbaseaudiosink.c:848:gst_base_audio_sink_render:<alsasink0> align
with prev sample, 11 < 11025
0:00:10.222367000        baseaudiosink
gstbaseaudiosink.c:880:gst_base_audio_sink_render:<alsasink0>
rendering at 231283 57/57
0:00:10.222412000        baseaudiosink
gstbaseaudiosink.c:895:gst_base_audio_sink_render:<alsasink0> wrote 57
of 57
0:00:10.222456000        baseaudiosink
gstbaseaudiosink.c:911:gst_base_audio_sink_render:<alsasink0> next
sample expected at 231340
0:00:10.222498000             basesink
gstbasesink.c:1924:gst_base_sink_render_object:<alsasink0> object
unref after render 0xb72eae60