[PATCH spice-server 13/28] red_channel: monitor connection latency using MSG_PING

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



---
 server/inputs_channel.c |   1 +
 server/main_channel.c   |   2 +-
 server/red_channel.c    | 228 ++++++++++++++++++++++++++++++++++++++++++++++++
 server/red_channel.h    |  18 ++++
 server/red_worker.c     |   2 +-
 server/smartcard.c      |   1 +
 server/spicevmc.c       |   1 +
 7 files changed, 251 insertions(+), 2 deletions(-)

diff --git a/server/inputs_channel.c b/server/inputs_channel.c
index 1a64e2d..09b6177 100644
--- a/server/inputs_channel.c
+++ b/server/inputs_channel.c
@@ -526,6 +526,7 @@ static void inputs_connect(RedChannel *channel, RedClient *client,
                                                           channel,
                                                           client,
                                                           stream,
+                                                          FALSE,
                                                           num_common_caps, common_caps,
                                                           num_caps, caps);
     if (!icc) {
diff --git a/server/main_channel.c b/server/main_channel.c
index 0fd5ab6..4fdd869 100644
--- a/server/main_channel.c
+++ b/server/main_channel.c
@@ -1088,7 +1088,7 @@ static MainChannelClient *main_channel_client_create(MainChannel *main_chan, Red
 {
     MainChannelClient *mcc = (MainChannelClient*)
                              red_channel_client_create(sizeof(MainChannelClient), &main_chan->base,
-                                                       client, stream, num_common_caps,
+                                                       client, stream, FALSE, num_common_caps,
                                                        common_caps, num_caps, caps);
     spice_assert(mcc != NULL);
     mcc->connection_id = connection_id;
diff --git a/server/red_channel.c b/server/red_channel.c
index b52f9e6..b1a6d57 100644
--- a/server/red_channel.c
+++ b/server/red_channel.c
@@ -29,6 +29,7 @@
 #include <fcntl.h>
 #include <unistd.h>
 #include <errno.h>
+#include <sys/ioctl.h>
 
 #include "common/generated_server_marshallers.h"
 #include "common/ring.h"
@@ -43,6 +44,20 @@ typedef struct EmptyMsgPipeItem {
     int msg;
 } EmptyMsgPipeItem;
 
+#define PING_TEST_TIMEOUT_MS 15000
+#define PING_TEST_IDLE_NET_TIMEOUT_MS 100
+
+enum QosPingState {
+    PING_STATE_NONE,
+    PING_STATE_TIMER,
+    PING_STATE_WARMUP,
+    PING_STATE_LATENCY,
+};
+
+static void red_channel_client_start_ping_timer(RedChannelClient *rcc, uint32_t timeout);
+static void red_channel_client_cancel_ping_timer(RedChannelClient *rcc);
+static void red_channel_client_restart_ping_timer(RedChannelClient *rcc);
+
 static void red_channel_client_event(int fd, int event, void *data);
 static void red_client_add_channel(RedClient *client, RedChannelClient *rcc);
 static void red_client_remove_channel(RedChannelClient *rcc);
@@ -481,6 +496,49 @@ static void red_channel_client_send_empty_msg(RedChannelClient *rcc, PipeItem *b
     red_channel_client_begin_send_message(rcc);
 }
 
+static void red_channel_client_send_ping(RedChannelClient *rcc)
+{
+    SpiceMsgPing ping;
+    struct timespec ts;
+
+    if (!rcc->latency_monitor.warmup_was_sent) { // latency test start
+        int delay_val;
+        socklen_t opt_size = sizeof(delay_val);
+
+        rcc->latency_monitor.warmup_was_sent = TRUE;
+        /*
+         * When testing latency, TCP_NODELAY must be switched on, otherwise,
+         * sending the ping message is delayed by Nagle algorithm, and the
+         * roundtrip measurment is less accurate (bigger).
+         */
+        rcc->latency_monitor.tcp_nodelay = 1;
+        if (getsockopt(rcc->stream->socket, IPPROTO_TCP, TCP_NODELAY, &delay_val,
+                       &opt_size) == -1) {
+            spice_warning("getsockopt failed, %s", strerror(errno));
+        }  else {
+            rcc->latency_monitor.tcp_nodelay = delay_val;
+            if (!delay_val) {
+                spice_debug("switching to TCP_NODELAY");
+                delay_val = 1;
+                if (setsockopt(rcc->stream->socket, IPPROTO_TCP, TCP_NODELAY, &delay_val,
+                               sizeof(delay_val)) == -1) {
+                   if (errno != ENOTSUP) {
+                        spice_warning("setsockopt failed, %s", strerror(errno));
+                    }
+                }
+            }
+        }
+    }
+
+    red_channel_client_init_send_data(rcc, SPICE_MSG_PING, NULL);
+    ping.id = rcc->latency_monitor.id;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    ping.timestamp = ts.tv_sec * 1000000000LL + ts.tv_nsec;
+    spice_marshall_msg_ping(rcc->send_data.marshaller, &ping);
+    spice_debug("time %lu", ping.timestamp);
+    red_channel_client_begin_send_message(rcc);
+}
+
 static void red_channel_client_send_item(RedChannelClient *rcc, PipeItem *item)
 {
     int handled = TRUE;
@@ -500,6 +558,10 @@ static void red_channel_client_send_item(RedChannelClient *rcc, PipeItem *item)
             red_channel_client_send_empty_msg(rcc, item);
             free(item);
             break;
+        case PIPE_ITEM_TYPE_PING:
+            red_channel_client_send_ping(rcc);
+            free(item);
+            break;
         default:
             handled = FALSE;
     }
@@ -549,7 +611,13 @@ static void red_channel_peer_on_out_msg_done(void *opaque)
         red_channel_client_restore_main_sender(rcc);
         spice_assert(rcc->send_data.header.data != NULL);
         red_channel_client_begin_send_message(rcc);
+    } else {
+        if (rcc->latency_monitor.timer && !rcc->send_data.blocked && rcc->pipe_size == 0) {
+            /* It is possible that the socket will become idle, so we may be able to test latency */
+            red_channel_client_restart_ping_timer(rcc);
+        }
     }
+
 }
 
 static void red_channel_client_pipe_remove(RedChannelClient *rcc, PipeItem *item)
@@ -636,8 +704,39 @@ static int red_channel_client_pre_create_validate(RedChannel *channel, RedClient
     return TRUE;
 }
 
+static void red_channel_client_push_ping(RedChannelClient *rcc)
+{
+    spice_debug(NULL);
+    spice_assert(rcc->latency_monitor.state == PING_STATE_NONE);
+    rcc->latency_monitor.state = PING_STATE_WARMUP;
+    rcc->latency_monitor.warmup_was_sent = FALSE;
+    rcc->latency_monitor.id = rand();
+    red_channel_client_pipe_add_type(rcc, PIPE_ITEM_TYPE_PING);
+    red_channel_client_pipe_add_type(rcc, PIPE_ITEM_TYPE_PING);
+}
+
+static void red_channel_client_ping_timer(void *opaque)
+{
+    int so_unsent_size = 0;
+    RedChannelClient *rcc = opaque;
+
+    spice_assert(rcc->latency_monitor.state == PING_STATE_TIMER);
+    red_channel_client_cancel_ping_timer(rcc);
+    /* retrieving the occupied size of the socket's tcp snd buffer (unacked + unsent) */
+    if (ioctl(rcc->stream->socket, TIOCOUTQ, &so_unsent_size) == -1) {
+        spice_printerr("ioctl(TIOCOUTQ) failed, %s", strerror(errno));
+    }
+    if (so_unsent_size > 0) {
+        spice_debug("tcp snd buffer is still occupied. rescheduling ping");
+        red_channel_client_start_ping_timer(rcc, PING_TEST_IDLE_NET_TIMEOUT_MS);
+    } else {
+        red_channel_client_push_ping(rcc);
+    }
+}
+
 RedChannelClient *red_channel_client_create(int size, RedChannel *channel, RedClient  *client,
                                             RedsStream *stream,
+                                            int monitor_latency,
                                             int num_common_caps, uint32_t *common_caps,
                                             int num_caps, uint32_t *caps)
 {
@@ -699,6 +798,14 @@ RedChannelClient *red_channel_client_create(int size, RedChannel *channel, RedCl
     red_client_add_channel(client, rcc);
     red_channel_ref(channel);
     pthread_mutex_unlock(&client->lock);
+
+    if (monitor_latency) {
+        rcc->latency_monitor.timer = channel->core->timer_add(
+            red_channel_client_ping_timer, rcc);
+        red_channel_client_start_ping_timer(rcc, PING_TEST_IDLE_NET_TIMEOUT_MS);
+        rcc->latency_monitor.roundtrip = -1;
+    }
+
     return rcc;
 error:
     free(rcc);
@@ -1106,6 +1213,14 @@ void red_channel_push(RedChannel *channel)
     }
 }
 
+int red_channel_client_get_roundtrip_ms(RedChannelClient *rcc)
+{
+    if (rcc->latency_monitor.roundtrip < 0) {
+        return rcc->latency_monitor.roundtrip;
+    }
+    return rcc->latency_monitor.roundtrip / 1000 / 1000;
+}
+
 static void red_channel_client_init_outgoing_messages_window(RedChannelClient *rcc)
 {
     rcc->ack_data.messages_window = 0;
@@ -1158,6 +1273,108 @@ static void red_channel_handle_migrate_data(RedChannelClient *rcc, uint32_t size
     red_channel_client_seamless_migration_done(rcc);
 }
 
+static void red_channel_client_restart_ping_timer(RedChannelClient *rcc)
+{
+    struct timespec ts;
+    uint64_t passed, timeout;
+
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+
+    passed = ts.tv_sec * 1000000000LL + ts.tv_nsec;
+    passed = passed - rcc->latency_monitor.last_pong_time;
+    passed /= 1000*1000;
+    timeout = PING_TEST_IDLE_NET_TIMEOUT_MS;
+    if (passed  < PING_TEST_TIMEOUT_MS) {
+        timeout += PING_TEST_TIMEOUT_MS - passed;
+    }
+
+    red_channel_client_start_ping_timer(rcc, timeout);
+}
+
+static void red_channel_client_start_ping_timer(RedChannelClient *rcc, uint32_t timeout)
+{
+    if (!rcc->latency_monitor.timer) {
+        return;
+    }
+    if (rcc->latency_monitor.state != PING_STATE_NONE) {
+        return;
+    }
+    rcc->latency_monitor.state = PING_STATE_TIMER;
+    rcc->channel->core->timer_start(rcc->latency_monitor.timer, timeout);
+}
+
+static void red_channel_client_cancel_ping_timer(RedChannelClient *rcc)
+{
+    if (!rcc->latency_monitor.timer) {
+        return;
+    }
+    if (rcc->latency_monitor.state != PING_STATE_TIMER) {
+        return;
+    }
+
+    rcc->channel->core->timer_cancel(rcc->latency_monitor.timer);
+    rcc->latency_monitor.state = PING_STATE_NONE;
+}
+
+static void red_channel_client_handle_pong(RedChannelClient *rcc, SpiceMsgPing *ping)
+{
+    uint64_t now;
+    struct timespec ts;
+
+    /* ignoring unexpected pongs, or post-migration pongs for pings that
+     * started just before migration */
+    if (ping->id != rcc->latency_monitor.id) {
+        spice_warning("ping-id (%u)!= pong-id %u",
+                      rcc->latency_monitor.id, ping->id);
+        return;
+    }
+
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    now =  ts.tv_sec * 1000000000LL + ts.tv_nsec;
+
+    spice_debug("now %lu", now);
+    if (rcc->latency_monitor.state == PING_STATE_WARMUP) {
+        rcc->latency_monitor.state = PING_STATE_LATENCY;
+        spice_debug("warmup roundtrip  %.2f (ms)", (now - ping->timestamp)/1000.0/1000.0);
+        return;
+    } else if (rcc->latency_monitor.state != PING_STATE_LATENCY) {
+        spice_warning("unexpected");
+        return;
+    }
+
+    /* set TCO_NODELAY=0, in case we reverted it for the test*/
+    if (!rcc->latency_monitor.tcp_nodelay) {
+        int delay_val = 0;
+
+        spice_debug("switching to back TCP_NODELAY=0");
+        if (setsockopt(rcc->stream->socket, IPPROTO_TCP, TCP_NODELAY, &delay_val,
+                       sizeof(delay_val)) == -1) {
+            if (errno != ENOTSUP) {
+                spice_warning("setsockopt failed, %s", strerror(errno));
+            }
+        }
+    }
+
+    /*
+     * The real network latency shouldn't change during the connection. However,
+     *  the measurements can be bigger than the real roundtrip due to other
+     *  threads or processes that are utilizing the network. We update the roundtrip
+     *  measurement with the minimal value we encountered till now.
+     */
+    if (rcc->latency_monitor.roundtrip < 0 ||
+        now - ping->timestamp < rcc->latency_monitor.roundtrip) {
+        rcc->latency_monitor.roundtrip = now - ping->timestamp;
+        spice_debug("roundtrip ms %.2f (ms)", rcc->latency_monitor.roundtrip/1000.0/1000.0);
+    } else {
+        spice_debug("not updating roundtrip. The latest latency measured was bigger (%.2f)",
+                    (now - ping->timestamp)/1000.0/1000.0);
+    }
+
+    rcc->latency_monitor.last_pong_time = now;
+    rcc->latency_monitor.state = PING_STATE_NONE;
+    red_channel_client_start_ping_timer(rcc, PING_TEST_TIMEOUT_MS);
+}
+
 int red_channel_client_handle_message(RedChannelClient *rcc, uint32_t size,
                                       uint16_t type, void *message)
 {
@@ -1188,6 +1405,9 @@ int red_channel_client_handle_message(RedChannelClient *rcc, uint32_t size,
     case SPICE_MSGC_MIGRATE_DATA:
         red_channel_handle_migrate_data(rcc, size, message);
         break;
+    case SPICE_MSGC_PONG:
+        red_channel_client_handle_pong(rcc, message);
+        break;
     default:
         spice_printerr("invalid message type %u", type);
         return FALSE;
@@ -1229,6 +1449,10 @@ void red_channel_client_begin_send_message(RedChannelClient *rcc)
         spice_printerr("BUG: header->type == 0");
         return;
     }
+
+    /* canceling the latency test timer till the nework is idle */
+    red_channel_client_cancel_ping_timer(rcc);
+
     spice_marshaller_flush(m);
     rcc->send_data.size = spice_marshaller_get_total_size(m);
     rcc->send_data.header.set_msg_size(&rcc->send_data.header,
@@ -1459,6 +1683,10 @@ void red_channel_client_disconnect(RedChannelClient *rcc)
     }
     reds_stream_free(rcc->stream);
     rcc->stream = NULL;
+    if (rcc->latency_monitor.timer) {
+        rcc->channel->core->timer_remove(rcc->latency_monitor.timer);
+        rcc->latency_monitor.timer = NULL;
+    }
     red_channel_remove_client(rcc);
     rcc->channel->channel_cbs.on_disconnect(rcc);
 }
diff --git a/server/red_channel.h b/server/red_channel.h
index 0bd4cb1..f770510 100644
--- a/server/red_channel.h
+++ b/server/red_channel.h
@@ -144,6 +144,7 @@ enum {
     PIPE_ITEM_TYPE_SET_ACK=1,
     PIPE_ITEM_TYPE_MIGRATE,
     PIPE_ITEM_TYPE_EMPTY_MSG,
+    PIPE_ITEM_TYPE_PING,
 
     PIPE_ITEM_TYPE_CHANNEL_BASE=101,
 };
@@ -222,6 +223,17 @@ typedef struct RedChannelCapabilities {
 
 int test_capabilty(uint32_t *caps, int num_caps, uint32_t cap);
 
+typedef struct RedChannelClientLatencyMonitor {
+    int state;
+    uint64_t last_pong_time;
+    SpiceTimer *timer;
+    uint32_t id;
+    int tcp_nodelay;
+    int warmup_was_sent;
+
+    int64_t roundtrip;
+} RedChannelClientLatencyMonitor;
+
 struct RedChannelClient {
     RingItem channel_link;
     RingItem client_link;
@@ -273,6 +285,8 @@ struct RedChannelClient {
 
     int wait_migrate_data;
     int wait_migrate_flush_mark;
+
+    RedChannelClientLatencyMonitor latency_monitor;
 };
 
 struct RedChannel {
@@ -343,6 +357,7 @@ void red_channel_set_data(RedChannel *channel, void *data);
 
 RedChannelClient *red_channel_client_create(int size, RedChannel *channel, RedClient *client,
                                             RedsStream *stream,
+                                            int monitor_latency,
                                             int num_common_caps, uint32_t *common_caps,
                                             int num_caps, uint32_t *caps);
 // TODO: tmp, for channels that don't use RedChannel yet (e.g., snd channel), but
@@ -417,6 +432,9 @@ void red_channel_client_begin_send_message(RedChannelClient *rcc);
  */
 SpiceMarshaller *red_channel_client_switch_to_urgent_sender(RedChannelClient *rcc);
 
+/* returns -1 if we don't have an estimation */
+int red_channel_client_get_roundtrip_ms(RedChannelClient *rcc);
+
 void red_channel_pipe_item_init(RedChannel *channel, PipeItem *item, int type);
 
 // TODO: add back the channel_pipe_add functionality - by adding reference counting
diff --git a/server/red_worker.c b/server/red_worker.c
index cb695fe..c992688 100644
--- a/server/red_worker.c
+++ b/server/red_worker.c
@@ -10089,7 +10089,7 @@ static CommonChannelClient *common_channel_client_create(int size,
 {
     MainChannelClient *mcc = red_client_get_main(client);
     RedChannelClient *rcc =
-        red_channel_client_create(size, &common->base, client, stream,
+        red_channel_client_create(size, &common->base, client, stream, FALSE,
                                   num_common_caps, common_caps, num_caps, caps);
     if (!rcc) {
         return NULL;
diff --git a/server/smartcard.c b/server/smartcard.c
index f1e6244..aad22aa 100644
--- a/server/smartcard.c
+++ b/server/smartcard.c
@@ -805,6 +805,7 @@ static void smartcard_connect_client(RedChannel *channel, RedClient *client,
                                                               channel,
                                                               client,
                                                               stream,
+                                                              FALSE,
                                                               num_common_caps, common_caps,
                                                               num_caps, caps);
 
diff --git a/server/spicevmc.c b/server/spicevmc.c
index aba2a5d..e10f183 100644
--- a/server/spicevmc.c
+++ b/server/spicevmc.c
@@ -474,6 +474,7 @@ static void spicevmc_connect(RedChannel *channel, RedClient *client,
     }
 
     rcc = red_channel_client_create(sizeof(RedChannelClient), channel, client, stream,
+                                    FALSE,
                                     num_common_caps, common_caps,
                                     num_caps, caps);
     if (!rcc) {
-- 
1.8.1

_______________________________________________
Spice-devel mailing list
Spice-devel@xxxxxxxxxxxxxxxxxxxxx
http://lists.freedesktop.org/mailman/listinfo/spice-devel


[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Security]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [ECOS]     [Asterisk Internet PBX]     [Linux API]     [Monitors]