1 files changed, 75 insertions, 0 deletions
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;
 }