test/throughput.sh

Ref: main worktree-web-client-spec   Size: 12.4 KiB   History

#!/bin/sh
# Output-throughput gate. Guards ONE bug class, the one that shipped: a
# a daemon whose VT engine is doing per-mutation work nobody asked for. Built
# Debug, ghostty runs its page-integrity check on every page mutation —
# a hash map over every cell plus a fresh DebugAllocator — and this exact
# workload went from 7ms to 3713ms. tmux does it in 6ms. That is the
# distance being watched: catastrophic, not marginal.
#
# The bounds are tight, and what makes a tight bound survivable is
# BEST-OF-N: noise only ever ADDS time, so the minimum of N runs is the
# honest "how fast can this go", while a real regression moves that minimum
# exactly as much as it moves the mean.
#
# Two numbers on the client leg, because they answer different questions.
# 60ms is the COMFORT TARGET — past it the thing feels bad to use, which is
# a judgement about the product. It reports and does not fail. 75ms is the
# CEILING, set from measurement: on an idle 16-core box the best-of-5
# minimum ranged 45-60ms across ten runs, so a hard 60 flaked 1 run in 10
# with nothing wrong. 60 sits ON the noise floor, and a gate pinned to the
# noise floor gets disabled by the third false alarm.
#
# The solo leg gets one hard bound because it has no such spread: 6ms on
# every one of those runs, never 5 or 7 as a minimum.
#
# Every reading is PRINTED, pass or fail, so drift toward the target stays
# visible while the gate is still green.
#
# Timing is taken INSIDE the session, bracketing the pipeline with the
# shell's own clock. That is the number a human feels; the client's view
# of when bytes arrived is a different question and not this one.
#
# Only meaningful against a ReleaseSafe build — see the `throughput`
# target in the Makefile, which is why this is not a build.zig step.
set -eu
MUX="$1"
PTYCLIENT="$2"

# The oracle, for now_ms_snippet alone. Every leg below times itself from
# INSIDE the session with the shell's own clock, and `date +%s%N` is GNU —
# so the text of that clock comes from the one place per OS that spells it,
# the same way soak.sh takes the two helpers it reads.
# shellcheck source=test/os_oracle.sh
. "$(dirname "$0")/os_oracle.sh"

# Lines of `yes`, and the wall-clock ceiling each leg must come in under.
#
# Every bound is overridable from the environment. All of them were
# calibrated on one idle 16-core box, and `make ci` now gates delivery on
# them, so a slower machine has to be able to relax the gate without
# editing this file — otherwise the only move left is deleting the target,
# and a deleted gate catches nothing. SOLO_MAX_MS carries the thinnest
# margin of the three: 10ms against an observed 6ms, on a bracket that
# includes `yes | head` fork and pipe cost.
SOLO_LINES=20000
SOLO_MAX_MS=${SOLO_MAX_MS:-10}
CLIENT_LINES=200000
CLIENT_WARN_MS=${CLIENT_WARN_MS:-60}
CLIENT_MAX_MS=${CLIENT_MAX_MS:-75}
# Leg 3 repaints a full screen over and over with NOBODY attached. Its
# own leg because `yes` cannot see what it sees: a one-character row is
# nearly free to render, so the solo leg above stays flat through a
# regression that makes full-width output 10x slower. Real output —
# vim, logs, a build — is full-width, and the daemon renders every row
# of it to hash it.
# 2^REPAINT_DOUBLINGS frames of ~1.8KB; 13 is ~15MB.
REPAINT_DOUBLINGS=${REPAINT_DOUBLINGS:-13}
# Measured either side of the fix, same box, best-of-5: 87ms with the
# detached check in place, 479ms without it. The ceiling sits near the
# good number rather than under the bad one — put it at 400 and a machine
# twice this fast runs the BROKEN build in 240ms and the gate says
# nothing. 2.3x over nominal, and the readings span 87-90.
#
# 5.5x here against 27x at 200x50: the penalty is per rendered row, and
# this leg renders 23 of 80 columns rather than 49 of 200.
REPAINT_MAX_MS=${REPAINT_MAX_MS:-200}
# Repeats per leg; the fastest one is the reading. See the header.
REPS=${REPS:-5}

TMPD="$(mktemp -d "${TMPDIR:-/tmp}/muxd-throughput-XXXXXX")"
# Every attach records a wall tile in $XDG_STATE_HOME/mux/wall; without a
# hermetic home this suite's throwaway sockets pile up in the developer's
# real wall file and the hub tries to open them all.
XDG_STATE_HOME="$TMPD/state"; XDG_CONFIG_HOME="$TMPD/cfg"; XDG_CACHE_HOME="$TMPD/cache"
export XDG_STATE_HOME XDG_CONFIG_HOME XDG_CACHE_HOME
SOCK="$TMPD/t.sock"
# Assigned BEFORE the trap is installed, not after the daemon launches:
# cleanup dereferences it under `set -u`, so a trap firing in between would
# die on an unbound variable and never reach the rm. Guarded with `if`
# rather than `&&` because a failing AND-OR list as a function's first
# statement is exactly the shape `set -e` is entitled to act on.
DPID=""
cleanup() {
    if [ -n "$DPID" ]; then kill "$DPID" 2>/dev/null || true; fi
    rm -rf "$TMPD"
}
trap cleanup EXIT INT TERM

"$MUX" d start --sock "$SOCK" --shell /bin/sh --cols 80 --rows 24 &
DPID=$!
i=0
while [ ! -S "$SOCK" ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done
[ -S "$SOCK" ] || { echo "throughput FAIL: socket never appeared"; exit 1; }

# A sentinel rather than a sleep: `sh` has to have reached its prompt and
# be reading, or the flood below is typed into a void and the leg times
# out reporting a throughput problem it never measured.
# Split by quotes the session's shell strips: the needle appears in the
# OUTPUT and never in the echoed command line, so this cannot match itself.
"$MUX" a send --sock "$SOCK" 'echo REA""DY\n' > /dev/null
i=0
while [ "$i" -lt 50 ]; do
    "$MUX" a capture --sock "$SOCK" | grep -qF 'READY' && break
    sleep 0.1
    i=$((i+1))
done
[ "$i" -lt 50 ] || { echo "throughput FAIL: shell never reached its prompt"; exit 1; }

# ---- leg 1: the daemon alone -------------------------------------------
# No client attached, so this is the engine and nothing else. It is the
# leg that catches the build-mode regression, because that cost is all
# inside feed().
# The `done` marker is a separate file on purpose: polling the timings file
# itself would read it after the first rep and call that the answer.
"$MUX" a send --sock "$SOCK" \
    "$(now_ms_snippet); for k in \$(seq $REPS); do A=\$(now_ms); yes | head -n $SOLO_LINES; B=\$(now_ms); echo \$(( B-A )) >> $TMPD/solo; done; echo ok > $TMPD/solo.done\n" \
    > /dev/null
i=0
while [ ! -s "$TMPD/solo.done" ] && [ "$i" -lt 60 ]; do sleep 0.5; i=$((i+1)); done
[ -s "$TMPD/solo.done" ] || {
    echo "throughput FAIL: $REPS x $SOLO_LINES lines had not finished after 30s"
    echo "  (Debug builds take ~3.7s per rep; 30s means something worse)"
    exit 1
}
SOLO_MS="$(sort -n "$TMPD/solo" | head -1)"

# A shell that died at startup writes no output and would sail past a
# timing bound it never exercised. The screen must actually be full of
# the flood. Byte needle: the grid arrives JSON-escaped, newlines as \n.
"$MUX" a capture --sock "$SOCK" | grep -qF 'y\ny\ny' || {
    echo "throughput FAIL: the flood left no output on the grid"
    "$MUX" a capture --sock "$SOCK"
    exit 1
}

echo "solo:   $SOLO_LINES lines, no client: ${SOLO_MS}ms (max ${SOLO_MAX_MS}ms)  [$(tr '\n' ' ' < "$TMPD/solo")]"
[ "$SOLO_MS" -lt "$SOLO_MAX_MS" ] || {
    echo "throughput FAIL: solo leg took ${SOLO_MS}ms, ceiling is ${SOLO_MAX_MS}ms"
    echo "  A Debug-built ghostty scores ~3713ms here. Check the optimize mode first."
    exit 1
}

# ---- leg 2: a real client on a real pty --------------------------------
# The full path — engine, delta, wire, replica, paint — because `mux` runs
# an engine of its own and can regress the same way the daemon did.
cat > "$TMPD/script" <<EOF
settle 500 8000
send $(now_ms_snippet); for k in \$(seq $REPS); do A=\$(now_ms); yes | head -n $CLIENT_LINES; B=\$(now_ms); echo \$(( B-A )) >> $TMPD/client; done; echo DON""E\r
expect DONE 90000
send \x1c\x1c
waitexit 5000
EOF
RC=0
"$PTYCLIENT" --cols 80 --rows 24 --out "$TMPD/out" --err "$TMPD/err" \
    -- "$MUX" --sock "$SOCK" < "$TMPD/script" > "$TMPD/log" 2>&1 || RC=$?
[ "$RC" -eq 0 ] || {
    echo "throughput FAIL: client leg exited $RC"
    echo "  (3 = the floods never completed inside the expect's 90s)"
    cat "$TMPD/log"
    exit 1
}
# Off disk, not out of the capture: `mux` is a replica painting a 24-row
# grid, so the capture holds coalesced screen deltas and an intermediate
# rep's line scrolls away between paints. Only the last one is ever
# reliably on screen, which is one reading, which is not a best-of.
CLIENT_ALL="$(cat "$TMPD/client" 2>/dev/null || true)"
CLIENT_MS="$(echo "$CLIENT_ALL" | sort -n | head -1)"
[ -n "$CLIENT_MS" ] || {
    echo "throughput FAIL: client leg recorded no timing"; cat "$TMPD/out"; exit 1;
}
[ "$(echo "$CLIENT_ALL" | wc -l)" -eq "$REPS" ] || {
    echo "throughput FAIL: wanted $REPS client readings, got: $CLIENT_ALL"
    exit 1
}

echo "client: $CLIENT_LINES lines, attached:  ${CLIENT_MS}ms (target ${CLIENT_WARN_MS}ms, max ${CLIENT_MAX_MS}ms)  [$(echo "$CLIENT_ALL" | tr '\n' ' ')]"
[ "$CLIENT_MS" -lt "$CLIENT_MAX_MS" ] || {
    echo "throughput FAIL: client leg took ${CLIENT_MS}ms, ceiling is ${CLIENT_MAX_MS}ms"
    exit 1
}
[ "$CLIENT_MS" -lt "$CLIENT_WARN_MS" ] || {
    echo "throughput SLOW: ${CLIENT_MS}ms is over the ${CLIENT_WARN_MS}ms comfort target"
    echo "  Not a failure. It is the number that decides whether this feels good to use."
}

# ---- leg 3: full-width repaint, nobody attached ------------------------
# "Nobody attached" is this leg's entire meaning, so it is asserted rather
# than assumed. Leg 2's `waitexit` proved the mux PROCESS is gone; it did
# not prove the daemon has reaped the client slot, and those are different
# instants. Measured with a slot still open, this leg would be timing the
# attached path against a detached ceiling and failing for the wrong
# reason. The greedy `.*` takes the LAST clients= in the line, which is the
# per-session count rather than the daemon-wide one.
i=0
while [ "$i" -lt 50 ]; do
    if [ "$("$MUX" d stats --sock "$SOCK" | sed -n 's/.*clients=\([0-9]*\).*/\1/p')" = "0" ]; then
        break
    fi
    sleep 0.1
    i=$((i+1))
done
[ "$i" -lt 50 ] || {
    echo "throughput FAIL: leg 2's client is still attached, so leg 3 would not"
    echo "  be measuring a detached session at all"
    "$MUX" d stats --sock "$SOCK"
    exit 1
}
#
# One frame: cursor home, then 23 rows of 79 columns. 23 and not 24 so the
# screen is REPAINTED rather than scrolled — scrolling is a different cost
# (memset and cursorScrollAbove) and it would drown the one being measured.
{
    printf '\033[H'
    i=0
    while [ "$i" -lt 23 ]; do
        printf '%79s\n' '' | tr ' ' x
        i=$((i+1))
    done
} > "$TMPD/frame"

# Doubling rather than a loop of appends: 13 cats instead of 8192.
cp "$TMPD/frame" "$TMPD/big"
i=0
while [ "$i" -lt "$REPAINT_DOUBLINGS" ]; do
    cat "$TMPD/big" "$TMPD/big" > "$TMPD/big2"
    mv "$TMPD/big2" "$TMPD/big"
    i=$((i+1))
done
REPAINT_BYTES=$(wc -c < "$TMPD/big")

rm -f "$TMPD/repaint" "$TMPD/repaint.done"
"$MUX" a send --sock "$SOCK" \
    "$(now_ms_snippet); for k in \$(seq $REPS); do A=\$(now_ms); cat $TMPD/big; B=\$(now_ms); echo \$(( B-A )) >> $TMPD/repaint; done; echo ok > $TMPD/repaint.done\n" \
    > /dev/null
i=0
while [ ! -s "$TMPD/repaint.done" ] && [ "$i" -lt 120 ]; do sleep 0.5; i=$((i+1)); done
[ -s "$TMPD/repaint.done" ] || {
    echo "throughput FAIL: $REPS repaints of $REPAINT_BYTES bytes unfinished after 60s"
    exit 1
}
REPAINT_ALL="$(cat "$TMPD/repaint" 2>/dev/null || true)"
REPAINT_MS="$(echo "$REPAINT_ALL" | sort -n | head -1)"
# Same two guards as leg 2's, in the same order. Unreachable given the
# `-s repaint.done` poll above, but an asymmetry between twins is an
# invitation to "fix" whichever one someone reads second.
[ -n "$REPAINT_MS" ] || {
    echo "throughput FAIL: repaint leg recorded no timing"; exit 1;
}
[ "$(echo "$REPAINT_ALL" | wc -l)" -eq "$REPS" ] || {
    echo "throughput FAIL: wanted $REPS repaint readings, got: $REPAINT_ALL"
    exit 1
}
# The screen must actually be full of the frame, or a shell that never ran
# the cat would score a perfect time for doing nothing.
"$MUX" a capture --sock "$SOCK" | grep -qF 'xxxxxxxx' || {
    echo "throughput FAIL: the repaint left no output on the grid"
    "$MUX" a capture --sock "$SOCK"
    exit 1
}

echo "repaint: $REPAINT_BYTES bytes, detached:  ${REPAINT_MS}ms (max ${REPAINT_MAX_MS}ms)  [$(echo "$REPAINT_ALL" | tr '\n' ' ')]"
[ "$REPAINT_MS" -lt "$REPAINT_MAX_MS" ] || {
    echo "throughput FAIL: repaint leg took ${REPAINT_MS}ms, ceiling is ${REPAINT_MAX_MS}ms"
    echo "  A detached session should not be rendering rows at all. Check that"
    echo "  sendUpdate still asks hasClientsIn BEFORE it diffs."
    exit 1
}

echo "throughput OK"