Hi,
On 6/17/19 8:33 PM, Francois Gouget wrote:
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_get_client_time() since the server-controlled
mmtime clock cannot be relied on. This conversion uses data from all
streams but is global so all streams ihave a common time reference.
have (has?)
- This is also where mmtime clock changes caused by server migration
are handled.
- It tracks the margin between the converted time-to-display frame
timestamp and the curren 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.
It seems once margin increase it's not decrease.
(i tested with streaming agent after playing a video for several seconds
margin goes up and latency stays), do we want gradual changes when
it's full screen streaming?
Generally speaking it makes the code more complex and hard to
follow (maybe worth more comments and variables description)
how do you test it? does it improve significantly the smoothness of
video streams?
- 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 | 22 ++---
src/channel-display-mjpeg.c | 14 +--
src/channel-display-priv.h | 18 +++-
src/channel-display.c | 178 ++++++++++++++++++++++++++++++++----
src/spice-session-priv.h | 1 +
src/spice-session.c | 46 ++++++++++
6 files changed, 240 insertions(+), 39 deletions(-)
diff --git a/src/channel-display-gst.c b/src/channel-display-gst.c
index 6fccf621..673f4177 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,9 +449,9 @@ 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,
+ frame->time, frame->size, frame->creation_time, duration,
decoder->decoding_queue->length, gstframe->queue_len);
if (!decoder->appsink) {
@@ -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 495df7ac..badd9d42 100644
--- a/src/channel-display-priv.h
+++ b/src/channel-display-priv.h
@@ -39,7 +39,7 @@ typedef struct display_stream display_stream;
typedef struct SpiceFrame SpiceFrame;
struct SpiceFrame {
- uint32_t mm_time;
+ uint32_t time;
SpiceRect dest;
uint8_t *data;
@@ -124,8 +124,22 @@ struct display_stream {
SpiceChannel *channel;
- /* stats */
uint32_t first_frame_mm_time;
+ uint32_t last_frame_mm_time;
+ uint32_t last_frame_time;
+
+ /* Lag management (see display_handle_stream_data()) */
+ uint32_t delay;
+ uint32_t margin_eval_start;
+ uint32_t margin_eval_count;
+ int32_t min_margin;
+ int32_t min_margin_next;
+ float avg_margin;
+ int32_t min_avg_margin;
+ int32_t max_avg_margin;
+ uint32_t margin_spread;
+
+ /* stats */
uint32_t arrive_late_count;
uint64_t arrive_late_time;
uint32_t num_drops_on_playback;
diff --git a/src/channel-display.c b/src/channel-display.c
index b26326d6..815242de 100644
--- a/src/channel-display.c
+++ b/src/channel-display.c
@@ -20,6 +20,7 @@
#ifdef HAVE_SYS_TYPES_H
#include <sys/types.h>
#endif
+#include <math.h> /* for ceilf() */
#include "spice-client.h"
#include "spice-common.h"
@@ -1378,8 +1379,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 */
@@ -1643,7 +1643,7 @@ static void display_stream_stats_save(display_stream *st,
static SpiceFrame *spice_frame_new(display_stream *st,
SpiceMsgIn *in,
- guint32 frame_mmtime)
+ guint32 frame_time)
{
SpiceFrame *frame;
guint8 *data_ptr;
@@ -1651,7 +1651,7 @@ 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->time = frame_time;
frame->dest = *dest_rect;
frame->data = data_ptr;
frame->size = data_size;
@@ -1672,44 +1672,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 */
Seems a bit weird to adjust to fixed server value, but currently i guess
it's better than changing server side.
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 (op->multi_media_time < st->last_frame_mm_time) {
+ /* 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 (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_get_client_time(session, op->multi_media_time);
This is not very clear to me, it's called frame_time but in practice
this sets offset or return current local monotonic 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);
Why is that?
+ 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;
margin = 0 ?
+ 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 += 0;
+
+ /* 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, frame_time);
if (!st->video_decoder->queue_frame(st->video_decoder, frame, margin)) {
destroy_stream(channel, op->id);
report_invalid_stream(channel, op->id);
@@ -1718,7 +1858,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..794d86a7 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_get_client_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..4e5a7823 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;
+ gint64 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_get_client_time(SpiceSession *session, guint32 mmtime)
It seems naming does not fit to action, wouldn't be reasonable
to imply it sets the offset too (or to separate to 2 functions)? i
would expect get function to do nothing but getting a value
Snir.
+{
+ g_return_val_if_fail(SPICE_IS_SESSION(session), g_get_monotonic_time());
+
+ SpiceSessionPrivate *s = session->priv;
+
+ guint32 now = g_get_monotonic_time() / 1000;
+ gint64 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)
{
_______________________________________________
Spice-devel mailing list
Spice-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/spice-devel