Claude
b7f63a6854
The matrix run on 2026-05-07 showed the same 1-stream-per-packet wire
shape AFTER the streamsLock fix — meaning the lock fix was correct
but didn't address the root cause. Adding diagnostics so the next
investigation has data to work with, instead of more theorizing.
Two pieces, both quiet by default:
(1) inspect-multiplexing.sh: histograms over packet_sent events that
answer "is the writer coalescing or not" without re-running the
matrix. Re-run on the existing run dir and we get:
- frames-per-packet histogram: should be skewed high (≥4) if
coalescing is working; skewed to 1 if regressed
- stream-frames-per-packet histogram: same shape but only
counting STREAM frames (filters out ack-only packets)
- first 30 packet_sent timestamps: did we burst 64 streams in
<50ms or did we dribble them out one-RTT-per-stream?
(2) InteropClient: per-chunk wall-clock split (enqueue ms vs
responses ms vs cumulative). Behind QUIC_INTEROP_DEBUG=1, off in
matrix runs by default. Tells us whether the bottleneck is
client-side (long enqueue ms — writer can't pack the batch) or
server-side (long responses ms — server processes streams
serially).
These together should localize bug to either:
A) our writer regressing one-stream-per-packet under live driver
load (despite MultiplexingCoalescingTest passing synchronously)
B) aioquic-qns serving 32-byte files from disk on macOS Docker FS
at 30-40ms each, so 32 chunks * 64 streams sequential = 60s
If (A), we have a writer bug to fix. If (B), the test runner is the
bottleneck and we should validate against a faster server (quic-go).
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
104 lines
3.9 KiB
Bash
Executable File
104 lines
3.9 KiB
Bash
Executable File
#!/usr/bin/env bash
|
|
# Pull the post-mortem diagnostics for the most recent multiplexing run.
|
|
# Runs from anywhere; resolves logs relative to the runner clone path
|
|
# you've been using (../quic-interop-runner from this repo).
|
|
set -euo pipefail
|
|
|
|
REPO_ROOT="$(cd "$(dirname "$0")/../.." && pwd)"
|
|
RUNNER_LOGS="${REPO_ROOT}/../quic-interop-runner/logs"
|
|
|
|
if [[ ! -d "$RUNNER_LOGS" ]]; then
|
|
echo "no runner logs at $RUNNER_LOGS" >&2
|
|
exit 1
|
|
fi
|
|
|
|
# Most recent run dir.
|
|
RUN_DIR="$(ls -1dt "$RUNNER_LOGS"/run-* 2>/dev/null | head -n 1 || true)"
|
|
if [[ -z "$RUN_DIR" ]]; then
|
|
echo "no run-* dirs under $RUNNER_LOGS" >&2
|
|
exit 1
|
|
fi
|
|
echo "==> run dir: $RUN_DIR"
|
|
|
|
# Layout: <run>/<server>_<client>/<testcase>/{client,server,sim}/
|
|
CASE_DIR="$(ls -1d "$RUN_DIR"/*amethyst*/multiplexing 2>/dev/null | head -n 1 || true)"
|
|
if [[ -z "$CASE_DIR" ]]; then
|
|
echo "no <pair>/multiplexing dir; tree under run:" >&2
|
|
find "$RUN_DIR" -maxdepth 3 -type d >&2
|
|
exit 1
|
|
fi
|
|
echo "==> case dir: $CASE_DIR"
|
|
|
|
echo
|
|
echo "=============== file tree under case dir ==============="
|
|
find "$CASE_DIR" -maxdepth 4 -type f -printf '%s\t%p\n' 2>/dev/null \
|
|
|| find "$CASE_DIR" -maxdepth 4 -type f -exec ls -l {} + 2>/dev/null
|
|
|
|
echo
|
|
echo "=============== output.txt (runner stdout — last 200 lines) ==============="
|
|
tail -n 200 "$CASE_DIR/output.txt" 2>/dev/null \
|
|
|| echo "(no output.txt)"
|
|
|
|
echo
|
|
echo "=============== server stderr (last 100 lines) ==============="
|
|
tail -n 100 "$CASE_DIR/server/stderr.log" 2>/dev/null \
|
|
|| echo "(no server/stderr.log)"
|
|
|
|
# Find the qlog. The runner mounts QLOGDIR=/logs/qlog so we land at
|
|
# client/qlog/<odcid>.sqlog inside the case dir.
|
|
QLOG="$(ls -1 "$CASE_DIR"/client/qlog/*.sqlog \
|
|
"$CASE_DIR"/client/qlog/*.qlog \
|
|
"$CASE_DIR"/client/*.sqlog \
|
|
"$CASE_DIR"/client/*.qlog 2>/dev/null | head -n 1 || true)"
|
|
|
|
if [[ -n "$QLOG" ]]; then
|
|
echo
|
|
echo "=============== qlog event-type histogram ==============="
|
|
echo "(file: $QLOG, $(wc -l <"$QLOG" | tr -d ' ') lines)"
|
|
grep -oE '"name":"[^"]+"' "$QLOG" | sort | uniq -c | sort -rn | head -n 20
|
|
|
|
echo
|
|
echo "=============== frames-per-packet histogram (sent) ==============="
|
|
# Smoking gun for "is the writer coalescing or sending one STREAM
|
|
# per datagram":
|
|
# - Many `frames=1` → regressed, one stream per packet on the wire
|
|
# - Most `frames>=4` → writer is bursting, server is the bottleneck
|
|
grep '"name":"transport:packet_sent"' "$QLOG" \
|
|
| awk -F'"frame_type":' '{print NF - 1}' \
|
|
| sort -n | uniq -c
|
|
|
|
echo
|
|
echo "=============== stream-frames-per-sent-packet histogram ==============="
|
|
# Same shape but counts STREAM frames specifically (vs ack/ping/etc).
|
|
# A "stream" frame_type means request data going out.
|
|
grep '"name":"transport:packet_sent"' "$QLOG" \
|
|
| awk -F'"frame_type":"stream"' '{print NF - 1}' \
|
|
| sort -n | uniq -c
|
|
|
|
echo
|
|
echo "=============== wall-clock arrival of first 30 sent stream-bearing packets ==============="
|
|
# Did we BURST 64 streams in ~50ms after handshake, or did we
|
|
# dribble them out over time?
|
|
grep '"name":"transport:packet_sent".*"frame_type":"stream"' "$QLOG" \
|
|
| head -n 30 \
|
|
| grep -oE '"time":[0-9]+' \
|
|
| head -n 30
|
|
|
|
echo
|
|
echo "=============== last 5 packet_received events ==============="
|
|
grep '"name":"transport:packet_received"' "$QLOG" | tail -n 5
|
|
|
|
echo
|
|
echo "=============== last 5 packet_sent events ==============="
|
|
grep '"name":"transport:packet_sent"' "$QLOG" | tail -n 5
|
|
|
|
echo
|
|
echo "=============== connection_closed events ==============="
|
|
grep '"name":"transport:connection_closed"' "$QLOG" || echo "(none — connection didn't formally close)"
|
|
|
|
echo
|
|
echo "=============== packet_dropped events (last 10) ==============="
|
|
grep '"name":"transport:packet_dropped"' "$QLOG" | tail -n 10 \
|
|
|| echo "(none)"
|
|
fi
|