|
| 1 | +--- |
| 2 | +name: devnet-profiling |
| 3 | +description: Use when profiling ethlambda / multi-client devnet performance from container logs — either (a) per-block BUILD timing (why blocks build slowly, cost per attestation carried, A/B build latency across branches/images), or (b) per-slot DUTY timing (where in the slot each client publishes its block, attestation and aggregate relative to slot start, which duties spill into the next slot, per-client timing comparison + a self-contained HTML visualization). Covers what Prometheus only aggregates. Keywords: block building time, propose to publish, leanVM proving, attestation_count, p50/p99 build latency, slow proposer, prover cost, duty timing, slot-relative offset, block/attestation/aggregate publish time, spill into next slot, client timing comparison, when do clients attest, duty completion vs expected, dropped duties, on-time rate. |
| 4 | +version: 0.4.0 |
| 5 | +--- |
| 6 | + |
| 7 | +# Devnet Profiling |
| 8 | + |
| 9 | +Two log-driven profilers for lean-consensus devnets, each recovering what |
| 10 | +Prometheus only aggregates: |
| 11 | + |
| 12 | +- **Block-build timing** — per-block build/proposal time, split by attestation |
| 13 | + count. This is the bulk of the doc below. |
| 14 | +- **Duty timing across the slot** — where in the slot each client publishes its |
| 15 | + block / attestation / aggregate, which spill into the next slot, and a per-client |
| 16 | + × duty **completion (dropped-duty) + on-time** table. See |
| 17 | + [`## Duty timing across the slot`](#duty-timing-across-the-slot); ships a |
| 18 | + self-contained HTML visualization. |
| 19 | + |
| 20 | +## Block-build timing |
| 21 | + |
| 22 | +Reconstruct **per-block** build performance from devnet container logs. The |
| 23 | +Prometheus histogram `lean_block_building_time_seconds` only gives coarse |
| 24 | +aggregates (largest finite bucket is 1.0s, so p99 of the slow path is unbounded) |
| 25 | +and cannot be split by attestation count. The logs can. |
| 26 | + |
| 27 | +**Core insight:** a few log signals, joined per build, recover everything: |
| 28 | + |
| 29 | +| Want | Signal (per proposer, in its own log) | |
| 30 | +|------|----------------------------------------| |
| 31 | +| build time | Δ between `We are the proposer for this slot slot=X` and `Finished building block slot=X` (matches the timing metric; **not** `Published block`, see below) | |
| 32 | +| publish-alignment wait | Δ between `Finished building block slot=X` and `Published block to gossipsub slot=X` (idle, not build cost) | |
| 33 | +| time to publish (total) | Δ between `We are the proposer for this slot slot=X` and `Published block to gossipsub slot=X` (= build + wait; still off the publish log) | |
| 34 | +| attestation count | `attestation_count=N` on the `Published block to gossipsub` line (distinct data roots) | |
| 35 | +| host speed (A/B normaliser) | `crypto_elapsed` on `Block proof verified` lines with `attestation_count=1` (identical work on every host) | |
| 36 | + |
| 37 | +**Build end is `Finished building block` (added #474), not publish.** Since the |
| 38 | +pre-build change (#445) the proposer builds at the previous slot's interval 4 and |
| 39 | +then sleeps until the slot boundary to publish, so `proposer → published` counts |
| 40 | +that idle wait. `Finished building block` is logged exactly where the timing |
| 41 | +guard drops, so `proposer → finished` is the true build time and matches |
| 42 | +`lean_block_building_time_seconds`. Logs predating #474 fall back to the publish |
| 43 | +marker (build time then includes the wait); the analyzer flags how many. |
| 44 | + |
| 45 | +## When to use |
| 46 | + |
| 47 | +- "Why are blocks slow to build?" / "what's the p99 build time?" |
| 48 | +- "Does branch/PR X change block-building time?" (A/B two devnets) |
| 49 | +- "What does each attestation in a block cost?" / "split build time by attestation count" |
| 50 | +- Build-failure or stall investigations where timing matters. |
| 51 | + |
| 52 | +**Not** for error/warning summaries, consensus progress, forks, or finalization |
| 53 | +health — use `devnet-log-review` for those. For running/operating the devnets |
| 54 | +themselves, see `multi-server-devnet`. |
| 55 | + |
| 56 | +## Workflow |
| 57 | + |
| 58 | +```bash |
| 59 | +S=.claude/skills/devnet-profiling/scripts |
| 60 | + |
| 61 | +# 1. Collect (per host; pipe to a file). Works over ssh or "local". |
| 62 | +bash $S/collect-build-logs.sh admin@ethlambda-2 > /tmp/e2_full.txt |
| 63 | +bash $S/collect-build-logs.sh admin@ethlambda-5 > /tmp/e5_full.txt |
| 64 | + |
| 65 | +# 2. Analyze. --max-slot matches the A/B window to the same first-N slots so a |
| 66 | +# younger chain / smaller DB isn't compared against an older one. |
| 67 | +python3 $S/analyze-build-timing.py /tmp/e2_full.txt /tmp/e5_full.txt --max-slot 2791 |
| 68 | +``` |
| 69 | + |
| 70 | +Output per file: build time n / avg / p50 / p99 (ms) split **by attestation |
| 71 | +count** (0 / 1 / ≥2), the **publish-alignment wait** (`finished → published`, |
| 72 | +idle), and the **total time to publish** (`proposer → published`, build + wait, |
| 73 | +off the publish log). |
| 74 | + |
| 75 | +## Interpreting results |
| 76 | + |
| 77 | +- **Read the cost per attestation off the att buckets.** att=0 is the floor (no |
| 78 | + proof to build); each further attestation adds the marginal proving cost. Both |
| 79 | + the level and the step are deployment-dependent, so compare buckets within one |
| 80 | + host before comparing hosts. |
| 81 | +- **Host-speed caveat (A/B across machines):** different hosts have different |
| 82 | + leanVM speed. Confirm with the `crypto_elapsed` proxy before attributing a |
| 83 | + build-time gap to the code. A ~1.5× verify-time difference between hosts swamps |
| 84 | + most per-bucket differences. |
| 85 | +- **Publish-alignment wait reads pre-build health.** A large wait means builds |
| 86 | + finish early at interval 4 and idle until the slot boundary (pre-build working |
| 87 | + as intended); a near-zero wait means builds overrun into their publish interval |
| 88 | + (slow builds eating the slack #445 bought). Watch build time vs wait together, |
| 89 | + not just total `proposer → published`. |
| 90 | + |
| 91 | +## Gotchas |
| 92 | + |
| 93 | +- **ANSI codes.** Logs are colorized: `slot[0m[2m=[0m16`, so `grep 'slot='` on |
| 94 | + raw lines finds nothing. `collect-build-logs.sh` greps only ANSI-free message |
| 95 | + substrings; `analyze-build-timing.py` strips ANSI before extracting fields. |
| 96 | + Do the same in any ad-hoc grep: `sed -E 's/\x1b\[[0-9;]*m//g'` first. |
| 97 | +- **Collect from all 16 nodes** — each proposes only ~1/16 of slots; one node is |
| 98 | + a thin sample. |
| 99 | +- **Matched window for A/B.** Use `--max-slot` so both sides cover the same first |
| 100 | + N chain slots (equal chain age / DB size). |
| 101 | +- **Prometheus is not enough** for this — it has no per-block att-count label and |
| 102 | + its build-time buckets top out at 1.0s. |
| 103 | +- **Builds no longer compact.** The proposer used to merge duplicate proofs for |
| 104 | + one attestation via `aggregate_proofs`, and earlier versions of this skill |
| 105 | + labelled each build with that. It no longer happens, so the machinery is gone; |
| 106 | + `aggregate_single_message_signatures` proving spans of `2^16+` now come only |
| 107 | + from the interval-2 aggregation worker and block-import re-aggregation, neither |
| 108 | + of which is build cost. Don't reintroduce a build-window overlap test against |
| 109 | + them — it mostly reports coincidence. |
| 110 | + |
| 111 | +## Duty timing across the slot |
| 112 | + |
| 113 | +When does each client actually perform its per-slot duties, relative to the slot |
| 114 | +start? Anchor each event to **its own slot** (`event − (genesis + slot·N)`, **not** |
| 115 | +wrapped mod slot); offsets beyond one slot are duties that **spilled into the next |
| 116 | +slot** — the problematic cases a mod-slot view silently hides. |
| 117 | + |
| 118 | +```bash |
| 119 | +S=.claude/skills/devnet-profiling/scripts |
| 120 | +bash $S/collect-duty-logs.sh admin@ethlambda-2 90m > events.txt # 90m = docker --since window |
| 121 | +python3 $S/analyze-duty-timing.py events.txt > summary.json |
| 122 | +python3 $S/render-duty-timing.py summary.json -o duty-timing.html \ |
| 123 | + --source "ethlambda-2 · devnet5" --window "90 min" --sampled 2026-07-01 |
| 124 | +# or one shot: |
| 125 | +bash $S/collect-duty-logs.sh admin@ethlambda-2 | python3 $S/analyze-duty-timing.py - \ |
| 126 | + | python3 $S/render-duty-timing.py - -o duty-timing.html |
| 127 | +``` |
| 128 | + |
| 129 | +The HTML is self-contained (inline CSS+JS, two SVG charts + tables, no external assets): |
| 130 | +(1) **absolute** offset across the slot + one slot past the boundary, with a `≥8s` |
| 131 | +overflow strip for 2+-slots-late events; (2) **lateness relative to each duty's own |
| 132 | +target** (0 = on time), making block/attestation/aggregate directly comparable. |
| 133 | +Duties are **superposed per client**; hover a ridge for per-bin counts. |
| 134 | + |
| 135 | +Below the charts a **Completion & on-time** table gives, per client × duty: **completed** |
| 136 | +(publishes seen), **completed %** (completed ÷ **expected** = the dropped-duty rate), and |
| 137 | +**in time / in time %** (published before the end of that duty's own 800 ms interval — |
| 138 | +block < 0.8s, attestation < 1.6s, aggregate < 2.4s — as a share of completed). `expected` |
| 139 | +encodes the duty model: attestation = nodes × slots (every validator every slot), block = |
| 140 | +the client's round-robin proposer share (nodes ÷ total × slots), aggregate = aggregator |
| 141 | +nodes × slots. This separates a **dropped** duty (completed % < 100) from a merely **late** |
| 142 | +one (low in-time %, completed % ~100 — e.g. slow-built blocks that publish past i0 but are |
| 143 | +never dropped). Slots span = attestation min→max; total validators from `#META nodes_total` |
| 144 | +(else inferred from the highest node index seen). |
| 145 | + |
| 146 | +`analyze-duty-timing.py` also prints a per-client **attestation-coverage report to |
| 147 | +stderr** (JSON/HTML untouched): it flags a client whose attestation signature |
| 148 | +returned nothing (likely a broken grep or all nodes syncing) and any node attesting |
| 149 | +well below its peers (sync-gated / degraded) — e.g. |
| 150 | +`⚠ ethlambda node 0: 270 attestations = 36% of peer median (749)`. It's the guardrail |
| 151 | +for the silent-zero class of bug (the ream-attestation ANSI regression would have tripped it). |
| 152 | + |
| 153 | +Duty-log signals (each client's OWN publishes; client auto-detected from container image): |
| 154 | + |
| 155 | +| client | block | attestation | aggregate | |
| 156 | +|--------|-------|-------------|-----------| |
| 157 | +| ethlambda | `Published block to gossipsub` | `Published attestation to gossipsub` | `Committee signature aggregated`, anchored to **`session_id`** (see note) | |
| 158 | +| ream | `Proposing block by Validator` (**attempt** — build often fails `>8 AttestationData`, never ships) | `ream_p2p…Broadcasted attestation` | — | |
| 159 | +| grandine | `Broadcasted block` joined to `Validator task: proposing block` (own proposals; the bare broadcast also fires on **relay**, ~5×) | `lean_client: Broadcasted attestation to subnet` | — | |
| 160 | + |
| 161 | +Gotchas: |
| 162 | +- **Strip ANSI BEFORE grep.** Clients dim the module path, so ANSI sits *inside* |
| 163 | + `module: message` spans — grepping the raw line misses them (ream attestation |
| 164 | + silently returns 0). `collect-duty-logs.sh` strips at capture. |
| 165 | +- **An absent lane isn't always a broken signature.** zeam logs duty publishes only at warning level → no rows; a stuck/syncing node (or one not doing a duty, e.g. an aggregator-only node that never attests) also yields zero rows for that duty. Confirm against raw logs before assuming the grep signature regressed. |
| 166 | +- **Completion % caveats.** `expected` = the client's active-node count × the window's slot |
| 167 | + span (block: × its round-robin proposer share). A node down for part of the window gets an |
| 168 | + inflated expected → read its completion % as a floor. A client that logs no duty lines at all |
| 169 | + (zeam) has no rows, so it's **absent** from the table — its drops are invisible to this |
| 170 | + log-based method (use Prometheus coverage for zeam). |
| 171 | +- **grandine `Broadcasted block` includes relays.** Collector emits `block_bcast` + |
| 172 | + `propose`; analyzer joins on slot to keep only own proposals. |
| 173 | +- **Aggregate rows come only from aggregator nodes** (`--is-aggregator`). |
| 174 | +- **Aggregate uses the interval-2 worker line, not the publish line.** `Published aggregated |
| 175 | + attestation to gossipsub` is emitted by TWO paths — the interval-2 duty *and* |
| 176 | + `run_reaggregate_from_block` (on block import, republishing block-borne votes with their |
| 177 | + stale `data.slot`). They share one log line, so anchoring it to `slot` yields nonsense |
| 178 | + offsets (tens of thousands of seconds, the imported blocks' old attestation slots). The |
| 179 | + `Committee signature aggregated` line is emitted only by the interval-2 worker and carries |
| 180 | + `session_id` = the tick the aggregation ran in; **anchor to `session_id`, not its `slot`** |
| 181 | + (the latter is the aggregated group's data slot and is often stale). This is aggregation- |
| 182 | + *complete* time, ~a few ms before the publish — the truest "when the aggregator did its work." |
| 183 | +- **Un-wrapped anchoring** surfaces aggregate backlog during a stall as offsets of |
| 184 | + thousands of seconds (re-aggregating old slots) — pooled into the `≥8s` overflow, |
| 185 | + not per-slot lateness. |
| 186 | +- **New client?** Wire its signatures into `client_of` + the `case` in |
| 187 | + `collect-duty-logs.sh`; the analyzer and renderer are already client-agnostic |
| 188 | + (they read `meta.clients` from the data). |
| 189 | + |
| 190 | +## Files |
| 191 | + |
| 192 | +Block-build timing: |
| 193 | +- `scripts/collect-build-logs.sh` — dump the three line types (NODE-prefixed) from a host's containers. |
| 194 | +- `scripts/analyze-build-timing.py` — parse + split by attestation count; `--max-slot`, `--min-slot`, `--genesis`. |
| 195 | +- `references/log-signals.md` — exact log lines and field formats for the build window and the host-speed proxy. |
| 196 | + |
| 197 | +Duty timing: |
| 198 | +- `scripts/collect-duty-logs.sh` — per-slot duty-publish events (client auto-detected from image; emits `#META` incl. `nodes_total` + `CLIENT NODE DUTY SLOT ISO_TS`). Resolves each node's container by its `_N$` index suffix, so it works on a multi-client mix (`ream_4`, `grandine_7`, `zeam_11`), not only `ethlambda_N`. Args: `<ssh_target|local> [window] [n_nodes] [prefix]`. |
| 199 | +- `scripts/analyze-duty-timing.py` — events → JSON summary (per-slot **un-wrapped** offsets; absolute + deadline-relative binning; per-duty `on_time` + `expected` counts for the completion/on-time table; `meta.clients` lane descriptors + `meta.n_slots`/`nodes_total`). |
| 200 | +- `scripts/render-duty-timing.py` + `scripts/duty-timing.template.html` — summary JSON → self-contained HTML (two superposed-per-client SVG charts + a Completion & on-time table); `--source/--window/--sampled` header chips. |
0 commit comments