packetdrill: implement relative time tolerance

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=<MSS in bytes>\n"
 		"\t[--mtu=<MTU in bytes>\n"
 		"\t[--tolerance_usecs=tolerance_usecs]\n"
+		"\t[--tolerance_percent=percentage]\n"
 		"\t[--tcp_ts_ecr_scaled]\n"
 		"\t[--tcp_ts_tick_usecs=<microseconds per TCP TS val tick>]\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;

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 */
 

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;
 }
 
@@ -174,20 +175,24 @@ 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, s64 last_event_usecs,
+		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;
+	s64 tolerance_usecs;
 
 	DEBUGP("expected: %.3f actual: %.3f  (secs)\n",
 	       usecs_to_secs(script_usecs), usecs_to_secs(actual_usecs));
 
 	if (time_type == ANY_TIME)
 		return STATUS_OK;
 
+	tolerance_usecs = get_tolerance_usecs(state, script_usecs,
+					      last_event_usecs);
+
 	if (time_type == ABSOLUTE_RANGE_TIME ||
 	    time_type == RELATIVE_RANGE_TIME) {
 		DEBUGP("expected_usecs_end %.3f\n",
@@ -280,7 +285,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,
+			last_event_time_usecs(state),
 			description, &error)) {
 		die("%s:%d: %s\n",
 		    state->config->script_path,

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 */
 };
 
@@ -154,6 +155,33 @@ 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;
+}
+
+/*
+ * 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
@@ -167,7 +195,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, s64 last_event_usecs,
+		       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

gtests/net/packetdrill/run_packet.c

@@ -1214,18 +1214,25 @@ 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;
+	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)
+	*/
+	tolerance_usecs = get_tolerance_usecs(state, state->event->time_usecs,
+						state->script_start_time_usecs);
 
 	switch (actual_option->kind) {
 	case TCPOPT_EOL:
@@ -1242,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;
@@ -1270,7 +1278,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 +1301,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 +1384,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 +1406,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,
+				last_event_time_usecs(state),
 				"outbound packet", error)) {
 		non_fatal = true;
 		goto out;

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) "
@@ -3511,12 +3514,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,
+						event->time_usecs,
 						"system call return", &error)) {
 				die("%s:%d: %s\n",
 				    state->config->script_path,