X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/fd2a01bc8a84835da407d8a1003b84028497ed5a..43d1fc38b83d1aadfd22263a5930caaf8e0c584c:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index c94837c..6a78872 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -35,6 +35,8 @@ #include "histogram.h" +//#define FTRACE + #ifndef DEBUG #define dbg(level, fmt, arg...) do {} while (0) #else @@ -57,9 +59,14 @@ struct options { unsigned timeout_ms; unsigned count; unsigned oneattime; - FILE *file; - FILE *histogram; + char *name; int length; + int userhist; + + /* Temporary variables */ + FILE *f_msgs; + FILE *f_hist; + FILE *f_stat; }; struct options opt = { @@ -69,8 +76,15 @@ struct options opt = { .length = 2, }; +struct { + unsigned enobufs; + unsigned overrun; + unsigned lost; +} stats; + int num_interfaces = 0; int count = 0; /* Number of sent messages */ +unsigned msg_in_progress = 0; int completion_pipe[2]; struct msg_info { @@ -87,14 +101,32 @@ struct msg_info msg_infos[MAX_INFOS]; struct histogram histogram; -int can_frame_sprintf(char *buf, struct can_frame *frame) -{ - char datastr[17]; - int i; - for (i=0; i<8; i++) - sprintf(&datastr[i*2], "%02x", frame->data[i]); - sprintf(buf, "id=0x%x, len=%d, data=%s", - frame->can_id, frame->can_dlc, datastr); +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) @@ -105,7 +137,7 @@ 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]; @@ -124,19 +156,19 @@ void msg_info_print(FILE *f, struct msg_info *mi) static long num = 0; char sent[64], received[64]; - can_frame_sprintf(sent, &mi->sent); - can_frame_sprintf(received, &mi->received); + 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", + 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 - fprintf(f, "%ld: %s [%s] -> %s (%s) -> %s (%s) [%s] = %s (%s), %s (%s)\n", + 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, @@ -210,9 +242,15 @@ 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); + 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 - timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent); + 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; } @@ -250,7 +288,65 @@ 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); +} + +void msg_info_free(struct msg_info *mi) +{ + mi->id = -1; } int send_frame(int socket) @@ -264,7 +360,7 @@ int send_frame(int socket) MEMSET_ZERO(frame); i = curr_msg+1; - while (msg_infos[i].id != 0 && i != curr_msg) { + while (msg_infos[i].id != -1 && i != curr_msg) { i++; if (i >= MAX_INFOS) i = 0; @@ -286,13 +382,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) + 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) @@ -311,7 +424,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; @@ -384,15 +500,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) @@ -406,7 +521,6 @@ void *measure_thread(void *arg) struct timespec timeout; struct sockaddr_can addr; sigset_t set; - unsigned msg_in_progress = 0; MEMSET_ZERO(pfd); @@ -446,21 +560,12 @@ 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; - } while (!finish_flag && (opt.count == 0 || count < opt.count || msg_in_progress != 0)) { @@ -525,9 +630,9 @@ struct poptOption optionsTable[] = { { "timeout",'t', POPT_ARG_INT|POPT_ARGFLAG_SHOW_DEFAULT, &opt.timeout_ms,0, "Timeout when period is zero", "ms"}, { "oneattime",'o', POPT_ARG_NONE, &opt.oneattime,0, "Send the next message only when the previous was finally received"}, { "verbose",'v', POPT_ARG_NONE, NULL, 'v', "Send the next message only when the previous was finally received"}, - { "file", 'f', POPT_ARG_STRING, NULL, 'f', "File where to store results", "filename"}, - { "histogram", 'h', POPT_ARG_STRING, NULL, 'h', "Store histogram in file", "filename"}, + { "name", 'n', POPT_ARG_STRING, &opt.name, 0, "Prefix of the generated files"}, { "length", 'l', POPT_ARG_INT|POPT_ARGFLAG_SHOW_DEFAULT, &opt.length, 0, "The length of generated messages", "bytes"}, + { "userhist", 'u', POPT_ARG_NONE, &opt.userhist, 0, "Generate histogram from userspace timestamps"}, POPT_AUTOHELP { NULL, 0, 0, NULL, 0 } }; @@ -536,6 +641,7 @@ int parse_options(int argc, const char *argv[]) { int c; poptContext optCon; /* context for parsing command-line options */ + void *local = talloc_new (NULL); optCon = poptGetContext(NULL, argc, argv, optionsTable, 0); //poptSetOtherOptionHelp(optCon, "[OPTIONS]* "); @@ -546,16 +652,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) @@ -569,17 +665,43 @@ int parse_options(int argc, const char *argv[]) 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() +{ + printf("\rSent %5d, in progress %5d", count, msg_in_progress); + fflush(stdout); +} int main(int argc, const char *argv[]) { pthread_t thread; sigset_t set; - int ret; + int ret, i; parse_options(argc, argv); @@ -588,9 +710,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(); + printf("\n"); + + stats.lost = msg_in_progress; pthread_join(thread, NULL); 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, "sent=%d\n", count); + fprintf(opt.f_stat, "overrun=%d\n", stats.overrun); + if (stats.overrun) + printf("overrun=%d\n", stats.overrun); + fprintf(opt.f_stat, "enobufs=%d\n", stats.enobufs); + if (stats.enobufs) + printf("enobufs=%d\n", stats.enobufs); + fprintf(opt.f_stat, "lost=%d\n", stats.lost); + if (stats.lost) + printf("lost=%d\n", stats.lost); + + fclose(opt.f_stat); return 0; }