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 {