X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/033225b0b43658326dc10859d1573ceb8d166c16..481e40ab64b66837af06aaefb14a2d8b45c01530:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index e32f960..b3f2002 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -10,8 +10,11 @@ #include #include #include +#include +#include #include #include +#include #include #include #include @@ -19,21 +22,21 @@ #include #include #include +#include +#include +#include #include #include -//#include +#include #include -#include -#include -#include + #include #include -#include -#include -#include #include "histogram.h" +//#define FTRACE + #ifndef DEBUG #define dbg(level, fmt, arg...) do {} while (0) #else @@ -56,16 +59,22 @@ struct options { unsigned timeout_ms; unsigned count; unsigned oneattime; - char *file; - char *histogram_fn; -} opt = { + FILE *file; + FILE *histogram; + int length; + int userhist; +}; + +struct options opt = { .id = 10, .period_us = 0, .timeout_ms = 1000, - + .length = 2, }; int num_interfaces = 0; +int count = 0; /* Number of sent messages */ +int completion_pipe[2]; struct msg_info { canid_t id; @@ -73,23 +82,53 @@ struct msg_info { struct timespec ts_sent, ts_sent_kern; struct timespec ts_rx_onwire, ts_rx_onwire_kern; struct timespec ts_rx_final, ts_rx_final_kern; + struct can_frame sent, received; }; #define MAX_INFOS 10000 struct msg_info msg_infos[MAX_INFOS]; -uint16_t curr_msg = 0; struct histogram histogram; +void sprint_canframe(char *buf , struct can_frame *cf, int sep) { + /* documentation see lib.h */ + + int i,offset; + int dlc = (cf->can_dlc > 8)? 8 : cf->can_dlc; + + if (cf->can_id & CAN_ERR_FLAG) { + sprintf(buf, "%08X#", cf->can_id & (CAN_ERR_MASK|CAN_ERR_FLAG)); + offset = 9; + } else if (cf->can_id & CAN_EFF_FLAG) { + sprintf(buf, "%08X#", cf->can_id & CAN_EFF_MASK); + offset = 9; + } else { + sprintf(buf, "%03X#", cf->can_id & CAN_SFF_MASK); + offset = 4; + } + + if (cf->can_id & CAN_RTR_FLAG) /* there are no ERR frames with RTR */ + sprintf(buf+offset, "R"); + else + for (i = 0; i < dlc; i++) { + sprintf(buf+offset, "%02X", cf->data[i]); + offset += 2; + if (sep && (i+1 < dlc)) + sprintf(buf+offset++, "."); + } +} + static inline struct msg_info *frame2info(struct can_frame *frame) { uint16_t idx; - if (frame->can_dlc == 2) { + if (frame->can_dlc >= 2) { memcpy(&idx, frame->data, sizeof(idx)); if (idx >= MAX_INFOS) error(1, 0, "%s idx too high", __FUNCTION__); - } else + } else { + error(1, 0, "%s error", __FUNCTION__); + } return &msg_infos[idx]; } @@ -99,28 +138,56 @@ static inline char *tstamp_str(const void *ctx, struct timespec *tstamp) tstamp->tv_sec, tstamp->tv_nsec/1000); } -void print_msg_info(struct msg_info *mi) +void msg_info_print(FILE *f, struct msg_info *mi) { struct timespec diff; void *local = talloc_new (NULL); - + static long num = 0; + char sent[64], received[64]; + + 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) - printf("%s -> %s (%s) = %s (%s)\n", - S(mi->ts_sent), S(mi->ts_rx_final_kern), S(mi->ts_rx_final), - DIFF(mi->ts_sent, mi->ts_rx_onwire_kern), - DIFF(mi->ts_sent, mi->ts_rx_onwire)); + + if (num_interfaces == 2) + fprintf(f, "%ld: %s %s -> %s (%s) %s = %s (%s)\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 - printf("%s -> %s (%s) -> %s (%s) = %s (%s), %s (%s)\n", - S(mi->ts_sent), - S(mi->ts_rx_onwire_kern), S(mi->ts_rx_onwire), - S(mi->ts_rx_final_kern), S(mi->ts_rx_final), - 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)); + fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%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)); +#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); @@ -129,7 +196,7 @@ void print_msg_info(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) { struct timespec ylocal = *yy, *y = &ylocal; @@ -144,12 +211,12 @@ int timespec_subtract (struct timespec *result, struct timespec *x, struct times y->tv_nsec += 1000000000 * nsec; y->tv_sec -= nsec; } - + /* Compute the time remaining to wait. `tv_nsec' is certainly positive. */ result->tv_sec = x->tv_sec - y->tv_sec; result->tv_nsec = x->tv_nsec - y->tv_nsec; - + /* Return 1 if result is negative. */ return x->tv_sec < y->tv_sec; } @@ -163,7 +230,16 @@ void dbg_print_timespec(char *msg, struct timespec *tv) static inline unsigned get_msg_latency_us(struct msg_info *mi) { struct timespec diff; - timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_rx_onwire_kern); + if (num_interfaces == 3) + if (opt.userhist) + timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_rx_onwire_kern); + else + timespec_subtract(&diff, &mi->ts_rx_final, &mi->ts_rx_onwire); + else + 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; } @@ -192,7 +268,7 @@ static inline int sock_get_if_index(int s, const char *if_name) { struct ifreq ifr; MEMSET_ZERO(ifr); - + strcpy(ifr.ifr_name, if_name); if (ioctl(s, SIOCGIFINDEX, &ifr) < 0) error(1, errno, "SIOCGIFINDEX '%s'", if_name); @@ -204,19 +280,104 @@ static inline get_tstamp(struct timespec *ts) clock_gettime(CLOCK_REALTIME, ts); } + +int trace_fd = -1; +int marker_fd = -1; + +int init_ftrace() +{ +#ifdef FTRACE + char *debugfs; + char path[256]; + FILE *f; + + debugfs = "/sys/kernel/debug"; + if (debugfs) { + strcpy(path, debugfs); + strcat(path,"/tracing/tracing_on"); + trace_fd = open(path, O_WRONLY); + if (trace_fd >= 0) + write(trace_fd, "1", 1); + + strcpy(path, debugfs); + strcat(path,"/tracing/trace_marker"); + marker_fd = open(path, O_WRONLY); + + strcpy(path, debugfs); + strcat(path,"/tracing/set_ftrace_pid"); + f = fopen(path, "w"); + fprintf(f, "%d\n", getpid()); + fclose(f); + system("echo function_graph > /sys/kernel/debug/tracing/current_tracer"); + system("echo can_send > /sys/kernel/debug/tracing/set_graph_function"); + system("echo > /sys/kernel/debug/tracing/trace"); + system("echo 1 > /sys/kernel/debug/tracing/tracing_enabled"); + } +#endif /* FTRACE */ +} + +static inline void trace_on() +{ + if (trace_fd >= 0) + write(trace_fd, "1", 1); +} + +static inline void trace_off(int ret) +{ + if (marker_fd >= 0) { + char marker[100]; + sprintf(marker, "write returned %d\n", ret); + write(marker_fd, marker, strlen(marker)); + } + if (trace_fd >= 0) + write(trace_fd, "0", 1); +} + +void msg_info_free(struct msg_info *mi) +{ + mi->id = -1; +} + int send_frame(int socket) { struct can_frame frame; struct msg_info *mi; int ret; + static int curr_msg = -1; + int i; + uint16_t idx; + + MEMSET_ZERO(frame); + i = curr_msg+1; + while (msg_infos[i].id != -1 && i != curr_msg) { + i++; + if (i >= MAX_INFOS) + i = 0; + } + if (i == curr_msg) + error(1, 0, "Msg info table is full! Probably, many packets were lost."); + else + curr_msg = i; frame.can_id = opt.id; - frame.can_dlc = 2; - memcpy(frame.data, &curr_msg, sizeof(curr_msg)); + if (opt.length < 2) + error(1, 0, "Length < 2 is not yet supported"); + frame.can_dlc = opt.length; + idx = curr_msg; + memcpy(frame.data, &idx, sizeof(idx)); mi = frame2info(&frame); + mi->id = frame.can_id; + 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) + msg_info_free(mi); return ret; } @@ -226,7 +387,7 @@ static inline void get_next_timeout(struct timespec *timeout) static struct timespec last = {-1, 0 }; clock_gettime(CLOCK_MONOTONIC, &now); - + if (last.tv_sec == -1) last = now; if (opt.period_us != 0) { @@ -235,7 +396,7 @@ static inline void get_next_timeout(struct timespec *timeout) while (last.tv_nsec >= 1000000000) { last.tv_nsec -= 1000000000; last.tv_sec++; - } + } timespec_subtract(timeout, &last, &now); } else if (opt.timeout_ms != 0) { timeout->tv_sec = opt.timeout_ms/1000; @@ -263,7 +424,7 @@ void receive(int s, struct can_frame *frame, struct timespec *ts_kern, struct ti /* these settings may be modified by recvmsg() */ iov.iov_len = sizeof(*frame); msg.msg_namelen = sizeof(addr); - msg.msg_controllen = sizeof(ctrlmsg); + msg.msg_controllen = sizeof(ctrlmsg); msg.msg_flags = 0; nbytes = recvmsg(s, &msg, 0); @@ -308,16 +469,20 @@ void process_final_rx(int s) struct timespec ts_kern, ts_user, ts_diff; 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_fn) + if (opt.histogram) histogram_add(&histogram, get_msg_latency_us(mi)); - if (!opt.file) - print_msg_info(mi); + ret = write(completion_pipe[1], &mi, sizeof(mi)); + if (ret == -1) + error(1, errno, "completion_pipe write"); } void *measure_thread(void *arg) @@ -327,11 +492,10 @@ void *measure_thread(void *arg) struct timespec timeout; struct sockaddr_can addr; sigset_t set; - int count = 0; unsigned msg_in_progress = 0; MEMSET_ZERO(pfd); - + for (i=0; i"); @@ -467,13 +639,23 @@ 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) error(1, 0, "%s: %s\n", 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"); @@ -490,36 +672,79 @@ int main(int argc, const char *argv[]) { pthread_t thread; sigset_t set; - int ret; - FILE *fhist; - + int ret, i; + parse_options(argc, argv); - + mlockall(MCL_CURRENT | MCL_FUTURE); signal(SIGINT, term_handler); signal(SIGTERM, term_handler); - if (opt.histogram_fn) { - histogram_init(&histogram, 1000000, 5); - fhist = fopen(opt.histogram_fn, "w"); - if (fhist == NULL) - error(1, errno, "open %s", opt.histogram_fn); + for (i=0; i 0 && (pfd[0].revents & POLLIN)) { + struct msg_info *mi; + int ret; + ret = read(completion_pipe[0], &mi, sizeof(mi)); + if (ret < sizeof(mi)) + error(1, errno, "read completion returned %d", ret); + if (opt.file) + msg_info_print(opt.file, mi); + msg_info_free(mi); + completed++; + } + + clock_gettime(CLOCK_MONOTONIC, &now); + if (timespec_subtract(&diff, &next, &now)) { + printf("\rMessage %d", count); + fflush(stdout); + next.tv_nsec += 100000000; + while (next.tv_nsec >= 1000000000) { + next.tv_nsec -= 1000000000; + next.tv_sec++; + } + } + } + printf("\rMessage %d\n", count); pthread_join(thread, NULL); - if (opt.histogram_fn) { - histogram_fprint(&histogram, fhist); - fclose(fhist); + close(completion_pipe[0]); + close(completion_pipe[1]); + + if (opt.histogram) { + histogram_fprint(&histogram, opt.histogram); + fclose(opt.histogram); } - + if (opt.file) + fclose(opt.file); + return 0; }