X-Git-Url: http://rtime.felk.cvut.cz/gitweb/can-benchmark.git/blobdiff_plain/467e092776691683b297e1328281cded11717298..dc7f5a3374014b178414d75c09b9484403f186cc:/latester/latester.c diff --git a/latester/latester.c b/latester/latester.c index 0906760..b396fd2 100644 --- a/latester/latester.c +++ b/latester/latester.c @@ -1,9 +1,10 @@ -/**************************************************************************/ -/* CAN latency tester */ -/* Copyright (C) 2010, 2011, 2012, 2013 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" @@ -91,6 +94,7 @@ 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; @@ -99,7 +103,6 @@ struct msg_info { struct timespec ts_rx_onwire, ts_rx_onwire_kern; struct timespec ts_rx_final, ts_rx_final_kern; struct can_frame sent, received; - unsigned lat_measured_us, tx_time_us; }; #define MAX_INFOS 10000 @@ -160,179 +163,27 @@ 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; -} - -uint32_t calc_bitmap_crc(uint32_t *bitmap, unsigned start, unsigned end) -{ - crc_t crc = 0; - 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); /* FIXME: This seems to be broken for end < 64 */ - crc = crc_update(crc, bitmap[3], end > 96 ? end - 96 : 0); - return (uint32_t)htons(crc << 17); -} - -void write_crc_to_bitmap(uint32_t crc, uint32_t *bitmap, struct can_frame *frame) -{ - unsigned index = frame->can_id & CAN_EFF_FLAG ? 2 : 1; - if (frame->can_dlc < 4) - bitmap[index] |= crc >> (frame->can_dlc*8); - if (frame->can_dlc == 3) - bitmap[index + 1] |= crc << 8; - if (frame->can_dlc >= 4 && frame->can_dlc < 8) - { - bitmap[index + 1] |= crc >> (frame->can_dlc*8); - if (frame->can_dlc == 7) - bitmap[index + 2] = crc << 8; - } - else if (frame->can_dlc == 8) - bitmap[index + 2] = 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)); - uint32_t crc; - -/* char received[64]; */ -/* sprint_canframe(received, frame, true); */ -/* printf("Frame: %s\n", received); */ - - if (frame->can_id & CAN_EFF_FLAG) { - // bit 31 0 - // [0] |...........................sBBBB| s = SOF, B = Base ID (11 bits) - // [1] |BBBBBBBSIEEEEEEEEEEEEEEEEEER10DLC4| S = SRR, I = IDE, E = Extended ID (18 bits), DLC4 = DLC - // [2] |00000000111111112222222233333333| Data bytes, MSB first - // [3] |44444444555555556666666677777777| - 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; - memcpy(&bitmap[2], &frame->data, frame->can_dlc); - start = 27; - end = 64 + 8*frame->can_dlc; - } else { - // bit 31 0 - // [0] |.............sIIIIIIIIIIIRE0DLC4| s = SOF, I = ID (11 bits), R = RTR, E = IDE, DLC4 = DLC - // [1] |00000000111111112222222233333333| Data bytes, MSB first - // [2] |44444444555555556666666677777777| - bitmap[0] = - (frame->can_id << 7) | - (!!(frame->can_id & CAN_RTR_FLAG)) << 6 | - 0 << 4 | - frame->can_dlc & 0xf; - memcpy(&bitmap[1], &frame->data, frame->can_dlc); - start = 13; - end = 32 + 8*frame->can_dlc; - } - crc = calc_bitmap_crc(bitmap, start, end); - write_crc_to_bitmap(crc, bitmap, frame); - end += 15; - - 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); - return stuffed; -} +int timespec_subtract (struct timespec *result, const struct timespec *x, const struct timespec *yy); -unsigned calc_frame_txtime_us(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 */ -} +static inline unsigned get_timestamp_diff_us(struct msg_info *mi); -void msg_info_print(FILE *f, 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); @@ -345,10 +196,10 @@ void msg_info_print(FILE *f, struct msg_info *mi) 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), - mi->tx_time_us); + tx_time_us); break; case 3: - fprintf(f, "%ld: %s %s -> %s (%s) -> %s (%s) %s = %s (%s), %s (%s) %d\n", + 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, @@ -356,7 +207,8 @@ void msg_info_print(FILE *f, struct msg_info *mi) 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), - mi->tx_time_us); + tx_time_us, + 1e-6*(diff_us - tx_time_us)); break; } #undef S @@ -368,7 +220,7 @@ void msg_info_print(FILE *f, 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) +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. */ @@ -398,7 +250,7 @@ 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 void calc_msg_latencies(struct msg_info *mi) +static inline unsigned get_timestamp_diff_us(struct msg_info *mi) { struct timespec diff; switch (num_interfaces) { @@ -415,10 +267,10 @@ static inline void calc_msg_latencies(struct msg_info *mi) timespec_subtract(&diff, &mi->ts_rx_final_kern, &mi->ts_sent); break; default: - return; + return 0; } - mi->lat_measured_us = diff.tv_sec * 1000000 + diff.tv_nsec/1000; - mi->tx_time_us = calc_frame_txtime_us(&mi->received); + unsigned us = diff.tv_sec * 1000000 + diff.tv_nsec/1000; + return us; } void set_sched_policy_and_prio(int policy, int rtprio) @@ -453,16 +305,16 @@ 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; @@ -564,7 +416,7 @@ int send_frame(int socket) return ret; } -static inline send_and_check(int s) +static inline void send_and_check(int s) { int ret; ret = send_frame(s); @@ -580,26 +432,34 @@ static inline send_and_check(int s) } } -static inline void get_next_timeout(struct timespec *timeout) +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; @@ -616,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; @@ -641,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; + } } } @@ -656,7 +527,7 @@ 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); @@ -671,7 +542,7 @@ void process_on_wire_rx(int s) 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; @@ -682,23 +553,73 @@ void process_final_rx(int s) mi->ts_rx_final = ts_user; mi->received = frame; - calc_msg_latencies(mi); - - histogram_add(&histogram, mi->lat_measured_us); - histogram_add(&histogram_gw, mi->lat_measured_us - mi->tx_time_us); - 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; int consecutive_timeouts = 0; MEMSET_ZERO(pfd); @@ -722,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, @@ -739,6 +670,9 @@ 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() send_and_check(pfd[0].fd) @@ -747,11 +681,12 @@ void *measure_thread(void *arg) SEND(); 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); @@ -804,7 +739,7 @@ void *measure_thread(void *arg) } } if (pfd[i].revents & ~POLLIN) - error(1, 0, "Unexpected pfd[%d].revents: 0x%04x\n", pfd[i].revents); + error(1, 0, "Unexpected pfd[%d].revents: 0x%04x\n", i, pfd[i].revents); } } @@ -907,7 +842,6 @@ void print_progress() int main(int argc, const char *argv[]) { pthread_t thread; - sigset_t set; int ret, i; parse_options(argc, argv); @@ -957,7 +891,8 @@ int main(int argc, const char *argv[]) ret = read(completion_pipe[0], &mi, sizeof(mi)); if (ret < sizeof(mi)) error(1, errno, "read completion returned %d", ret); - msg_info_print(opt.f_msgs, mi); + + msg_info_process(opt.f_msgs, mi); msg_info_free(mi); completed++; } @@ -1008,6 +943,7 @@ int main(int argc, const char *argv[]) fclose(opt.f_msgs); if (opt.f_stat) { + struct histogram_stats hs; fprintf(opt.f_stat, "cmdline='"); for (i=0; i