From b3a038b94ec2a616cf1614606c906398296603a7 Mon Sep 17 00:00:00 2001 From: Eric Dumazet Date: Thu, 8 Mar 2018 16:11:35 -0800 Subject: [PATCH 1/3] packetdrill: implement relative time tolerance packetdrill tries to accommodate difference between expected time and observed time using a (configurable) maximum value of the difference. Add a percentage based tolerance, which is helpful for long running tests. Default of 0.5 % means that 5ms of drift per second is allowed. If one event happens 10 seconds after the last one, the tolerance would be 50 ms. Can be changed with --tolerance_percent= --- gtests/net/packetdrill/config.c | 11 ++++++++++- gtests/net/packetdrill/config.h | 4 +++- gtests/net/packetdrill/run.c | 17 ++++++++++++++--- gtests/net/packetdrill/run.h | 3 ++- gtests/net/packetdrill/run_packet.c | 22 ++++++++++++++++++---- gtests/net/packetdrill/run_system_call.c | 1 + 6 files changed, 48 insertions(+), 10 deletions(-) diff --git a/gtests/net/packetdrill/config.c b/gtests/net/packetdrill/config.c index 37e2eb08..435b168b 100644 --- a/gtests/net/packetdrill/config.c +++ b/gtests/net/packetdrill/config.c @@ -50,6 +50,7 @@ enum option_codes { OPT_MTU, OPT_INIT_SCRIPTS, OPT_TOLERANCE_USECS, + OPT_TOLERANCE_PERCENT, OPT_WIRE_CLIENT, OPT_WIRE_SERVER, OPT_WIRE_SERVER_IP, @@ -86,6 +87,7 @@ struct option options[] = { { "mtu", .has_arg = true, NULL, OPT_MTU }, { "init_scripts", .has_arg = true, NULL, OPT_INIT_SCRIPTS }, { "tolerance_usecs", .has_arg = true, NULL, OPT_TOLERANCE_USECS }, + { "tolerance_percent", .has_arg = true, NULL, OPT_TOLERANCE_PERCENT }, { "wire_client", .has_arg = false, NULL, OPT_WIRE_CLIENT }, { "wire_server", .has_arg = false, NULL, OPT_WIRE_SERVER }, { "wire_server_ip", .has_arg = true, NULL, OPT_WIRE_SERVER_IP }, @@ -124,6 +126,7 @@ void show_usage(void) "\t[--mss=\n" "\t[--mtu=\n" "\t[--tolerance_usecs=tolerance_usecs]\n" + "\t[--tolerance_percent=percentage]\n" "\t[--tcp_ts_ecr_scaled]\n" "\t[--tcp_ts_tick_usecs=]\n" "\t[--strict_segments]\n" @@ -224,6 +227,7 @@ void set_default_config(struct config *config) config->ip_version = IP_VERSION_4; config->live_bind_port = 8080; config->live_connect_port = 8080; + config->tolerance_percent = 0.5; /* 5ms / second */ config->tolerance_usecs = 4000; config->speed = TUN_DRIVER_SPEED_CUR; config->mtu = TUN_DRIVER_DEFAULT_MTU; @@ -448,10 +452,15 @@ static void process_option(int opt, char *optarg, struct config *config, config->speed = speed; break; case OPT_TOLERANCE_USECS: - config->tolerance_usecs = atoi(optarg); + config->tolerance_usecs = atol(optarg); if (config->tolerance_usecs <= 0) die("%s: bad --tolerance_usecs: %s\n", where, optarg); break; + case OPT_TOLERANCE_PERCENT: + config->tolerance_percent = atof(optarg); + if (config->tolerance_percent < 0.0 || config->tolerance_percent > 100.0) + die("%s: bad --tolerance_percent: %s\n", where, optarg); + break; case OPT_TCP_TS_ECR_SCALED: config->tcp_ts_ecr_scaled = true; break; diff --git a/gtests/net/packetdrill/config.h b/gtests/net/packetdrill/config.h index 649a8c4f..4a66f72a 100644 --- a/gtests/net/packetdrill/config.h +++ b/gtests/net/packetdrill/config.h @@ -113,7 +113,9 @@ struct config { int live_prefix_len; /* IPv4/IPv6 interface prefix len */ - int tolerance_usecs; /* tolerance for time divergence */ + long tolerance_usecs; /* tolerance for time divergence */ + double tolerance_percent; /* tolerance for time divergence in percent */ + bool tcp_ts_ecr_scaled; /* scale arbitrary inbound TS ECR? */ int tcp_ts_tick_usecs; /* microseconds per TS val tick */ diff --git a/gtests/net/packetdrill/run.c b/gtests/net/packetdrill/run.c index 37ec449e..984c447a 100644 --- a/gtests/net/packetdrill/run.c +++ b/gtests/net/packetdrill/run.c @@ -174,13 +174,14 @@ s64 now_usecs(struct state *state) */ int verify_time(struct state *state, enum event_time_t time_type, s64 script_usecs, s64 script_usecs_end, - s64 live_usecs, const char *description, char **error) + s64 live_usecs, struct event *last_event, + const char *description, char **error) { s64 expected_usecs = script_usecs - state->script_start_time_usecs; s64 expected_usecs_end = script_usecs_end - state->script_start_time_usecs; s64 actual_usecs = live_usecs - state->live_start_time_usecs; - int tolerance_usecs = state->config->tolerance_usecs; + long tolerance_usecs = state->config->tolerance_usecs; DEBUGP("expected: %.3f actual: %.3f (secs)\n", usecs_to_secs(script_usecs), usecs_to_secs(actual_usecs)); @@ -188,6 +189,14 @@ int verify_time(struct state *state, enum event_time_t time_type, if (time_type == ANY_TIME) return STATUS_OK; + if (last_event) { + s64 delta = script_usecs - last_event->time_usecs; + long dynamic_tolerance; + + dynamic_tolerance = (state->config->tolerance_percent / 100.0) * delta; + if (dynamic_tolerance > tolerance_usecs) + tolerance_usecs = dynamic_tolerance; + } if (time_type == ABSOLUTE_RANGE_TIME || time_type == RELATIVE_RANGE_TIME) { DEBUGP("expected_usecs_end %.3f\n", @@ -280,7 +289,9 @@ void check_event_time(struct state *state, s64 live_usecs) if (verify_time(state, state->event->time_type, state->event->time_usecs, - state->event->time_usecs_end, live_usecs, + state->event->time_usecs_end, + live_usecs, + state->last_event, description, &error)) { die("%s:%d: %s\n", state->config->script_path, diff --git a/gtests/net/packetdrill/run.h b/gtests/net/packetdrill/run.h index da564547..3f619091 100644 --- a/gtests/net/packetdrill/run.h +++ b/gtests/net/packetdrill/run.h @@ -167,7 +167,8 @@ static inline s64 live_time_to_script_time_usecs(struct state *state, */ extern int verify_time(struct state *state, enum event_time_t time_type, s64 script_usecs, s64 script_usecs_end, - s64 live_usecs, const char *description, char **error); + s64 live_usecs, struct event *last_event, + const char *description, char **error); extern void check_event_time(struct state *state, s64 live_usecs); /* Set the start (and end time, if applicable) for the event if it diff --git a/gtests/net/packetdrill/run_packet.c b/gtests/net/packetdrill/run_packet.c index 6d992328..07419d67 100644 --- a/gtests/net/packetdrill/run_packet.c +++ b/gtests/net/packetdrill/run_packet.c @@ -1214,18 +1214,31 @@ static int verify_outbound_live_ipv6_flowlabel( } static int verify_outbound_tcp_option( - struct config *config, + struct state *state, struct packet *actual_packet, struct packet *script_packet, struct tcp_option *actual_option, struct tcp_option *script_option, char **error) { + struct config *config = state->config; u32 script_ts_val, actual_ts_val; int ts_val_tick_usecs; long tolerance_usecs; + double dynamic_tolerance; + s64 delta; tolerance_usecs = config->tolerance_usecs; + /* Note that for TCP TS, we do not want to compute the tolerance based + * on last event (as we do in verify_time()) + * last event might have happened few ms in the past. + * What matters here is the cumulative time (from the beginning of the test) + */ + delta = state->event->time_usecs - state->script_start_time_usecs; + + dynamic_tolerance = (config->tolerance_percent / 100.0) * delta; + if (dynamic_tolerance > tolerance_usecs) + tolerance_usecs = dynamic_tolerance; switch (actual_option->kind) { case TCPOPT_EOL: @@ -1270,7 +1283,7 @@ static int verify_outbound_tcp_option( /* Verify that the TCP option values matched expected values. */ static int verify_outbound_live_tcp_options( - struct config *config, + struct state *state, struct packet *actual_packet, struct packet *script_packet, char **error) { @@ -1293,7 +1306,7 @@ static int verify_outbound_live_tcp_options( return STATUS_ERR; } - if (verify_outbound_tcp_option(config, actual_packet, + if (verify_outbound_tcp_option(state, actual_packet, script_packet, a_opt, s_opt, error) != STATUS_OK) { return STATUS_ERR; @@ -1376,7 +1389,7 @@ static int verify_outbound_live_packet( if (script_packet->tcp) { /* Verify TCP options matched expected values. */ if (verify_outbound_live_tcp_options( - state->config, actual_packet, script_packet, + state, actual_packet, script_packet, error)) { non_fatal = true; goto out; @@ -1398,6 +1411,7 @@ static int verify_outbound_live_packet( DEBUGP("packet time_usecs: %lld\n", live_packet->time_usecs); if (verify_time(state, time_type, script_usecs, script_usecs_end, live_packet->time_usecs, + state->last_event, "outbound packet", error)) { non_fatal = true; goto out; diff --git a/gtests/net/packetdrill/run_system_call.c b/gtests/net/packetdrill/run_system_call.c index 7070fe56..333f7a57 100644 --- a/gtests/net/packetdrill/run_system_call.c +++ b/gtests/net/packetdrill/run_system_call.c @@ -3517,6 +3517,7 @@ static void *system_call_thread(void *arg) event->time_type, syscall->end_usecs, 0, state->syscalls->live_end_usecs, + state->last_event, "system call return", &error)) { die("%s:%d: %s\n", state->config->script_path, From 968b1ad3e8f7f2e06e0db673c3d49f75e882ef6c Mon Sep 17 00:00:00 2001 From: Yousuk Seung Date: Thu, 4 Oct 2018 15:48:28 -0700 Subject: [PATCH 2/3] packetdrill: improve dynamic tolerance of blocking syscall Packetdrill calculates the dynamic tolerance based on delta between time of the last and current event. This delta value is irrelevant for a blocking system call and the last event is unpredictable and depends on the timing. Instead we can use the delta between the start and end time specified in the packetdrill with an ellipse. --- gtests/net/packetdrill/run.c | 8 ++++---- gtests/net/packetdrill/run.h | 9 ++++++++- gtests/net/packetdrill/run_packet.c | 2 +- gtests/net/packetdrill/run_system_call.c | 9 +++++++-- 4 files changed, 20 insertions(+), 8 deletions(-) diff --git a/gtests/net/packetdrill/run.c b/gtests/net/packetdrill/run.c index 984c447a..0c9a36b6 100644 --- a/gtests/net/packetdrill/run.c +++ b/gtests/net/packetdrill/run.c @@ -174,7 +174,7 @@ s64 now_usecs(struct state *state) */ int verify_time(struct state *state, enum event_time_t time_type, s64 script_usecs, s64 script_usecs_end, - s64 live_usecs, struct event *last_event, + s64 live_usecs, s64 last_event_usecs, const char *description, char **error) { s64 expected_usecs = script_usecs - state->script_start_time_usecs; @@ -189,8 +189,8 @@ int verify_time(struct state *state, enum event_time_t time_type, if (time_type == ANY_TIME) return STATUS_OK; - if (last_event) { - s64 delta = script_usecs - last_event->time_usecs; + if (last_event_usecs != NO_TIME_RANGE) { + s64 delta = script_usecs - last_event_usecs; long dynamic_tolerance; dynamic_tolerance = (state->config->tolerance_percent / 100.0) * delta; @@ -291,7 +291,7 @@ void check_event_time(struct state *state, s64 live_usecs) state->event->time_usecs, state->event->time_usecs_end, live_usecs, - state->last_event, + last_event_time_usecs(state), description, &error)) { die("%s:%d: %s\n", state->config->script_path, diff --git a/gtests/net/packetdrill/run.h b/gtests/net/packetdrill/run.h index 3f619091..34a39579 100644 --- a/gtests/net/packetdrill/run.h +++ b/gtests/net/packetdrill/run.h @@ -154,6 +154,13 @@ static inline s64 live_time_to_script_time_usecs(struct state *state, return script_time_usecs; } +/* Get the time of the last event if exists, or NO_TIME_RANGE. */ +static inline s64 last_event_time_usecs(struct state *state) +{ + return state->last_event == NULL ? NO_TIME_RANGE : + state->last_event->time_usecs; +} + /* * See if something that happened at the given actual live wall time * in microseconds happened reasonably close to the time at which we @@ -167,7 +174,7 @@ static inline s64 live_time_to_script_time_usecs(struct state *state, */ extern int verify_time(struct state *state, enum event_time_t time_type, s64 script_usecs, s64 script_usecs_end, - s64 live_usecs, struct event *last_event, + s64 live_usecs, s64 last_event_usecs, const char *description, char **error); extern void check_event_time(struct state *state, s64 live_usecs); diff --git a/gtests/net/packetdrill/run_packet.c b/gtests/net/packetdrill/run_packet.c index 07419d67..dfce22dc 100644 --- a/gtests/net/packetdrill/run_packet.c +++ b/gtests/net/packetdrill/run_packet.c @@ -1411,7 +1411,7 @@ static int verify_outbound_live_packet( DEBUGP("packet time_usecs: %lld\n", live_packet->time_usecs); if (verify_time(state, time_type, script_usecs, script_usecs_end, live_packet->time_usecs, - state->last_event, + last_event_time_usecs(state), "outbound packet", error)) { non_fatal = true; goto out; diff --git a/gtests/net/packetdrill/run_system_call.c b/gtests/net/packetdrill/run_system_call.c index 333f7a57..d776abed 100644 --- a/gtests/net/packetdrill/run_system_call.c +++ b/gtests/net/packetdrill/run_system_call.c @@ -3511,13 +3511,18 @@ static void *system_call_thread(void *arg) */ invoke_system_call(state, event, syscall); - /* Check end time for the blocking system call. */ + /* Check end time for the blocking system call. + * For a blocking system call we compute the + * dynamic tolerance based on the start and end + * time. The last event here is unpredictable + * and irrelevant. + */ assert(state->syscalls->live_end_usecs >= 0); if (verify_time(state, event->time_type, syscall->end_usecs, 0, state->syscalls->live_end_usecs, - state->last_event, + event->time_usecs, "system call return", &error)) { die("%s:%d: %s\n", state->config->script_path, From 25db6b7be03e3c20f2bf789c2a57c36014e6618c Mon Sep 17 00:00:00 2001 From: Jian Yang Date: Wed, 25 Mar 2020 13:43:52 -0700 Subject: [PATCH 3/3] packetdrill: consider relative time tolerance for timestamping Packetdrill checks difference between expected time and observed time using a tolerance, which is set as the higher of a fixed value (tolerance_usecs) or a percentage(tolerance_percent) times duration. Extend this check for SCM_TIMESTAMPING records. --- gtests/net/packetdrill/run.c | 12 ++++-------- gtests/net/packetdrill/run.h | 21 +++++++++++++++++++++ gtests/net/packetdrill/run_packet.c | 19 +++++++------------ gtests/net/packetdrill/run_system_call.c | 7 +++++-- 4 files changed, 37 insertions(+), 22 deletions(-) diff --git a/gtests/net/packetdrill/run.c b/gtests/net/packetdrill/run.c index 0c9a36b6..ff268388 100644 --- a/gtests/net/packetdrill/run.c +++ b/gtests/net/packetdrill/run.c @@ -92,6 +92,7 @@ struct state *state_new(struct config *config, state->code = code_new(config); state->fds = NULL; state->num_events = 0; + state->last_tcp_timestamp_usecs = NO_TIME_RANGE; return state; } @@ -181,7 +182,7 @@ int verify_time(struct state *state, enum event_time_t time_type, s64 expected_usecs_end = script_usecs_end - state->script_start_time_usecs; s64 actual_usecs = live_usecs - state->live_start_time_usecs; - long tolerance_usecs = state->config->tolerance_usecs; + s64 tolerance_usecs; DEBUGP("expected: %.3f actual: %.3f (secs)\n", usecs_to_secs(script_usecs), usecs_to_secs(actual_usecs)); @@ -189,14 +190,9 @@ int verify_time(struct state *state, enum event_time_t time_type, if (time_type == ANY_TIME) return STATUS_OK; - if (last_event_usecs != NO_TIME_RANGE) { - s64 delta = script_usecs - last_event_usecs; - long dynamic_tolerance; + tolerance_usecs = get_tolerance_usecs(state, script_usecs, + last_event_usecs); - dynamic_tolerance = (state->config->tolerance_percent / 100.0) * delta; - if (dynamic_tolerance > tolerance_usecs) - tolerance_usecs = dynamic_tolerance; - } if (time_type == ABSOLUTE_RANGE_TIME || time_type == RELATIVE_RANGE_TIME) { DEBUGP("expected_usecs_end %.3f\n", diff --git a/gtests/net/packetdrill/run.h b/gtests/net/packetdrill/run.h index 34a39579..0cd5ebba 100644 --- a/gtests/net/packetdrill/run.h +++ b/gtests/net/packetdrill/run.h @@ -105,6 +105,7 @@ struct state { s64 script_start_time_usecs; /* time of first event in script */ s64 script_last_time_usecs; /* time of previous event in script */ s64 live_start_time_usecs; /* time of first event in live test */ + s64 last_tcp_timestamp_usecs; /* time of previous tcp_timestamp */ int num_events; /* events executed so far */ }; @@ -161,6 +162,26 @@ static inline s64 last_event_time_usecs(struct state *state) state->last_event->time_usecs; } +/* + * Return the greater between static and dynamic tolerance + * Static tolerance: state->config->tolerance_usecs + * Dynamic tolerance: state->config->tolerance_percent * time_delta + */ +static inline s64 get_tolerance_usecs(struct state *state, s64 script_usecs, + s64 last_event_usecs) +{ + s64 tolerance_usecs = state->config->tolerance_usecs; + + if (last_event_usecs != NO_TIME_RANGE) { + s64 delta = script_usecs - last_event_usecs; + s64 d_tol = (state->config->tolerance_percent / 100.0) * delta; + + if (d_tol > tolerance_usecs) + tolerance_usecs = d_tol; + } + return tolerance_usecs; +} + /* * See if something that happened at the given actual live wall time * in microseconds happened reasonably close to the time at which we diff --git a/gtests/net/packetdrill/run_packet.c b/gtests/net/packetdrill/run_packet.c index dfce22dc..247d0f6f 100644 --- a/gtests/net/packetdrill/run_packet.c +++ b/gtests/net/packetdrill/run_packet.c @@ -1224,21 +1224,15 @@ static int verify_outbound_tcp_option( struct config *config = state->config; u32 script_ts_val, actual_ts_val; int ts_val_tick_usecs; - long tolerance_usecs; - double dynamic_tolerance; - s64 delta; + s64 tolerance_usecs; - tolerance_usecs = config->tolerance_usecs; /* Note that for TCP TS, we do not want to compute the tolerance based * on last event (as we do in verify_time()) * last event might have happened few ms in the past. * What matters here is the cumulative time (from the beginning of the test) */ - delta = state->event->time_usecs - state->script_start_time_usecs; - - dynamic_tolerance = (config->tolerance_percent / 100.0) * delta; - if (dynamic_tolerance > tolerance_usecs) - tolerance_usecs = dynamic_tolerance; + tolerance_usecs = get_tolerance_usecs(state, state->event->time_usecs, + state->script_start_time_usecs); switch (actual_option->kind) { case TCPOPT_EOL: @@ -1255,9 +1249,10 @@ static int verify_outbound_tcp_option( */ if (ts_val_tick_usecs && ((abs((s32)(actual_ts_val - script_ts_val)) * - ts_val_tick_usecs) > - tolerance_usecs)) { - asprintf(error, "bad outbound TCP timestamp value, tolerance %ld", tolerance_usecs); + ts_val_tick_usecs) > tolerance_usecs)) { + asprintf(error, + "bad outbound TCP timestamp value, tolerance %lld", + tolerance_usecs); return STATUS_ERR; } break; diff --git a/gtests/net/packetdrill/run_system_call.c b/gtests/net/packetdrill/run_system_call.c index d776abed..5389edf0 100644 --- a/gtests/net/packetdrill/run_system_call.c +++ b/gtests/net/packetdrill/run_system_call.c @@ -702,9 +702,12 @@ static bool scm_timestamping_expect_eq(struct state *state, s64 exp_usecs = script_time_to_live_time_usecs(state, timespec_to_usecs(&expected->ts[i])); s64 actual_usecs = timespec_to_usecs(&actual->ts[i]); + s64 tolerance_usecs = get_tolerance_usecs(state, actual_usecs, + state->last_tcp_timestamp_usecs); + state->last_tcp_timestamp_usecs = actual_usecs; + /* difference exceeds configured timing tolerance */ - if (llabs(exp_usecs - actual_usecs) > - state->config->tolerance_usecs) { + if (llabs(exp_usecs - actual_usecs) > tolerance_usecs) { asprintf(error, "Bad timestamp %d in scm_timestamping %d: " "expected=%lld (%lld) actual=%lld (%lld) "