[Spice-devel] [PATCH spice-server 13/28] red_channel: monitor connection latency using MSG_PING
Yonit Halperin
yhalperi at redhat.com
Tue Feb 26 10:03:59 PST 2013
---
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
More information about the Spice-devel
mailing list