From 0cfde1d2b81d51e73e45e178cdce58e10dcda0a4 Mon Sep 17 00:00:00 2001 From: Michal Sojka Date: Sat, 24 Sep 2011 00:27:39 +0200 Subject: [PATCH] Draw histograms after substracting message tx time --- gw-tests/mod.sh | 4 ++-- latester/histogram.h | 3 ++- latester/latester.c | 39 ++++++++++++++++++++++++++++++--------- 3 files changed, 34 insertions(+), 12 deletions(-) diff --git a/gw-tests/mod.sh b/gw-tests/mod.sh index a1f68fa..4652b92 100755 --- a/gw-tests/mod.sh +++ b/gw-tests/mod.sh @@ -41,13 +41,13 @@ ADDITIONAL_PLOTS=detail plot_cmds() { if [[ "$1" = detail ]]; then - range=140:200 + range=0:200 echo "set logscale y" echo "set key left bottom reverse Left" echo "set xlabel 'Time [{/Symbol m}s]'" using="using (\$1*1000):2" else - range=0.05:100 + range=0.0:100 echo "set logscale xy" echo "set xlabel 'Time [ms]'" using="" diff --git a/latester/histogram.h b/latester/histogram.h index 4a9aade..64dcb22 100644 --- a/latester/histogram.h +++ b/latester/histogram.h @@ -23,8 +23,9 @@ int histogram_init(struct histogram *h, return -1; } -void histogram_add(struct histogram *h, unsigned value) +void histogram_add(struct histogram *h, int value) { + if (value < 0) value = 0; unsigned index = value / h->resolution; if (index >= h->allocated) index = h->allocated - 1; diff --git a/latester/latester.c b/latester/latester.c index 30e62f1..1ab9781 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -67,6 +67,7 @@ struct options { /* Temporary variables */ FILE *f_msgs; FILE *f_hist; + FILE *f_hist_gw; FILE *f_stat; }; @@ -98,12 +99,13 @@ 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 struct msg_info msg_infos[MAX_INFOS]; -struct histogram histogram; +struct histogram histogram, histogram_gw; void sprint_canframe(char *buf , struct can_frame *cf, int sep) { /* documentation see lib.h */ @@ -204,6 +206,10 @@ unsigned calc_stuff_bits(struct can_frame *frame) { crc_t crc = 0; uint32_t crcx; +/* char received[64]; */ +/* sprint_canframe(received, frame, true); */ +/* printf("Frame: %s\n", received); */ + if (frame->can_id & CAN_EFF_FLAG) { bitmap[0] = ((frame->can_id & CAN_EFF_MASK) >> 25); @@ -269,9 +275,10 @@ unsigned calc_stuff_bits(struct can_frame *frame) { ones = !ones; } //printf ("STUFFED %d BITS\n", stuffed); + return stuffed; } -unsigned calc_frame_txtime(struct can_frame *frame) { +unsigned calc_frame_txtime_us(struct can_frame *frame) { return calc_stuff_bits(frame) + 1 + /* SOF */ 11 + /* ID A */ @@ -310,7 +317,7 @@ 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), - calc_frame_txtime(&mi->received)); + mi->tx_time_us); break; case 3: fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s) %d\n", @@ -321,7 +328,7 @@ 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), - calc_frame_txtime(&mi->received)); + mi->tx_time_us); break; } #undef S @@ -363,7 +370,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 unsigned get_msg_latency_us(struct msg_info *mi) +static inline void calc_msg_latencies(struct msg_info *mi) { struct timespec diff; switch (num_interfaces) { @@ -380,9 +387,10 @@ static inline unsigned get_msg_latency_us(struct msg_info *mi) timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent); break; default: - return 0; + return; } - return diff.tv_sec * 1000000 + diff.tv_nsec/1000; + mi->lat_measured_us = diff.tv_sec * 1000000 + diff.tv_nsec/1000; + mi->tx_time_us = calc_frame_txtime_us(&mi->received); } void set_sched_policy_and_prio(int policy, int rtprio) @@ -646,7 +654,10 @@ void process_final_rx(int s) mi->ts_rx_final = ts_user; mi->received = frame; - histogram_add(&histogram, get_msg_latency_us(mi)); + 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) @@ -829,12 +840,19 @@ int parse_options(int argc, const char *argv[]) } if (opt.name) { - char *f = talloc_asprintf(local, "%s-hist.txt", opt.name); + char *f = talloc_asprintf(local, "%s-hist-raw.txt", opt.name); opt.f_hist = fopen(f, "w"); if (!opt.f_hist) error(1, errno, "fopen: %s", f); } + if (opt.name) { + char *f = talloc_asprintf(local, "%s-hist.txt", opt.name); + opt.f_hist_gw = fopen(f, "w"); + if (!opt.f_hist_gw) + error(1, errno, "fopen: %s", f); + } + if (opt.name) { char *f = talloc_asprintf(local, "%s-stat.txt", opt.name); opt.f_stat = fopen(f, "w"); @@ -875,6 +893,7 @@ int main(int argc, const char *argv[]) msg_infos[i].id = -1; histogram_init(&histogram, 5000000, 1); + histogram_init(&histogram_gw, 5000000, 1); ret = pipe(completion_pipe); if (ret == -1) @@ -952,7 +971,9 @@ int main(int argc, const char *argv[]) close(completion_pipe[1]); histogram_fprint(&histogram, opt.f_hist); + histogram_fprint(&histogram_gw, opt.f_hist_gw); fclose(opt.f_hist); + fclose(opt.f_hist_gw); fclose(opt.f_msgs); -- 2.39.2