Bench log: the observer stall of 4 Oct 2026, measured, and what changed

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
igneum-labs 2026-10-04 13:27:49 +00:00
parent 344893ee11
commit bdd6f602f5

View file

@ -796,3 +796,41 @@ Implementation (devnet-v4): `difficulty_v2_activation_daa` in `Params` (every ne
Test network (`sim/difficulty/testnet_v2.py`, 3 nodes on 29600 to 29622, the 60x file with the devnet epoch, genesis bits 2^16, activation 900 on nodes 1 and 2, node 3 without it; CPU miners A from 0, B from minute 4, off at 19, back at 23): node 1 reached DAA 900 at 1,022 s; node 3 rejected the first v2 block ("difficulty of 520437997 is not the expected value of 520406991"), banned its peer and stayed at DAA 900 (901 headers, a prefix of node 1's 1,472); nodes 1 and 2 agreed on every header and the sink. Under v2 the leave eased 6,589 to 5,972 over 180 s (std 0.036, no peak), the rejoin hardened 6,154 to 8,312 within 60 s and held within 3%. The v1 phase is not readable: the load swung the CPU miners' delivered hash rate 2x on its own (difficulty fell 40% after B joined). Record `records/testnet-v2-2026-10-04.csv`. Repeat on a quiet machine, 30 minutes.
Rollout: only `igneumd` changes (the Mac build, `infra/cross/build-linux.sh` for the seed and the Hetzner nodes, the Windows package for PC 1's node); every node of a chain needs the same `"difficulty_v2_activation_daa": N` in its override file before the height or it forks off there. First the 12 Hetzner nodes on their own chain (N = current DAA + 1,800, restart one by one, a miner joins inside an epoch, no flips after the height), then the devnet with N about two hours ahead: observer node, seed, Mac node 1, PC 1's node, in that order, by the project lead. A new network sets 0.
Not done: a quiet-machine test-network run; the DAG model's red blocks and the Mac's log series; v2 with +-500 ms stamp jitter.
## 4 October 2026, the observer stored nothing for 78 minutes, then 7,022 blocks in two minutes
Mac, load average 200 to 300 from other agents' simulations (`uptime` at 14:21 BST: 83 / 224 / 206). The
observer (`tools/observer/observer.mjs`, reading the Mac's non-mining peer on wRPC 28640) kept writing
`live_state` every 2 s, so the page said LIVE with `age_s` 0.1 while its newest stored block was 4,868 s old;
the DAG panel showed "waiting for the first block" and one identity while PC 1 mined at 122 MH/s.
Measured from `live_blocks` (`received_at` minus the header timestamp, UTC):
| Window | Blocks stored | Mean lag s | Max lag s |
|---|---|---|---|
| 11:30 to 11:55, five-minute slots | 150 to 451 each | 4 to 11 | 12 to 61 |
| 11:57 to 13:15 | 0 | | |
| 13:15 slot (the restart at 13:18) | 7,023 | 2,487 | 4,911 |
| 13:20 slot | 135 | 10 | 84 |
The 7,022 catch-up blocks carried header times spread evenly over the gap (66 to 95 per minute by header time),
and `blocks_per_minute` was bucketed by processing time, so the hour chart showed 3,762 and 3,260 for 13:18 and
13:19 against a true 76 and 63. The lag was already 4 to 11 s on average before the gap, and the observer's
colour marking from this morning did a `getBlock` per chain block inline on the same timers as the block flush.
What changed (commit "Observer: decoupled ingest, lag metric, per-minute by header time, feed self-check,
restart loop"):
| Change | Where | Measured after |
|---|---|---|
| Notifications only enqueue; a drain loop handles them in bounded batches; block flush, colour marking and certificate work on separate timers, none waits on another | `observer.mjs` | queue_depth 0 |
| Mergesets taken from each notification's verbose data (bounded cache of 4,000); `getBlock` only on a miss, four in flight | `observer.mjs` | 0 RPC fetch failures in the first 5 min |
| `live_state.observer_lag_s` (now minus newest stored header time) and `queue_depth`; served by `/api/live`; the page shows "observer N s behind" past 30 s instead of "waiting for the first block" | `observer.mjs`, `site/api/live.mjs`, `site/live.html` | lag 0.7 s at 13:27 UTC |
| `blocks_per_minute` and `blocks_60s` bucketed by the block's own timestamp, reseeded from the table on start | `observer.mjs` | 13:18 = 76, 13:19 = 63; max in the hour 110 |
| Self-check: no `blockAdded` for 60 s while the node's `block_count` advances resubscribes; two failed attempts exit 2 | `observer.mjs` | not yet triggered |
| `tools/observer/run.sh`: restart loop, same env and log (`/tmp/igneum-devnet/observer-mjs-v4.out`) | new | running since 13:26 UTC |
Open: the gap itself. Zero blocks for 78 minutes followed by every missed block arriving with its original header
time is also what a stalled observer node delivering its own catch-up looks like; the lag metric now makes either
case visible on the page within 30 s, and the self-check covers the dead-subscription case. Node logs for 11:57
to 13:18 UTC would settle which it was.