[Spice-devel] [PATCH spice-gtk 1/8] channel-display: collect and print video stream stats
Yonit Halperin
yhalperi at redhat.com
Tue Feb 26 10:04:51 PST 2013
also prints the number of underflows during a spice-pulse audio playback
---
gtk/channel-display-priv.h | 17 ++++++++++++++++
gtk/channel-display.c | 50 ++++++++++++++++++++++++++++++++++++++++++++--
gtk/spice-pulse.c | 9 ++++++++-
3 files changed, 73 insertions(+), 3 deletions(-)
diff --git a/gtk/channel-display-priv.h b/gtk/channel-display-priv.h
index ff0f484..f57dc6e 100644
--- a/gtk/channel-display-priv.h
+++ b/gtk/channel-display-priv.h
@@ -50,6 +50,12 @@ typedef struct display_surface {
SpiceJpegDecoder *jpeg_decoder;
} display_surface;
+typedef struct drops_sequence_stats {
+ uint32_t len;
+ uint32_t start_mm_time;
+ uint32_t duration;
+} drops_sequence_stats;
+
typedef struct display_stream {
SpiceMsgIn *msg_create;
SpiceMsgIn *msg_clip;
@@ -71,6 +77,17 @@ typedef struct display_stream {
GQueue *msgq;
guint timeout;
SpiceChannel *channel;
+
+ /* stats */
+ uint32_t first_frame_mm_time;
+ uint32_t num_drops_on_arive;
+ uint64_t arrive_late_time;
+ uint32_t num_drops_on_playback;
+ uint32_t num_input_frames;
+ drops_sequence_stats cur_drops_seq_stats;
+ GArray *drops_seqs_stats_arr;
+ uint32_t num_drops_seqs;
+
} display_stream;
void stream_get_dimensions(display_stream *st, int *width, int *height);
diff --git a/gtk/channel-display.c b/gtk/channel-display.c
index c098ddb..ab4d3bd 100644
--- a/gtk/channel-display.c
+++ b/gtk/channel-display.c
@@ -1065,6 +1065,7 @@ static void display_handle_stream_create(SpiceChannel *channel, SpiceMsgIn *in)
st->surface = find_surface(c, op->surface_id);
st->msgq = g_queue_new();
st->channel = channel;
+ st->drops_seqs_stats_arr = g_array_new(FALSE, FALSE, sizeof(drops_sequence_stats));
region_init(&st->region);
display_update_stream_region(st);
@@ -1082,12 +1083,10 @@ static gboolean display_stream_schedule(display_stream *st)
guint32 time, d;
SpiceStreamDataHeader *op;
SpiceMsgIn *in;
-
if (st->timeout)
return TRUE;
time = spice_session_get_mm_time(spice_channel_get_session(st->channel));
-
in = g_queue_peek_head(st->msgq);
g_return_val_if_fail(in != NULL, TRUE);
@@ -1100,6 +1099,7 @@ static gboolean display_stream_schedule(display_stream *st)
} else {
in = g_queue_pop_head(st->msgq);
spice_msg_in_unref(in);
+ st->num_drops_on_playback++;
if (g_queue_get_length(st->msgq) == 0)
return TRUE;
}
@@ -1262,15 +1262,32 @@ static void display_handle_stream_data(SpiceChannel *channel, SpiceMsgIn *in)
op->multi_media_time = mmtime + 100; /* workaround... */
}
+ if (!st->num_input_frames) {
+ st->first_frame_mm_time = op->multi_media_time;
+ }
+ st->num_input_frames++;
if (op->multi_media_time < mmtime) {
CHANNEL_DEBUG(channel, "stream data too late by %u ms (ts: %u, mmtime: %u), dropin",
mmtime - op->multi_media_time, op->multi_media_time, mmtime);
+ st->arrive_late_time += mmtime - op->multi_media_time;
+ st->num_drops_on_arive++;
+ if (!st->cur_drops_seq_stats.len) {
+ st->cur_drops_seq_stats.start_mm_time = op->multi_media_time;
+ }
+ st->cur_drops_seq_stats.len++;
return;
}
spice_msg_in_ref(in);
g_queue_push_tail(st->msgq, in);
display_stream_schedule(st);
+ if (st->cur_drops_seq_stats.len) {
+ st->cur_drops_seq_stats.duration = op->multi_media_time -
+ st->cur_drops_seq_stats.start_mm_time;
+ g_array_append_val(st->drops_seqs_stats_arr, st->cur_drops_seq_stats);
+ memset(&st->cur_drops_seq_stats, 0, sizeof(st->cur_drops_seq_stats));
+ st->num_drops_seqs++;
+ }
}
/* coroutine context */
@@ -1304,6 +1321,8 @@ static void destroy_stream(SpiceChannel *channel, int id)
{
SpiceDisplayChannelPrivate *c = SPICE_DISPLAY_CHANNEL(channel)->priv;
display_stream *st;
+ uint64_t drops_duration_total = 0;
+ int i;
g_return_if_fail(c != NULL);
g_return_if_fail(c->streams != NULL);
@@ -1313,6 +1332,33 @@ static void destroy_stream(SpiceChannel *channel, int id)
if (!st)
return;
+ CHANNEL_DEBUG(channel, "%s: id %d #frames-in %d #drops-on-arive %d (%.2f) avg-late-time %.2f"
+ " #drops-on-playback %d (%.2f)", __FUNCTION__,
+ id,
+ st->num_input_frames,
+ st->num_drops_on_arive, st->num_drops_on_arive / ((double)st->num_input_frames),
+ st->num_drops_on_arive ? st->arrive_late_time / ((double)st->num_drops_on_arive): 0,
+ st->num_drops_on_playback,
+ st->num_drops_on_playback / ((double)st->num_input_frames));
+ if (st->num_drops_seqs) {
+ CHANNEL_DEBUG(channel, "%s: #drops sequences %u ==>", __FUNCTION__, st->num_drops_seqs);
+ }
+ for (i = 0; i < st->num_drops_seqs; i++) {
+ drops_sequence_stats *stats = &g_array_index(st->drops_seqs_stats_arr,
+ drops_sequence_stats,
+ i);
+ drops_duration_total += stats->duration;
+ CHANNEL_DEBUG(channel, "%s: \t len %u start-ms %u duration-ms %u", __FUNCTION__,
+ stats->len,
+ stats->start_mm_time - st->first_frame_mm_time,
+ stats->duration);
+ }
+ if (st->num_drops_seqs) {
+ CHANNEL_DEBUG(channel, "%s: drops total duration %lu ==>", __FUNCTION__, drops_duration_total);
+ }
+
+ g_array_free(st->drops_seqs_stats_arr, TRUE);
+
switch (st->codec) {
case SPICE_VIDEO_CODEC_TYPE_MJPEG:
stream_mjpeg_cleanup(st);
diff --git a/gtk/spice-pulse.c b/gtk/spice-pulse.c
index 6a977c4..295ea4f 100644
--- a/gtk/spice-pulse.c
+++ b/gtk/spice-pulse.c
@@ -34,6 +34,7 @@ struct stream {
pa_operation *uncork_op;
pa_operation *cork_op;
gboolean started;
+ guint num_underflow;
};
struct _SpicePulsePrivate {
@@ -251,8 +252,13 @@ static void stream_state_callback(pa_stream *s, void *userdata)
static void stream_underflow_cb(pa_stream *s, void *userdata)
{
+ SpicePulsePrivate *p;
+
SPICE_DEBUG("PA stream underflow!!");
+ p = SPICE_PULSE_GET_PRIVATE(userdata);
+ g_return_if_fail(p != NULL);
+ p->playback.num_underflow++;
#ifdef PULSE_ADJUST_LATENCY
const pa_buffer_attr *buffer_attr;
pa_buffer_attr new_buffer_attr;
@@ -310,6 +316,7 @@ static void playback_start(SpicePlaybackChannel *channel, gint format, gint chan
g_return_if_fail(p != NULL);
p->playback.started = TRUE;
+ p->playback.num_underflow = 0;
if (p->playback.stream &&
(p->playback.spec.rate != frequency ||
@@ -383,7 +390,7 @@ static void playback_stop(SpicePlaybackChannel *channel, gpointer data)
SpicePulse *pulse = data;
SpicePulsePrivate *p = pulse->priv;
- SPICE_DEBUG("%s", __FUNCTION__);
+ SPICE_DEBUG("%s: #underflow %u", __FUNCTION__, p->playback.num_underflow);
p->playback.started = FALSE;
if (!p->playback.stream)
--
1.8.1
More information about the Spice-devel
mailing list