From: Francois Gouget <fgouget@xxxxxxxxxxxxxxx>
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@xxxxxxxxxxxxxxx>
---
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(-)
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)
{
--
2.20.1
_______________________________________________
Spice-devel mailing list
Spice-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/spice-devel