X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/0d33c2e1156b523b8fea545e8ae1448bd50b8abb..dc7f5a3374014b178414d75c09b9484403f186cc:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index c980f24..b396fd2 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,8 +31,10 @@ #include #include +#include "canframelen.h" #include #include +#include #include "histogram.h" @@ -59,10 +62,16 @@ struct options { unsigned timeout_ms; unsigned count; unsigned oneattime; - FILE *file; - FILE *histogram; + char *name; int length; int userhist; + int quiet; + + /* Temporary variables */ + FILE *f_msgs; + FILE *f_hist; + FILE *f_hist_gw; + FILE *f_stat; }; struct options opt = { @@ -75,11 +84,17 @@ struct options opt = { struct { unsigned enobufs; unsigned overrun; + unsigned lost; + struct timespec tic, tac; + unsigned timeouts; + unsigned invalid_frame; } stats; int num_interfaces = 0; int count = 0; /* Number of sent messages */ +unsigned msg_in_progress = 0; int completion_pipe[2]; +struct timespec can_tsdiff = {0, 0}; /* can_rx2_ts - can_rx1_ts */ struct msg_info { canid_t id; @@ -93,7 +108,7 @@ struct msg_info { #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 */ @@ -123,7 +138,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) { @@ -131,10 +146,15 @@ static inline struct msg_info *frame2info(struct can_frame *frame) if (idx >= MAX_INFOS) error(1, 0, "%s idx too high", __FUNCTION__); } else { - + 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) @@ -143,66 +163,64 @@ static inline char *tstamp_str(const void *ctx, struct timespec *tstamp) tstamp->tv_sec, tstamp->tv_nsec/1000); } -void msg_info_print(FILE *f, struct msg_info *mi) +int timespec_subtract (struct timespec *result, const struct timespec *x, const struct timespec *yy); + +static inline unsigned get_timestamp_diff_us(struct msg_info *mi); + +void msg_info_process(FILE *f, struct msg_info *mi) { 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); #define S(ts) tstamp_str(local, &ts) #define DIFF(a, b) (timespec_subtract(&diff, &b, &a), S(diff)) - if (num_interfaces == 2) - fprintf(f, "%ld: %s %s -> %s (%s) %s = %s (%s)\n", + switch (num_interfaces) { + case 2: + 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)); - else - fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s)\n", + DIFF(mi->ts_sent, mi->ts_rx_final_kern), + DIFF(mi->ts_sent, mi->ts_rx_final), + tx_time_us); + break; + case 3: + 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, 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), + tx_time_us, + 1e-6*(diff_us - tx_time_us)); + break; + } #undef S #undef DIFF num++; talloc_free (local); } -int msg_info_store(FILE *f, struct msg_info *mi) -{ - struct timespec diff; - void *local = talloc_new (NULL); - static long num = 0; - -#define S(ts) tstamp_str(local, &ts) -#define DIFF(a, b) (timespec_subtract(&diff, &b, &a), S(diff)) - - if (num_interfaces == 2) - fprintf(f, "%ld %d %d %s\n", - num, mi->id, mi->length, - DIFF(mi->ts_sent, mi->ts_rx_final_kern)); - else - fprintf(f, "%ld %d %d %s\n", - num, mi->id, mi->length, - DIFF(mi->ts_rx_onwire_kern, mi->ts_rx_final_kern)); -#undef S -#undef DIFF - talloc_free (local); -} - - /* 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. */ @@ -232,20 +250,27 @@ 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 unsigned get_timestamp_diff_us(struct msg_info *mi) { struct timespec diff; - if (num_interfaces == 3) + switch (num_interfaces) { + case 3: if (opt.userhist) timespec_subtract(&diff, &mi->ts_rx_final, &mi->ts_rx_onwire); else timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_rx_onwire_kern); - else + break; + case 2: if (opt.userhist) timespec_subtract(&diff, &mi->ts_rx_final, &mi->ts_sent); else timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent); - return diff.tv_sec * 1000000 + diff.tv_nsec/1000; + break; + default: + return 0; + } + unsigned us = diff.tv_sec * 1000000 + diff.tv_nsec/1000; + return us; } void set_sched_policy_and_prio(int policy, int rtprio) @@ -280,22 +305,22 @@ 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); + clock_gettime(CLOCK_MONOTONIC/*REALTIME*/, ts); } int trace_fd = -1; int marker_fd = -1; -int init_ftrace() +void init_ftrace() { #ifdef FTRACE char *debugfs; char path[256]; FILE *f; - + debugfs = "/sys/kernel/debug"; if (debugfs) { strcpy(path, debugfs); @@ -338,11 +363,16 @@ static inline void trace_off(int ret) write(trace_fd, "0", 1); } -void msg_info_free(struct msg_info *mi) +static inline void msg_info_free(struct msg_info *mi) { mi->id = -1; } +static inline bool msg_info_used(struct msg_info *mi) +{ + return mi->id != -1; +} + int send_frame(int socket) { struct can_frame frame; @@ -354,7 +384,7 @@ int send_frame(int socket) MEMSET_ZERO(frame); i = curr_msg+1; - while (msg_infos[i].id != -1 && i != curr_msg) { + while (msg_info_used(&msg_infos[i]) && i != curr_msg) { i++; if (i >= MAX_INFOS) i = 0; @@ -376,36 +406,60 @@ int send_frame(int socket) mi->length = frame.can_dlc; get_tstamp(&mi->ts_sent); mi->sent = frame; - + trace_on(); ret = write(socket, &frame, sizeof(frame)); trace_off(ret); - if (ret == -1) + if (ret == -1 || num_interfaces == 1) msg_info_free(mi); return ret; } -static inline void get_next_timeout(struct timespec *timeout) +static inline void send_and_check(int s) +{ + int ret; + ret = send_frame(s); + if (ret != sizeof(struct can_frame)) { +/* if (ret == -1 && errno == ENOBUFS && opt.period_us == 0 && !opt.oneattime) { */ +/* stats.enobufs++; */ +/* /\* Ignore this error - pfifo_fast qeuue is full *\/ */ +/* } else */ + error(1, errno, "send_frame (line %d)", __LINE__); + } else { + count++; + msg_in_progress++; + } +} + +static inline void get_next_timeout(struct timespec *timeout, bool advance) { struct timespec now; static struct timespec last = {-1, 0 }; clock_gettime(CLOCK_MONOTONIC, &now); - if (last.tv_sec == -1) + if (last.tv_sec == -1) { last = now; + last.tv_nsec = last.tv_nsec/1000000*1000000; + } if (opt.period_us != 0) { - last.tv_sec += opt.period_us/1000000; - last.tv_nsec += (opt.period_us%1000000)*1000; - while (last.tv_nsec >= 1000000000) { - last.tv_nsec -= 1000000000; - last.tv_sec++; + if (advance) { + last.tv_sec += opt.period_us/1000000; + last.tv_nsec += (opt.period_us%1000000)*1000; + while (last.tv_nsec >= 1000000000) { + last.tv_nsec -= 1000000000; + last.tv_sec++; + } } if (timespec_subtract(timeout, &last, &now) /* is negative */) { stats.overrun++; memset(timeout, 0, sizeof(*timeout)); } +/* printf("next %ld.%06ld now %ld.%06ld --> timeout %ld.%06ld\n", */ +/* last.tv_sec, last.tv_nsec/1000, */ +/* now.tv_sec, now.tv_nsec/1000, */ +/* timeout->tv_sec, timeout->tv_nsec/1000); */ } else if (opt.timeout_ms != 0) { timeout->tv_sec = opt.timeout_ms/1000; timeout->tv_nsec = (opt.timeout_ms%1000)*1000000; @@ -422,6 +476,7 @@ void receive(int s, struct can_frame *frame, struct timespec *ts_kern, struct ti struct sockaddr_can addr; int nbytes; static uint64_t dropcnt = 0; + bool have_hwtstamp = 0; iov.iov_base = frame; msg.msg_name = &addr; @@ -447,10 +502,20 @@ void receive(int s, struct can_frame *frame, struct timespec *ts_kern, struct ti for (cmsg = CMSG_FIRSTHDR(&msg); 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); + if (cmsg->cmsg_type == SO_TIMESTAMPNS) { + if(!have_hwtstamp) + memcpy(ts_kern, CMSG_DATA(cmsg), sizeof(struct timespec)); + } + else if (cmsg->cmsg_type == SO_TIMESTAMPING) { + struct timespec *ts = (struct timespec *) CMSG_DATA(cmsg); + memcpy(ts_kern, &ts[2], sizeof(struct timespec)); + have_hwtstamp = 1; + } + else if (cmsg->cmsg_type == SO_RXQ_OVFL) { + uint32_t ovfl; + memcpy(&ovfl, CMSG_DATA(cmsg), sizeof(ovfl)); + dropcnt += ovfl; + } } } @@ -462,45 +527,100 @@ 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); mi = frame2info(&frame); - mi->ts_rx_onwire_kern = ts_kern; - mi->ts_rx_onwire = ts_user; + if (msg_info_used(mi)) { + mi->ts_rx_onwire_kern = ts_kern; + mi->ts_rx_onwire = ts_user; + } else + stats.invalid_frame++; } 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; - + receive(s, &frame, &ts_kern, &ts_user); mi = frame2info(&frame); mi->ts_rx_final_kern = ts_kern; mi->ts_rx_final = ts_user; mi->received = frame; - if (opt.histogram) - histogram_add(&histogram, get_msg_latency_us(mi)); - ret = write(completion_pipe[1], &mi, sizeof(mi)); if (ret == -1) error(1, errno, "completion_pipe write"); } +void determine_can_timing_offset(struct pollfd *pfd, int nifc) +{ + int uiofd; + volatile uint32_t *can_crossbar; + uint32_t oldreg; + struct can_frame frame; + struct timespec ts_rx1, ts_rx2, ts_dummy; + int res; + + if(nifc < 2) + return; + + uiofd = open("/dev/uio0", O_RDWR); + if(uiofd < 0) + { + perror("determine_can_timing_offset: /dev/uio0"); + return; + } + + can_crossbar = (volatile uint32_t *) mmap(NULL, 4096, PROT_READ | PROT_WRITE, MAP_SHARED, uiofd, 0); + if(can_crossbar == MAP_FAILED) + { + perror("mmap"); + goto cleanup1; + } + + // Bit: 20 19 18 17 16 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 + // STBY E3 E2 E1 E0 I3 I2 I1 I0 C3 C2 C1 C0 + // C*: can* (outer can physical interface) connection line assignment (0-3) + // I*: ifc* (inner can network interface) connection line assignment (0-3) + // E*: can* output enable: 1 = connect to physical interface, 0 = disconnect from physical interface, conenect RX and TX together + // STBY: CAN Transceivers standby mode + oldreg = can_crossbar[0]; + can_crossbar[0] = 0x00000000; // connect all interfaces together, disable output, disable standby + + frame.can_id = 0x00; + frame.can_dlc = 4; + memcpy(frame.data, "SYNC", 4); + res = write(pfd[0].fd, &frame, sizeof(frame)); + if(res != sizeof(frame)) + { + perror("write"); + goto cleanup2; + } + + receive(pfd[1].fd, &frame, &ts_rx1, &ts_dummy); + receive(pfd[2].fd, &frame, &ts_rx2, &ts_dummy); + timespec_subtract(&can_tsdiff, &ts_rx2, &ts_rx1); + +cleanup2: + can_crossbar[0] = oldreg; + munmap((void*)can_crossbar, 4096); +cleanup1: + close(uiofd); +} + void *measure_thread(void *arg) { int s, i, ret; struct pollfd pfd[3]; struct timespec timeout; struct sockaddr_can addr; - sigset_t set; - unsigned msg_in_progress = 0; + int consecutive_timeouts = 0; MEMSET_ZERO(pfd); @@ -523,10 +643,20 @@ void *measure_thread(void *arg) if (bind(s, (struct sockaddr *)&addr, sizeof(addr)) < 0) error(1, errno, "bind"); - const int timestamp_on = 1; - if (setsockopt(s, SOL_SOCKET, SO_TIMESTAMPNS, - ×tamp_on, sizeof(timestamp_on)) < 0) - error(1, errno, "setsockopt SO_TIMESTAMP"); + // TODO: set HW TSTAMP flags? + const int so_timestamping_flags = SOF_TIMESTAMPING_RAW_HARDWARE; + if (setsockopt(s, SOL_SOCKET, SO_TIMESTAMPING, + &so_timestamping_flags, + sizeof(so_timestamping_flags)) < 0) + { + perror("setsockopt SO_TIMESTAMPING"); + fprintf(stderr, "Falling back to SW timestamps.\n"); + + const int timestamp_on = 1; + if (setsockopt(s, SOL_SOCKET, SO_TIMESTAMPNS, + ×tamp_on, sizeof(timestamp_on)) < 0) + error(1, errno, "setsockopt SO_TIMESTAMPNS"); + } const int dropmonitor_on = 1; if (setsockopt(s, SOL_SOCKET, SO_RXQ_OVFL, @@ -540,33 +670,23 @@ void *measure_thread(void *arg) pfd[i].events = POLLIN; } + determine_can_timing_offset(pfd, num_interfaces); + + set_sched_policy_and_prio(SCHED_FIFO, 40); -#define SEND() \ - do { \ - ret = send_frame(pfd[0].fd); \ - if (ret != sizeof(struct can_frame)) { \ - if (ret == -1 && errno == ENOBUFS && opt.period_us == 0 && !opt.oneattime) { \ - stats.enobufs++; \ - /* Ignore this error - pfifo_fast qeuue is full */ \ - } else \ - error(1, errno, "send_frame (line %d)", __LINE__); \ - } \ - else { \ - count++; \ - msg_in_progress++; \ - } \ - } while (0) - - if (opt.oneattime) { +#define SEND() send_and_check(pfd[0].fd) + + if (opt.oneattime) SEND(); - count = 1; - } + get_tstamp(&stats.tic); + ret = 0; while (!finish_flag && (opt.count == 0 || count < opt.count || msg_in_progress != 0)) { - get_next_timeout(&timeout); + get_next_timeout(&timeout, ret == 0); + //printf("timeout %ld.%06ld\n", timeout.tv_sec, timeout.tv_nsec/1000); //printf("ppoll"); fflush(stdout); ret = ppoll(pfd, num_interfaces, &timeout, NULL); //printf("=%d\n", ret); @@ -581,7 +701,13 @@ void *measure_thread(void *arg) SEND(); } } else { - error(1, 0, "poll timeout"); + /* Lost message - send a new one */ + stats.timeouts++; + consecutive_timeouts++; + if (consecutive_timeouts < 10) + SEND(); + else /* Something is really broken */ + finish_flag = 1; } break; default: // Event @@ -594,13 +720,16 @@ 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--; pfd[i].revents = 0; @@ -609,9 +738,13 @@ 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); } } + get_tstamp(&stats.tac); + for (i=0; i"); @@ -648,16 +782,6 @@ int parse_options(int argc, const char *argv[]) case 'd': num_interfaces++; break; - case 'f': - opt.file = fopen(poptGetOptArg(optCon), "w"); - if (!opt.file) - error(1, errno, "fopen: %s", poptGetOptArg(optCon)); - break; - case 'h': - opt.histogram = fopen(poptGetOptArg(optCon), "w"); - if (!opt.histogram) - error(1, errno, "fopen: %s", poptGetOptArg(optCon)); - break; } } if (c < -1) @@ -665,22 +789,59 @@ int parse_options(int argc, const char *argv[]) poptBadOption(optCon, POPT_BADOPTION_NOALIAS), poptStrerror(c)); - if (num_interfaces < 2 || num_interfaces > 3) - error(1, 0, "-d option must be given exactly 2 or 3 times"); + if (num_interfaces < 1 || num_interfaces > 3) + error(1, 0, "-d option must only be given one, two or three times"); if (opt.oneattime && opt.period_us) error(1, 0, "oneattime and period cannot be specified at the same time"); - poptFreeContext(optCon); + if (opt.name) { + char *f = talloc_asprintf(local, "%s-msgs.txt", opt.name); + opt.f_msgs = fopen(f, "w"); + if (!opt.f_msgs) + error(1, errno, "fopen: %s", f); + } + + if (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"); + if (!opt.f_stat) + error(1, errno, "fopen: %s", f); + } + poptFreeContext(optCon); + talloc_free(local); return 0; } +void print_progress() +{ + if (! opt.quiet) { + if (num_interfaces > 1) + printf("\rSent %5d, in progress %5d", count, msg_in_progress); + else + printf("\rSent %5d", count); + fflush(stdout); + } +} int main(int argc, const char *argv[]) { pthread_t thread; - sigset_t set; int ret, i; parse_options(argc, argv); @@ -693,9 +854,8 @@ int main(int argc, const char *argv[]) for (i=0; i= 1000000000) { next.tv_nsec -= 1000000000; next.tv_sec++; } } + if (opt.count != 0 && count >= opt.count) { + if (allsent.tv_sec == 0) + allsent = now; + timespec_subtract(&diff, &now, &allsent); + if (diff.tv_sec >= 1) + finish_flag = 1; + } } - printf("\rMessage %d\n", count); + print_progress(); + if (!opt.quiet) + printf("\n"); + + stats.lost = msg_in_progress; 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]); - if (opt.histogram) { - histogram_fprint(&histogram, opt.histogram); - fclose(opt.histogram); + histogram_fprint(&histogram, opt.f_hist); + histogram_fprint(&histogram_gw, opt.f_hist_gw); + if (opt.f_hist) + fclose(opt.f_hist); + if (opt.f_hist_gw) + fclose(opt.f_hist_gw); + if (opt.f_msgs) + fclose(opt.f_msgs); + + if (opt.f_stat) { + struct histogram_stats hs; + fprintf(opt.f_stat, "cmdline='"); + for (i=0; i