From b9d7ea257442c336414458fdf29d51d98b453374 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 4 Jul 2026 15:40:26 +0000 Subject: [PATCH] =?UTF-8?q?perf(nip77):=20direct-build=20NEG-MSG=20wire=20?= =?UTF-8?q?frames=20(~2.5=E2=80=932.8=C3=97=20serialization)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The server's per-round reconcile spends a large slice turning the ~1MB hex reconcile frame into wire JSON: the generic (Jackson) serializer wraps the hex string in a value node and scans every char for JSON escapes a [0-9a-f] payload can never contain, then re-copies. NegMsgMessage.toJson() now builds ["NEG-MSG","",""] directly — no node tree, no escape scan of the hex. Fast path fires only for escape-free printable-ASCII subIds (what the JSON encoder emits verbatim); exotic subIds fall back to the generic serializer, so output is byte-identical. RelaySession.send routes through message.toJson() (default unchanged for every other message type). Measured (toJson + UTF-8, per frame): 64KiB 2.5×, 250KiB 2.6×, 500KiB (strfry cap) 2.8× — ~2.5ms saved per NEG-MSG, ~35ms over a 14-round reconcile. Correctness: a subId battery asserts byte-identity with the generic path, and GeodeVsStrfryNegentropySyncTest (real strfry) reconciles against the fast-built frames. Also records the ingest-latency candidate as measured-not-worth-it: the IngestQueue pipeline overhead is only ~0.17ms p50, <10% of the ~2.4ms receipt→queryable gap — that gap lives in the REQ-visibility path, not the writer. Full write-up in quartz/plans/2026-07-04-sync-serialization-and-ingest-latency.md. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_012EZeWww5TJnzBZKPoc6mvU --- ...4-sync-serialization-and-ingest-latency.md | 60 ++++++++++ .../nip01Core/relay/server/RelaySession.kt | 5 +- .../quartz/nip77Negentropy/NegMsgMessage.kt | 37 +++++++ .../relay/prodbench/IngestLatencyBenchmark.kt | 8 ++ .../prodbench/NegMsgSerializationBenchmark.kt | 104 ++++++++---------- 5 files changed, 156 insertions(+), 58 deletions(-) create mode 100644 quartz/plans/2026-07-04-sync-serialization-and-ingest-latency.md diff --git a/quartz/plans/2026-07-04-sync-serialization-and-ingest-latency.md b/quartz/plans/2026-07-04-sync-serialization-and-ingest-latency.md new file mode 100644 index 0000000000..7b21a9cb47 --- /dev/null +++ b/quartz/plans/2026-07-04-sync-serialization-and-ingest-latency.md @@ -0,0 +1,60 @@ +# Two more relayBench gaps: NEG-MSG serialization (fixed) + ingest latency (measured, not worth it) + +Follow-up to the 1M relayBench run and the NIP-77 diagnosis +(`2026-07-04-negentropy-reconcile-profiling.md`). Both were measured in +isolation first so the fix could be judged on the delta. + +## NEG-MSG wire serialization — **fixed** (~2.5–2.8×) + +The server's per-round reconcile JFR put a large slice in serialization: a +reconcile frame is `Hex.encode`d to a ~1 MB hex string, then the outgoing +`NegMsgMessage` was turned into wire JSON by the generic (Jackson) +serializer, which wraps the giant hex string in a value node and **scans +every char for JSON escapes** a `[0-9a-f]` payload can never contain, then +re-copies. + +`NegMsgMessage.toJson()` now builds `["NEG-MSG","",""]` directly — +no node tree, no escape scan of the hex. The fast path fires only when the +client-chosen `subId` is escape-free printable ASCII (the bytes the JSON +encoder emits verbatim); any exotic subId (quotes, control chars, non-ASCII) +falls back to the generic serializer, so output is **byte-identical**. +`RelaySession.send` now routes through `message.toJson()` (default is +unchanged for every other message type). + +Measured (`NegMsgSerializationBenchmark`, toJson + UTF-8, per frame): + +| frame | generic | fast | speedup | +|---|---:|---:|---:| +| 64 KiB | 0.47 ms | 0.19 ms | 2.5× | +| 250 KiB | 1.97 ms | 0.76 ms | 2.6× | +| 500 KiB (strfry cap) | 3.87 ms | 1.37 ms | 2.8× | + +At the 500 KB frame cap that's ~2.5 ms saved per NEG-MSG, ~35 ms over a +14-round reconcile — server-side, on top of the (library-side) prefix-sum +fingerprint work. Correctness: a subId battery asserts byte-identity with +the generic path, and the `GeodeVsStrfryNegentropySyncTest` interop test +(real strfry) reconciles against the fast-built frames. + +## Receipt➜queryable ingest latency — **measured, not worth fixing** + +Hypothesis: geode's group-commit `IngestQueue` (two channel handoffs, +submit→verifier→writer) adds latency for a single event on an idle relay, +explaining the 1M gap (geode 4.68 ms vs strfry 2.32 ms p50). + +`IngestLatencyBenchmark` timed `submit→onComplete` (fires after COMMIT = +queryable) vs a direct `batchInsert`: + +| path | p50 | p90 | p99 | +|---|---:|---:|---:| +| IngestQueue (submit→OK) | 0.21 ms | 0.31 ms | 0.50 ms | +| direct batchInsert | 0.05 ms | 0.09 ms | 0.17 ms | +| **pipeline overhead** | **0.17 ms** | | | + +The whole ingest trip is ~0.2 ms — the pipeline overhead (~0.17 ms) is <10% +of the ~2.4 ms gap. A single-event fast path in the (carefully-tuned) writer +can't close it. **The gap is in the cross-connection REQ-visibility/poll +path, not ingest** — the probe publishes on one connection and hammer-polls +`REQ {ids:[id]}` on another, so it's dominated by websocket round-trips + +how fast a committed row surfaces to a concurrent reader, not the write. A +real fix needs that path profiled; the writer is not the lever. Benchmark +kept as the evidence. diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/server/RelaySession.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/server/RelaySession.kt index 05cec0fad3..6acacc1705 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/server/RelaySession.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/server/RelaySession.kt @@ -120,7 +120,10 @@ class RelaySession( fun send(message: Message) { try { - onSend(OptimizedJsonMapper.toJson(message)) + // message.toJson() defaults to OptimizedJsonMapper.toJson(this) for + // every type; NegMsgMessage overrides it with a direct-build wire + // path (identical output, ~2× faster on big reconcile frames). + onSend(message.toJson()) } catch (e: Exception) { Log.w("ClientSession") { "Failed to send to ${e.message}" } } diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip77Negentropy/NegMsgMessage.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip77Negentropy/NegMsgMessage.kt index dd97b52475..b532ae0bcc 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip77Negentropy/NegMsgMessage.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip77Negentropy/NegMsgMessage.kt @@ -20,6 +20,7 @@ */ package com.vitorpamplona.quartz.nip77Negentropy +import com.vitorpamplona.quartz.nip01Core.core.OptimizedJsonMapper import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.Message class NegMsgMessage( @@ -28,7 +29,43 @@ class NegMsgMessage( ) : Message { override fun label() = LABEL + /** + * Wire form is `["NEG-MSG","",""]`. The `` payload is a + * reconciliation frame that can be ~1 MB and is *always* lowercase hex + * (`Hex.encode`), so it never needs JSON escaping. The generic serializer + * still wraps it in a value node and scans every char for escapes it can + * never find, then re-copies — profiling put that at a large slice of the + * server's per-round reconcile cost. Build the string directly instead, + * skipping the scan and the intermediate nodes (measured ~2× faster at the + * 500 KB frame cap). + * + * The fast path only fires when [subId] is plain printable ASCII with no + * `"`/`\` — exactly the bytes the JSON encoder would emit verbatim — so + * the output is byte-identical to the generic path. Any exotic subId + * (control chars, quotes, non-ASCII) falls back to it. + */ + override fun toJson(): String { + if (!isEscapeFreeAscii(subId)) return OptimizedJsonMapper.toJson(this) + return buildString(message.length + subId.length + 16) { + append("[\"") + append(LABEL) + append("\",\"") + append(subId) + append("\",\"") + append(message) + append("\"]") + } + } + companion object { const val LABEL = "NEG-MSG" + + /** True when every char is printable ASCII (0x20–0x7e) and not `"`/`\`. */ + private fun isEscapeFreeAscii(s: String): Boolean { + for (c in s) { + if (c < ' ' || c > '~' || c == '"' || c == '\\') return false + } + return true + } } } diff --git a/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/IngestLatencyBenchmark.kt b/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/IngestLatencyBenchmark.kt index f3db69ef12..d9bf32999a 100644 --- a/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/IngestLatencyBenchmark.kt +++ b/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/IngestLatencyBenchmark.kt @@ -45,6 +45,14 @@ import kotlin.test.Test * `store.batchInsert(listOf(e))` — the delta is exactly the pipeline's * coroutine-handoff overhead, the thing a single-event fast path would save. * + * **Verdict (measured): the pipeline is not the bottleneck.** The overhead + * came out at ~0.17 ms p50 (queue 0.21 ms vs direct 0.05 ms) — the whole + * ingest trip is ~0.2 ms, far under the ~2.4 ms receipt➜queryable gap the 1M + * run showed (geode 4.68 vs strfry 2.32 ms). So a single-event fast path in + * [IngestQueue] can close <10 % of the gap; it isn't worth the complexity. + * The gap lives in the cross-connection REQ-visibility/poll path, not the + * writer — a separate investigation. This benchmark stays as the evidence. + * * Prints percentiles; no speed assertion (container-noisy). */ class IngestLatencyBenchmark { diff --git a/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/NegMsgSerializationBenchmark.kt b/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/NegMsgSerializationBenchmark.kt index c5edbeeb34..6114db7f8c 100644 --- a/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/NegMsgSerializationBenchmark.kt +++ b/quartz/src/jvmTest/kotlin/com/vitorpamplona/quartz/nip01Core/relay/prodbench/NegMsgSerializationBenchmark.kt @@ -20,58 +20,26 @@ */ package com.vitorpamplona.quartz.nip01Core.relay.prodbench +import com.vitorpamplona.quartz.nip01Core.core.OptimizedJsonMapper import com.vitorpamplona.quartz.nip77Negentropy.NegMsgMessage import kotlin.test.Test import kotlin.test.assertEquals /** - * Isolates the per-round NEG-MSG serialization tax that geode's server-path - * JFR attributed ~40% of reconcile time to: a reconcile produces a binary - * frame, `Hex.encode`s it to a ~1 MB hex String, then the outgoing [Message] - * is turned into wire JSON by [com.vitorpamplona.quartz.nip01Core.kotlinSerialization.MessageKSerializer], - * which builds a `JsonElement` tree (wrapping the giant hex string in a - * `JsonPrimitive`) and re-serializes it — scanning every hex char for JSON - * escapes that a `[0-9a-f]` payload can never contain — before Ktor UTF-8 - * encodes it to the socket. + * Measures the NEG-MSG wire-serialization fix and guards its correctness. + * geode's server-path JFR attributed a large slice of per-round reconcile + * time to turning the reconcile frame into wire JSON: `Hex.encode` → the + * generic (Jackson) [com.vitorpamplona.quartz.nip01Core.core.OptimizedJsonMapper] + * serializer, which wraps the ~1 MB hex string in a value node and scans + * every char for JSON escapes a `[0-9a-f]` payload can never contain. * - * The wire is trivially `["NEG-MSG","",""]`, so a direct - * `StringBuilder` skips the tree. This measures the current `toJson()` path - * against that direct build (both followed by the UTF-8 encode a websocket - * text frame pays), at realistic NEG-MSG sizes, and asserts they produce - * byte-identical wire output. + * [NegMsgMessage.toJson] now builds `["NEG-MSG","",""]` directly + * (fast path for escape-free ASCII subIds; generic fallback otherwise). + * This asserts the fast path is **byte-identical** to the generic path + * across a battery of subIds — including exotic ones that must hit the + * fallback — and times the two at realistic frame sizes. */ class NegMsgSerializationBenchmark { - /** Direct wire build — `["NEG-MSG","",""]`, hex needs no escaping. */ - private fun directWire( - subId: String, - hex: String, - ): String = - buildString(hex.length + subId.length + 16) { - append("[\"NEG-MSG\",") - append(jsonString(subId)) // client-chosen subId: escape defensively - append(',') - append('"') - append(hex) // pure hex, no escaping possible - append("\"]") - } - - /** Minimal JSON string encoder for the (short, usually-safe) subId. */ - private fun jsonString(s: String): String = - buildString(s.length + 2) { - append('"') - for (c in s) { - when (c) { - '"' -> append("\\\"") - '\\' -> append("\\\\") - '\n' -> append("\\n") - '\r' -> append("\\r") - '\t' -> append("\\t") - else -> if (c < ' ') append("\\u%04x".format(c.code)) else append(c) - } - } - append('"') - } - private fun hexPayload(rawBytes: Int): String { val chars = "0123456789abcdef" val sb = StringBuilder(rawBytes * 2) @@ -83,37 +51,59 @@ class NegMsgSerializationBenchmark { return sb.toString() } + @Test + fun fastPathIsByteIdenticalToGeneric() { + val hex = hexPayload(1024) + val subIds = + listOf( + "bench-sync", + "sub_123", + "a".repeat(64), + "", // empty + "with\"quote", // → fallback + "with\\backslash", // → fallback + "tab\there", // → fallback + "new\nline", // → fallback + "unicode-é中", // non-ASCII → fallback + "ctrlchar", // → fallback + ) + for (sub in subIds) { + val msg = NegMsgMessage(sub, hex) + assertEquals( + OptimizedJsonMapper.toJson(msg), + msg.toJson(), + "toJson() must match the generic serializer for subId=<$sub>", + ) + } + } + private fun bench( label: String, rawFrameBytes: Int, ) { - val subId = "bench-sync" val hex = hexPayload(rawFrameBytes) - val msg = NegMsgMessage(subId, hex) - - // Correctness: direct build must equal the serializer's wire output. - assertEquals(msg.toJson(), directWire(subId, hex), "wire mismatch for $label") + val msg = NegMsgMessage("bench-sync", hex) val warmup = 200 val runs = 500 var sink = 0 + repeat(warmup) { sink = sink xor msg.toJson().length xor OptimizedJsonMapper.toJson(msg).length } - repeat(warmup) { sink = sink xor msg.toJson().length xor directWire(subId, hex).length } - + // Include the UTF-8 encode a websocket text frame pays either way. val t0 = System.nanoTime() - repeat(runs) { sink = sink xor msg.toJson().encodeToByteArray().size } - val curMs = (System.nanoTime() - t0) / 1e6 / runs + repeat(runs) { sink = sink xor OptimizedJsonMapper.toJson(msg).encodeToByteArray().size } + val genMs = (System.nanoTime() - t0) / 1e6 / runs val t1 = System.nanoTime() - repeat(runs) { sink = sink xor directWire(subId, hex).encodeToByteArray().size } + repeat(runs) { sink = sink xor msg.toJson().encodeToByteArray().size } val fastMs = (System.nanoTime() - t1) / 1e6 / runs - println(" %-18s cur %6.3f ms direct %6.3f ms %.1f× (sink=%d)".format(label, curMs, fastMs, curMs / fastMs, sink and 1)) + println(" %-16s generic %6.3f ms fast %6.3f ms %.1f× (sink=%d)".format(label, genMs, fastMs, genMs / fastMs, sink and 1)) } @Test - fun negMsgWireSerialization() { - println("─ NegMsgSerializationBenchmark: toJson()+utf8 vs direct build+utf8 ─") + fun negMsgWireSerializationSpeedup() { + println("─ NegMsgSerializationBenchmark: generic vs fast toJson()+utf8 ─") bench("64 KiB frame", 64 * 1024) bench("250 KiB frame", 250 * 1024) bench("500 KiB frame", 500 * 1024) // strfry's frame cap