docs(bench): Phase 1 message-path baseline results

Records the micro + macro baseline (Apple M4, macOS 26.5, refc, Nim
2.2.4) with both scenarios' verbatim output, CSV, per-node decode/hash
breakdown, and the Phase 1 acceptance verdict. Validates the analysis:
receiver decodes the same proto bytes 4x, aggregate 6 decodes / 5 hashes
per relayed message; micro determinism 4.03% (<5%).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
NagyZoltanPeter 2026-07-15 04:41:39 +02:00
parent cf8502eb49
commit 2a4da679f2
No known key found for this signature in database
GPG Key ID: 3E1F97CF4A7B6F42

View File

@ -0,0 +1,88 @@
# Message-path benchmark — Phase 1 baseline
Baseline capture on the **current branch before Phases 2/3**, produced by
`apps/benchmarks/message_path_bench.nim` (see
[plan_phase1_bench.md](plan_phase1_bench.md)). Re-run after each phase and diff
against these numbers.
## Environment
| Item | Value |
|---|---|
| Commit (harness) | `cf8502eb4975ae6bc8a5667a5d179cd154e8e1d1` |
| Branch | `experimental/chore-nocopy-e2e-perf-harness` |
| Machine | Apple M4 |
| OS | macOS 26.5 (arm64) |
| Nim | 2.2.4, `--mm:refc` |
| Build | `-d:msgPathCounters -d:chronicles_log_level=ERROR`, `--passL:librln_v2.0.2.a` |
| Run | `nimble benchMessagePath` (or `./build/message_path_bench`) |
| Workload | seed 42, payload mix 10/50/150 kB @ 25/50/25 %, N=1000 + 100 warmup |
## 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,828.591,1206.9,641375,1925042,2.000,2.000,130.00,130.11,1.54,7
micro_run2,1000,10/50/150kB@25/50/25,795.166,1257.6,619167,1810625,2.000,2.000,130.00,130.11,1.51,8
macro,1000,10/50/150kB@25/50/25,4367.314,229.0,3510750,10701375,6.000,5.000,325.00,390.33,141.58,10
```
| Scenario | msg/s | decodes/msg | hashes/msg | decoded_MB | hashed_MB | occ_mem_delta_MB |
|---|---|---|---|---|---|---|
| micro run1 | 1206.9 | 2.000 | 2.000 | 130.11 | 130.00 | 1.54 |
| micro run2 | 1257.6 | 2.000 | 2.000 | 130.11 | 130.00 | 1.51 |
| macro | 229.0 | 6.000 | 5.000 | 390.33 | 325.00 | 141.58 |
Micro determinism: run1=1206.9 msg/s, run2=1257.6 msg/s → **variance 4.03 %**
(< 5 % target; two earlier back-to-back runs were 1.90 % and 3.12 %). The
decode/hash *counts* are byte-exact reproducible across every run.
## Interpretation vs. the analysis
**Decode / hash counts validate [async_copy_analysis.md](async_copy_analysis.md).**
The counter is a single process-global (both in-process nodes share it), so the
macro per-message numbers are the aggregate of publisher (node A) + receiver
(node B). Breakdown of the macro **6 decodes / 5 hashes** per message:
| Counter | Node A (publish) | Node B (receive) | Total |
|---|---|---|---|
| `WakuMessage.decode` | 1 (`onSend` observer) | 4 (ordered validator, `onRecv`, `onValidated`, subscribe topicHandler) | **6** |
| `computeMessageHash` | 2 (`publish` :686, `onSend``logMessageInfo`) | 3 (`onValidated``logMessageInfo`, archive, store-sync) | **5** |
- The **inbound-decode claim (≥4 decodes on a relayed message)** is confirmed:
node B alone decodes the same proto bytes **4×**
(`waku_relay/protocol.nim` validator :543, `onRecv` :271, `onValidated` :326,
topicHandler :603).
- The micro scenario isolates the non-observer path and shows the **2 decodes /
2 hashes** it exercises (validator + topicHandler decode; archive + store-sync
hash) — the observers only fire under real libp2p dispatch, which the macro
scenario adds.
### Caveats
1. **Log level elides some hash sites.** Built at `chronicles_log_level=ERROR`,
`computeMessageHash` calls that appear *only* as disabled log arguments are
not evaluated (chronicles skips disabled-sink args) — notably the
`node.publish` `notice` at `waku_node/relay.nim:148`. Sites bound to a `let`
(archive :101, store-sync :78, `logMessageInfo` :217, `publish` :686) run
regardless of level and are the ones counted here.
2. **Filter not mounted.** Per the plan, node B has archive + store-sync but not
filter. The analysis's "46 hashes" upper end assumes an active filter
(`waku_filter_v2` adds ~2 more receiver-side `computeMessageHash` passes,
:195 + :246). With filter mounted the receiver-side hash count would rise
from 3 toward the analysis's upper bound.
3. **`occupied_mem_delta`** is a coarse `getOccupiedMem()` before/after delta on
the refc heap, not a per-message allocation trace; use it for order-of-
magnitude trend, not exact bytes. `decoded_MB` / `hashed_MB` (exact byte
totals fed to decode/hash) are the reliable volume metrics.
## Acceptance gate (Phase 1)
| # | Criterion | Verdict |
|---|---|---|
| 1 | Representative tests green (production untouched except no-op templates) | **PASS**`tests/waku_core/test_message_digest` 5/5, `tests/waku_relay/test_protocol` 20/20 |
| 2 | Production build without `-d:msgPathCounters` compiles (templates vanish) | **PASS**`nim check apps/wakunode2` clean; relay test built without the define |
| 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 46 | **PASS** — decodes 6.0, hashes 5.0 (process aggregate; receiver-side decodes = 4) |
| 5 | This baseline doc committed | **PASS** |