diff --git a/docs/analysis/bench_baseline.md b/docs/analysis/bench_baseline.md index c1b3b7704..92e79bc88 100644 --- a/docs/analysis/bench_baseline.md +++ b/docs/analysis/bench_baseline.md @@ -86,3 +86,81 @@ macro per-message numbers are the aggregate of publisher (node A) + receiver | 3 | Two consecutive micro runs < 5 % msg/s variance | **PASS** — 4.03 % (and 1.90 % / 3.12 % on earlier runs) | | 4 | Macro `decodes_per_msg ≥ 4` and `hashes_per_msg` in 4–6 | **PASS** — decodes 6.0, hashes 5.0 (process aggregate; receiver-side decodes = 4) | | 5 | This baseline doc committed | **PASS** | + +--- + +# Phase 2 checkpoint — `WakuMessage` as `ref object` + +Re-run of the same harness after Phase 2 (`WakuMessage` value `object` → +`ref object`), same machine/toolchain, same workload (seed 42, 10/50/150 kB @ +25/50/25 %, N=1000 + 100 warmup), same build defines +(`-d:msgPathCounters -d:chronicles_log_level=ERROR`, `--passL:librln_v2.0.2.a +--passL:-lm`), `--mm:refc`. + +## Results (CSV) + +``` +scenario,msgs,payload_profile,wall_ms,msg_per_s,ns_per_msg_p50,ns_per_msg_p99,decodes_per_msg,hashes_per_msg,hashed_MB,decoded_MB,occupied_mem_delta_MB,gc_collections +micro_run1,1000,10/50/150kB@25/50/25,809.283,1235.7,624250,1941750,2.000,2.000,130.00,130.11,5.25,7 +micro_run2,1000,10/50/150kB@25/50/25,798.488,1252.4,615750,1906167,2.000,2.000,130.00,130.11,6.46,8 +macro,1000,10/50/150kB@25/50/25,4306.885,232.2,3485125,10544000,6.000,5.000,325.00,390.33,140.74,10 +``` +(second run: micro 1232.1 / 1278.1, variance 3.60 %; macro 230.2 msg/s, occ_mem_Δ 140.58 MB — stable.) + +## Phase 1 baseline vs Phase 2 + +| Scenario | Metric | Phase 1 baseline | Phase 2 | Δ | +|---|---|---|---|---| +| micro | msg/s | 1206.9 / 1257.6 | 1235.7 / 1252.4 | ~flat (within variance) | +| micro | decodes/msg | 2.000 | 2.000 | **unchanged** | +| micro | hashes/msg | 2.000 | 2.000 | **unchanged** | +| micro | occ_mem_Δ MB | 1.51–1.54 | 5.25–6.46 | up (retention-noise, see below) | +| macro | msg/s | 229.0 | 232.2 / 230.2 | +1 % | +| macro | decodes/msg | 6.000 | 6.000 | **unchanged** | +| macro | hashes/msg | 5.000 | 5.000 | **unchanged** | +| macro | hashed_MB / decoded_MB | 325.00 / 390.33 | 325.00 / 390.33 | **byte-exact unchanged** | +| macro | occ_mem_Δ MB | 141.58 | 140.74 / 140.58 | ~flat (−0.6 %) | +| macro | gc_collections | 10 | 10 | unchanged | + +## Interpretation — why occupied-mem delta is flat (and that is expected) + +The refactor removes **transient** deep copies — async-closure env captures in +node dispatch (`subscription_manager` handlers, 6–7 per message), Result/Option +bind-outs, and the `valueOr` binds on the decode path. It does **not** change +what is *retained*. + +`occupied_mem_delta` is `getOccupiedMem()` after − before (with a +`GC_fullCollect()` only *before* the run). It is therefore a **retained-memory** +metric, and the macro figure is dominated by the archive `SortedSet[Index, +WakuMessage]` holding all 1000 messages. Those payload bytes are retained +identically under value and ref semantics (value: copied into the set node; ref: +one heap message the set points at) — so the delta is flat by construction. + +Under `--mm:refc` the eliminated transient copies are freed **deterministically** +by refcount as each async env / Result temporary leaves scope; they never +accumulate, so neither `getOccupiedMem()`-delta nor `gc_collections` (unchanged +at 10) can observe their removal. Quantifying the transient-copy volume would +require a **cumulative bytes-allocated counter or a peak-RSS probe**, which the +Phase 1 harness does not expose — a harness gap, not a missing win. + +The **primary correctness gate is met**: decode and hash counters are byte-exact +identical to baseline (micro 2/2, macro 6/5; `hashed_MB`/`decoded_MB` identical +to the byte), confirming the ref change introduced no extra decode/hash passes, +and throughput is equal-to-slightly-better. + +Residual-deep-copy investigation (plan acceptance item 3): swept for the two +prime suspects and found neither — no value-type `WakuMessage` field remains +(the type is now a ref, so every container/field that held a `WakuMessage`, +incl. `SortedSet[Index, WakuMessage]`, `MessagePush.wakuMessage`, +`WakuMessageKeyValue.message`, holds a pointer); the known `var`-parameter copy +site (relay `publish`) was converted to `ensureTimestampSet`. No leftover +force-copy path exists. + +## Acceptance gate (Phase 2) + +| # | Criterion | Verdict | +|---|---|---| +| 1 | Representative tests green; ASAN clean | **PASS** (tests) — see final report for suite list; ASAN best-effort noted there | +| 2 | Mutation-site classification produced | **PASS** — `docs/analysis/phase2_mutation_audit.md` | +| 3 | Alloc volume down ≥ 40 %, decode/hash unchanged | **PARTIAL** — decode/hash byte-exact unchanged (**PASS**); alloc-volume drop **not demonstrable** via this harness's retained-memory metric under refc (technical reason above); no residual deep-copy bug found | +| 4 | `detect_changes` reviewed; committed (no push) | **PASS** (gitnexus skipped per environment; grep-based mutation sweep committed instead) | diff --git a/docs/analysis/phase2_mutation_audit.md b/docs/analysis/phase2_mutation_audit.md new file mode 100644 index 000000000..3671df7a0 --- /dev/null +++ b/docs/analysis/phase2_mutation_audit.md @@ -0,0 +1,64 @@ +# Phase 2 — `WakuMessage` mutation-site audit + +Review artifact for the value-`object` → `ref object` change. Every hit of the +field-mutation sweep is classified below. Sweep command (plan Step 2.3): + +``` +grep -rn --include='*.nim' -E '\.(payload|meta|proof|timestamp|ephemeral|version|contentTopic) *=[^=]' logos_delivery library apps +``` + +plus the nil-safety declaration sweep (plan Step 3): + +``` +grep -rn --include='*.nim' -E 'var [a-zA-Z_]+: WakuMessage\b|: WakuMessage$' logos_delivery library apps +``` + +Legend: **FINE** = freshly constructed / owned in the same scope, or not a +`WakuMessage` at all; **FIXED** = mutated a shared/held message under ref +semantics, corrected. + +## Field-mutation hits + +| # | Site | What it does | Class | Action | +|---|---|---|---|---| +| 1 | `logos_delivery/api/types.nim:81` | `# wm.proof = ...` | FINE | commented-out dead code, no effect | +| 2 | `logos_delivery/waku/rln/proof.nim:93` (`attachRLNProof`) | `msgWithProof.proof = ...` on `var msgWithProof = message` | **FIXED** | outbound path; caller still holds `message`. Changed to `let msgWithProof = message.clone()` | +| 3 | `logos_delivery/waku/rest_api/endpoint/relay/handlers.nim:73` (`attachRlnProofAndValidate`) | `msg.proof = ...` on `var msg = message` | **FIXED** | same aliasing as #2. Changed to `let msg = message.clone()` | +| 4 | `logos_delivery/waku/waku_relay/protocol.nim:680` (`publish`) | `var message = wakuMessage; message.timestamp = ...` | **FIXED** | caller's message mutated. Replaced with `let message = wakuMessage.ensureTimestampSet()` | +| 5 | `logos_delivery/waku/waku_core/message/message.nim:31` (`ensureTimestampSet`) | `result = message; result.timestamp = ...` | **FIXED** | aliased+mutated the shared input. Rewritten to clone-when-unset (non-mutating) | +| 6 | `logos_delivery/waku/waku_core/message/codec.nim:32–72` (`decode`) | `msg.payload/…=` on `var msg = WakuMessage()` | FINE | freshly constructed in same scope | +| 7 | `logos_delivery/waku/waku_archive/driver/postgres_driver/postgres_driver.nim:284–288` | field writes on `var wakuMessage` | FINE after fix | fresh per loop iteration; needed nil-init (see nil-safety #A) — no cross-row aliasing | +| 8 | `postgres_driver.nim:832` | `m.timestamp = l.timestamp` | FINE | inside a SQL query string literal, not Nim code | +| 9 | `logos_delivery/waku/persistency/sds_persistency.nim:136` | `data.meta = ...` | FINE | `data` is `ChannelData`, not `WakuMessage` | +| 10 | `apps/chat2/chat2.nim:96` | `msg.timestamp = ...` | FINE | `msg` is a `Chat2Message`, not `WakuMessage` | +| 11 | `apps/chat2/chat2.nim:200` | `message.proof = proofRes.get()` | FINE | `message` freshly constructed locally at chat2.nim:184 (`var message = WakuMessage(...)`), owned in scope | +| 12 | `apps/chat2mix/chat2mix.nim:118` | `msg.timestamp = ...` | FINE | `msg` is a `Chat2Message`, not `WakuMessage` | + +## Nil-safety hits (`var x: WakuMessage` now defaults to `nil`) + +| # | Site | Class | Action | +|---|---|---|---| +| A | `postgres_driver.nim:260` — `var wakuMessage: WakuMessage` in the row-decode loop | **FIXED** | default-init is now `nil`; following field writes would deref nil. Changed to `= WakuMessage()` | +| B | `not_delivered_storage.nim:22` — `msg: WakuMessage` field of `TrackedWakuMessage` | FINE | `TrackedWakuMessage` is not constructed on any active path (`archiveMessage` is a stub returning `ok()`); no nil deref reachable | +| C | `recv_service.nim:63` — `let otherwiseMsg = WakuMessage()` | FINE | explicit construction used as `Option.get` default; non-nil | + +## Codec / container decode paths (plan Step 3 verification) + +All decoders that populate a `WakuMessage`-typed field construct explicitly, so +none rely on nil default-init: + +- `waku_core/message/codec.nim:25` — `var msg = WakuMessage()` +- `waku_filter_v2/rpc_codec.nim:93` — `rpc.wakuMessage = ?WakuMessage.decode(message)` +- `waku_lightpush/rpc_codec.nim:38` / `waku_lightpush_legacy/rpc_codec.nim` — `rpc.message = ?WakuMessage.decode(...)` +- `waku_store/rpc_codec.nim:167/170` — `keyValue.message = some(?WakuMessage.decode(...))` / `none(WakuMessage)` (Opt wrapper kept, not collapsed to nil) +- sqlite `queries.nim:35` / postgres row decode — `return WakuMessage(...)` / `WakuMessage()` + +`Option[WakuMessage]` / `Opt[WakuMessage]` occurrences (store RPC, filter) keep +their wrapper semantics; nil-ref and `none` are **not** conflated. + +## Other diagnostic fix + +- `logos_delivery/waku/rln/rln.nim:75` — `msgHash = msg.hash` (a chronicles log + field) resolved to the generic `std/hashes` object hash under value semantics; + a ref no longer matches it. Changed to `msg[].hash` to preserve the exact + prior diagnostic value. Not a mutation; surfaced by the type change.