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");
