|
| 1 | +# λ Async Copy Elimination in the Message Path — Summary Report |
| 2 | + |
| 3 | +Deep-copy and hash-recomputation analysis of Logos Messaging under chronos / refc, and the |
| 4 | +measured result of removing them. |
| 5 | + |
| 6 | +> **Logos Messaging (Nim) · logos-delivery · 2026-07-15** |
| 7 | +> Nim 2.2.4 · `--mm:refc` · chronos 4.2.2 · Apple M4 |
| 8 | +> |
| 9 | +> Branch train: `master` → `experimental/chore-nocopy-e2e-perf-harness` (2a4da679) |
| 10 | +> → `experimental/chore-nocopy-wakumessage-refobj` (3d98a28d) |
| 11 | +> → `experimental/chore-nocopy-wakuenvelop` (a6f1065a · be6bfed6) |
| 12 | +> |
| 13 | +> HTML version: [`nocopy_summary_report.html`](nocopy_summary_report.html) |
| 14 | +
|
| 15 | +--- |
| 16 | + |
| 17 | +## 01 — Hypothesis & Static Analysis |
| 18 | + |
| 19 | +**Hypothesis.** Under `--mm:refc`, chronos async gates and Result/Option idioms force deep copies |
| 20 | +of every `seq`-carrying value they touch. A single inbound relayed `WakuMessage` (three heap seqs + |
| 21 | +a string) was predicted to cost on the order of **19 + F full-payload copies** (F = filter peers) |
| 22 | +and **4–6 SHA-256 passes**, almost all redundant. A secondary memory hypothesis was stated up |
| 23 | +front: *no real gain in retained memory is expected (the copies are temporaries), but a slower |
| 24 | +heap-allocation elevation pattern on the GC side.* Both were put to measurement. |
| 25 | + |
| 26 | +### Where chronos deep-copies (root mechanics) |
| 27 | + |
| 28 | +| Copy point | Mechanism | refc | ORC | |
| 29 | +|---|---|---|---| |
| 30 | +| Every `{.async.}` call, per seq/string param | params lambda-lifted into the closure-iterator env (`asyncmacro.nim:445-517`) | deep copy per param | elided (move) | |
| 31 | +| `complete(future, val)` | `val: T` not `sink`; `internalValue = val` (`asyncfutures.nim:198-202`); `move()` degrades to copy under refc | 1–2 copies | 1 copy | |
| 32 | +| `let x = await f(...)` | `value()` returns `lent T`; the bind to `x` copies | 1 copy | 1 copy | |
| 33 | +| Result/Option bind-out (`valueOr`, `?`, `get`) | accessors are `lent`/templates; the `let` bind of a large value copies; `valueOr`/`?` also copy an lvalue Result | 1 copy per bind | usually moved | |
| 34 | + |
| 35 | +### Accumulated per-message budget on the inbound relay path (static count, verified by counters) |
| 36 | + |
| 37 | +| Cost class | Sites | Count / msg | |
| 38 | +|---|---|---| |
| 39 | +| **Redundant proto decodes** of the same bytes | `waku_relay/protocol.nim` — ordered validator :543 · onRecv observer :271 · onValidated :326 · topicHandler :603 (+ onSend :341 outbound) | 4 (receiver), ≈2 avoidable copies each | |
| 40 | +| **Async closure env captures** of the decoded message | `node/subscription_manager.nim` — uniqueTopicHandler :72 + trace/filter/archive/sync/internal/legacyApp handlers :45–82 | 7 deep copies | |
| 41 | +| **Hash recomputation** (`computeMessageHash`) | relay :217/:553/:571/:686 · archive :101 · filter :195/:246 · store-sync :78 · node publish :148 | 4–6 SHA-256 passes | |
| 42 | +| **Per-peer buffer copy** (filter push) | `waku_filter_v2/protocol.nim:170` — `{.async.}` by-value buffer per subscribed peer | F copies | |
| 43 | +| **Total** | vs. theoretical minimum ≈ 3 (decode once · hash once · encode once) | **≈ 19 + F copies, 4–6 hashes** | |
| 44 | + |
| 45 | +Phase 1 instrumentation confirmed the static analysis before any fix: the two-node benchmark |
| 46 | +measured 6.0 decodes / 5.0 hashes per message process-wide — the receiver alone decoding the |
| 47 | +identical proto bytes 4×. At the 10/50/150 kB payload profile this amplifies a 50 kB message into |
| 48 | +≈ 1 MB of heap traffic. |
| 49 | + |
| 50 | +--- |
| 51 | + |
| 52 | +## 02 — Three Phases, One Branch Train |
| 53 | + |
| 54 | +Each phase lives on its own local branch, chained for a PR train off `master`. Every phase ends |
| 55 | +with the same harness re-run, so each claim is a measured delta, not a projection. |
| 56 | + |
| 57 | +### Phase 01 — Measure first: e2e performance harness |
| 58 | + |
| 59 | +`experimental/chore-nocopy-e2e-perf-harness` · 4 commits → `2a4da679` |
| 60 | + |
| 61 | +- Micro + macro benchmark (`apps/benchmarks/message_path_bench.nim`), deterministic fixed-seed workload. |
| 62 | +- `-d:msgPathCounters`: counters inside `WakuMessage.decode` and `computeMessageHash` — zero cost when undefined. |
| 63 | +- Baseline committed (`bench_baseline.md`) before touching production code. |
| 64 | + |
| 65 | +> **Gate:** counters must confirm ≥ 4 decodes and 4–6 hashes/msg — **passed** (6.0 / 5.0 aggregate). |
| 66 | +
|
| 67 | +### Phase 02 — Copies become pointers: WakuMessage as `ref object` |
| 68 | + |
| 69 | +`experimental/chore-nocopy-wakumessage-refobj` · 5 commits → `3d98a28d` |
| 70 | + |
| 71 | +- Every assignment / async capture / Result bind of a message: 3-seq deep copy → pointer + refcount. No signature changes. |
| 72 | +- Structural `==`, explicit `clone()`, immutable-by-convention. |
| 73 | +- Aliasing audit of all mutation sites; **5 real fixes** (publish timestamp, `ensureTimestampSet`, 2× RLN proof attach, postgres nil-init). ASAN clean. |
| 74 | + |
| 75 | +> **Gate:** decode/hash counters byte-identical to baseline (no behavior change) — **passed** (2/2 · 6/5 unchanged). |
| 76 | +
|
| 77 | +### Phase 03 — Decode once, hash once: WakuEnvelope API break |
| 78 | + |
| 79 | +`experimental/chore-nocopy-wakuenvelop` · 7 commits → `a6f1065a` |
| 80 | + |
| 81 | +- `WakuEnvelope` = (msg · pubsubTopic · hash) as one ref; `WakuRelayHandler` takes the envelope; archive/filter/sync/FFI reuse `envelope.hash`. |
| 82 | +- Unused onRecv observer decode deleted; onValidated/onSend decodes gated to DEBUG. |
| 83 | +- Filter push buffer shared across peers (no per-peer copy). |
| 84 | + |
| 85 | +> **Gate:** receiver-side ≤ 2 decodes and exactly 1 hash per message — **passed** (2.0 / 1.0). |
| 86 | +
|
| 87 | +--- |
| 88 | + |
| 89 | +## 03 — Measurement Method |
| 90 | + |
| 91 | +| Scenario | Entry endpoint | Exit endpoint (measured) | What it isolates | |
| 92 | +|---|---|---|---| |
| 93 | +| **micro** — in-process, no network | raw proto bytes into the relay's registered *ordered validator*, then its *topicHandler* | return of the full dispatch chain (trace → archive insert → store-sync → internal event) | the receiver pipeline, low-noise (0.4–4 % variance) | |
| 94 | +| **macro** — end-to-end | `nodeA.publish()` — public node API → gossipsub → loopback TCP | application-level relay handler on node B, firing only after validation, decode, dispatch and archive insert complete | the full pipeline incl. libp2p observers | |
| 95 | + |
| 96 | +Workload: fixed seed 42, payload mix **10 / 50 / 150 kB at 25 / 50 / 25 %**, N = 1000 + 100 warmup, |
| 97 | +unique payload prefix + timestamp (no gossipsub dedup). Publisher flow-controlled to a 32-message |
| 98 | +window. Decode/hash counters live inside the codec and hash procs themselves — they count reality, |
| 99 | +not expectations. Peak heap via `getMaxMem()`; heap series sampled every 50 messages; retained |
| 100 | +delta via `getOccupiedMem()` after `GC_fullCollect()`. |
| 101 | + |
| 102 | +Final comparison ran both branch heads back-to-back in one session on the same machine (one |
| 103 | +post-refactor pass discarded for a >5 % variance load spike, rerun within bounds). Not covered by |
| 104 | +these numbers: RLN validation, filter push to remote peers, REST/FFI boundary, real network latency. |
| 105 | + |
| 106 | +--- |
| 107 | + |
| 108 | +## 04 — Measured Gains — Before vs. After |
| 109 | + |
| 110 | +"Before" = pre-Phase-2 head (`2a4da679`: original production code + harness). |
| 111 | +"After" = post-Phase-3 head (`a6f1065a`). Same-session A/B. |
| 112 | + |
| 113 | +| | | | |
| 114 | +|---|---|---| |
| 115 | +| **+86 %** micro throughput (1,223 → 2,274 msg/s) | **+57 %** e2e throughput (225 → 353 msg/s) | **−21 %** peak heap (515 → 408 MB macro) | |
| 116 | + |
| 117 | +### Full comparison |
| 118 | + |
| 119 | +| Metric | Before | After | Δ | |
| 120 | +|---|---:|---:|---:| |
| 121 | +| micro msg/s | 1,222.8 | 2,273.7 | **+85.9 %** | |
| 122 | +| micro p50 / p99 per msg | 630 µs / 1.94 ms | 338 µs / 1.09 ms | −46 % / −44 % | |
| 123 | +| micro decodes / hashes per msg | 2.0 / 2.0 | 2.0 / 1.0 | hash −50 % | |
| 124 | +| macro msg/s (e2e) | 225.5 | 353.1 | **+56.6 %** | |
| 125 | +| macro p50 / p99 inter-arrival | 3.55 ms / 10.7 ms | 2.29 ms / 7.5 ms | −35 % / −30 % | |
| 126 | +| macro decodes / hashes per msg (aggregate) | 6.0 / 5.0 | 3.0 / 3.0 | −50 % / −40 % | |
| 127 | +| — receiver-side only | 4 dec / 3 hash | **2 dec / 1 hash** | gate met | |
| 128 | +| bytes decoded / hashed per 1000 msgs | 390 / 325 MB | 195 / 195 MB | −50 % / −40 % | |
| 129 | +| peak heap `getMaxMem` (micro / macro) | 333.6 / 514.9 MB | 263.6 / 408.4 MB | **−21 % both** | |
| 130 | +| GC collections (micro / macro) | 7–8 / 10 | 7–8 / 10 | identical | |
| 131 | +| retained-mem slope, macro | ≈ 12.6 MB / 100 msg | ≈ 13.2 MB / 100 msg | flat (archive-driven) | |
| 132 | + |
| 133 | +### Memory hypothesis — verdict |
| 134 | + |
| 135 | +**(a) No real retained-memory gain — CONFIRMED.** Retention slope is identical before and after — |
| 136 | +it is the archive holding the same 1000 messages. The eliminated copies were temporaries, exactly |
| 137 | +as hypothesized. |
| 138 | + |
| 139 | +**(b) Slower heap-elevation pattern — REFUTED; level shift instead.** Slope and collection counts |
| 140 | +are unchanged: under refc the transient copies were refcount-freed deterministically and never |
| 141 | +accumulated toward collection triggers. The win manifests as a **−21 % peak heap** and a |
| 142 | +~65–75 MB lower level throughout the run — the copies cost CPU (memcpy + alloc/free churn) and |
| 143 | +peak footprint, not GC-cycle pressure. Quantifying raw churn would require cumulative-allocation |
| 144 | +counters or malloc profiling. |
| 145 | + |
| 146 | +--- |
| 147 | + |
| 148 | +## Conclusions & Open Items |
| 149 | + |
| 150 | +The message path now performs one decode per trust boundary and one hash per message, carried by |
| 151 | +reference through every async gate. Verification at each phase: representative suites green |
| 152 | +(~160+ tests), ASAN clean on the dispatch path, counters byte-exact where no change was claimed. |
| 153 | + |
| 154 | +- Per-shard payload byte gauges (`waku_relay_*_msg_bytes_per_shard`) now populate only at DEBUG/TRACE — decide before merge if dashboards need them. |
| 155 | +- Archive/filter keep thin `(topic, msg)` compat overloads; removable later. |
| 156 | +- Lightpush `validateMessage` double-encode deferred (needs `PushMessageHandler` signature change). |
| 157 | +- Under a future ORC build the remaining `complete()`/await-bind copies persist — returning refs from async procs stays best practice. |
| 158 | + |
| 159 | +Sources: `async_copy_analysis.md` · `async_copy_fix_plan.md` · `plan_phase{1,2,3}_*.md` · |
| 160 | +`bench_baseline.md` · `phase2_mutation_audit.md` · `speed_gain_pre2_post3.md` — all committed on |
| 161 | +the branch train. |
| 162 | + |
| 163 | +*Logos.co · λ Logos Messaging · Engineering Report · 2026-07-15* |
0 commit comments