[Spice-devel] [PATCH spice-server 13/28] red_channel: monitor connection latency using MSG_PING
Yonit Halperin
yhalperi at redhat.com
Mon Apr 15 11:51:23 PDT 2013
On 04/14/2013 09:28 AM, Alon Levy wrote:
> 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?
Sending the time is not necessary. Just kept it in order to be
compatible with the way we used it so far.
>
> another note: should we drop the special case main channel ping later?
>
Maybe, or at least move it to use red_channel.
> 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.
>
I'm not sure I understand your comment.
In order to send the ping message immediately, TCP_NODELAY is set.
We save the old state in rcc->latency_monitor.tcp_nodelay, and revert
TCP_NODELAY in red_channel_client_handle_pong
>> + 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?
>
I don't know which os ported it. I know that Windows didn't.
>> + 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)
>
So I guess that in the future you can just reset the network statistics
when changing the network?
>> + * 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