[spice-gtk,v3,1/6] channel-display: Minimize the stream lag by ignoring the server one

Submitted by Frediano Ziglio on July 26, 2019, 9:52 a.m.

Details

Message ID 20190726095213.15655-2-fziglio@redhat.com
State New
Headers show
Series "Client-side video stream lag reduction" ( rev: 2 ) in Spice

Not browsing as part of any series.

Commit Message

Frediano Ziglio July 26, 2019, 9:52 a.m.
From: Francois Gouget <fgouget@codeweavers.com>

The client is in a better position than the server to pick the minimum
lag needed to compensate for frame arrival time jitter and ensure
smooth video playback.
To do so:
- It ignores the lag specified by the server through the mmtime clock
  adjustments (but this lag is still tracked for the stream reports).
- It performs its own frame mmtime conversion to the local monotonic
  clock spice_session_mmtime2client_time() since the server-controlled
  mmtime clock cannot be relied on. This conversion uses data from all
  streams but is global so all streams have a common time reference.
- spice_session_mmtime2client_time() also handles the mmtime clock
  changes caused by server migration.
- It tracks the margin between the converted time-to-display frame
  timestamp and the current time and adds a delay to ensure this margin
  remains positive.
- This delay introduces the video stream lag. It is continuously
  adjusted to either be as low as possible, or match the audio
  playback delay for proper lip sync.
- Delay adjustments are gradual, speeding up or slowing down video
  playback until the average margin matches the target lag.
- Changes in the average margin are tracked (see margin_spread) to
  avoid nudging the delay in response to minor random variations.

Signed-off-by: Francois Gouget <fgouget@codeweavers.com>
---
 src/channel-display-gst.c   |  20 ++--
 src/channel-display-mjpeg.c |  14 +--
 src/channel-display-priv.h  |  24 ++++-
 src/channel-display.c       | 180 ++++++++++++++++++++++++++++++++----
 src/spice-session-priv.h    |   1 +
 src/spice-session.c         |  46 +++++++++
 6 files changed, 247 insertions(+), 38 deletions(-)

Patch hide | download patch | download mbox

diff --git a/src/channel-display-gst.c b/src/channel-display-gst.c
index 6fccf621..7ad6009b 100644
--- a/src/channel-display-gst.c
+++ b/src/channel-display-gst.c
@@ -50,7 +50,7 @@  typedef struct SpiceGstDecoder {
 
     /* ---------- Decoding and display queues ---------- */
 
-    uint32_t last_mm_time;
+    uint32_t last_frame_time;
 
     GMutex queues_mutex;
     GQueue *decoding_queue;
@@ -297,8 +297,8 @@  static void schedule_frame(SpiceGstDecoder *decoder)
             break;
         }
 
-        if (spice_mmtime_diff(gstframe->encoded_frame->mm_time, now) >= 0) {
-            decoder->timer_id = g_timeout_add(gstframe->encoded_frame->mm_time - now,
+        if (spice_mmtime_diff(gstframe->encoded_frame->time, now) >= 0) {
+            decoder->timer_id = g_timeout_add(gstframe->encoded_frame->time - now,
                                               display_frame, decoder);
         } else if (decoder->display_frame && !decoder->pending_samples) {
             /* Still attempt to display the least out of date frame so the
@@ -307,8 +307,8 @@  static void schedule_frame(SpiceGstDecoder *decoder)
             decoder->timer_id = g_timeout_add(0, display_frame, decoder);
         } else {
             SPICE_DEBUG("%s: rendering too late by %u ms (ts: %u, mmtime: %u), dropping",
-                        __FUNCTION__, now - gstframe->encoded_frame->mm_time,
-                        gstframe->encoded_frame->mm_time, now);
+                        __FUNCTION__, now - gstframe->encoded_frame->time,
+                        gstframe->encoded_frame->time, now);
             stream_dropped_frame_on_playback(decoder->base.stream);
             decoder->display_frame = NULL;
             free_gst_frame(gstframe);
@@ -449,7 +449,7 @@  sink_event_probe(GstPad *pad, GstPadProbeInfo *info, gpointer data)
              *   or more frame intervals.
              */
             record(frames_stats,
-                   "frame mm_time %u size %u creation time %" PRId64
+                   "frame time %u size %u creation time %" PRId64
                    " decoded time %" PRId64 " queue %u before %u",
                    frame->mm_time, frame->size, frame->creation_time, duration,
                    decoder->decoding_queue->length, gstframe->queue_len);
@@ -689,13 +689,13 @@  static gboolean spice_gst_decoder_queue_frame(VideoDecoder *video_decoder,
         return TRUE;
     }
 
-    if (spice_mmtime_diff(frame->mm_time, decoder->last_mm_time) < 0) {
+    if (spice_mmtime_diff(frame->time, decoder->last_frame_time) < 0) {
         SPICE_DEBUG("new-frame-time < last-frame-time (%u < %u):"
                     " resetting stream",
-                    frame->mm_time, decoder->last_mm_time);
+                    frame->time, decoder->last_frame_time);
         /* Let GStreamer deal with the frame anyway */
     }
-    decoder->last_mm_time = frame->mm_time;
+    decoder->last_frame_time = frame->time;
 
     if (margin < 0 &&
         decoder->base.codec_type == SPICE_VIDEO_CODEC_TYPE_MJPEG) {
@@ -778,7 +778,7 @@  VideoDecoder* create_gstreamer_decoder(int codec_type, display_stream *stream)
         decoder->base.queue_frame = spice_gst_decoder_queue_frame;
         decoder->base.codec_type = codec_type;
         decoder->base.stream = stream;
-        decoder->last_mm_time = stream_get_time(stream);
+        decoder->last_frame_time = stream_get_time(stream);
         g_mutex_init(&decoder->queues_mutex);
         decoder->decoding_queue = g_queue_new();
 
diff --git a/src/channel-display-mjpeg.c b/src/channel-display-mjpeg.c
index 647d31b0..d3ab77c8 100644
--- a/src/channel-display-mjpeg.c
+++ b/src/channel-display-mjpeg.c
@@ -181,16 +181,16 @@  static void mjpeg_decoder_schedule(MJpegDecoder *decoder)
     decoder->cur_frame = NULL;
     do {
         if (frame) {
-            if (spice_mmtime_diff(time, frame->mm_time) <= 0) {
-                guint32 d = frame->mm_time - time;
+            if (spice_mmtime_diff(time, frame->time) <= 0) {
+                guint32 d = frame->time - time;
                 decoder->cur_frame = frame;
                 decoder->timer_id = g_timeout_add(d, mjpeg_decoder_decode_frame, decoder);
                 break;
             }
 
             SPICE_DEBUG("%s: rendering too late by %u ms (ts: %u, mmtime: %u), dropping ",
-                        __FUNCTION__, time - frame->mm_time,
-                        frame->mm_time, time);
+                        __FUNCTION__, time - frame->time,
+                        frame->time, time);
             stream_dropped_frame_on_playback(decoder->base.stream);
             spice_frame_free(frame);
         }
@@ -226,12 +226,12 @@  static gboolean mjpeg_decoder_queue_frame(VideoDecoder *video_decoder,
 
     last_frame = g_queue_peek_tail(decoder->msgq);
     if (last_frame) {
-        if (spice_mmtime_diff(frame->mm_time, last_frame->mm_time) < 0) {
+        if (spice_mmtime_diff(frame->time, last_frame->time) < 0) {
             /* This should really not happen */
             SPICE_DEBUG("new-frame-time < last-frame-time (%u < %u):"
                         " resetting stream",
-                        frame->mm_time,
-                        last_frame->mm_time);
+                        frame->time,
+                        last_frame->time);
             mjpeg_decoder_drop_queue(decoder);
         }
     }
diff --git a/src/channel-display-priv.h b/src/channel-display-priv.h
index 16c12c6e..a8994655 100644
--- a/src/channel-display-priv.h
+++ b/src/channel-display-priv.h
@@ -39,14 +39,18 @@  typedef struct display_stream display_stream;
 
 typedef struct SpiceFrame SpiceFrame;
 struct SpiceFrame {
-    uint32_t mm_time;
+    /* Display time. See stream_get_time(). */
+    uint32_t time;
+
     SpiceRect dest;
 
     uint8_t *data;
     uint32_t size;
     gpointer data_opaque;
 
-    /* stats */
+    /* For statistics and to correlate with the server logs for debugging. */
+    uint32_t mm_time;
+    /* To compute decoding time for statistics. */
     gint64 creation_time;
 };
 
@@ -124,6 +128,22 @@  struct display_stream {
 
     SpiceChannel                *channel;
 
+    uint32_t             last_frame_mm_time;
+    uint32_t             last_frame_time;
+
+    /* lag management (see display_handle_stream_data()) */
+    uint32_t             delay;
+    int32_t              min_margin;
+    float                avg_margin;
+    uint32_t             margin_spread;
+
+    /* margin evaluation */
+    uint32_t             margin_eval_start;
+    uint32_t             margin_eval_count;
+    int32_t              min_margin_next;
+    int32_t              min_avg_margin;
+    int32_t              max_avg_margin;
+
     /* stats */
     uint32_t             first_frame_mm_time;
     uint32_t             arrive_late_count;
diff --git a/src/channel-display.c b/src/channel-display.c
index 44555e3f..acc66dd1 100644
--- a/src/channel-display.c
+++ b/src/channel-display.c
@@ -21,6 +21,7 @@ 
 #include <sys/types.h>
 #endif
 #include <glib/gi18n-lib.h>
+#include <math.h> /* for ceilf() */
 
 #include "spice-client.h"
 #include "spice-common.h"
@@ -1429,8 +1430,7 @@  static uint32_t spice_msg_in_frame_data(SpiceMsgIn *frame_msg, uint8_t **data)
 G_GNUC_INTERNAL
 guint32 stream_get_time(display_stream *st)
 {
-    SpiceSession *session = spice_channel_get_session(st->channel);
-    return session ? spice_session_get_mm_time(session) : 0;
+    return g_get_monotonic_time() / 1000;
 }
 
 /* coroutine or main context */
@@ -1694,7 +1694,8 @@  static void display_stream_stats_save(display_stream *st,
 
 static SpiceFrame *spice_frame_new(display_stream *st,
                                    SpiceMsgIn *in,
-                                   guint32 frame_mmtime)
+                                   guint32 mm_time,
+                                   guint32 frame_time)
 {
     SpiceFrame *frame;
     guint8 *data_ptr;
@@ -1702,7 +1703,8 @@  static SpiceFrame *spice_frame_new(display_stream *st,
     guint32 data_size = spice_msg_in_frame_data(in, &data_ptr);
 
     frame = g_new(SpiceFrame, 1);
-    frame->mm_time = frame_mmtime;
+    frame->mm_time = mm_time;
+    frame->time = frame_time;
     frame->dest = *dest_rect;
     frame->data = data_ptr;
     frame->size = data_size;
@@ -1723,44 +1725,184 @@  void spice_frame_free(SpiceFrame *frame)
     g_free(frame);
 }
 
+/* Pick an initial value likely to cover the network jitter and not to cause
+ * a significant lag. The delay will be adjusted from there.
+ */
+#define INITIAL_DELAY 40
+
+/* Collect data on a long enough period to capture rare events, but short
+ * enough so that the algorithm is still responsive to changes.
+ */
+#define MARGIN_EVAL_TIME (1 * 1000)
+
+/* Make sure we have enough data points even if the framerate is very low. */
+#define MARGIN_EVAL_COUNT 20
+
 /* coroutine context */
 static void display_handle_stream_data(SpiceChannel *channel, SpiceMsgIn *in)
 {
+    SpiceSession *session = spice_channel_get_session(channel);
     SpiceDisplayChannelPrivate *c = SPICE_DISPLAY_CHANNEL(channel)->priv;
     SpiceStreamDataHeader *op = spice_msg_in_parsed(in);
     display_stream *st = get_stream_by_id(channel, op->id);
-    guint32 mmtime;
-    int32_t margin, margin_report;
+    guint32 current_mmtime, frame_interval;
+    guint32 stream_time, frame_time;
+    gint32 mmtime_margin, margin;
     SpiceFrame *frame;
 
     g_return_if_fail(st != NULL);
-    mmtime = stream_get_time(st);
+
+    current_mmtime = spice_session_get_mm_time(session);
 
     if (spice_msg_in_type(in) == SPICE_MSG_DISPLAY_STREAM_DATA_SIZED) {
         CHANNEL_DEBUG(channel, "stream %u contains sized data", op->id);
     }
 
+    frame_interval = 0;
+    mmtime_margin = 400; /* server's default mm_time offset */
     if (op->multi_media_time == 0) {
-        g_critical("Received frame with invalid 0 timestamp! perhaps wrong graphic driver?");
-        op->multi_media_time = mmtime + 100; /* workaround... */
-    }
+        g_critical("Received frame with invalid 0 timestamp! Perhaps wrong graphic driver?");
+        op->multi_media_time = current_mmtime; /* workaround... */
+        frame_interval = spice_mmtime_diff(op->multi_media_time, st->last_frame_mm_time);
+    } else if (st->last_frame_mm_time == 0) {
+        /* First frame so frame_interval is unknown */
+        mmtime_margin = spice_mmtime_diff(op->multi_media_time, current_mmtime);
+    } else if (spice_mmtime_diff(op->multi_media_time, st->last_frame_mm_time) < 0) {
+        /* This can happen when migrating from a server with a high mm_time
+         * (i.e. high uptime) to one with a low mm_time:
+         * - server A sends a frame with A_mm_time
+         * - client receives the frame and sets last_frame_mm_time = A_mm_time
+         * - server B sends a frame with B_mm_time
+         * - client receives server B's frame with B_mm_time << A_mm_time
+         * Also note that although server B would normally send an mm_time
+         * reset message, there is no guarantee it will be received before
+         * server B's first frame so it's not much help.
+         */
+        SPICE_DEBUG("%u got an out of order frame -%u", op->id,
+                    st->last_frame_mm_time - op->multi_media_time);
+        st->last_frame_mm_time = op->multi_media_time;
+    } else if (spice_mmtime_diff(op->multi_media_time, st->last_frame_mm_time) > 1000) {
+        /* Streams are supposed to send at least 1 frame per second.
+         * So it's more likely that we got migrated from a server with a low
+         * mm_time (i.e. low uptime) to one with a high mm_time. See the case
+         * above for details. In such a case simply reinitialize the stream.
+         */
+        SPICE_DEBUG("%u got an abnormally long mm_time frame interval %u", op->id,
+                    op->multi_media_time - st->last_frame_mm_time);
+        st->last_frame_time = 0;
+    } else {
+        mmtime_margin = spice_mmtime_diff(op->multi_media_time, current_mmtime);
+        frame_interval = spice_mmtime_diff(op->multi_media_time, st->last_frame_mm_time);
+    }
+    display_stream_stats_save(st, op->multi_media_time, current_mmtime);
+    st->last_frame_mm_time = op->multi_media_time;
+
+    /* Compute the local frame mmtime */
+    stream_time = stream_get_time(st);
+    frame_time = spice_session_mmtime2client_time(session, op->multi_media_time);
+    guint32 target_lag = spice_session_get_playback_latency(session);
+    if (st->last_frame_time == 0) {
+        margin = spice_mmtime_diff(frame_time, stream_time);
+        st->delay = MAX(target_lag - margin, INITIAL_DELAY);
+        frame_time += st->delay;
+        margin += st->delay;
+
+        st->margin_eval_start = stream_time;
+        st->margin_eval_count = 0;
+        st->min_margin = 0; /* Force wait before reducing the delay */
+        st->min_margin_next = margin;
+        st->avg_margin = margin;
+        st->max_avg_margin = st->min_avg_margin = margin;
+        st->margin_spread = st->delay;
+    } else {
+        frame_time = MAX(frame_time + st->delay,
+                         st->last_frame_time + (frame_interval + 3) / 4);
+        margin = spice_mmtime_diff(frame_time, stream_time);
+
+        /* Note that when using integers the moving average can stabilize up to
+         * weight/2-1 away from the true average (where weight=16 here) due
+         * to the rounding errors (e.g. consider 1 16 16...).
+         * So use a float for avg_margin.
+         */
+        st->avg_margin = (st->avg_margin * 15 + margin) / 16;
+        if (st->avg_margin < st->min_avg_margin) {
+            st->min_avg_margin = st->avg_margin;
+        } else if (st->avg_margin > st->max_avg_margin) {
+            st->max_avg_margin = ceilf(st->avg_margin);
+        }
+
+        if (margin < st->min_margin_next) {
+            st->min_margin_next = margin;
+            /* Take into account signs that the situation worsened without
+             * delay.
+             */
+            st->min_margin = MIN(st->min_margin, st->min_margin_next);
+        }
 
-    margin = margin_report = op->multi_media_time - mmtime;
-    if (margin > 0) {
-        SpiceSession *s = spice_channel_get_session(channel);
+        /* Only replace the current min_margin and margin_spread estimates once
+         * enough data has been collected for the *_next values, both in term
+         * of elapsed time and number of frames.
+         */
+        st->margin_eval_count++;
+        if (stream_time - st->margin_eval_start > MARGIN_EVAL_TIME &&
+            st->margin_eval_count >= MARGIN_EVAL_COUNT) {
+            st->min_margin = st->min_margin_next;
+
+            st->margin_eval_start = stream_time;
+            st->margin_eval_count = 1;
+            st->min_margin_next = margin;
+
+            st->margin_spread = (st->max_avg_margin - st->min_avg_margin + 1) / 2;
+            st->min_avg_margin = st->avg_margin;
+            st->max_avg_margin = ceilf(st->avg_margin);
+        }
 
-        if (st->surface->streaming_mode && !spice_session_is_playback_active(s)) {
-            CHANNEL_DEBUG(channel, "video margin: %d, set to 0 since there is no playback", margin);
-            margin = 0;
+        if (margin < 0) {
+            gint32 nudge = -margin;
+            margin += nudge;
+            st->delay += nudge;
+            frame_time = stream_time + (frame_interval + 3) / 4;
+
+            /* The delay nudge also impacts the margin history */
+            st->min_margin_next += nudge;
+            st->min_margin = margin;
+            st->avg_margin += nudge;
+            st->min_avg_margin += nudge;
+            st->max_avg_margin += nudge;
+        } else {
+            /* Try to match the target lag without making needless adjustments
+             * for minor offsets.
+             */
+            gint32 nudge = 0;
+            if (st->avg_margin + st->margin_spread < target_lag) {
+                nudge = MIN((frame_interval + 3) / 4,
+                            target_lag - st->avg_margin);
+            } else if (st->min_margin > 0 &&
+                       st->avg_margin  > target_lag + st->margin_spread) {
+                nudge = -MIN((frame_interval + 3) / 4,
+                             MIN(st->avg_margin - target_lag,
+                                 st->min_margin));
+            }
+            if (nudge) {
+                st->delay += nudge;
+                frame_time += nudge;
+
+                /* The delay nudge also impacts the margin history */
+                st->min_margin_next += nudge;
+                st->min_margin += nudge;
+                st->avg_margin += nudge;
+                st->min_avg_margin += nudge;
+                st->max_avg_margin += nudge;
+            }
         }
     }
-    display_stream_stats_save(st, op->multi_media_time, mmtime);
+    st->last_frame_time = frame_time;
 
     /* Let the video decoder queue the frames so it can optimize their
      * decoding and best decide if/when to drop them when they are late,
      * taking into account the impact on later frames.
      */
-    frame = spice_frame_new(st, in, op->multi_media_time);
+    frame = spice_frame_new(st, in, op->multi_media_time, frame_time);
     if (!st->video_decoder->queue_frame(st->video_decoder, frame, margin)) {
         destroy_stream(channel, op->id);
         report_invalid_stream(channel, op->id);
@@ -1769,7 +1911,7 @@  static void display_handle_stream_data(SpiceChannel *channel, SpiceMsgIn *in)
 
     if (c->enable_adaptive_streaming) {
         display_update_stream_report(SPICE_DISPLAY_CHANNEL(channel), op->id,
-                                     op->multi_media_time, margin_report);
+                                     op->multi_media_time, mmtime_margin);
         if (st->playback_sync_drops_seq_len >= STREAM_PLAYBACK_SYNC_DROP_SEQ_LEN_LIMIT) {
             spice_session_sync_playback_latency(spice_channel_get_session(channel));
             st->playback_sync_drops_seq_len = 0;
diff --git a/src/spice-session-priv.h b/src/spice-session-priv.h
index 6ece7e01..d88276f1 100644
--- a/src/spice-session-priv.h
+++ b/src/spice-session-priv.h
@@ -50,6 +50,7 @@  GSocketConnection* spice_session_channel_open_host(SpiceSession *session, SpiceC
 void spice_session_channel_new(SpiceSession *session, SpiceChannel *channel);
 void spice_session_channel_migrate(SpiceSession *session, SpiceChannel *channel);
 
+guint32 spice_session_mmtime2client_time(SpiceSession *session, guint32 src_time);
 void spice_session_set_mm_time(SpiceSession *session, guint32 time);
 guint32 spice_session_get_mm_time(SpiceSession *session);
 
diff --git a/src/spice-session.c b/src/spice-session.c
index 04ba124a..e6a96133 100644
--- a/src/spice-session.c
+++ b/src/spice-session.c
@@ -102,6 +102,7 @@  struct _SpiceSessionPrivate {
     guint             channels_destroying;
     gboolean          client_provided_sockets;
     guint64           mm_time_offset;
+    guint32           client_time_offset;
     SpiceSession      *migration;
     GList             *migration_left;
     SpiceSessionMigration migration_state;
@@ -129,6 +130,10 @@  struct _SpiceSessionPrivate {
     PhodavServer      *webdav;
 };
 
+/* Initialize the client_time_offset to an unlikely value.
+ * See spice_session_get_client_time().
+ */
+# define UNSET_CLIENT_TIME_OFFSET 0xd1ceca5e
 
 /**
  * SECTION:spice-session
@@ -292,6 +297,7 @@  static void spice_session_init(SpiceSession *session)
     SPICE_DEBUG("Supported channels: %s", channels);
     g_free(channels);
 
+    s->client_time_offset = UNSET_CLIENT_TIME_OFFSET;
     s->images = cache_image_new((GDestroyNotify)pixman_image_unref);
     s->glz_window = glz_decoder_window_new();
     update_proxy(session, NULL);
@@ -2385,6 +2391,46 @@  int spice_session_get_connection_id(SpiceSession *session)
     return s->connection_id;
 }
 
+G_GNUC_INTERNAL
+guint32 spice_session_mmtime2client_time(SpiceSession *session, guint32 mmtime)
+{
+    g_return_val_if_fail(SPICE_IS_SESSION(session), g_get_monotonic_time() / 1000);
+
+    SpiceSessionPrivate *s = session->priv;
+
+    guint32 now = g_get_monotonic_time() / 1000;
+    guint32 new_offset = now - mmtime;
+
+    if (s->client_time_offset == UNSET_CLIENT_TIME_OFFSET) {
+        /* Initialize the time offset.
+         * Note that UNSET_CLIENT_TIME_OFFSET can be any value including 0
+         * which is common on low-latency LANs. But an unlikely one helps when
+         * adding a trace in this codepath.
+         */
+        s->client_time_offset = new_offset;
+        return now;
+    }
+    if (new_offset < s->client_time_offset - 1000 ||
+        new_offset > s->client_time_offset + 1000) {
+        /* The change in offset was likely caused by a server migration.
+         * Reset the time offset.
+         */
+        s->client_time_offset = new_offset;
+        return now;
+    }
+    if (new_offset < s->client_time_offset) {
+        /* The previous message we used to compute the offset was probably
+         * delayed resulting in a too large offset. Eventually the offset
+         * should settle to the true clock offset plus the network latency,
+         * excluding the network jitter.
+         */
+        s->client_time_offset = new_offset;
+        return now;
+    }
+
+    return mmtime + s->client_time_offset;
+}
+
 G_GNUC_INTERNAL
 guint32 spice_session_get_mm_time(SpiceSession *session)
 {

Comments

Actually I found something I'm a bit unhappy with in this patch.

So one goal is to make sure all streams are in sync. This is why the 
mmtime conversion is performed globally: if two frames from different 
streams have the same mmtime, the resulting client-side timestamps 
should be identical too. That's only possible by applying the same 
offset to all streams, which is what spice_session_mmtime2client_time() 
does.

But then each stream applies its own delay to make sure it has enough 
margin to ensure a smooth playback. Thus, since the delays are different 
the frame playback may not be in sync across streams.

So I think the delay management should be handled globally too which I 
think should be quite doable. But I have been busy with other stuff so I 
did not get time to investigate and resubmit.