From: Michal Sojka <sojkam1@fel.cvut.cz>
Date: Fri, 17 Oct 2014 14:52:12 +0000 (+0200)
Subject: latester: Cleanup and correct subtraction with negative results
X-Git-Tag: pc-sw-update~6
X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/commitdiff_plain/3bd8177e9074df7ad74134a49072a4097026e38f?hp=2c56cfb6f9e9fa6c85cb3eddceb036200697f835

latester: Cleanup and correct subtraction with negative results

- Cleanup = move more complex calculation from RT thread to processing
  thread.
- Negative result happened what message TX time was greater than
  timestamp difference. This can happen if first timestamp is delayed
  and the second not.
---

diff --git a/latester/latester.c b/latester/latester.c
index 72e123b..60e106b 100644
--- a/latester/latester.c
+++ b/latester/latester.c
@@ -101,7 +101,6 @@ struct msg_info {
 	struct timespec ts_rx_onwire, ts_rx_onwire_kern;
 	struct timespec ts_rx_final, ts_rx_final_kern;
 	struct can_frame sent, received;
-	unsigned lat_measured_us, tx_time_us;
 };
 
 #define MAX_INFOS 10000
@@ -162,18 +161,27 @@ static inline char *tstamp_str(const void *ctx, struct timespec *tstamp)
 			       tstamp->tv_sec, tstamp->tv_nsec/1000);
 }
 
-int timespec_subtract (struct timespec *result, struct timespec *x, struct timespec *yy);
+int timespec_subtract (struct timespec *result, const struct timespec *x, const struct timespec *yy);
 
-void msg_info_print(FILE *f, struct msg_info *mi)
+static inline unsigned get_timestamp_diff_us(struct msg_info *mi);
+
+void msg_info_process(FILE *f, struct msg_info *mi)
 {
-	struct timespec diff, routing_delay, tx_time;
+	struct timespec diff;
 	void *local = talloc_new (NULL);
 	static long num = 0;
 	char sent[64], received[64];
+	int diff_us = get_timestamp_diff_us(mi);
+	int tx_time_us = calc_frame_length(&mi->received);
+
+	/* Update histograms */
+	histogram_add(&histogram, diff_us);
+	histogram_add(&histogram_gw, diff_us - tx_time_us);
 
 	if (!f)
 		return;
 
+	/* Print information to a file */
 	sprint_canframe(sent, &mi->sent, true);
 	sprint_canframe(received, &mi->received, true);
 
@@ -186,15 +194,10 @@ void msg_info_print(FILE *f, struct msg_info *mi)
 			num, S(mi->ts_sent), sent, S(mi->ts_rx_final_kern), S(mi->ts_rx_final), received,
 			DIFF(mi->ts_sent, mi->ts_rx_final_kern),
 			DIFF(mi->ts_sent, mi->ts_rx_final),
-			mi->tx_time_us);
+			tx_time_us);
 		break;
 	case 3:
-		tx_time.tv_sec = 0;
-		tx_time.tv_nsec = mi->tx_time_us*1000;
-		timespec_subtract(&routing_delay, &mi->ts_rx_final_kern, &mi->ts_rx_onwire_kern);
-		timespec_subtract(&routing_delay, &routing_delay, &tx_time);
-
-		fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s) %d %s\n",
+		fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s) %d %.6f\n",
 			num, S(mi->ts_sent), sent,
 			S(mi->ts_rx_onwire_kern), S(mi->ts_rx_onwire),
 			S(mi->ts_rx_final_kern), S(mi->ts_rx_final), received,
@@ -202,8 +205,8 @@ void msg_info_print(FILE *f, struct msg_info *mi)
 			DIFF(mi->ts_sent, mi->ts_rx_onwire),
 			DIFF(mi->ts_rx_onwire_kern, mi->ts_rx_final_kern),
 			DIFF(mi->ts_rx_onwire, mi->ts_rx_final),
-			mi->tx_time_us,
-			S(routing_delay));
+			tx_time_us,
+			1e-6*(diff_us - tx_time_us));
 		break;
 	}
 #undef S
@@ -215,7 +218,7 @@ void msg_info_print(FILE *f, struct msg_info *mi)
 /* Subtract the `struct timespec' values X and Y, storing the result in
    RESULT.  Return 1 if the difference is negative, otherwise 0.  */
 
-int timespec_subtract (struct timespec *result, struct timespec *x, struct timespec *yy)
+int timespec_subtract (struct timespec *result, const struct timespec *x, const struct timespec *yy)
 {
 	struct timespec ylocal = *yy, *y = &ylocal;
 	/* Perform the carry for the later subtraction by updating Y. */
@@ -245,7 +248,7 @@ void dbg_print_timespec(char *msg, struct timespec *tv)
 	printf("%s sec=%ld nsec=%ld\n", msg, tv->tv_sec, tv->tv_nsec);
 }
 
-static inline void calc_msg_latencies(struct msg_info *mi)
+static inline unsigned get_timestamp_diff_us(struct msg_info *mi)
 {
 	struct timespec diff;
 	switch (num_interfaces) {
@@ -262,10 +265,10 @@ static inline void calc_msg_latencies(struct msg_info *mi)
 			timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent);
 		break;
 	default:
-		return;
+		return 0;
 	}
-	mi->lat_measured_us = diff.tv_sec * 1000000 + diff.tv_nsec/1000;
-	mi->tx_time_us = calc_frame_length(&mi->received);
+	unsigned us = diff.tv_sec * 1000000 + diff.tv_nsec/1000;
+	return us;
 }
 
 void set_sched_policy_and_prio(int policy, int rtprio)
@@ -540,11 +543,6 @@ void process_final_rx(int s)
 	mi->ts_rx_final = ts_user;
 	mi->received = frame;
 
-	calc_msg_latencies(mi);
-
-	histogram_add(&histogram, mi->lat_measured_us);
-	histogram_add(&histogram_gw, mi->lat_measured_us - mi->tx_time_us);
-
 	ret = write(completion_pipe[1], &mi, sizeof(mi));
 	if (ret == -1)
 		error(1, errno, "completion_pipe write");
@@ -814,7 +812,8 @@ int main(int argc, const char *argv[])
 			ret = read(completion_pipe[0], &mi, sizeof(mi));
 			if (ret < sizeof(mi))
 				error(1, errno, "read completion returned %d", ret);
-			msg_info_print(opt.f_msgs, mi);
+
+			msg_info_process(opt.f_msgs, mi);
 			msg_info_free(mi);
 			completed++;
 		}