stats: add statistics for queue times

4 files changed, 89 insertions, 2 deletions

diff --git a/server/display-channel.cpp b/server/display-channel.cpp
index 4bd0cf41..5c96be5c 100644
--- a/server/display-channel.cpp
+++ b/server/display-channel.cpp
@@ -78,11 +78,13 @@ void display_channel_compress_stats_reset(DisplayChannel *display)
 
 void display_channel_compress_stats_print(DisplayChannel *display)
 {
+    spice_return_if_fail(display);
+
+    queue_print_stats();
+
 #ifdef COMPRESS_STAT
     uint32_t id;
 
-    spice_return_if_fail(display);
-
     id = display->id();
 
     spice_info("==> Compression stats for display %u", id);
diff --git a/server/red-channel-client.cpp b/server/red-channel-client.cpp
index b7567ffb..3f8d64d1 100644
--- a/server/red-channel-client.cpp
+++ b/server/red-channel-client.cpp
@@ -489,8 +489,82 @@ void RedChannelClient::send_empty_msg(RedPipeItem *base)
     begin_send_message();
 }
 
+#ifdef QUEUE_STAT
+
+static const struct {
+    const char desc[8];
+    int64_t limit;
+} queues[] = {
+    { "<0.1ms", NSEC_PER_MILLISEC * 1 / 10 },
+    { "<0.2ms", NSEC_PER_MILLISEC * 2 / 10 },
+    { "<0.5ms", NSEC_PER_MILLISEC * 5 / 10 },
+    { "<1ms", NSEC_PER_MILLISEC * 1 },
+    { "<2ms", NSEC_PER_MILLISEC * 2 },
+    { "<5ms", NSEC_PER_MILLISEC * 5 },
+    { "<10ms", NSEC_PER_MILLISEC * 10 },
+    { "<20ms", NSEC_PER_MILLISEC * 20 },
+    { "<50ms", NSEC_PER_MILLISEC * 50 },
+    { ">50ms", INT64_MAX }
+};
+#define NUM_QUEUE G_N_ELEMENTS(queues)
+
+static uint64_t queue_counts[NUM_QUEUE];
+static uint64_t queue_total_count = 0;
+static uint64_t queue_total_time = 0;
+static uint64_t queue_min = UINT64_MAX, queue_max = 0;
+
+static inline void queue_pipe_init(RedPipeItem *item)
+{
+    item->time_added = spice_get_monotonic_time_ns();
+}
+
+static void queue_pipe_add(const RedPipeItem *item)
+{
+    spice_assert(item->time_added);
+
+    red_time_t time_ns = spice_get_monotonic_time_ns() - item->time_added;
+
+    queue_total_time += time_ns;
+    queue_total_count++;
+    if (queue_max < time_ns)
+        queue_max = time_ns;
+    if (queue_min > time_ns)
+        queue_min = time_ns;
+
+    int i;
+    for (i = 0; i < NUM_QUEUE; ++i)
+        if (time_ns < queues[i].limit || i == NUM_QUEUE-1) {
+            ++queue_counts[i];
+            break;
+        }
+}
+
+void queue_print_stats(void)
+{
+    const char *sep;
+    char distribution[256], *p = distribution;
+    int i;
+
+    for (i = 0, sep = ""; i < NUM_QUEUE; ++i, sep = ", ")
+        p += sprintf(p, "%s%s=%" PRIu64, sep, queues[i].desc, queue_counts[i]);
+
+#define TIME_FMT "%gms"
+#define TIME_CONV(n) ((double)(n)/NSEC_PER_MILLISEC)
+    spice_info("avg="TIME_FMT", max="TIME_FMT", min="TIME_FMT" (n=%"PRIu64") queue time distribution: %s",
+               TIME_CONV(queue_total_time / queue_total_count),
+               TIME_CONV(queue_max), TIME_CONV(queue_min),
+               queue_total_count,
+               distribution);
+}
+#else
+static inline void queue_pipe_add(const RedPipeItem *item) {}
+static inline void queue_pipe_init(RedPipeItem *item) {}
+#endif
+
 void RedChannelClient::send_any_item(RedPipeItem *item)
 {
+    queue_pipe_add(item);
+
     spice_assert(no_item_being_sent());
     priv->reset_send_data();
     switch (item->type) {
@@ -1381,6 +1455,7 @@ inline bool RedChannelClient::prepare_pipe_add(RedPipeItem *item)
     if (priv->pipe.empty()) {
         priv->watch_update_mask(SPICE_WATCH_EVENT_READ | SPICE_WATCH_EVENT_WRITE);
     }
+    queue_pipe_init(item);
     return true;
 }
 
diff --git a/server/red-channel.h b/server/red-channel.h
index 60fef188..c4fd8a1d 100644
--- a/server/red-channel.h
+++ b/server/red-channel.h
@@ -202,6 +202,12 @@ inline RedChannel::CreationFlags operator|(RedChannel::CreationFlags a, RedChann
 #define red_channel_message(...) red_channel_log_generic(g_message, __VA_ARGS__)
 #define red_channel_debug(...) red_channel_log_generic(g_debug, __VA_ARGS__)
 
+#ifdef QUEUE_STAT
+void queue_print_stats(void);
+#else
+static inline void queue_print_stats(void) {}
+#endif
+
 #include "pop-visibility.h"
 
 #endif /* RED_CHANNEL_H_ */
diff --git a/server/red-pipe-item.h b/server/red-pipe-item.h
index 10e5a12c..5ae77647 100644
--- a/server/red-pipe-item.h
+++ b/server/red-pipe-item.h
@@ -62,6 +62,10 @@ struct RedPipeItem: public red::shared_ptr_counted
     const int type;
 
     void add_to_marshaller(SpiceMarshaller *m, uint8_t *data, size_t size);
+
+#ifdef QUEUE_STAT
+    red_time_t time_added;
+#endif
 };
 
 typedef red::shared_ptr<RedPipeItem> RedPipeItemPtr;