diag(quic-interop): trim inspect-multiplexing.sh to actionable sections only
Removed: - file tree dump (sanity check, only useful once) - output.txt last 200 lines (overlaps with writer traces; runner spam already filtered at run-matrix.sh level) - peer MAX_DATA frame grep (qlog observer doesn't emit max_data frames yet, always prints 'no max_data frames') - per-packet stream_id grep (qlog observer doesn't emit stream_id per-frame, always prints 'no stream_id field') - last 5 packet_received / packet_sent (we have steady-state from the histograms; the FIRST 10 packets are what reveal the burst shape, last 5 doesn't add signal) - frames-per-packet histogram (overlapped with stream-frames; the stream-frames histogram is the focused version) - separate qlog event-type histogram (not informative for the current investigation) - first 10 packet_received (server-side response shape, not the bug we're chasing) Kept: - writer-side debug traces (the smoking gun for the live driver bug) - server stderr tail (peer's CONNECTION_CLOSE if any) - stream-frames-per-sent-packet histogram (coalescing or not) - transport_parameters (peer's TPs) - first 10 packet_sent (burst shape after handshake) - connection_closed + packet_dropped (failure indicators)
This commit is contained in:
Claude
@@ -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/<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
|
||||
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)"
|
||||
|
||||
Reference in New Issue
Block a user