[Spice-devel] [PATCH spice-server 13/28] red_channel: monitor connection latency using MSG_PING
Alon Levy
alevy at redhat.com
Sun Apr 14 06:28:46 PDT 2013
On Tue, Feb 26, 2013 at 01:03:59PM -0500, Yonit Halperin wrote:
ACK.
just a note: maybe we should not send our time, but an id, to not leak
information?
another note: should we drop the special case main channel ping later?
other notes (all nitpick quality) below.
> ---
> 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) {
Does this update delay_val? if so, rcc->latency_monitor.tcp_nodelay
contains the old value here.
> + 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) {
Is this ioctl portable?
> + 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,
But it could, roaming. (future)
> + * 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 at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/spice-devel
More information about the Spice-devel
mailing list