X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/dc339fcb790e6956b559dc82992194eae6071611..f25b222a670ec0bd5b7d2137e3d137dc15e86aa7:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index b7bb38b..a4f825c 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -1,9 +1,10 @@ -/**************************************************************************/ -/* CAN latency tester */ -/* Copyright (C) 2010 Michal Sojka, DCE FEE CTU Prague */ -/* License: GPLv2 */ -/**************************************************************************/ +/*******************************************************************************/ +/* CAN latency tester */ +/* Copyright (C) 2010, 2011, 2012, 2013, 2014 Michal Sojka, DCE FEE CTU Prague */ +/* License: GPLv2 */ +/*******************************************************************************/ +#define _GNU_SOURCE #include #include #include @@ -30,6 +31,7 @@ #include #include +#include "canframelen.h" #include #include @@ -67,6 +69,7 @@ struct options { /* Temporary variables */ FILE *f_msgs; FILE *f_hist; + FILE *f_hist_gw; FILE *f_stat; }; @@ -98,12 +101,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 */ @@ -133,7 +137,7 @@ void sprint_canframe(char *buf , struct can_frame *cf, int sep) { } } -static inline struct msg_info *frame2info(struct can_frame *frame) +static inline uint16_t frame_index(struct can_frame *frame) { uint16_t idx; if (frame->can_dlc >= 2) { @@ -144,7 +148,12 @@ static inline struct msg_info *frame2info(struct can_frame *frame) error(1, 0, "%s error", __FUNCTION__); } - return &msg_infos[idx]; + return idx; +} + +static inline struct msg_info *frame2info(struct can_frame *frame) +{ + return &msg_infos[frame_index(frame)]; } static inline char *tstamp_str(const void *ctx, struct timespec *tstamp) @@ -153,13 +162,18 @@ 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); + void msg_info_print(FILE *f, struct msg_info *mi) { - struct timespec diff; + struct timespec diff, routing_delay, tx_time; void *local = talloc_new (NULL); static long num = 0; char sent[64], received[64]; + if (!f) + return; + sprint_canframe(sent, &mi->sent, true); sprint_canframe(received, &mi->received, true); @@ -168,20 +182,28 @@ void msg_info_print(FILE *f, struct msg_info *mi) switch (num_interfaces) { case 2: - fprintf(f, "%ld: %s %s -> %s (%s) %s = %s (%s)\n", + fprintf(f, "%ld: %s %s -> %s (%s) %s = %s (%s) %d\n", 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)); + DIFF(mi->ts_sent, mi->ts_rx_final_kern), + DIFF(mi->ts_sent, mi->ts_rx_final), + mi->tx_time_us); break; case 3: - fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s)\n", + 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", 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, DIFF(mi->ts_sent, mi->ts_rx_onwire_kern), 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)); + DIFF(mi->ts_rx_onwire, mi->ts_rx_final), + mi->tx_time_us, + S(routing_delay)); break; } #undef S @@ -223,7 +245,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) { @@ -240,9 +262,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_length(&mi->received); } void set_sched_policy_and_prio(int policy, int rtprio) @@ -277,7 +300,7 @@ static inline int sock_get_if_index(int s, const char *if_name) return ifr.ifr_ifindex; } -static inline get_tstamp(struct timespec *ts) +static inline void get_tstamp(struct timespec *ts) { clock_gettime(CLOCK_REALTIME, ts); } @@ -286,7 +309,7 @@ static inline get_tstamp(struct timespec *ts) int trace_fd = -1; int marker_fd = -1; -int init_ftrace() +void init_ftrace() { #ifdef FTRACE char *debugfs; @@ -388,7 +411,7 @@ int send_frame(int socket) return ret; } -static inline send_and_check(int s) +static inline void send_and_check(int s) { int ret; ret = send_frame(s); @@ -466,9 +489,12 @@ void receive(int s, struct can_frame *frame, struct timespec *ts_kern, struct ti cmsg && (cmsg->cmsg_level == SOL_SOCKET); cmsg = CMSG_NXTHDR(&msg,cmsg)) { if (cmsg->cmsg_type == SO_TIMESTAMPNS) - *ts_kern = *(struct timespec *)CMSG_DATA(cmsg); - else if (cmsg->cmsg_type == SO_RXQ_OVFL) - dropcnt += *(__u32 *)CMSG_DATA(cmsg); + memcpy(ts_kern, CMSG_DATA(cmsg), sizeof(struct timespec)); + else if (cmsg->cmsg_type == SO_RXQ_OVFL) { + uint32_t ovfl; + memcpy(&ovfl, CMSG_DATA(cmsg), sizeof(ovfl)); + dropcnt += ovfl; + } } } @@ -480,7 +506,7 @@ void process_tx(int s) void process_on_wire_rx(int s) { - struct timespec ts_kern, ts_user, ts_diff; + struct timespec ts_kern, ts_user; struct can_frame frame; struct msg_info *mi; receive(s, &frame, &ts_kern, &ts_user); @@ -495,7 +521,7 @@ void process_on_wire_rx(int s) void process_final_rx(int s) { - struct timespec ts_kern, ts_user, ts_diff; + struct timespec ts_kern, ts_user; struct can_frame frame; struct msg_info *mi; int ret; @@ -506,7 +532,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) @@ -519,7 +548,6 @@ void *measure_thread(void *arg) struct pollfd pfd[3]; struct timespec timeout; struct sockaddr_can addr; - sigset_t set; int consecutive_timeouts = 0; MEMSET_ZERO(pfd); @@ -606,13 +634,15 @@ void *measure_thread(void *arg) } pfd[0].revents = 0; - if (num_interfaces == 3 && pfd[1].revents != 0) { + if (num_interfaces == 3 && pfd[1].revents & POLLIN) { process_on_wire_rx(pfd[1].fd); pfd[1].revents = 0; } + if (num_interfaces == 3 && pfd[1].revents & ~POLLIN) + error(1, 0, "Unexpected pfd[1].revents: 0x%04x\n", pfd[1].revents); i = (num_interfaces == 2) ? 1 : 2; - if (pfd[i].revents != 0) { + if (pfd[i].revents & POLLIN) { consecutive_timeouts = 0; process_final_rx(pfd[i].fd); msg_in_progress--; @@ -622,6 +652,8 @@ void *measure_thread(void *arg) SEND(); } } + if (pfd[i].revents & ~POLLIN) + error(1, 0, "Unexpected pfd[%d].revents: 0x%04x\n", i, pfd[i].revents); } } @@ -685,12 +717,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"); @@ -717,7 +756,6 @@ void print_progress() int main(int argc, const char *argv[]) { pthread_t thread; - sigset_t set; int ret, i; parse_options(argc, argv); @@ -731,6 +769,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) @@ -740,6 +779,13 @@ int main(int argc, const char *argv[]) error(1, errno, "pipe fcntl"); init_ftrace(); + if (getenv("LATESTER_CONTROL_HACKBENCH")) { + char cmd[1000]; + sprintf(cmd, "ssh -x -a -S $HOME/.ssh/cangw-connection root@192.168.2.3 'kill -CONT -%s'", + getenv("LATESTER_CONTROL_HACKBENCH")); + printf("Running: %s\n", cmd); + system(cmd); + } pthread_create(&thread, 0, measure_thread, NULL); @@ -789,40 +835,54 @@ int main(int argc, const char *argv[]) pthread_join(thread, NULL); + if (getenv("LATESTER_CONTROL_HACKBENCH")) { + char cmd[1000]; + sprintf(cmd, "ssh -x -a -S $HOME/.ssh/cangw-connection root@192.168.2.3 'kill -STOP -%s'", + getenv("LATESTER_CONTROL_HACKBENCH")); + printf("Running: %s\n", cmd); + system(cmd); + } + close(completion_pipe[0]); close(completion_pipe[1]); histogram_fprint(&histogram, opt.f_hist); - fclose(opt.f_hist); - fclose(opt.f_msgs); - - - fprintf(opt.f_stat, "cmdline='"); - for (i=0; i