[Spice-devel] [PATCH spice-gtk v5] channel-display: Instrument code to get frame and queue statistics

[Frediano Ziglio]

This patch is based on some work from Victor Toso (statistics) and
Snir Sheriber (GStreamer probing).
All GstBuffers are queued into decoding_queue and a probe is
attached to the sink in order to understand when the buffers
are decoded.
Previously we didn't add frames to decoding_queue in case of direct
rendering as there was nothing to dequeue them, now we need it to
compute the timing.
When a buffer is decoded the time spent and queue length are
computed.

Signed-off-by: Frediano Ziglio <fziglio at redhat.com>
---
 src/channel-display-gst.c  | 49 +++++++++++++++++++++++++++++++++-----
 src/channel-display-priv.h |  3 +++
 src/channel-display.c      |  1 +
 3 files changed, 47 insertions(+), 6 deletions(-)

Changes since v4:
- add creation time to log

diff --git a/src/channel-display-gst.c b/src/channel-display-gst.c
index 56bb611b..7d7b435d 100644
--- a/src/channel-display-gst.c
+++ b/src/channel-display-gst.c
@@ -247,6 +247,13 @@ static SpiceGstFrame *get_decoded_frame(SpiceGstDecoder *decoder, GstBuffer *buf
         if (num_frames_dropped != 0) {
             SPICE_DEBUG("the GStreamer pipeline dropped %u frames", num_frames_dropped);
         }
+
+        const SpiceFrame *frame = gstframe->encoded_frame;
+        int64_t duration = g_get_monotonic_time() - frame->creation_time;
+        SPICE_DEBUG("frame mm_time %u size %u creation time %" G_GINT64_FORMAT
+                    " decoded time %" G_GINT64_FORMAT " queue %u",
+                    frame->mm_time, frame->size, frame->creation_time,
+                    duration, decoder->decoding_queue->length);
     }
     return gstframe;
 }
@@ -389,6 +396,37 @@ static void app_source_setup(GstElement *pipeline G_GNUC_UNUSED,
     decoder->appsrc = GST_APP_SRC(gst_object_ref(source));
 }
 
+static GstPadProbeReturn
+sink_event_probe(GstPad *pad, GstPadProbeInfo *info, gpointer data)
+{
+    SpiceGstDecoder *decoder = (SpiceGstDecoder*)data;
+
+    if (info->type & GST_PAD_PROBE_TYPE_BUFFER) { // Buffer arrived
+        GstBuffer *buffer = GST_PAD_PROBE_INFO_BUFFER(info);
+        g_mutex_lock(&decoder->queues_mutex);
+        SpiceGstFrame *gstframe = get_decoded_frame(decoder, buffer);
+        if (gstframe) {
+            free_gst_frame(gstframe);
+        }
+        g_mutex_unlock(&decoder->queues_mutex);
+    }
+    return GST_PAD_PROBE_OK;
+}
+
+/* This function is called to used to set a probe on the sink */
+static void
+deep_element_added_cb(GstBin *pipeline, GstBin *bin, GstElement *element,
+                      SpiceGstDecoder *decoder)
+{
+    /* attach a probe to the sink in case we don't have appsink (that
+     * is the frames does not go to new_sample */
+    if (GST_IS_BASE_SINK(element) && decoder->appsink == NULL) {
+        GstPad *pad = gst_element_get_static_pad(element, "sink");
+        gst_pad_add_probe(pad, GST_PAD_PROBE_TYPE_BUFFER, sink_event_probe, decoder, NULL);
+        gst_object_unref(pad);
+    }
+}
+
 static gboolean create_pipeline(SpiceGstDecoder *decoder)
 {
     GstBus *bus;
@@ -450,6 +488,7 @@ static gboolean create_pipeline(SpiceGstDecoder *decoder)
 #endif
     }
 
+    g_signal_connect(playbin, "deep-element-added", G_CALLBACK(deep_element_added_cb), decoder);
     g_signal_connect(playbin, "source-setup", G_CALLBACK(app_source_setup), decoder);
 
     g_object_set(playbin,
@@ -629,12 +668,10 @@ static gboolean spice_gst_decoder_queue_frame(VideoDecoder *video_decoder,
     GST_BUFFER_DTS(buffer) = GST_CLOCK_TIME_NONE;
     GST_BUFFER_PTS(buffer) = pts;
 
-    if (decoder->appsink != NULL) {
-        SpiceGstFrame *gst_frame = create_gst_frame(buffer, frame);
-        g_mutex_lock(&decoder->queues_mutex);
-        g_queue_push_tail(decoder->decoding_queue, gst_frame);
-        g_mutex_unlock(&decoder->queues_mutex);
-    }
+    SpiceGstFrame *gst_frame = create_gst_frame(buffer, frame);
+    g_mutex_lock(&decoder->queues_mutex);
+    g_queue_push_tail(decoder->decoding_queue, gst_frame);
+    g_mutex_unlock(&decoder->queues_mutex);
 
     if (gst_app_src_push_buffer(decoder->appsrc, buffer) != GST_FLOW_OK) {
         SPICE_DEBUG("GStreamer error: unable to push frame");
diff --git a/src/channel-display-priv.h b/src/channel-display-priv.h
index c5c3f5c8..495df7ac 100644
--- a/src/channel-display-priv.h
+++ b/src/channel-display-priv.h
@@ -45,6 +45,9 @@ struct SpiceFrame {
     uint8_t *data;
     uint32_t size;
     gpointer data_opaque;
+
+    /* stats */
+    gint64 creation_time;
 };
 
 typedef struct VideoDecoder VideoDecoder;
diff --git a/src/channel-display.c b/src/channel-display.c
index ae2c4fbc..d46b3a37 100644
--- a/src/channel-display.c
+++ b/src/channel-display.c
@@ -1657,6 +1657,7 @@ static SpiceFrame *spice_frame_new(display_stream *st,
     frame->size = data_size;
     frame->data_opaque = in;
     spice_msg_in_ref(in);
+    frame->creation_time = g_get_monotonic_time();
     return frame;
 }
 
-- 
2.20.1