]> rtime.felk.cvut.cz Git - can-benchmark.git/blobdiff - latester/latester.c
Do not call poll with negative timeout
[can-benchmark.git] / latester / latester.c
index 3df0a6c46c18786a22aa203d0851a200e26afde9..c980f247ac9841b3aa4755aa3966880c2550865e 100644 (file)
@@ -35,6 +35,8 @@
 
 #include "histogram.h"
 
+//#define FTRACE
+
 #ifndef DEBUG
 #define dbg(level, fmt, arg...) do {} while (0)
 #else
@@ -59,15 +61,22 @@ struct options {
        unsigned oneattime;
        FILE *file;
        FILE *histogram;
+       int length;
+       int userhist;
 };
 
 struct options opt = {
        .id = 10,
        .period_us = 0,
        .timeout_ms = 1000,
-
+       .length = 2,
 };
 
+struct {
+       unsigned enobufs;
+       unsigned overrun;
+} stats;
+
 int num_interfaces = 0;
 int count = 0;                 /* Number of sent messages */
 int completion_pipe[2];
@@ -78,6 +87,7 @@ 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
@@ -85,15 +95,45 @@ struct msg_info msg_infos[MAX_INFOS];
 
 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];
 }
 
@@ -107,26 +147,32 @@ 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)
-               fprintf(f, "%s -> %s (%s) = %s (%s)\n",
-                      S(mi->ts_sent), S(mi->ts_rx_final_kern), S(mi->ts_rx_final),
+               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, "%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);
 }
 
@@ -134,17 +180,18 @@ 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, "%d %d %s\n",
-                       mi->id, mi->length,
+               fprintf(f, "%ld %d %d %s\n",
+                       num, mi->id, mi->length,
                        DIFF(mi->ts_sent, mi->ts_rx_final_kern));
        else
-               fprintf(f, "%d %d %s\n",
-                       mi->id, mi->length,
+               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
@@ -189,9 +236,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;
 }
 
@@ -232,6 +285,64 @@ 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;
@@ -240,9 +351,10 @@ int send_frame(int socket)
        static int curr_msg = -1;
        int i;
        uint16_t idx;
-       
+
+       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;
@@ -253,7 +365,9 @@ int send_frame(int socket)
                curr_msg = i;
 
        frame.can_id = opt.id;
-       frame.can_dlc = 2;
+       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);
@@ -261,13 +375,15 @@ int send_frame(int socket)
        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));
-       return ret;
-}
+       trace_off(ret);
 
-void msg_info_free(struct msg_info *mi)
-{
-       mi->id = 0;
+       if (ret == -1)
+               msg_info_free(mi);
+       return ret;
 }
 
 static inline void get_next_timeout(struct timespec *timeout)
@@ -286,7 +402,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;
@@ -364,6 +483,7 @@ void process_final_rx(int s)
        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));
@@ -420,15 +540,22 @@ void *measure_thread(void *arg)
                        pfd[i].events = POLLIN;
        }
 
-       set_sched_policy_and_prio(SCHED_FIFO, 99);
-
-#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++;                      \
+       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) {
@@ -501,6 +628,8 @@ struct poptOption optionsTable[] = {
        { "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"},
+       { "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 }
 };
@@ -552,7 +681,7 @@ int main(int argc, const char *argv[])
 {
        pthread_t thread;
        sigset_t set;
-       int ret;
+       int ret, i;
 
        parse_options(argc, argv);
 
@@ -561,8 +690,11 @@ int main(int argc, const char *argv[])
        signal(SIGINT, term_handler);
        signal(SIGTERM, term_handler);
 
+       for (i=0; i<MAX_INFOS; i++)
+               msg_infos[i].id = -1;
+
        if (opt.histogram) {
-               histogram_init(&histogram, 1000000, 1);
+               histogram_init(&histogram, 5000000, 1);
        }
 
        ret = pipe(completion_pipe);
@@ -571,6 +703,8 @@ int main(int argc, const char *argv[])
        ret = fcntl(completion_pipe[1], F_SETFL, O_NONBLOCK);
        if (ret == -1)
                error(1, errno, "pipe fcntl");
+
+       init_ftrace();
        
        pthread_create(&thread, 0, measure_thread, NULL);
 
@@ -621,5 +755,10 @@ int main(int argc, const char *argv[])
        if (opt.file)
                fclose(opt.file);
 
+       if (stats.overrun)
+               printf("overrun=%d\n", stats.overrun);
+       if (stats.enobufs)
+               printf("enobufs=%d\n", stats.enobufs);
+
        return 0;
 }