From b7f63a6854f40e955886ab434798f84301c4845a Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 7 May 2026 12:26:58 +0000 Subject: [PATCH] diag(quic-interop): targeted multiplex traces MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- quic/interop/inspect-multiplexing.sh | 27 +++++++++++++++++++ .../quic/interop/runner/InteropClient.kt | 23 +++++++++++++++- 2 files changed, 49 insertions(+), 1 deletion(-) diff --git a/quic/interop/inspect-multiplexing.sh b/quic/interop/inspect-multiplexing.sh index 73f76c8d4..9a63b1918 100755 --- a/quic/interop/inspect-multiplexing.sh +++ b/quic/interop/inspect-multiplexing.sh @@ -57,6 +57,33 @@ if [[ -n "$QLOG" ]]; then 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 diff --git a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt index 39112ec8a..2e59fd32d 100644 --- a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt +++ b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt @@ -50,6 +50,8 @@ import kotlin.system.exitProcess * - `1` — testcase failed (bug in our impl, OR partner) * - `127` — testcase not implemented (runner skips, doesn't fail) */ +private fun nowMs(): Long = System.currentTimeMillis() + private const val EXIT_OK = 0 private const val EXIT_FAIL = 1 private const val EXIT_UNSUPPORTED = 127 @@ -348,7 +350,16 @@ private fun runTransferTest( // ~10 streams/packet. Coalescing recovered // by batching enqueues + single wake. val collected = mutableListOf>() - urls.chunked(MULTIPLEX_PARALLELISM).forEach { chunk -> + // Quiet by default. QUIC_INTEROP_DEBUG=1 emits one + // line per chunk to stderr — wall-clock split between + // "all enqueued" and "all responded" lets us see + // whether time is spent in the writer (lots of ms + // before responses start arriving) or the server + // (responses dribble in over a long stretch). + val debug = System.getenv("QUIC_INTEROP_DEBUG") == "1" + val transferStartMs = nowMs() + urls.chunked(MULTIPLEX_PARALLELISM).forEachIndexed { chunkIdx, chunk -> + val chunkStartMs = nowMs() // Single lock-held batch open + enqueue. // Without this, openBidiStream's per-call // lock acquire / release lets the send loop @@ -356,6 +367,7 @@ private fun runTransferTest( // stream per packet. val handles = client.prepareRequests(authority, chunk.map { it.path }) driver.wakeup() + val enqueuedMs = nowMs() coroutineScope { val deferreds = chunk.zip(handles).map { (url, handle) -> @@ -369,6 +381,15 @@ private fun runTransferTest( } deferreds.forEach { collected += it.await() } } + if (debug) { + val doneMs = nowMs() + System.err.println( + "[interop] chunk=$chunkIdx size=${chunk.size} " + + "enqueue=${enqueuedMs - chunkStartMs}ms " + + "responses=${doneMs - enqueuedMs}ms " + + "cumulative=${doneMs - transferStartMs}ms", + ) + } } collected } else {