diff --git a/quic/interop/inspect-multiplexing.sh b/quic/interop/inspect-multiplexing.sh index 81c948919..c5aa271c5 100755 --- a/quic/interop/inspect-multiplexing.sh +++ b/quic/interop/inspect-multiplexing.sh @@ -1,7 +1,7 @@ #!/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). +# (../quic-interop-runner from this repo). set -euo pipefail REPO_ROOT="$(cd "$(dirname "$0")/../.." && pwd)" @@ -12,7 +12,6 @@ if [[ ! -d "$RUNNER_LOGS" ]]; then 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 @@ -29,20 +28,12 @@ if [[ -z "$CASE_DIR" ]]; then 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 "=============== writer-side debug traces (DEBUG=1 build only) ===============" -# Per-drain frame/budget stats from buildApplicationPacket. Empty -# unless the image was built with `make build DEBUG=1`. +# Per-drain frame/budget stats from buildApplicationPacket. The +# smoking-gun section for "writer is iterating N active streams but +# emits only 1 STREAM frame per packet". Empty unless the image was +# built with `make build DEBUG=1`. WRITER_LINES=$(grep -c '\[writer' "$CASE_DIR/output.txt" 2>/dev/null || echo 0) if [[ "$WRITER_LINES" -gt 0 ]]; then echo "($WRITER_LINES writer trace lines; first 30:)" @@ -54,96 +45,49 @@ if [[ "$WRITER_LINES" -gt 0 ]]; then echo "active histogram (active stream count at drain time):" grep -oE 'active=[0-9]+' "$CASE_DIR/output.txt" | sort | uniq -c | sort -rn else - echo "(no [writer.* lines — run with DEBUG=1 image: cd quic/interop && make build DEBUG=1)" + echo "(no [writer.* lines — rebuild image with: cd quic/interop && make build DEBUG=1)" fi echo -echo "=============== server stderr (last 100 lines) ===============" -tail -n 100 "$CASE_DIR/server/stderr.log" 2>/dev/null \ +echo "=============== server stderr (last 50 lines) ===============" +# Peer's CONNECTION_CLOSE reason if any; processing pace via stream +# create/discard cadence. +tail -n 50 "$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/.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 + 2>/dev/null | head -n 1 || true)" +if [[ -z "$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 "=============== first 10 packet_sent events (full) ===============" - # The very first stream-bearing packets reveal whether we burst - # the chunk's 64 streams OR dribbled them out one per RTT. Look - # at the `frames` array — if it has 13 stream entries, writer - # is bursting; if 1, writer is regressed. - grep '"name":"transport:packet_sent"' "$QLOG" | head -n 10 - - echo - echo "=============== first 10 packet_received events (full) ===============" - # If we sent N streams in burst, server should respond with N - # responses interleaved as it processes them. Spread tells us - # server-side serial cost. - grep '"name":"transport:packet_received"' "$QLOG" | head -n 10 - # If initial_max_data is small (e.g. < 1000 bytes), our writer - # gets throttled to one stream per packet because connBudget - # exhausts after the first stream. Each subsequent stream has to - # wait for a MAX_DATA frame from the peer (1 RTT each). - grep '"name":"transport:parameters_set"' "$QLOG" - - echo - echo "=============== peer MAX_DATA frame timestamps + values (received) ===============" - # If MAX_DATA frames arrive with small bumps and at one-per-RTT - # cadence, we're flow-control bottlenecked: peer extends credit - # by ~50 bytes per RTT, we send one stream per credit bump. - grep '"name":"transport:packet_received"' "$QLOG" \ - | grep -oE '"frame_type":"max_data"[^}]*' \ - | head -n 30 || echo "(no max_data frames in qlog — may need to upgrade qlog observer)" - - echo - echo "=============== first 30 packet_sent stream offsets (per-stream byte count) ===============" - # If every stream emits exactly one ~50-byte chunk before the next - # stream starts, we're connection-flow-control bound. - grep '"name":"transport:packet_sent"' "$QLOG" \ - | grep -oE '"stream_id":[0-9]+' \ - | head -n 30 || echo "(no stream_id field in qlog — may need to upgrade qlog observer)" - - 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)" + echo "(no qlog under $CASE_DIR/client/qlog — skipping qlog sections)" + exit 0 fi + +echo +echo "=============== qlog ($QLOG, $(wc -l <"$QLOG" | tr -d ' ') lines) ===============" + +echo +echo "stream-frames-per-sent-packet histogram:" +# Many `0` = ack-only; many `1` = the bug; many `>=4` = writer +# coalescing as intended. +grep '"name":"transport:packet_sent"' "$QLOG" \ + | awk -F'"frame_type":"stream"' '{print NF - 1}' \ + | sort -n | uniq -c + +echo +echo "transport_parameters (local + remote):" +grep '"name":"transport:parameters_set"' "$QLOG" + +echo +echo "first 10 packet_sent (full) — burst shape after handshake:" +grep '"name":"transport:packet_sent"' "$QLOG" | head -n 10 + +echo +echo "connection_closed events (peer CCs are the smoking gun for spec violations):" +grep '"name":"transport:connection_closed"' "$QLOG" || echo "(none)" + +echo +echo "packet_dropped events (last 10):" +grep '"name":"transport:packet_dropped"' "$QLOG" | tail -n 10 \ + || echo "(none)"