Hi, This implements ping(1)-like summary statistics for tcpbench(1), e.g.
^C --- localhost tcpbench statistics --- 1099642814 bytes sent over 4.126 seconds bandwidth min/avg/max/std-dev = 1228.131/2117.309/2491.399/517.779 Mbps The std-dev especially would have helped me catch a TCP performance problem sooner last year. The patch is longish; I can split it up if wanted. Note: - the udp struct statctx singleton is now a global; this lets udp_process_slice() drop an argument to match tcp_process_slice() - adopt ping(1)'s output cosmetics on ^C - to make the client/server stats more comparable: - the udp server now computes stats from first read, not process start. - the tcp server now skips stats for slices that complete with no established connections. I'm no expert on the intricacies of floating point and I referred to [0][1][2] for the online/streaming algorithms. djm@ liked the direction; looking for oks on the code. cheers, Richard. [0] https://en.wikipedia.org/wiki/Algorithms_for_calculating_variance#Welford's_online_algorithm [1] https://nestedsoftware.com/2018/03/20/calculating-a-moving-average-on-streaming-data-5a7k.22879.html [2] https://nestedsoftware.com/2018/03/27/calculating-standard-deviation-on-streaming-data-253l.23919.html Index: Makefile =================================================================== RCS file: /cvs/src/usr.bin/tcpbench/Makefile,v retrieving revision 1.8 diff -u -p -u -p -r1.8 Makefile --- Makefile 9 Jul 2017 21:23:19 -0000 1.8 +++ Makefile 1 May 2020 09:57:26 -0000 @@ -1,7 +1,7 @@ # $OpenBSD: Makefile,v 1.8 2017/07/09 21:23:19 espie Exp $ PROG= tcpbench -LDADD= -lkvm -levent -DPADD= ${LIBKVM} ${LIBEVENT} +LDADD= -lm -lkvm -levent +DPADD= ${LIBM} ${LIBKVM} ${LIBEVENT} .include <bsd.prog.mk> Index: tcpbench.c =================================================================== RCS file: /cvs/src/usr.bin/tcpbench/tcpbench.c,v retrieving revision 1.61 diff -u -p -u -p -r1.61 tcpbench.c --- tcpbench.c 12 Feb 2020 14:46:36 -0000 1.61 +++ tcpbench.c 1 May 2020 09:57:26 -0000 @@ -50,6 +50,7 @@ #include <fcntl.h> #include <poll.h> #include <paths.h> +#include <math.h> #include <kvm.h> #include <nlist.h> @@ -101,6 +102,8 @@ struct statctx { u_long udp_slice_pkts; }; +struct statctx *udp_sc; /* singleton */ + static void signal_handler(int, short, void *); static void saddr_ntop(const struct sockaddr *, socklen_t, char *, size_t); static void drop_gid(void); @@ -114,19 +117,22 @@ static void list_kvars(void); static void check_kvar(const char *); static char ** check_prepare_kvars(char *); static void stats_prepare(struct statctx *); +static void summary_display(void); static void tcp_stats_display(unsigned long long, long double, float, struct statctx *, struct inpcb *, struct tcpcb *, struct socket *); static void tcp_process_slice(int, short, void *); static void tcp_server_handle_sc(int, short, void *); static void tcp_server_accept(int, short, void *); -static void server_init(struct addrinfo *, struct statctx *); +static void server_init(struct addrinfo *); static void client_handle_sc(int, short, void *); -static void client_init(struct addrinfo *, int, struct statctx *, - struct addrinfo *); +static void client_init(struct addrinfo *, int, struct addrinfo *); static int clock_gettime_tv(clockid_t, struct timeval *); static void udp_server_handle_sc(int, short, void *); static void udp_process_slice(int, short, void *); static int map_tos(char *, int *); +static void quit(int, short, void *); +static void wrapup(int); + /* * We account the mainstats here, that is the stats * for all connections, all variables starting with slice @@ -135,10 +141,17 @@ static int map_tos(char *, int *); * between all slices so far. */ static struct { - unsigned long long slice_bytes; /* bytes for last slice */ + struct timeval t_first; /* first connect / packet */ + unsigned long long total_bytes; /* bytes since t_first */ + unsigned long long n_slices; /* slices since start */ + unsigned long long slice_bytes; /* bytes since slice reset */ long double peak_mbps; /* peak mbps so far */ + long double floor_mbps; /* floor mbps so far */ + long double mean_mbps; /* mean mbps so far */ + long double nvariance_mbps; /* for online std dev */ int nconns; /* connected clients */ struct event timer; /* process timer */ + const char *host; /* remote server for display */ } mainstats; /* When adding variables, also add to tcp_stats_display() */ @@ -201,10 +214,13 @@ signal_handler(int sig, short event, voi */ switch (sig) { case SIGINT: + printf("\n"); + wrapup(0); + break; /* NOTREACHED */ case SIGTERM: case SIGHUP: warnx("Terminated by signal %d", sig); - exit(0); + wrapup(0); break; /* NOTREACHED */ default: errx(1, "unexpected signal %d", sig); @@ -479,7 +495,38 @@ stats_prepare(struct statctx *sc) if (clock_gettime_tv(CLOCK_MONOTONIC, &sc->t_start) == -1) err(1, "clock_gettime_tv"); sc->t_last = sc->t_start; + if (!timerisset(&mainstats.t_first)) + mainstats.t_first = sc->t_start; +} + +static void +summary_display(void) +{ + struct timeval t_cur, t_diff; + long double std_dev; + unsigned long long total_elapsed; + char *direction; + + if (!ptb->sflag) { + direction = "sent"; + printf("--- %s tcpbench statistics ---\n", mainstats.host); + } else { + direction = "received"; + printf("--- tcpbench server statistics ---\n"); + } + + std_dev = sqrtl(mainstats.nvariance_mbps / mainstats.n_slices); + + if (clock_gettime_tv(CLOCK_MONOTONIC, &t_cur) == -1) + err(1, "clock_gettime_tv"); + timersub(&t_cur, &mainstats.t_first, &t_diff); + total_elapsed = t_diff.tv_sec * 1000 + t_diff.tv_usec / 1000; + printf("%llu bytes %s over %.3Lf seconds\n", + mainstats.total_bytes, direction, total_elapsed/1000.0L); + printf("bandwidth min/avg/max/std-dev = %.3Lf/%.3Lf/%.3Lf/%.3Lf Mbps\n", + mainstats.floor_mbps, mainstats.mean_mbps, mainstats.peak_mbps, + std_dev); } static void @@ -546,7 +593,7 @@ static void tcp_process_slice(int fd, short event, void *bula) { unsigned long long total_elapsed, since_last; - long double mbps, slice_mbps = 0; + long double mbps, old_mean_mbps, slice_mbps = 0; float bwperc; struct statctx *sc; struct timeval t_cur, t_diff; @@ -554,6 +601,11 @@ tcp_process_slice(int fd, short event, v struct tcpcb tcpcb; struct socket sockb; + if (TAILQ_EMPTY(&sc_queue)) + return; /* don't pollute stats */ + + mainstats.n_slices++; + TAILQ_FOREACH(sc, &sc_queue, entry) { if (clock_gettime_tv(CLOCK_MONOTONIC, &t_cur) == -1) err(1, "clock_gettime_tv"); @@ -581,51 +633,79 @@ tcp_process_slice(int fd, short event, v /* process stats for this slice */ if (slice_mbps > mainstats.peak_mbps) mainstats.peak_mbps = slice_mbps; + if (slice_mbps < mainstats.floor_mbps) + mainstats.floor_mbps = slice_mbps; + old_mean_mbps = mainstats.mean_mbps; + mainstats.mean_mbps += (slice_mbps - mainstats.mean_mbps) / + mainstats.n_slices; + + /* "Welford's method" for online variance + * see Knuth, TAoCP Volume 2, 3rd edn., p232 */ + mainstats.nvariance_mbps += (slice_mbps - old_mean_mbps) * + (slice_mbps - mainstats.mean_mbps); + printf("Conn: %3d Mbps: %12.3Lf Peak Mbps: %12.3Lf Avg Mbps: %12.3Lf\n", mainstats.nconns, slice_mbps, mainstats.peak_mbps, mainstats.nconns ? slice_mbps / mainstats.nconns : 0); - mainstats.slice_bytes = 0; + mainstats.slice_bytes = 0; set_slice_timer(mainstats.nconns > 0); } static void -udp_process_slice(int fd, short event, void *v_sc) +udp_process_slice(int fd, short event, void *bula) { - struct statctx *sc = v_sc; unsigned long long total_elapsed, since_last, pps; - long double slice_mbps; + long double old_mean_mbps, slice_mbps; struct timeval t_cur, t_diff; + mainstats.n_slices++; + if (clock_gettime_tv(CLOCK_MONOTONIC, &t_cur) == -1) err(1, "clock_gettime_tv"); - /* Calculate pps */ - timersub(&t_cur, &sc->t_start, &t_diff); + + timersub(&t_cur, &udp_sc->t_start, &t_diff); total_elapsed = t_diff.tv_sec * 1000 + t_diff.tv_usec / 1000; - timersub(&t_cur, &sc->t_last, &t_diff); + + timersub(&t_cur, &udp_sc->t_last, &t_diff); since_last = t_diff.tv_sec * 1000 + t_diff.tv_usec / 1000; if (since_last == 0) return; - slice_mbps = (sc->bytes * 8) / (since_last * 1000.0); - pps = (sc->udp_slice_pkts * 1000) / since_last; + + slice_mbps = (udp_sc->bytes * 8) / (since_last * 1000.0); + pps = (udp_sc->udp_slice_pkts * 1000) / since_last; + if (slice_mbps > mainstats.peak_mbps) mainstats.peak_mbps = slice_mbps; + if (slice_mbps < mainstats.floor_mbps) + mainstats.floor_mbps = slice_mbps; + old_mean_mbps = mainstats.mean_mbps; + mainstats.mean_mbps += (slice_mbps - mainstats.mean_mbps) / + mainstats.n_slices; + + /* "Welford's method" for online variance + * see Knuth, TAoCP Volume 2, 3rd edn., p232 */ + mainstats.nvariance_mbps += (slice_mbps - old_mean_mbps) * + (slice_mbps - mainstats.mean_mbps); + printf("Elapsed: %11llu Mbps: %11.3Lf Peak Mbps: %11.3Lf %s PPS: %7llu\n", total_elapsed, slice_mbps, mainstats.peak_mbps, ptb->sflag ? "Rx" : "Tx", pps); /* Clean up this slice time */ - sc->t_last = t_cur; - sc->bytes = 0; - sc->udp_slice_pkts = 0; + udp_sc->t_last = t_cur; + udp_sc->bytes = 0; + udp_sc->udp_slice_pkts = 0; + + mainstats.slice_bytes = 0; set_slice_timer(1); } static void -udp_server_handle_sc(int fd, short event, void *v_sc) +udp_server_handle_sc(int fd, short event, void *bula) { + static int first_read = 1; ssize_t n; - struct statctx *sc = v_sc; n = read(fd, ptb->dummybuf, ptb->dummybuf_len); if (n == 0) @@ -638,12 +718,16 @@ udp_server_handle_sc(int fd, short event if (ptb->vflag >= 3) fprintf(stderr, "read: %zd bytes\n", n); - /* If this was our first packet, start slice timer */ - if (mainstats.peak_mbps == 0) + if (first_read) { + first_read = 0; + stats_prepare(udp_sc); set_slice_timer(1); + } /* Account packet */ - sc->udp_slice_pkts++; - sc->bytes += n; + udp_sc->udp_slice_pkts++; + udp_sc->bytes += n; + mainstats.slice_bytes += n; + mainstats.total_bytes += n; } static void @@ -680,6 +764,7 @@ tcp_server_handle_sc(int fd, short event fprintf(stderr, "read: %zd bytes\n", n); sc->bytes += n; mainstats.slice_bytes += n; + mainstats.total_bytes += n; } static void @@ -731,10 +816,12 @@ tcp_server_accept(int fd, short event, v sc->tcp_ts = ts; sc->fd = sock; stats_prepare(sc); + event_set(&sc->ev, sc->fd, EV_READ | EV_PERSIST, tcp_server_handle_sc, sc); event_add(&sc->ev, NULL); TAILQ_INSERT_TAIL(&sc_queue, sc, entry); + mainstats.nconns++; if (mainstats.nconns == 1) set_slice_timer(1); @@ -744,7 +831,7 @@ tcp_server_accept(int fd, short event, v } static void -server_init(struct addrinfo *aitop, struct statctx *udp_sc) +server_init(struct addrinfo *aitop) { char tmp[128]; int sock, on = 1; @@ -806,7 +893,7 @@ server_init(struct addrinfo *aitop, stru if ((ev = calloc(1, sizeof(*ev))) == NULL) err(1, "calloc"); event_set(ev, sock, EV_READ | EV_PERSIST, - udp_server_handle_sc, udp_sc); + udp_server_handle_sc, NULL); event_add(ev, NULL); } else { if ((ts = calloc(1, sizeof(*ts))) == NULL) @@ -841,30 +928,30 @@ client_handle_sc(int fd, short event, vo if (errno == EINTR || errno == EWOULDBLOCK || (UDP_MODE && errno == ENOBUFS)) return; - err(1, "write"); + warn("write"); + wrapup(1); } if (TCP_MODE && n == 0) { fprintf(stderr, "Remote end closed connection"); - exit(1); + wrapup(1); } if (ptb->vflag >= 3) fprintf(stderr, "write: %zd bytes\n", n); sc->bytes += n; mainstats.slice_bytes += n; + mainstats.total_bytes += n; if (UDP_MODE) sc->udp_slice_pkts++; } static void -client_init(struct addrinfo *aitop, int nconn, struct statctx *udp_sc, - struct addrinfo *aib) +client_init(struct addrinfo *aitop, int nconn, struct addrinfo *aib) { struct statctx *sc; struct addrinfo *ai; char tmp[128]; int i, r, sock; - sc = udp_sc; for (i = 0; i < nconn; i++) { for (sock = -1, ai = aitop; ai != NULL; ai = ai->ai_next) { saddr_ntop(ai->ai_addr, ai->ai_addrlen, tmp, @@ -926,13 +1013,17 @@ client_init(struct addrinfo *aitop, int if (TCP_MODE) { if ((sc = calloc(1, sizeof(*sc))) == NULL) err(1, "calloc"); - } + } else + sc = udp_sc; + sc->fd = sock; stats_prepare(sc); + event_set(&sc->ev, sc->fd, EV_WRITE | EV_PERSIST, client_handle_sc, sc); event_add(&sc->ev, NULL); TAILQ_INSERT_TAIL(&sc_queue, sc, entry); + mainstats.nconns++; if (mainstats.nconns == 1) set_slice_timer(1); @@ -998,7 +1089,27 @@ map_tos(char *s, int *val) static void quit(int sig, short event, void *arg) { - exit(0); + wrapup(0); +} + +static void +wrapup(int err) +{ + const int transfers = timerisset(&mainstats.t_first); + const int stats = (mainstats.floor_mbps != INFINITY); + + if (transfers) { + if (!stats) { + if (UDP_MODE) + udp_process_slice(0, 0, NULL); + else + tcp_process_slice(0, 0, NULL); + } + + summary_display(); + } + + exit(err); } int @@ -1016,7 +1127,6 @@ main(int argc, char **argv) struct nlist nl[] = { { "_tcbtable" }, { "" } }; const char *host = NULL, *port = DEFAULT_PORT, *srcbind = NULL; struct event ev_sigint, ev_sigterm, ev_sighup, ev_progtimer; - struct statctx *udp_sc = NULL; struct sockaddr_un sock_un; /* Init world */ @@ -1159,7 +1269,7 @@ main(int argc, char **argv) drop_gid(); if (!ptb->sflag || ptb->Uflag) - host = argv[0]; + mainstats.host = host = argv[0]; if (ptb->Uflag) if (unveil(host, "rwc") == -1) @@ -1244,6 +1354,9 @@ main(int argc, char **argv) err(1, "malloc"); arc4random_buf(ptb->dummybuf, ptb->dummybuf_len); + timerclear(&mainstats.t_first); + mainstats.floor_mbps = INFINITY; + /* Setup libevent and signals */ event_init(); signal_set(&ev_sigterm, SIGTERM, signal_handler, NULL); @@ -1258,15 +1371,14 @@ main(int argc, char **argv) if ((udp_sc = calloc(1, sizeof(*udp_sc))) == NULL) err(1, "calloc"); udp_sc->fd = -1; - stats_prepare(udp_sc); - evtimer_set(&mainstats.timer, udp_process_slice, udp_sc); + evtimer_set(&mainstats.timer, udp_process_slice, NULL); } else { print_tcp_header(); evtimer_set(&mainstats.timer, tcp_process_slice, NULL); } if (ptb->sflag) - server_init(aitop, udp_sc); + server_init(aitop); else { if (secs > 0) { timerclear(&tv); @@ -1274,7 +1386,7 @@ main(int argc, char **argv) evtimer_set(&ev_progtimer, quit, NULL); evtimer_add(&ev_progtimer, &tv); } - client_init(aitop, nconn, udp_sc, aib); + client_init(aitop, nconn, aib); if (pledge("stdio", NULL) == -1) err(1, "pledge");