diff --git a/app/main.c b/app/main.c index 39c86ab..f1c2c0f 100644 --- a/app/main.c +++ b/app/main.c @@ -639,6 +639,7 @@ SSL_CTX *init_openssl(const tpx_listen_conf_t *config, int logfd) { | SSL_OP_CIPHER_SERVER_PREFERENCE; SSL_CTX_set_options(ctx, opts); + SSL_CTX_set_mode(ctx, SSL_MODE_RELEASE_BUFFERS); if (config->cacerts != NULL) { if (load_servcert(config, ctx, logfd) == 0) diff --git a/benchmark/README.md b/benchmark/README.md index a1cdaba..1b59987 100644 --- a/benchmark/README.md +++ b/benchmark/README.md @@ -286,7 +286,7 @@ and #44 means there are no TLS knobs to sweep. ## Measurements -Four modes, all driven by `bench.sh` onto one CSV schema. The harness emits the +Five modes, all driven by `bench.sh` onto one CSV schema. The harness emits the CSV, a committed plotting script renders the images, and CSV, script and images are all committed together. @@ -314,6 +314,28 @@ are all committed together. points are where a payload spans several queue chunks. Connections persist for the whole run rather than churning, since at small payloads a churning client measures its own ephemeral port table instead of the proxy. +5. **Message round trip on held connections,** `-m message`. N connections + established once and held, each sending one `-b` byte message every `-i` + milliseconds against the echo sink, swept over N. The other four modes all + miss this: handshake and rate close a connection the moment it is up, idle + sends nothing at all, and bulk streams continuously with `-n 0` so the + window is never small. That leaves the steady state of every workload the + proxy is actually for, an MQTT broker or a game server or an RPC service, + unmeasured, and it is where Nagle, a wake-up per message and any per-message + allocation show up. The latency columns for this mode are `msg_*` and + describe a round trip; `hs_*` still describes the handshakes that set the + connections up. + + The send grid is absolute and fixed in advance, so a connection whose + response came back later than its own interval skips the slots it missed and + they are counted in `shed`. Advancing from completion instead would let a + slow subject quietly lower the offered rate until it matched whatever it + could serve, which is the same reason `-m rate` exists. Each connection + takes a phase fixed once at setup so a thread's sends spread evenly over one + interval; `-L` puts them all in phase instead, which is what a game tick + looks like. Run it over the wire like the first three modes rather than with + `GEN=local`, since a generator sharing the subject's CPU adds scheduler + noise to exactly the tail this mode exists to measure. Two derived quantities normalize the rest and carry the comparison: **CPU per handshake** and **MB/s per core**. A subject that wins on rate while spending a @@ -343,6 +365,21 @@ that, `thermal_throttle/package_throttle_count` is read before and after every run and any movement fails it, because a run that throttled part way through reports a median that no configuration produced. +**Resumption actually happening.** With `-K`, `tlsload` prints `reused=` on the +`completed=` line of every raw file, counting the handshakes the server +resumed. A `-K` run reporting `reused=0` measured full handshakes in both arms +and says nothing about resumption. Two things made that the default outcome +until 2026-08-11 and both are worth knowing, since either one alone is enough to +turn the flag into a no-op: TLS 1.3 has no session to take when `SSL_connect()` +returns, because the server sends NewSessionTicket afterwards and only a read +processes it, so the session has to be collected from +`SSL_CTX_sess_set_new_cb()`; and `SSL_free()` on a connection closed without +`close_notify` runs `ssl_clear_bad_session()`, which calls +`SSL_CTX_remove_session()` and sets `not_resumable` on the session object +itself, so a session held by reference is spoiled by the connection that +supplied it and then by every connection that offers it. `tlsload` keeps a +copy, and hands out a copy per connection, for that reason. + **Ephemeral ports.** The client closes first in every churn test, so TIME_WAIT accumulates on the generator. Linux holds TIME_WAIT for 60 seconds and exposes no sysctl for the length, and the default `ip_local_port_range` of 32768 to @@ -463,6 +500,23 @@ since repeatable runs matter more here than peak ones, and this chassis otherwise throttles. To undo it without rebooting, write `0` to `intel_pstate/no_turbo` and `powersave` back to every `scaling_governor`. +`bench.sh` brings each subject up with `compose up -d` and no `--build`, so it +runs whatever is already tagged `tlsproxy:bench-deb` and a change to the tree +does not reach it. Rebuild first, and note that a local `cmake --build build` +does nothing here since the subject is the image and the image compiles its own +copy from the build context: + +```sh +docker compose --profile tlsproxy build tlsproxy +``` + +`provenance.txt` records `tlsproxy_sha` from `git rev-parse HEAD`, which is +blind to uncommitted work, so two runs either side of an unstaged change are +indistinguishable in it. When measuring something not yet committed, keep the +old image under a second tag (`docker tag tlsproxy:bench-deb +tlsproxy:bench-deb-`) and retag to pick the arm, since `compose.yml` +names one image. + Then any of the four modes: ```sh @@ -471,8 +525,14 @@ Then any of the four modes: ./bench.sh -m idle -x "1000 5000 20000" -d 30 -R 3 GEN=local ./bench.sh -m bulk -x "64 1024 8192 65536 1048576" \ -c 32 -n 0 -d 8 -R 3 +./bench.sh -m message -x "1000 5000 20000" -b 200 -i 1000 -d 30 -R 3 +./bench.sh -m message -x "1000 5000" -b 200 -i 33 -L -d 30 -R 3 ``` +The two message runs are the two shapes worth having: a message a second per +connection is the MQTT and RPC case, and 33 ms in lockstep is a 30 Hz game +tick. `-b` is the message size each way, since the sink echoes. + `bulk` runs with `GEN=local` because a gigabit link caps the data path far below what the subjects can move, so across the wire it would measure the NIC. It pins the generator to `6,7,14,15`, off the subject's cpuset. The subject @@ -494,7 +554,7 @@ the underlying column goes up or down. | Path | State | | --- | --- | | `README.md` | this file, the method | -| `bench.sh` | the entry point for all four modes, writing provenance and the git SHA into every result | +| `bench.sh` | the entry point for all five modes, writing provenance and the git SHA into every result | | `report.py` | renders a results directory as markdown; `--against baseline/` adds deltas | | `BASELINE.md` | the reference numbers as a report, with the caveats that stop them being a published result | | `baseline/` | the CSVs and provenance behind it at `6e847f2`, tracked so a later run has something to diff against | @@ -506,7 +566,7 @@ the underlying column goes up or down. | `backend/nginx.conf` | the HTTP backend, for the tests that speak HTTP over the tunnel | | `backend/sink/` | the discard/echo backend, static on `scratch` so its cgroup accounts for connection state and nothing else | | `generators/build.sh` | builds `tlsload`, `tls-perf` and `wrk2` for the generator host and records what they are | -| `generators/tlsload/` | the open-model generator: handshake, hold and request modes, client-pinned TLS parameters, latency percentiles | +| `generators/tlsload/` | the open-model generator: handshake, hold, request and message modes, client-pinned TLS parameters, latency percentiles | | `diag/` | per-second memory and socket-state time series for one subject under load | | `monitoring.yml` | Prometheus, cAdvisor, node-exporter and Grafana, split out so bringing up the benchmark does not bring them up beside the subject | | `prometheus.yml` | configuration for the above | diff --git a/benchmark/bench.sh b/benchmark/bench.sh index f87fffd..599724f 100755 --- a/benchmark/bench.sh +++ b/benchmark/bench.sh @@ -1,12 +1,18 @@ #!/bin/sh # Drives one benchmark mode across subjects and writes CSV, raw generator -# output and provenance into results/. All four modes share one CSV +# output and provenance into results/. All five modes share one CSV # schema and one set of validity checks. # # bench.sh -m handshake -x "64 256 1024 4096" closed loop, axis = concurrency # bench.sh -m rate -x "2000 4000 6000 8000" open loop, axis = offered rate # bench.sh -m idle -x "1000 5000 20000" held open, axis = connections # bench.sh -m bulk -x "64 1024 65536" echo, axis = payload bytes +# bench.sh -m message -x "1000 5000 20000" echo, axis = connections +# +# message holds its connections and sends one small message per connection every +# -i milliseconds, so its latency columns are msg_* and describe a round trip +# rather than a handshake. The hs_* columns still describe the handshakes that +# set the connections up. set -eu here=$(CDPATH= cd -- "$(dirname -- "$0")" && pwd) @@ -39,9 +45,11 @@ reps=6 dur=10 threads=4 resume=0 +interval=1000 +lockstep=0 backend="" -while getopts "m:s:e:x:c:r:b:n:R:d:t:B:K" o; do +while getopts "m:s:e:x:c:r:b:n:R:d:t:B:i:LK" o; do case $o in m) mode=$OPTARG ;; s) subjects=$OPTARG ;; e) certs=$OPTARG ;; x) axis=$OPTARG ;; @@ -49,21 +57,24 @@ while getopts "m:s:e:x:c:r:b:n:R:d:t:B:K" o; do b) payload=$OPTARG ;; n) reqs=$OPTARG ;; R) reps=$OPTARG ;; d) dur=$OPTARG ;; t) threads=$OPTARG ;; B) backend=$OPTARG ;; + i) interval=$OPTARG ;; L) lockstep=1 ;; K) resume=1 ;; - *) echo "usage: $0 -m handshake|rate|idle|bulk [-x values] [-s subjects]" >&2 + *) echo "usage: $0 -m handshake|rate|idle|bulk|message [-x values]" \ + "[-s subjects]" >&2 exit 2 ;; esac done case $mode in -handshake|rate|idle|bulk) : ;; -*) echo "mode must be handshake, rate, idle or bulk" >&2; exit 2 ;; +handshake|rate|idle|bulk|message) : ;; +*) echo "mode must be handshake, rate, idle, bulk or message" >&2; exit 2 ;; esac -# bulk needs the sink echoing; the rest only need it to hold and to close. +# bulk and message need the sink echoing; the rest only need it to hold and to +# close. if [ -z "$backend" ]; then backend=backend-sink - [ "$mode" = bulk ] && backend=backend-echo + case $mode in bulk|message) backend=backend-echo ;; esac fi run=$(date -u +%Y%m%dT%H%M%SZ) @@ -130,6 +141,8 @@ wait_ready() { echo "cipher $CIPHER" echo "tls_version $TLSVER" echo "resumption $resume" + [ "$mode" = message ] && echo "msg_interval_ms $interval" + [ "$mode" = message ] && echo "msg_lockstep $lockstep" echo "duration_s $dur" echo "reps $reps" echo "threads $threads" @@ -149,7 +162,7 @@ wait_ready() { done } > "$out/provenance.txt" 2>&1 -echo "run,sha,mode,model,subject,cert,resume,axis,concurrency,offered_rate,payload,reqs,threads,duration,rep,completed,rate,errors,shed,hs_p50,hs_p95,hs_p99,hs_p999,hs_max,mb_per_sec,cpu_cores,ws_peak_bytes,anon_bytes,file_bytes,slab_bytes,mem_max_delta,throttle_delta,workers_stable,run_ok" > "$csv" +echo "run,sha,mode,model,subject,cert,resume,axis,concurrency,offered_rate,payload,reqs,threads,duration,rep,completed,rate,errors,shed,hs_p50,hs_p95,hs_p99,hs_p999,hs_max,msg_p50,msg_p95,msg_p99,msg_p999,msg_max,mb_per_sec,cpu_cores,ws_peak_bytes,anon_bytes,file_bytes,slab_bytes,mem_max_delta,throttle_delta,workers_stable,run_ok" > "$csv" bport=8080 case $backend in backend-sink) bport=8081 ;; backend-echo) bport=8082 ;; esac @@ -171,9 +184,9 @@ for cert in $certs; do for x in $axis; do a_conc=$conc; a_rate=$rate; a_pay=$payload case $mode in - handshake|idle) a_conc=$x ;; - rate) a_rate=$x ;; - bulk) a_pay=$x ;; + handshake|idle|message) a_conc=$x ;; + rate) a_rate=$x ;; + bulk) a_pay=$x ;; esac case $mode in @@ -181,7 +194,9 @@ for cert in $certs; do idle) margs="-m hold -c $a_conc -H 0" ;; rate) margs="-m handshake -r $a_rate -M 400000" ;; bulk) margs="-m request -c $a_conc -b $a_pay -n $reqs" ;; + message) margs="-m message -c $a_conc -b $a_pay -I $interval" ;; esac + [ "$mode" = message ] && [ "$lockstep" = 1 ] && margs="$margs -L" [ "$resume" = 1 ] && margs="$margs -R" for rep in $(seq 1 "$reps"); do @@ -224,12 +239,22 @@ for cert in $certs; do if (kv[1]=="p99") p99=kv[2] if (kv[1]=="p999") p999=kv[2] if (kv[1]=="max") mx=kv[2] } } + # Left empty rather than zeroed for the modes that send no + # messages, so a median never averages in a column that was + # never measured. + /^messages=/ { + for (i=1;i<=NF;i++) { split($i,kv,"=") + if (kv[1]=="msg_ms_p50") m50=kv[2] + if (kv[1]=="p95") m95=kv[2] + if (kv[1]=="p99") m99=kv[2] + if (kv[1]=="p999") m999=kv[2] + if (kv[1]=="max") mmx=kv[2] } } /^bytes_up=/ { for (i=1;i<=NF;i++) { split($i,kv,"=") if (kv[1]=="mbytes_per_sec") mb=kv[2] } } - END { printf "%d,%d,%d,%d,%s,%s,%s,%s,%s,%s,%d", + END { printf "%d,%d,%d,%d,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%d", comp+0, rt+0, er+0, sh+0, p50+0, p95+0, p99+0, - p999+0, mx+0, mb+0, ok+0 } + p999+0, mx+0, m50, m95, m99, m999, mmx, mb+0, ok+0 } ' "$raw") ok=${stats##*,}; stats=${stats%,*} @@ -237,7 +262,11 @@ for cert in $certs; do 'BEGIN{printf "%.3f",(b-a)/1000000/d}') stable=0; [ "$pre_procs" = "$post_procs" ] && stable=1 tdelta=$((post_thr - pre_thr)); mmdelta=$((post_mm - pre_mm)) - model=closed; [ "$mode" = rate ] && model=open + # message is open per message rather than per connection: the + # send grid is fixed in advance, so a subject that cannot keep + # up misses slots instead of being offered less. + model=closed + case $mode in rate|message) model=open ;; esac echo "$run,$sha,$mode,$model,$subj,$cert,$resume,$x,$a_conc,$a_rate,$a_pay,$reqs,$threads,$dur,$rep,$stats,$cores,$ws,$anon,$file,$slab,$mmdelta,$tdelta,$stable,$ok" >> "$csv" diff --git a/benchmark/generators/tlsload/tlsload.c b/benchmark/generators/tlsload/tlsload.c index 15158b1..0c45d57 100644 --- a/benchmark/generators/tlsload/tlsload.c +++ b/benchmark/generators/tlsload/tlsload.c @@ -7,9 +7,12 @@ // in advance from a Poisson process, so a subject that slows down accumulates // a queue and eventually sheds, which is the behaviour worth measuring. // -// Modes cover the three shapes a TLS terminator sees: connection churn -// (handshake), many mostly-idle connections (hold), and bulk transfer over -// established connections (request). +// Modes cover the four shapes a TLS terminator sees: connection churn +// (handshake), many mostly-idle connections (hold), bulk transfer over +// established connections (request), and small messages on a fixed schedule +// over held connections (message), which is what MQTT, game traffic and RPC +// all look like and is the only mode whose latency is per message rather than +// per handshake. // // Needs -D_GNU_SOURCE for accept4/SOCK_NONBLOCK and -lssl -lcrypto -lpthread. @@ -34,17 +37,20 @@ #define MAX_EVENTS 1024 #define IO_BUF 65536 -enum { M_HANDSHAKE, M_HOLD, M_REQUEST }; -enum { S_CONNECT, S_HANDSHAKE, S_ACTIVE, S_HOLD }; +enum { M_HANDSHAKE, M_HOLD, M_REQUEST, M_MESSAGE }; +enum { S_CONNECT, S_HANDSHAKE, S_ACTIVE, S_HOLD, S_TICKET, S_MSG_WAIT }; typedef struct conn { struct conn *next; // free list + struct conn *wheel_next; // timer wheel bucket, message mode int fd; SSL *ssl; int state; int in_use; uint64_t t_start; - uint64_t deadline; // hold mode + uint64_t deadline; // hold mode, and the ticket wait + uint64_t due; // message mode: next send on the grid + uint64_t t_msg; // message mode: this message left at int reqs_left; size_t wsent; // bytes written this request size_t rrecv; // bytes read back this request @@ -61,11 +67,21 @@ typedef struct { // open model: absolute nanosecond times for the arrivals this thread owns uint64_t *sched; long nsched, next_sched; + // message mode: one bucket per millisecond of the send grid, so a + // connection whose response came back late still fires on its own slot + // rather than queueing behind whatever finished first + conn_t **wheel; + long nwheel; + uint64_t wheel_ms; // the millisecond the wheel has run to + long nstarted, quota; // message mode: connections, established once // results uint64_t *lat; // handshake latency, ns long nlat, caplat; + uint64_t *mlat; // message round trip, ns + long nmlat, capmlat; uint64_t completed, errors, shed; uint64_t bytes_up, bytes_down; + uint64_t reused; // handshakes the server resumed SSL_SESSION *sess; char io[IO_BUF]; } worker_t; @@ -78,13 +94,17 @@ static struct { int hold; // seconds, 0 = until the run ends long payload; int reqs; + int interval; // message mode, ms between sends + int lockstep; // message mode, all connections in phase } cfg = { .port = "8443", .mode = M_HANDSHAKE, .threads = 4, .conc = 64, - .dur = 10, .tlsver = 3, .cap = 200000, .reqs = 1, .payload = 1024 }; + .dur = 10, .tlsver = 3, .cap = 200000, .reqs = 1, .payload = 1024, + .interval = 1000 }; static SSL_CTX *ctx; static struct addrinfo *addr; static volatile sig_atomic_t stop_now; static uint64_t t_end; +static int ex_worker = -1; // SSL ex_data slot holding the worker static uint64_t now_ns(void) { struct timespec ts; @@ -96,6 +116,32 @@ static void on_signal(int sig) { (void)sig; stop_now = 1; } static void die(const char *m) { fprintf(stderr, "tlsload: %s\n", m); exit(1); } +// TLS 1.3 has no session to take at the end of SSL_connect(): the server sends +// NewSessionTicket afterwards, and OpenSSL only calls this once a read has +// processed one. Taking SSL_get1_session() at handshake completion instead +// yields a session with no PSK, which SSL_set_session() then cannot resume, so +// -R measured nothing and the arms of a resumption test came out identical. +// Each thread keeps its own session, so no locking is needed here. +static int on_new_session(SSL *ssl, SSL_SESSION *sess) { + worker_t *w = SSL_get_ex_data(ssl, ex_worker); + if (!w) + return 0; // we did not take a reference + // A copy rather than a reference. Freeing an SSL that was closed without + // close_notify runs ssl_clear_bad_session(), which calls + // SSL_CTX_remove_session() and sets not_resumable on the session object, + // and every mode here except -S closes exactly that way. Holding a + // reference means that flag lands on the session this thread is about to + // resume with, so SSL_SESSION_is_resumable() is 1 in this callback and 0 by + // the time the next connection offers it. + SSL_SESSION *copy = SSL_SESSION_dup(sess); + if (!copy) + return 0; + if (w->sess) + SSL_SESSION_free(w->sess); + w->sess = copy; + return 0; +} + // ---------------------------------------------------------------- connections static void conn_release(worker_t *w, conn_t *c) { @@ -171,6 +217,32 @@ static void record_latency(worker_t *w, uint64_t ns) { w->lat[w->nlat++] = ns; } +static void record_mlat(worker_t *w, uint64_t ns) { + if (w->nmlat < w->capmlat) + w->mlat[w->nmlat++] = ns; +} + +static void msg_arm(worker_t *w, conn_t *c) { + long b = (long)((c->due / 1000000ull) % (uint64_t)w->nwheel); + c->wheel_next = w->wheel[b]; + w->wheel[b] = c; + c->state = S_MSG_WAIT; +} + +// The grid is absolute, so a connection whose response came back later than +// its own interval skips the slots it missed and they are counted as shed. +// Advancing from now instead would let a slow subject silently lower the +// offered rate until it matched whatever it could serve. +static void msg_schedule(worker_t *w, conn_t *c, uint64_t now) { + uint64_t step = (uint64_t)cfg.interval * 1000000ull; + c->due += step; + while (c->due <= now) { + c->due += step; + w->shed++; + } + msg_arm(w, c); +} + // Returns 0 if the connection was released. static int conn_drive(worker_t *w, conn_t *c) { for (;;) { @@ -191,10 +263,22 @@ static int conn_drive(worker_t *w, conn_t *c) { return 0; } SSL_set_fd(c->ssl, c->fd); + SSL_set_ex_data(c->ssl, ex_worker, w); if (cfg.sni) SSL_set_tlsext_host_name(c->ssl, cfg.sni); - if (cfg.resume && w->sess) - SSL_set_session(c->ssl, w->sess); + // Offer a copy for the same reason the callback keeps one: the + // SSL_free() at the end of this connection would otherwise mark + // the thread's session not resumable and only the first connection + // would ever resume. SSL_set_session() takes its own reference, so + // dropping ours here leaves the copy with the connection that is + // about to spoil it. + if (cfg.resume && w->sess) { + SSL_SESSION *use = SSL_SESSION_dup(w->sess); + if (use) { + SSL_set_session(c->ssl, use); + SSL_SESSION_free(use); + } + } c->state = S_HANDSHAKE; break; } @@ -202,15 +286,34 @@ static int conn_drive(worker_t *w, conn_t *c) { int r = SSL_connect(c->ssl); if (r == 1) { record_latency(w, now_ns() - c->t_start); - if (cfg.resume) { - SSL_SESSION *s = SSL_get1_session(c->ssl); - if (s) { - if (w->sess) - SSL_SESSION_free(w->sess); - w->sess = s; + if (SSL_session_reused(c->ssl)) + w->reused++; + if (cfg.mode == M_MESSAGE) { + // A phase fixed once per connection rather than a fresh + // offset each message, so the send times stay a grid while + // the thread's connections still spread over one interval. + uint64_t step = (uint64_t)cfg.interval * 1000000ull; + long idx = (long)(c - w->pool); + c->due = now_ns() + (cfg.lockstep ? 0 + : step * (uint64_t)idx / (uint64_t)w->npool); + if (conn_arm(w, c, EPOLLIN | EPOLLRDHUP) == -1) { + w->errors++; + conn_release(w, c); + return 0; } + msg_arm(w, c); + return 1; } if (cfg.mode == M_HANDSHAKE) { + // Only the first connection of each thread waits for the + // ticket, since one session is all a thread resumes with + // and holding every connection open past its handshake + // would turn a churn test into a hold test. + if (cfg.resume && !w->sess) { + c->state = S_TICKET; + c->deadline = now_ns() + 250000000ull; + break; + } w->completed++; conn_release(w, c); return 0; @@ -283,6 +386,14 @@ static int conn_drive(worker_t *w, conn_t *c) { } if (c->wsent >= (size_t)cfg.payload && c->rrecv >= (size_t)cfg.payload) { + if (cfg.mode == M_MESSAGE) { + uint64_t t = now_ns(); + record_mlat(w, t - c->t_msg); + w->completed++; + msg_schedule(w, c, t); + return conn_arm(w, c, EPOLLIN | EPOLLRDHUP) == -1 + ? (w->errors++, conn_release(w, c), 0) : 1; + } // -n 0 keeps the connection for the whole run, which is what // a data-path test wants: otherwise small payloads finish // fast, connections churn, and the generator measures its own @@ -306,12 +417,15 @@ static int conn_drive(worker_t *w, conn_t *c) { } return 1; } - case S_HOLD: { + case S_HOLD: + case S_MSG_WAIT: { // A held connection becomes readable for two very different // reasons: the peer closed, or the server sent TLS 1.3 // NewSessionTicket records after the handshake. Reading is the // only way to tell them apart, and treating a ticket as a close - // turns this mode into a churn test. + // turns this mode into a churn test. In message mode the send is + // driven by the timer wheel rather than by readiness, so a read + // here is never the response to anything. int r = SSL_read(c->ssl, w->io, IO_BUF); if (r > 0) return 1; @@ -322,6 +436,22 @@ static int conn_drive(worker_t *w, conn_t *c) { conn_release(w, c); return 0; } + case S_TICKET: { + // Waiting for NewSessionTicket, which is the only thing that makes + // the session resumable. The read is what drives on_new_session(). + int r = SSL_read(c->ssl, w->io, IO_BUF); + if (r <= 0) { + int e = SSL_get_error(c->ssl, r); + ERR_clear_error(); + if ((e == SSL_ERROR_WANT_READ || e == SSL_ERROR_WANT_WRITE) + && !w->sess && now_ns() < c->deadline) + return conn_arm(w, c, EPOLLIN) == -1 + ? (w->errors++, conn_release(w, c), 0) : 1; + } + w->completed++; + conn_release(w, c); + return 0; + } default: conn_release(w, c); return 0; @@ -331,11 +461,46 @@ static int conn_drive(worker_t *w, conn_t *c) { // ---------------------------------------------------------------- worker loop +// Fire every send slot up to now. Buckets are one millisecond wide, which is +// the resolution the loop already runs at in closed loop. +static void msg_tick(worker_t *w, uint64_t now) { + uint64_t ms = now / 1000000ull; + // The loop runs many times per millisecond, so most calls have nothing to + // do. Returning here rather than subtracting matters: the arithmetic below + // is unsigned, and one lap of underflow replays the whole ring. + if (ms < w->wheel_ms) + return; + // Never replay more than one ring, or a thread that stalled would fire + // every connection it owns in a single tick. + if (ms - w->wheel_ms >= (uint64_t)w->nwheel) + w->wheel_ms = ms - (uint64_t)w->nwheel + 1; + for (; w->wheel_ms <= ms; w->wheel_ms++) { + long b = (long)(w->wheel_ms % (uint64_t)w->nwheel); + conn_t *c = w->wheel[b]; + w->wheel[b] = NULL; + while (c) { + conn_t *nxt = c->wheel_next; + c->wheel_next = NULL; + // A connection released while queued is never restarted, so it is + // simply not in S_MSG_WAIT any more and gets skipped here. + if (c->in_use && c->state == S_MSG_WAIT) { + c->t_msg = now; + c->wsent = c->rrecv = 0; + c->state = S_ACTIVE; + conn_drive(w, c); + } + c = nxt; + } + } +} + static void *worker_main(void *arg) { worker_t *w = arg; struct epoll_event evs[MAX_EVENTS]; uint64_t last_sweep = 0; + w->wheel_ms = now_ns() / 1000000ull; + for (;;) { uint64_t now = now_ns(); if (stop_now || now >= t_end) @@ -349,6 +514,14 @@ static void *worker_main(void *arg) { if (w->inflight >= cfg.cap / cfg.threads || conn_start(w) == -1) w->shed++; } + } else if (cfg.mode == M_MESSAGE) { + // Exactly the requested number of connections, established once. + // A connection that dies is counted and not replaced, since + // replacing it mid-run would put a fresh handshake into the middle + // of a measurement about held connections. + while (w->nstarted < w->quota && conn_start(w) == 0) + w->nstarted++; + msg_tick(w, now); } else { while (w->inflight < cfg.conc && conn_start(w) == 0) ; @@ -426,15 +599,17 @@ static void build_schedule(worker_t *w, uint64_t t0) { static void usage(void) { fprintf(stderr, "usage: tlsload [options] \n" - " -m handshake|hold|request what each connection does (handshake)\n" + " -m handshake|hold|request|message what each connection does\n" " -c N closed loop: hold N concurrent connections (64)\n" " -r RATE open loop: start RATE connections/sec on a fixed schedule\n" " -M N max in-flight in open loop (200000)\n" " -d SECS duration (10)\n" " -t N threads (4)\n" " -H SECS hold seconds per connection, 0 = until the run ends\n" - " -b BYTES payload per request (1024)\n" + " -b BYTES payload per request or per message (1024)\n" " -n N requests per connection, 0 = until the run ends (1)\n" + " -I MS message mode: ms between one connection's sends (1000)\n" + " -L message mode: all connections in phase, like a game tick\n" " -V 1.2|1.3 TLS version (1.3)\n" " -G LIST group list, eg X25519\n" " -k LIST ciphersuite (1.3) or cipher list (1.2)\n" @@ -446,12 +621,13 @@ static void usage(void) { int main(int argc, char **argv) { int opt; - while ((opt = getopt(argc, argv, "m:c:r:M:d:t:H:b:n:V:G:k:s:RqS")) != -1) { + while ((opt = getopt(argc, argv, "m:c:r:M:d:t:H:b:n:I:LV:G:k:s:RqS")) != -1) { switch (opt) { case 'm': if (!strcmp(optarg, "handshake")) cfg.mode = M_HANDSHAKE; else if (!strcmp(optarg, "hold")) cfg.mode = M_HOLD; else if (!strcmp(optarg, "request")) cfg.mode = M_REQUEST; + else if (!strcmp(optarg, "message")) cfg.mode = M_MESSAGE; else usage(); break; case 'c': cfg.conc = atoi(optarg); break; @@ -462,6 +638,8 @@ int main(int argc, char **argv) { case 'H': cfg.hold = atoi(optarg); break; case 'b': cfg.payload = atol(optarg); break; case 'n': cfg.reqs = atoi(optarg); break; + case 'I': cfg.interval = atoi(optarg); break; + case 'L': cfg.lockstep = 1; break; case 'V': cfg.tlsver = !strcmp(optarg, "1.2") ? 2 : 3; break; case 'G': cfg.group = optarg; break; case 'k': cfg.cipher = optarg; break; @@ -477,6 +655,12 @@ int main(int argc, char **argv) { cfg.port = argv[optind + 1]; if (cfg.threads < 1 || cfg.threads > 256) die("threads must be 1-256"); if (cfg.conc < cfg.threads) cfg.conc = cfg.threads; + // The wheel is one bucket per millisecond and a slot must be reachable + // within one ring, so the interval bounds both directions. + if (cfg.mode == M_MESSAGE && (cfg.interval < 1 || cfg.interval > 600000)) + die("-I must be 1-600000 ms"); + if (cfg.mode == M_MESSAGE && cfg.payload > IO_BUF) + die("-b must not exceed 65536 in message mode"); signal(SIGPIPE, SIG_IGN); signal(SIGINT, on_signal); @@ -495,12 +679,15 @@ int main(int argc, char **argv) { SSL_CTX_set_min_proto_version(ctx, v); SSL_CTX_set_max_proto_version(ctx, v); SSL_CTX_set_verify(ctx, SSL_VERIFY_NONE, NULL); + ex_worker = SSL_get_ex_new_index(0, NULL, NULL, NULL, NULL); + if (ex_worker < 0) die("SSL_get_ex_new_index"); if (!cfg.resume) { SSL_CTX_set_session_cache_mode(ctx, SSL_SESS_CACHE_OFF); SSL_CTX_set_options(ctx, SSL_OP_NO_TICKET); } else { SSL_CTX_set_session_cache_mode(ctx, SSL_SESS_CACHE_CLIENT | SSL_SESS_CACHE_NO_INTERNAL_STORE); + SSL_CTX_sess_set_new_cb(ctx, on_new_session); } if (cfg.group && !SSL_CTX_set1_groups_list(ctx, cfg.group)) die("bad group list"); @@ -534,6 +721,19 @@ int main(int argc, char **argv) { w->lat = malloc((size_t)w->caplat * sizeof(uint64_t)); if (!w->lat) die("out of memory for the latency samples"); memset(w->io, 'x', sizeof(w->io)); + if (cfg.mode == M_MESSAGE) { + w->quota = cfg.conc / cfg.threads; + w->nwheel = cfg.interval + 64; + w->wheel = calloc((size_t)w->nwheel, sizeof(conn_t *)); + if (!w->wheel) die("out of memory for the timer wheel"); + // One slot per connection per interval, and a fifth again for a + // subject that runs ahead of the grid rather than behind it. + long want = w->quota * (cfg.dur * 1000 / cfg.interval + 2); + w->capmlat = want + want / 5 + 1024; + if (w->capmlat > 8000000) w->capmlat = 8000000; + w->mlat = malloc((size_t)w->capmlat * sizeof(uint64_t)); + if (!w->mlat) die("out of memory for the message samples"); + } if (cfg.rate > 0.0) build_schedule(w, t0); } @@ -545,12 +745,13 @@ int main(int argc, char **argv) { for (int i = 0; i < cfg.threads; i++) pthread_join(ws[i].th, NULL); - uint64_t done = 0, errs = 0, shed = 0, up = 0, down = 0; - long total = 0; + uint64_t done = 0, errs = 0, shed = 0, up = 0, down = 0, reused = 0; + long total = 0, mtotal = 0; for (int i = 0; i < cfg.threads; i++) { done += ws[i].completed; errs += ws[i].errors; shed += ws[i].shed; up += ws[i].bytes_up; down += ws[i].bytes_down; - total += ws[i].nlat; + reused += ws[i].reused; + total += ws[i].nlat; mtotal += ws[i].nmlat; } uint64_t *all = malloc((size_t)(total ? total : 1) * sizeof(uint64_t)); if (!all) die("out of memory merging latencies"); @@ -560,23 +761,43 @@ int main(int argc, char **argv) { all[k++] = ws[i].lat[j]; qsort(all, (size_t)total, sizeof(uint64_t), cmp_u64); + uint64_t *mall = malloc((size_t)(mtotal ? mtotal : 1) * sizeof(uint64_t)); + if (!mall) die("out of memory merging message latencies"); + k = 0; + for (int i = 0; i < cfg.threads; i++) + for (long j = 0; j < ws[i].nmlat; j++) + mall[k++] = ws[i].mlat[j]; + qsort(mall, (size_t)mtotal, sizeof(uint64_t), cmp_u64); + double secs = (double)cfg.dur; + static const char *modenames[] = { "handshake", "hold", "request", + "message" }; printf("mode=%s model=%s target=%s duration=%d threads=%d\n", - cfg.mode == M_HANDSHAKE ? "handshake" - : (cfg.mode == M_HOLD ? "hold" : "request"), - cfg.rate > 0.0 ? "open" : "closed", + modenames[cfg.mode], + cfg.rate > 0.0 || cfg.mode == M_MESSAGE ? "open" : "closed", cfg.rate > 0.0 ? "rate" : "concurrency", cfg.dur, cfg.threads); if (cfg.rate > 0.0) printf("offered_rate=%.0f\n", cfg.rate); else printf("concurrency=%d\n", cfg.conc); - printf("completed=%llu rate=%.0f errors=%llu shed=%llu\n", + if (cfg.mode == M_MESSAGE) + printf("msg_interval_ms=%d lockstep=%d offered_msg_rate=%.0f\n", + cfg.interval, cfg.lockstep, + (double)cfg.conc * 1000.0 / (double)cfg.interval); + printf("completed=%llu rate=%.0f errors=%llu shed=%llu reused=%llu\n", (unsigned long long)done, (double)done / secs, - (unsigned long long)errs, (unsigned long long)shed); + (unsigned long long)errs, (unsigned long long)shed, + (unsigned long long)reused); printf("handshakes=%ld hs_ms_p50=%.3f p95=%.3f p99=%.3f p999=%.3f max=%.3f\n", total, pct(all, total, 50), pct(all, total, 95), pct(all, total, 99), pct(all, total, 99.9), pct(all, total, 100)); - if (cfg.mode == M_REQUEST) + if (cfg.mode == M_MESSAGE) + printf("messages=%ld msg_ms_p50=%.3f p95=%.3f p99=%.3f p999=%.3f " + "max=%.3f\n", + mtotal, pct(mall, mtotal, 50), pct(mall, mtotal, 95), + pct(mall, mtotal, 99), pct(mall, mtotal, 99.9), + pct(mall, mtotal, 100)); + if (cfg.mode == M_REQUEST || cfg.mode == M_MESSAGE) printf("bytes_up=%llu bytes_down=%llu mbytes_per_sec=%.2f\n", (unsigned long long)up, (unsigned long long)down, (double)(up + down) / secs / 1048576.0); diff --git a/benchmark/report.py b/benchmark/report.py index 3a9b0a1..4b6c32b 100755 --- a/benchmark/report.py +++ b/benchmark/report.py @@ -104,6 +104,16 @@ def cell(v, base, fmt="{:.0f}", lower_is_better=False): "bulk": ("Data path against payload size", "payload bytes", [("mb_per_sec", "MB/s", 1.0, "{:.0f}", False), ("cpu_cores", "cores", 1.0, "{:.2f}", True)]), + # A message mode row describes a round trip on a connection that was + # already up, so the interesting columns are the tail and the missed slots, + # not the median, which every subject gets right. + "message": ("Message round trip on held connections", "connections", + [("msg_p50", "p50 ms", 1.0, "{:.2f}", True), + ("msg_p99", "p99 ms", 1.0, "{:.2f}", True), + ("msg_p999", "p999 ms", 1.0, "{:.2f}", True), + ("msg_max", "max ms", 1.0, "{:.1f}", True), + ("rate", "msg/s", 1.0, "{:.0f}", False), + ("shed", "missed slots", 1.0, "{:.0f}", True)]), } @@ -163,7 +173,7 @@ def main(): print(f"tlsproxy SHA: {', '.join(shas)}") if base: print("Percentages are against the baseline, positive meaning better.") - for m in ["handshake", "rate", "idle", "bulk"]: + for m in ["handshake", "rate", "idle", "bulk", "message"]: if m in data: print(render(m, data[m], base.get(m) if base else None)) return 0