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

[Frediano Ziglio]

> Hi,
> 
> On Wed, Jan 23, 2019 at 11:28:57AM +0000, Frediano Ziglio wrote:
> > 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.
> > 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  | 45 +++++++++++++++++++++++++++++++++-----
> >  src/channel-display-priv.h |  3 +++
> >  src/channel-display.c      |  1 +
> >  3 files changed, 43 insertions(+), 6 deletions(-)
> > 
> > Changes since v1:
> > - use G_GUINT64_FORMAT instead of PRIu64, SPICE_DEBUG is using GLib
> >   function which expects GNU formatting, it gives a warning compiling
> >   for Windows
> > 
> > diff --git a/src/channel-display-gst.c b/src/channel-display-gst.c
> > index 08c9f8fb..c15f94f2 100644
> > --- a/src/channel-display-gst.c
> > +++ b/src/channel-display-gst.c
> > @@ -248,6 +248,12 @@ 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);
> >      }
> > +    if (gstframe) {
> > +        const SpiceFrame *frame = gstframe->encoded_frame;
> > +        uint64_t duration = g_get_monotonic_time() - frame->creation_time;
> > +        SPICE_DEBUG("frame mm_time %u size %u decoded time %"
> > G_GUINT64_FORMAT " queue %u",
> > +                    frame->mm_time, frame->size, duration,
> > decoder->decoding_queue->length);

[1]

> > +    }
> >      return gstframe;
> >  }
> >  
> > @@ -391,6 +397,34 @@ static void app_source_setup(GstElement *pipeline
> > G_GNUC_UNUSED,
> >      gst_caps_unref(caps);
> >      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
> 
> C-style comments instead?
> 

C99 added "//" style comment, so unless you want C89 compatibility
the comment above IS C-style.
We use the new style in a lot of places for short comments.

> > +        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);
> > +        }

[2]

> > +        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
> > +add_elem_cb(GstBin * pipeline, GstBin * bin, GstElement * element,
> > SpiceGstDecoder *decoder)
> > +{
> > +    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);
> > +    }
> > +}
> >  #endif
> >  
> >  static gboolean create_pipeline(SpiceGstDecoder *decoder)
> > @@ -455,6 +489,7 @@ static gboolean create_pipeline(SpiceGstDecoder
> > *decoder)
> >  #endif
> >      }
> >  
> > +    g_signal_connect(playbin, "deep-element-added",
> > G_CALLBACK(add_elem_cb), decoder);
> >      g_signal_connect(playbin, "source-setup",
> >      G_CALLBACK(app_source_setup), decoder);
> >  
> >      g_object_set(playbin,
> > @@ -660,12 +695,10 @@ static gboolean
> > spice_gst_decoder_queue_frame(VideoDecoder *video_decoder,
> >      GST_BUFFER_DTS(buffer) = GST_CLOCK_TIME_NONE;
> >      GST_BUFFER_PTS(buffer) = gst_clock_get_time(decoder->clock) -
> >      gst_element_get_base_time(decoder->pipeline) + ((uint64_t)MAX(0,
> >      latency)) * 1000 * 1000;
> >  
> > -    if (decoder->appsink != NULL) {
> 
> From the commit log, I don't follow why this check can be removed
> 

Oh, we use the decoding_queue to match the input with the output and compute
the decoded time, see [1] and [2].

> > -        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);
> 
> Cheers,
> Victor
> 
> >  
> >      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;
> >  }
> >  

Frediano