fix(node,store): take the full-table scans off the dispatch loop and repair finalization pruning - #423
Conversation
lean_tick_interval_duration_seconds is observed inside onTick, so it
records nothing at all while the dispatch loop is blocked: the failure it
should report makes it go quiet rather than spike. Its top bucket is 1.6s
besides, so it could not size a stall even when one ends.
Add lean_tick_last_age_seconds, written from outside the loop, and
lean_dispatch_event_duration_seconds{event} with buckets to 600s so a slow
handler is attributable rather than only visible as a late tick.
updateFinalizedFromHead called FC.Prune before PruneOnFinalization. FC.Prune removes the finalized-below ancestors and every losing branch from the ProtoArray; PruneOnFinalization then asks that same array which roots to delete, via GetCanonicalAnalysis. After the prune the parent walk terminates at the new root, so canonical has length 1 and canonical[1:] is empty, and the siblings are already gone so nonCanonical is empty. Both delete lists came back empty every time. The effect is that TableStates and TableBlockHeaders were never pruned at all. Only pruneLiveChain worked, because it scans by slot rather than going through fork choice. On devnet-5 that left 13,184 states and ~22,600 headers after thousands of finalizations, which is what made the full-table scans on the dispatch loop expensive enough to stall the slot clock. Take the delete lists before pruning fork choice. The regression test fails on the old ordering with all three symptoms.
The dispatch loop is one goroutine and it keeps the slot clock. Four full-table Pebble scans ran on it, all O(chain length). At ~22,600 blocks the mean tick interval reached 38-288s against an 800ms target, with 49% of CPU in pebbleIterator.Next and 24% in snappy.decode. Every duty the clock drives - propose, attest, aggregate, head update, prune - stopped. EstimateTableBytes iterated every entry of every table and copied keys and values, and ran for all six tables on each imported block. Ask Pebble's version metadata for the range instead, and sample it off the loop. The number changes: SST bytes for the range, not logical live bytes, and it excludes the memtable. StatesCount scanned 13,184 states once per slot to print one log line. Removed. MaxStoredBlockSlot scanned and SSZ-decoded every header up to three times a slot for the duty gate. It is a high-water mark now, raised on both write paths and seeded by one scan per process. Seeding matters: a fresh store reporting 0 would read the whole chain as a network stall. It deliberately still covers pending headers, not just imported ones - a live-chain index would miss a persisted pending block and let a restarted node resume duties on a stale head. BlockRoots materialised every root into a map per proposal to answer a handful of membership questions. KnownRoots is a predicate now. Also time every dispatch event and publish tick age, both off the loop.
gean applied the sync-lag duty gate to aggregation as well as to block production and attestation, reasoning that aggregates built on a stale view get dropped anyway. That holds with several aggregators. It inverts with one: the sole aggregator withholds the aggregates the network is waiting on at exactly the moment it is furthest behind, so nothing justifies, nothing finalizes, finalization pruning never runs, and the lag that closed the gate gets worse. Observed on devnet-5 as not_synced climbing to ~4,100 per node with justification frozen; stopping two lagging nodes advanced justification 1,520 slots in five minutes. leanSpec gates interval 2 on is_aggregator alone. ethlambda has a duty gate and applies it to attestation and proposal but not to aggregation. lantern has no gate. Only ream gates aggregation. The work stays bounded without the gate: a session has a slot-anchored deadline and MaxGroupsPerSession, so an aggregate built on a stale view costs one bounded proving budget and is dropped by peers, which is strictly better than producing none. Drops the not_synced skip reason with it - nothing can emit it now.
Both found in review of #423. A failed seeding scan latched permanently. scanMaxStoredBlockSlot returned 0 for an unopenable read view, and a mid-iteration failure was indistinguishable from reaching the end of the table, because Next reports false either way. sync.Once then cached that understated mark forever. It is not just a bad gauge: an understated watermark inflates the duty gate's computed network lag, which can trip the network-stall carve-out and let the node resume duties on a stale head - the behaviour the carve-out exists to prevent. Iterator grows an Err method so a truncated scan is distinguishable from a complete one. The seed reports errors, latches only on success, and is now run at startup before the dispatch loop, which also removes the last full-table scan from the duty path. The storage sampler could outlive shutdown. waitForShutdown cancels, sleeps 500ms, and returns; backend.Close then runs from a defer with nothing joining the workers. A sampler still mid-round calls into a closed Pebble instance, which panics. Track the storage-reading goroutines on a WaitGroup and join them in main before Close. Cancellation checks between tables help responsiveness but are not what makes it safe. Tests cover both: a truncated scan that must not latch, and a wait that must block until the sampler returns.
The previous test asserted recovery by constructing a second ConsensusStore, whose seeded flag is unset regardless of whether the first store latched its failure. It would have passed against the bug it claims to cover. Seed twice on the same store, against a backend that truncates the first block-header scan and then behaves normally. The truncation yields one real entry before failing, so the partial answer is a plausible lower slot rather than an obvious zero - the shape that would otherwise be cached as a reasonable-looking watermark. Verified both tests fail when the seed latches on failure and pass when it does not. Also narrows the WaitForStorageWorkers documentation to what it actually covers. The aggregation, proposal, recovery and attestation workers and the fetch batcher all read storage and none is joined; that is a pre-existing shutdown gap, and closing it means deciding how long shutdown may block on in-flight proving.
|
Devnet validation complete — 14 hours, 12,400 slots, 15 nodes (4 gean / 6 ethlambda / 5 lantern), gean sole aggregator, zero restarts. Full detail added to the description; the headline: The tick loop never slipped.
Worst case is 6.6 ms above an 800 ms target. Sampled every 30 minutes, gean_0 runs 0.79998–0.80549 with the final sample identical to the first — no drift. That is the part that matters, since the old failure mode was degradation with chain length. Pruning is running — States table is 16 MB, against roughly 4.6 GB retained by the old build at a comparable height. Total on-disk 1.26 GB vs ethlambda's 1.71 GB. Two trends noted and neither blocking: The two caveats from review still stand as written: historical database bloat is not repaired for upgraded nodes, and the aggregation deadline cannot interrupt a proof already running. |
Description
The dispatch loop is a single goroutine and it keeps the slot clock. Four full-table Pebble scans were running on it, all O(chain length). At ~22,600 blocks the mean tick interval reached 38–288s against an 800ms target, and every duty the clock drives — propose, attest, aggregate, head update, prune — stopped. Silently: the code that would have reported a problem was never reached.
Four commits, each buildable on its own.
5bb11d1— finalization pruning was inert (the root of the growth)updateFinalizedFromHeadcalledFC.PrunebeforePruneOnFinalization.FC.Pruneremoves the finalized-below ancestors and every losing branch from the ProtoArray;PruneOnFinalizationthen asks that same array which roots to delete viaGetCanonicalAnalysis. After the prune the parent walk terminates at the new root, socanonicalhas length 1 andcanonical[1:]is empty, and the siblings are already gone sononCanonicalis empty. Both delete lists came back empty every time.So
TableStatesandTableBlockHeaderswere never pruned at all — onlypruneLiveChainworked, because it scans by slot rather than going through fork choice. That is why devnet-5 held 13,184 states and ~22,600 headers after thousands of finalizations, and why the scans below got expensive enough to matter.2c6c0da— the scansEstimateTableBytesStatesCountMaxStoredBlockSlotatomic.Uint64high-water markBlockRootsEstimateTableByteschanges meaning: SST bytes for the key range, not logical live bytes, and it excludes the memtable. For a size gauge that is the more useful figure; the test asserts the new contract.MaxStoredBlockSlotdeliberately still covers pending headers, not just imported ones. A live-chain index would have been cheaper but would miss a persisted pending block — a node restarting with head 100 and a pending block at 109 would read its own import lag as a network stall and resume duties on a stale head, which is the dead-fork behaviour the gate's carve-out exists to prevent. Covered byTestMaxStoredBlockSlotSeedsFromDiskAfterRestart.84e2ebf— aggregation is no longer behind the sync-lag duty gategean gated aggregation as well as block production and attestation, reasoning that aggregates built on a stale view get dropped anyway. That holds with several aggregators. It inverts with one: the sole aggregator withholds the aggregates the network is waiting on at exactly the moment it is furthest behind, so nothing justifies, nothing finalizes, pruning never runs, and the lag that closed the gate gets worse.
Observed on devnet-5 as
not_syncedclimbing to ~4,100 per node with justification frozen; stopping two lagging nodes advanced justification 1,520 slots in five minutes.Checked against the other implementations, on the branches they actually run:
timeline.py:49case 2 if is_aggregator)build/leanvm-track-main)ethlambda is the informative one: it has a duty gate and applies it to two of three duties. The exclusion is deliberate, not an omission.
Work stays bounded without the gate, but only between groups: a session has a slot-anchored deadline and
MaxGroupsPerSession, and the deadline is checked between proofs. It cannot interrupt a native proof already running, so one overlong proof still overruns it. The bound is "at mostMaxGroupsPerSessionproofs per slot, the last of which may overrun" — not a hard time limit. Correcting an overstatement in the original description.Drops the
not_syncedskip reason with it, since nothing can emit it now.478f7e3— signals that survive a stalllean_tick_interval_duration_secondsis observed insideonTick, so it records nothing while the loop is blocked: the failure it should report makes it go quiet rather than spike. Its top bucket is 1.6s besides, so it could not have sized a 288s stall. Addslean_tick_last_age_seconds(written from outside the loop) andlean_dispatch_event_duration_seconds{event}with buckets to 600s, so a slow handler is attributable rather than only visible as a late tick.Evidence
30-second CPU profile of a stalled node:
The 24% in
snappy.decodeis the tell — only a scan that reads values decompresses that much, which isrecordTableBytesandStatesCount. A goroutine dump put the dispatch goroutine insidepebbleIterator.Next → sstable.readBlock → vfs.Prefetch → syscall, not parked on a channel.Degradation is monotonic in chain length:
Associated Issue
None — this targets
fix/aggregation-skip-visibility, notmainor adevnet-Nbranch.Related context: #371 (recursive aggregation exceeding the slot budget, stalling finalization) describes the same symptom from a different cause; #368 (
ProtoArray.Prune()O(N²)) is adjacent to the pruning path touched here but is not addressed.Review follow-ups (
8bfad59)Two lifecycle findings from review, both fixed:
scanMaxStoredBlockSlotreturned 0 for an unopenable read view, and a mid-iteration failure was indistinguishable from reaching the end of the table, sinceNextreports false either way.sync.Oncethen cached that understated mark forever. Not merely a bad gauge — an understated watermark inflates the duty gate's computed network lag, which can trip the network-stall carve-out and resume duties on a stale head, the behaviour the carve-out exists to prevent.storage.Iteratorgrows anErr() errorso a truncated scan is distinguishable from a complete one; seeding reports errors, latches only on success, and now runs at startup before dispatch — which also removes the last full-table scan from the duty path.waitForShutdowncancels, sleeps 500ms and returns;backend.Closethen runs from a defer with nothing joining the workers. A sampler mid-round calls into a closed Pebble instance, which panics. Storage-reading goroutines are now tracked on aWaitGroupand joined inmainbeforeClose.Known gap, not addressed here
Existing database bloat is not repaired. Pruning only knows roots still in fork choice, and restart restoration anchors at the justified block (
internal/node/restore.go), excluding older headers from replay. States orphaned by the pre-fix pruning bug therefore stay on disk indefinitely on an upgraded node. That wants a one-off cleanup, not another recurring scan on the dispatch path — worth its own issue. A node started from fresh data is unaffected.Test Plan
go test ./internal/...— 25/25 packages pass;go vet ./internal/...andgofmtclean.TestFinalizationPrunesAncestorAndLosingBranch(new) — builds genesis → a(1) → b(2) → c(3) with a losing fork x(2), finalizes b, asserts x is removed entirely and a's state is dropped while b's and c's survive. Verified it fails on the pre-fix ordering with all three symptoms, which is the point of it.TestMaxStoredBlockSlotSeedsFromDiskAfterRestart(new) — head 100 with a persisted pending block at 109, new store over the same backend, asserts 109. This is the case a live-chain index would get wrong.TestMaxStoredBlockSlotTracksInserts(new) — the mark rises on insert and never falls.TestMaxStoredBlockSlotDoesNotLatchAFailedSeed(new) — a truncated header scan must report an error and must not cache its partial answer; a later store over the same data recovers the real mark.TestWaitForStorageWorkersBlocksUntilSamplerReturns(new) — the wait must not return while the sampler runs, and must return once the context is cancelled. Passes under-race.TestPebbleEstimateTableBytesupdated to the new contract: zero before flush, non-zero after, each table attributed to its own prefix range.Devnet validation
Validated on a 15-node devnet — 4 gean, 6 ethlambda, 5 lantern, 4 committees, gean the sole aggregator. Fresh genesis, 14 hours, 12,400 slots, zero restarts.
The tick loop never slipped.
max_over_timeof the 10m mean tick interval across the whole run:Worst case in fourteen hours is 6.6 ms above an 800 ms target. Sampling gean_0 every 30 minutes across the run gives min 0.79998, max 0.80549, and the last sample (0.79999) is indistinguishable from the first (0.80000) — no drift, no rising tail. That matters more than the absolute number: the old build's failure mode was degradation with chain length, and 12,400 slots of growth produced no trend at all.
For reference, on the same network: lantern 0.7999–0.8001, ethlambda 0.8330–0.9261.
Pruning is demonstrably running. Before the ordering fix these counts were always zero:
blockstracksnon_canonicalexactly, which is the losing-branch deletion the ordering bug prevented.The database is an order of magnitude smaller, and smaller than ethlambda's at the same height (
lean_table_bytes):16 MB of states, against roughly 4.6 GB retained by the old build at a comparable height (13,184 states at ~350 KB). That retention is what made the scans fatal.
Dispatch-event breakdown (
lean_dispatch_event_duration_seconds, new in this PR), gean_0 at slot 12,349:tickblockproposal_resultearly_aggregateblockis the largest consumer and is the synchronous signature-verification and STF path noted below — comfortably inside budget for one block, butdrainPendingBlockscan process up to 256 back-to-back.Two growth trends observed, neither blocking. Between slot 166 and slot 12,349,
tickwent 6 ms → 17 ms and RSS went 2.3 GB → 3.8 GB. The first is expected: the database grew from empty to 1.26 GB, so point reads cost marginally more, and 17 ms of an 800 ms budget leaves no pressure. The second is not storage — a 16 MB states table cannot account for 3.8 GB of RSS, and ~97% of gean's RSS sits outside the Go heap in XMSS/leanVM allocations. That is a prover-memory question, separate from this PR, and worth its own issue.Behaviour changes worth knowing about
lean_aggregator_skipped_total{reason="not_synced"}will stop appearing. Any dashboard panel keyed on it needs updating.lean_aggregation_worker_total_time_secondsto rise during catch-up.EstimateTableBytesreports a different quantity, so the storage-size gauge will step to new values on deploy.Checklist