latester: Cleanup and correct subtraction with negative results

[can-benchmark.git] / latester / latester.c

diff --git a/latester/latester.c b/latester/latester.c
index 72e123b25af1383fb112aeb88ca162c18c53bae5..60e106b564d8b9f636ab4c02d59899eee510527f 100644 (file)
--- 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++;
                }