X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/3406f77a4d776d415515ad718c7b44482db075b3..b0d0a09235093cf11fbe83ce502d7079bc255f7e:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index 85288f7..30e62f1 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -1,6 +1,6 @@ /**************************************************************************/ /* CAN latency tester */ -/* Copyright (C) 2010 Michal Sojka, DCE FEE CTU Prague */ +/* Copyright (C) 2010, 2011 Michal Sojka, DCE FEE CTU Prague */ /* License: GPLv2 */ /**************************************************************************/ @@ -35,6 +35,8 @@ #include "histogram.h" +//#define FTRACE + #ifndef DEBUG #define dbg(level, fmt, arg...) do {} while (0) #else @@ -57,9 +59,15 @@ 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_stat; }; struct options opt = { @@ -69,8 +77,18 @@ struct options opt = { .length = 2, }; +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 msg_info { @@ -115,7 +133,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) { @@ -123,10 +141,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) @@ -135,6 +158,139 @@ static inline char *tstamp_str(const void *ctx, struct timespec *tstamp) tstamp->tv_sec, tstamp->tv_nsec/1000); } +/* Functions and types for CRC checks. + * + * Generated on Wed Sep 21 22:30:11 2011, + * by pycrc v0.7.8, http://www.tty1.net/pycrc/ + * using the configuration: + * Width = 15 + * Poly = 0x4599 + * XorIn = 0x0000 + * ReflectIn = False + * XorOut = 0x0000 + * ReflectOut = False + * Algorithm = table-driven + *****************************************************************************/ +typedef uint16_t crc_t; + +static const crc_t crc_table[2] = { + 0x0000, 0x4599 +}; + +crc_t crc_update(crc_t crc, uint32_t data, size_t bit_len) +{ + unsigned int tbl_idx; +/* crc_t bc = crc; */ +/* uint32_t bd = data; */ +/* size_t bl = bit_len; */ + + while (bit_len--) { + tbl_idx = (crc >> 14) ^ (data >> 31); + crc = crc_table[tbl_idx & 0x01] ^ (crc << 1); + data <<= 1; + } + crc = crc & 0x7fff; +/* printf("crc: 0x%04x -> 0x%04x data: 0x%08x len: %d\n", */ +/* bc, crc, bd, bl); */ + return crc; +} + +unsigned calc_stuff_bits(struct can_frame *frame) { + uint32_t bitmap[4]; + unsigned start = 0, end; + uint32_t mask, ones = 0, basemask = 0xf8000000; + unsigned stuffed = 0; + memset(bitmap, 0, sizeof(bitmap)); + crc_t crc = 0; + uint32_t crcx; + + if (frame->can_id & CAN_EFF_FLAG) { + bitmap[0] = + ((frame->can_id & CAN_EFF_MASK) >> 25); + bitmap[1] = + ((frame->can_id & CAN_EFF_MASK) >> 18) << 25 | + 3 << 23 | + ((frame->can_id & CAN_EFF_MASK) & 0x3ffff) << 7 | + (!!(frame->can_id & CAN_RTR_FLAG)) << 6 | + 0 << 4 | + frame->can_dlc & 0xf; + bitmap[2] = htonl(((uint32_t*)frame->data)[0]); + bitmap[3] = htonl(((uint32_t*)frame->data)[1]); + start = 27; + end = 64 + 8*frame->can_dlc; + crc = crc_update(crc, bitmap[0] << start, 32-start); + crc = crc_update(crc, bitmap[1], 32); + crc = crc_update(crc, bitmap[2], end - 64 > 32 ? 32 : end - 64); + crc = crc_update(crc, bitmap[3], end > 96 ? end - 96 : 0); + crcx = (uint32_t)htons(crc) << 17; + if (frame->can_dlc < 4) + bitmap[2] |= crcx >> (frame->can_dlc*8); + if (frame->can_dlc = 3) + bitmap[3] |= crcx << 8; + if (frame->can_dlc >= 4) + bitmap[3] |= crcx >> (frame->can_dlc*8); + } else { + bitmap[0] = + (frame->can_id << 7) | + (!!(frame->can_id & CAN_RTR_FLAG)) << 6 | + 0 << 4 | + frame->can_dlc & 0xf; + bitmap[1] = htonl(((uint32_t*)frame->data)[0]); + bitmap[2] = htonl(((uint32_t*)frame->data)[1]); + start = 13; + end = 32 + 8*frame->can_dlc; + } + /* TODO: Calc stuff bits in CRC */ + while (start < end) { + mask = basemask >> (start & 0x1f); + while (1) { + ones = ones ? mask : 0; + uint32_t chunk = (bitmap[start >> 5] & mask) ^ ones; + //printf("start=%d bitmap=0x%08x mask=0x%08x ones=0x%08x chunk=0x%08x\n", start, bitmap[start >> 5], mask, ones, chunk); + if (chunk) { + unsigned change = __builtin_clz(chunk); + start = start & ~0x1f | change; + basemask = 0xf8000000; + } else { + unsigned oldstart = start; + start += __builtin_popcount(mask); + mask = (oldstart & 0x1f) ? basemask << (-oldstart & 0x1f) : 0; + //printf("oldstart=%d shl=%d mask=0x%08x\n", oldstart, -oldstart & 0x1f, mask); + if (mask && start < end) + continue; + if (start <= end && !mask) { + stuffed++; + basemask = 0xf0000000; + //printf("stuffed %d\n", !ones); + } + } + break; + } + ones = !ones; + } + //printf ("STUFFED %d BITS\n", stuffed); +} + +unsigned calc_frame_txtime(struct can_frame *frame) { + return calc_stuff_bits(frame) + + 1 + /* SOF */ + 11 + /* ID A */ + ((frame->can_id & CAN_EFF_FLAG) ? + 1 + /* SRR */ + 1 + /* IDE */ + 18 + /* ID B */ + 1 + /* RTR */ + 2 /* r1, r0 */ + : + 1 + /* rtr */ + 2) + /* ide, r0 */ + 4 + /* dlc */ + 8*frame->can_dlc + + 15 + /* CRC */ + 3 + /* CRC del, ACK, ACK del */ + 7; /* EOF */ +} + void msg_info_print(FILE *f, struct msg_info *mi) { struct timespec diff; @@ -148,49 +304,32 @@ void msg_info_print(FILE *f, struct msg_info *mi) #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), + calc_frame_txtime(&mi->received)); + break; + case 3: + fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s) %d\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), + calc_frame_txtime(&mi->received)); + 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. */ @@ -227,10 +366,22 @@ void dbg_print_timespec(char *msg, struct timespec *tv) static inline unsigned get_msg_latency_us(struct msg_info *mi) { struct timespec diff; - if (num_interfaces == 3) - timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_rx_onwire_kern); - else - timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent); + 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); + 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); + break; + default: + return 0; + } return diff.tv_sec * 1000000 + diff.tv_nsec/1000; } @@ -268,7 +419,70 @@ static inline int sock_get_if_index(int s, const char *if_name) static inline get_tstamp(struct timespec *ts) { - clock_gettime(CLOCK_MONOTONIC, 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); +} + +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) @@ -282,7 +496,7 @@ int send_frame(int socket) MEMSET_ZERO(frame); i = curr_msg+1; - while (msg_infos[i].id != 0 && i != curr_msg) { + while (msg_info_used(&msg_infos[i]) && i != curr_msg) { i++; if (i >= MAX_INFOS) i = 0; @@ -304,13 +518,30 @@ 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 || num_interfaces == 1) + msg_info_free(mi); return ret; } -void msg_info_free(struct msg_info *mi) +static inline send_and_check(int s) { - mi->id = 0; + 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) @@ -329,7 +560,10 @@ static inline void get_next_timeout(struct timespec *timeout) last.tv_nsec -= 1000000000; last.tv_sec++; } - timespec_subtract(timeout, &last, &now); + if (timespec_subtract(timeout, &last, &now) /* is negative */) { + stats.overrun++; + memset(timeout, 0, sizeof(*timeout)); + } } else if (opt.timeout_ms != 0) { timeout->tv_sec = opt.timeout_ms/1000; timeout->tv_nsec = (opt.timeout_ms%1000)*1000000; @@ -391,8 +625,11 @@ void process_on_wire_rx(int s) 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++; } @@ -402,15 +639,14 @@ void process_final_rx(int s) 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)); + histogram_add(&histogram, get_msg_latency_us(mi)); ret = write(completion_pipe[1], &mi, sizeof(mi)); if (ret == -1) @@ -424,7 +660,7 @@ void *measure_thread(void *arg) struct timespec timeout; struct sockaddr_can addr; sigset_t set; - unsigned msg_in_progress = 0; + int consecutive_timeouts = 0; MEMSET_ZERO(pfd); @@ -464,21 +700,14 @@ void *measure_thread(void *arg) pfd[i].events = POLLIN; } - set_sched_policy_and_prio(SCHED_FIFO, 99); + set_sched_policy_and_prio(SCHED_FIFO, 40); -#define SEND() \ - do { \ - ret = send_frame(pfd[0].fd); \ - if (ret != sizeof(struct can_frame)) \ - error(1, errno, "send_frame (line %d)", __LINE__); \ - count++; \ - msg_in_progress++; \ - } while (0) +#define SEND() send_and_check(pfd[0].fd) - if (opt.oneattime) { + if (opt.oneattime) SEND(); - count = 1; - } + + get_tstamp(&stats.tic); while (!finish_flag && (opt.count == 0 || count < opt.count || msg_in_progress != 0)) { @@ -498,7 +727,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 @@ -511,13 +746,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; @@ -526,9 +764,13 @@ void *measure_thread(void *arg) SEND(); } } + if (pfd[i].revents & ~POLLIN) + error(1, 0, "Unexpected pfd[%d].revents: 0x%04x\n", pfd[i].revents); } } + get_tstamp(&stats.tac); + for (i=0; i"); @@ -564,16 +808,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) @@ -581,23 +815,54 @@ 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.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-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; + int ret, i; parse_options(argc, argv); @@ -606,9 +871,10 @@ int main(int argc, const char *argv[]) signal(SIGINT, term_handler); signal(SIGTERM, term_handler); - if (opt.histogram) { - histogram_init(&histogram, 5000000, 1); - } + 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); - } - if (opt.file) - fclose(opt.file); + histogram_fprint(&histogram, opt.f_hist); + fclose(opt.f_hist); + fclose(opt.f_msgs); + + + fprintf(opt.f_stat, "cmdline='"); + for (i=0; i