latency queries

[Antoine Martin]

Hi,

We are using GStreamer 1.x for forwarding sound to and from the xpra
python client and server using pipelines like this one:
appsrc do-timestamp=1 name=src emit-signals=0 block=0 is-live=0 \
        stream-type=0 format=4 \
    ! gdpdepay ! opusdec ! audioconvert \
    ! audioresample ! volume name=volume volume=1.0 \
    ! queue name=queue min-threshold-time=0 max-size-buffers=0 \
    ! max-size-bytes=0 max-size-time=450000000 leaky=2 \
    ! pulsesink client-name=Xpra async=True qos=True sync=False
The producer runs a similar pipeline with an appsink at the end where we
capture the compressed buffers. The codec and muxer actually used are
negotiated.
This works very well and in order to figure out the latency of this
pipeline, we use the current level of the queue element as an approximation.

First question: this runs over the network and because of jitter, the
queue element tends to grow so we have heuristics that try to bring it
back down when the current queue level is relatively stable but high
compared to the expected jitter.
We do this by temporarily lowering the max-level, which causes some
buffers to leak, then re-raising it again to give it some headroom.
Is there a better way? (this runs over our own transport which is backed
by ssh, tcp, named pipes or even vsock - so no UDP yet)
The target use-case is media players (ie: youtube in a browser), so I
think that distorting the audio is not really a good option unless we
can keep it to a minimum. The current approach only causes a brief
cracking noise.

I would like to use the latency query to get a more accurate value, but
calling get_latency() on the pipeline object always returns
GST_CLOCK_TIME_NONE.
I don't think this would help, but I couldn't find any examples of
manually emitting this latency query using python code. (looks like this
should be done automatically anyway?)

What I've tried (different combinations of):
* is-live=1, which seems to be needed, otherwise you see:
gstaudiobasesink.c:498:gst_audio_base_sink_query:<pulsesink0> peer or we
are not live, don't care about latency
* passing the timestamps that we get from the buffers on the producer
and setting those on the buffers we inject in appsrc (which was causing
other problems before with the queue element - so we stopped doing that)
* running the sink with "sync=True" or "async=False" (I've read the docs
a number of times but I am still not 100% clear on what we should be using)

Any advice would be much appreciated.

Thanks
Antoine

PS:
output from GST_DEBUG=5 xpra attach |& grep -i latency
running with is-live=1, sync=True, async=False, do-timestamp=0 and
forwarding the buffer's timestamps to appsrc on Fedora 23:

0:00:00.114583871 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:2494:gst_bin_do_latency_func:<pipeline0> querying latency
0:00:00.114589455 18342 0x5653bd37fec0 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x5653bd53d230
latency
0:00:00.114600786 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:4107:gst_bin_query:<pipeline0> Sending query 0x5653bd53d230
(type latency) to sink children
0:00:00.114618145 18342 0x5653bd37fec0 DEBUG          audiobasesink
gstaudiobasesink.c:452:gst_audio_base_sink_query:<pulsesink0> latency query
0:00:00.114622312 18342 0x5653bd37fec0 DEBUG               basesink
gstbasesink.c:1120:gst_base_sink_query_latency:<pulsesink0> we are ready
for LATENCY query
0:00:00.114626679 18342 0x5653bd37fec0 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x5653bd53d190
latency
0:00:00.114631826 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<pulsesink0:sink> peer query
0x5653bd53d190 (latency)
0:00:00.114637785 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<queue:src> doing query 0x5653bd53d190 (latency)
0:00:00.114651020 18342 0x5653bd37fec0 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x5653bd53d280
latency
0:00:00.114656549 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<queue:sink> peer query 0x5653bd53d280
(latency)
0:00:00.114661422 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<volume:src> doing query 0x5653bd53d280
(latency)
0:00:00.114667032 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<volume:sink> peer query 0x5653bd53d280
(latency)
0:00:00.114672352 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<audioresample0:src> doing query
0x5653bd53d280 (latency)
0:00:00.114678018 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<audioresample0:sink> peer query
0x5653bd53d280 (latency)
0:00:00.114683449 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<audioconvert0:src> doing query
0x5653bd53d280 (latency)
0:00:00.114688519 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<audioconvert0:sink> peer query
0x5653bd53d280 (latency)
0:00:00.114693471 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<opusdec0:src> doing query 0x5653bd53d280
(latency)
0:00:00.114697636 18342 0x5653bd37fec0 DEBUG           audiodecoder
gstaudiodecoder.c:2942:gst_audio_decoder_src_query:<opusdec0:src>
received query latency query: 0x5653bd53d280, GstQueryLatency,
live=(boolean)false, min-latency=(guint64)0,
max-latency=(guint64)18446744073709551615;
0:00:00.114728082 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<opusdec0:sink> peer query
0x5653bd53d280 (latency)
0:00:00.114733741 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<gdpdepay0:src> doing query 0x5653bd53d280
(latency)
0:00:00.114746802 18342 0x5653bd37fec0 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x5653bd53e0f0
latency
0:00:00.114752171 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<gdpdepay0:sink> peer query
0x5653bd53e0f0 (latency)
0:00:00.114757307 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<src:src> doing query 0x5653bd53e0f0 (latency)
0:00:00.114763444 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<src:src> sent query 0x5653bd53e0f0
(latency), result 1
0:00:00.114770326 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3272:gst_pad_query_default:<gdpdepay0:src> not forwarding
0x5653bd53d280 (latency) query
0:00:00.114776448 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<gdpdepay0:src> sent query 0x5653bd53d280
(latency), result 1
0:00:00.114782298 18342 0x5653bd37fec0 DEBUG           audiodecoder
gstaudiodecoder.c:2909:gst_audio_decoder_src_query_default:<opusdec0>
Peer latency: live 1, min 0:00:00.000000000 max 0:00:00.000000000
0:00:00.114791023 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<opusdec0:src> sent query 0x5653bd53d280
(latency), result 1
0:00:00.114796742 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<audioconvert0:src> sent query
0x5653bd53d280 (latency), result 1
0:00:00.114802743 18342 0x5653bd37fec0 DEBUG          audioresample
gstaudioresample.c:1304:gst_audio_resample_query:<audioresample0> Peer
latency: min 0:00:00.000000000 max 0:00:00.000000000
0:00:00.114809781 18342 0x5653bd37fec0 DEBUG          audioresample
gstaudioresample.c:1314:gst_audio_resample_query:<audioresample0> Our
latency: 0:00:00.000000000
0:00:00.114814870 18342 0x5653bd37fec0 DEBUG          audioresample
gstaudioresample.c:1322:gst_audio_resample_query:<audioresample0>
Calculated total latency : min 0:00:00.000000000 max 0:00:00.000000000
0:00:00.114820969 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<audioresample0:src> sent query
0x5653bd53d280 (latency), result 1
0:00:00.114826432 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<volume:src> sent query 0x5653bd53d280
(latency), result 1
0:00:00.114832259 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3272:gst_pad_query_default:<queue:src> not forwarding
0x5653bd53d190 (latency) query
0:00:00.114836124 18342 0x5653bd37fec0 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<queue:src> sent query 0x5653bd53d190
(latency), result 1
0:00:00.114839728 18342 0x5653bd37fec0 DEBUG               basesink
gstbasesink.c:1162:gst_base_sink_query_latency:<pulsesink0> latency
query: live: 1, have_latency 1, upstream: 1, min 0:00:00.000000000, max
0:00:00.000000000
0:00:00.114846009 18342 0x5653bd37fec0 DEBUG          audiobasesink
gstaudiobasesink.c:469:gst_audio_base_sink_query:<pulsesink0> we are not
negotiated, can't report latency yet
0:00:00.114849633 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:3948:bin_query_latency_fold:<pulsesink0> failed query
0:00:00.114887793 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:3963:bin_query_latency_done:<pipeline0> latency min
0:00:00.000000000, max 99:99:99.999999999, live 0
0:00:00.114900121 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:2505:gst_bin_do_latency_func:<pipeline0> got min latency
0:00:00.000000000, max latency 99:99:99.999999999, live 0
0:00:00.114907461 18342 0x5653bd37fec0 INFO               GST_EVENT
gstevent.c:1245:gst_event_new_latency: creating latency event
0:00:00.000000000
0:00:00.114913348 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstevent.c:302:gst_event_new_custom: creating new event 0x5653bd52b340
latency 56321
0:00:00.114918057 18342 0x5653bd37fec0 DEBUG       GST_ELEMENT_PADS
gstelement.c:1562:gst_element_send_event: send latency event on element
pipeline0
0:00:00.114922315 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:2891:gst_bin_send_event:<pipeline0> Sending latency event to
sink children
0:00:00.114932071 18342 0x5653bd37fec0 DEBUG       GST_ELEMENT_PADS
gstelement.c:1562:gst_element_send_event: send latency event on element
pulsesink0
0:00:00.114937174 18342 0x5653bd37fec0 DEBUG               basesink
gstbasesink.c:4447:gst_base_sink_send_event:<pulsesink0> handling event
0x5653bd52b340 latency event: 0x5653bd52b340, time 99:99:99.999999999,
seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.114946047 18342 0x5653bd37fec0 DEBUG               basesink
gstbasesink.c:4464:gst_base_sink_send_event:<pulsesink0> latency set to
0:00:00.000000000
0:00:00.114949719 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<queue:src> have event type
latency event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.114966727 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<volume:src> have event type
latency event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.114972767 18342 0x5653bd37fec0 DEBUG          basetransform
gstbasetransform.c:1989:gst_base_transform_src_eventfunc:<volume>
handling event 0x5653bd52b340 latency event: 0x5653bd52b340, time
99:99:99.999999999, seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.114977691 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<audioresample0:src> have
event type latency event: 0x5653bd52b340, time 99:99:99.999999999,
seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.114983733 18342 0x5653bd37fec0 DEBUG          basetransform
gstbasetransform.c:1989:gst_base_transform_src_eventfunc:<audioresample0> handling
event 0x5653bd52b340 latency event: 0x5653bd52b340, time
99:99:99.999999999, seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.114990457 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<audioconvert0:src> have
event type latency event: 0x5653bd52b340, time 99:99:99.999999999,
seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.114997137 18342 0x5653bd37fec0 DEBUG          basetransform
gstbasetransform.c:1989:gst_base_transform_src_eventfunc:<audioconvert0>
handling event 0x5653bd52b340 latency event: 0x5653bd52b340, time
99:99:99.999999999, seq-num 49, GstEventLatency, latency=(guint64)0;
0:00:00.115002642 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<opusdec0:src> have event
type latency event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.115006866 18342 0x5653bd37fec0 DEBUG           audiodecoder
gstaudiodecoder.c:2531:gst_audio_decoder_src_event:<opusdec0> received
event 56321, latency
0:00:00.115016091 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<gdpdepay0:src> have event
type latency event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.115023363 18342 0x5653bd37fec0 DEBUG              GST_EVENT
gstpad.c:5401:gst_pad_send_event_unchecked:<src:src> have event type
latency event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.115029756 18342 0x5653bd37fec0 DEBUG                basesrc
gstbasesrc.c:1982:gst_base_src_default_event:<src> handle event latency
event: 0x5653bd52b340, time 99:99:99.999999999, seq-num 49,
GstEventLatency, latency=(guint64)0;
0:00:00.115069503 18342 0x5653bd37fec0 DEBUG               basesink
gstbasesink.c:4494:gst_base_sink_send_event:<pulsesink0> handled event
0x5653bd52b340 latency event: 0x5653bd52b340, time 99:99:99.999999999,
seq-num 49, GstEventLatency, latency=(guint64)0;: 1
0:00:00.115106164 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:2931:gst_bin_send_event:<pipeline0> Sending latency event to
src pads
0:00:00.115110976 18342 0x5653bd37fec0 INFO                     bin
gstbin.c:2520:gst_bin_do_latency_func:<pipeline0> configured latency of
0:00:00.000000000
0:00:00.115122918 18342 0x5653bd37fec0 DEBUG                    bin
gstbin.c:2477:gst_bin_recalculate_latency:<pipeline0> latency returned 1
2016-04-05 11:22:24,597 sound output latency=18446744073709551615
0:00:00.390115742 18342 0x5653bd53d140 DEBUG                basesrc
gstbasesrc.c:2198:gst_base_src_do_sync:<src> no latency needed, live 1,
sync 0
0:00:00.395602861 18342 0x5653bd53d140 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.395609632 18342 0x5653bd53d140 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: -1
0:00:00.395961338 18342 0x5653bd53d140 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.395968259 18342 0x5653bd53d140 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: -1
0:00:00.396351921 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.396361073 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: -1
0:00:00.396602983 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.396607848 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: -1
0:00:00.396617192 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.396623362 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: -1
0:00:00.397482243 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:177:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency time: 10000 usec
0:00:00.397486331 18342 0x5653bd53d0f0 DEBUG             ringbuffer
gstaudioringbuffer.c:179:gst_audio_ring_buffer_debug_spec_buff: acquire
ringbuffer: latency segments: 11
0:00:00.398111291 18342 0x5653bd53d140 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x7fdd10002d90
latency
0:00:00.398119639 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<opusdec0:sink> peer query
0x7fdd10002d90 (latency)
0:00:00.398127146 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<gdpdepay0:src> doing query 0x7fdd10002d90
(latency)
0:00:00.398144370 18342 0x5653bd53d140 DEBUG                  query
gstquery.c:674:gst_query_new_custom: creating new query 0x7fdd100028f0
latency
0:00:00.398150933 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3940:gst_pad_peer_query:<gdpdepay0:sink> peer query
0x7fdd100028f0 (latency)
0:00:00.398155029 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3815:gst_pad_query:<src:src> doing query 0x7fdd100028f0 (latency)
0:00:00.398163443 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<src:src> sent query 0x7fdd100028f0
(latency), result 1
0:00:00.398168060 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3272:gst_pad_query_default:<gdpdepay0:src> not forwarding
0x7fdd10002d90 (latency) query
0:00:00.398174458 18342 0x5653bd53d140 DEBUG               GST_PADS
gstpad.c:3837:gst_pad_query:<gdpdepay0:src> sent query 0x7fdd10002d90
(latency), result 1
0:00:00.398487034 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1621:gst_audio_base_sink_sync_latency:<pulsesink0>
checking preroll
0:00:00.398492147 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1642:gst_audio_base_sink_sync_latency:<pulsesink0>
possibly waiting for clock to reach 0:00:00.000000000
0:00:00.398536428 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1649:gst_audio_base_sink_sync_latency:<pulsesink0>
clock returned 1 0:00:00.284058835
0:00:00.398545850 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1663:gst_audio_base_sink_sync_latency:<pulsesink0>
latency synced
0:00:00.398563665 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1679:gst_audio_base_sink_sync_latency:<pulsesink0>
late preroll, adding jitter
0:00:00.398609341 18342 0x5653bd53d0f0 DEBUG          audiobasesink
gstaudiobasesink.c:1688:gst_audio_base_sink_sync_latency:<pulsesink0>
internal time: 0:00:00.000000000 external time: 10:30:41.203811636
2016-04-05 11:22:24,871 sound output latency=18446744073709551615
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel