execution/commitment: record the trunk-preload duration and bytes counters - #23067
Conversation
…nters commitment_trunk_preload_duration_seconds_total and commitment_trunk_preload_bytes_total were declared in trunk_pin_metrics.go but never written, so both read 0 for the life of the process. There was no metric signal for how much work the adaptive pin controller was doing, or how long it spent doing it. Record both at the two places a preload actually runs: the initial view in promoteLocked and the per-block step in runExtensionLocked, covering the parallel and serial paths. A promote whose Run fails is rolled back, so it contributes its duration but no bytes. Tests assert both counters advance across a promote and across an extension.
There was a problem hiding this comment.
Pull request overview
This PR fixes two previously “dead” Prometheus counters in execution/commitment by recording trunk-preload duration and pinned-bytes whenever the adaptive pin controller actually performs a trunk preload (both initial promote and per-block extensions). This improves observability of the adaptive pin controller’s workload without changing preload behavior or metric cardinality.
Changes:
- Add a small helper (
recordPreload) to consistently record preload wall time and newly pinned bytes. - Instrument both promote and extension paths (serial and parallel) to emit the two counters.
- Add unit tests ensuring both counters advance on promote and on extension (with guards to avoid vacuous passes).
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
execution/commitment/trunk_pin_metrics.go |
Adds recordPreload helper to update duration/bytes counters. |
execution/commitment/adaptive_pin.go |
Records preload duration/bytes around Run calls in promote and extension paths. |
execution/commitment/adaptive_pin_test.go |
Adds tests verifying the counters advance for promote and extension workloads. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
Both metric tests required time.Since over a preload that takes microseconds. Windows' timer granularity rounds that to zero, so they failed on every Windows run since the branch was pushed, while macOS and Linux passed. Assert only the byte counter there — nothing else writes it, so it still proves recordPreload is wired — and cover the elapsed time directly with a backdated start, which is exact on any timer.
|
Fixed the Windows failure in fbce91e. Both metric tests asserted The product code was fine; the assertion was wrong. Now:
Verified the new test fails when the duration line is removed from |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 3 out of 3 changed files in this pull request and generated no new comments.
Suppressed comments (1)
execution/commitment/adaptive_pin.go:370
- In the serial extension path, bytesPinned is computed as (state.preload.usedBytes - before). However, ContractTrunkPreload.Run can return an error after pinning some entries without committing chunkUsedBytes into p.usedBytes (it returns early on reader error), while the pinned entries remain in the cache/state for retry. That means failed extension runs can under-report pinned bytes (and behave differently from the parallel path, where usedBytes is incremented per pin), making commitment_trunk_preload_bytes_total inaccurate in the presence of transient reader errors.
state.preload.pinTxNum = txNum
before, started := state.preload.usedBytes, time.Now()
_, _, err := state.preload.Run(stepBudget, reader, c.cache, c.logger)
recordPreload(started, state.preload.usedBytes-before)
return err
…exactly (erigontech#23066) ## Problem `ContractTrunkPreloadParallel.Run` can spin forever in its wave loop, wedging the node. The loop only breaks on `budgetHit`, which `pin()` raises on a *strict* overflow. A wave that pins nothing never raises it, and the frontier is reassigned at the same depth — identical state on re-entry. Two ways a wave pins nothing: - **Whole miss set deferred.** `fileBudget` on re-entry is `stepCap - (usedBytes + dbHitsBytes)`, bit-identical to the value that caused the deferral, because the db-hits consume exactly the bytes the deferral already accounted for. Infinite. - **Capped fetch resolves to nothing.** Every fetched key is absent from the file layer — the normal shape at the BFS fringe, where a set `afterMap` bit names a leaf with no branch record. Re-enters once per chunk: bounded, but quadratic. ## Impact Hit in production on a Gnosis validator (`release/3.6`, 4402a1d): ``` sortAndPartitionFrontier preload_parallel.go:121 Run preload_parallel.go:216 runExtensionLocked adaptive_pin.go:354 OnBlockComplete adaptive_pin.go:206 SharedDomains.Commit domain_shared.go:1030 updateForkChoice forkchoice.go:742 ``` The stuck goroutine holds the execution semaphore inside an FCU, so `NewPayload` blocks while holding the fork-choice write mutex. The CL slot ticker stops and ~420 `getAttesterDuties` handlers pile up on the read lock. The node stopped attesting and producing for 17h while burning a core; `eth_syncing` still reported `false`. Two dumps minutes apart showed the same goroutine id, receiver and `dbBranches` pointers — livelock, not a slow walk. 68,732 extension runs over 5.9d uptime before it hit. ## Fix End the step when a wave defers part of its miss set and pinned nothing. Each iteration now either breaks, strictly shrinks the frontier, or increments `nextDepth`. Deferred work resumes on the next `Run`, so there is no throughput cost. Also: - Floor the file fetch at `minEntryBytes` — below one entry's cost the batch is pure waste. - Add the missing `cache == nil` check to `PreloadContractTrunkParallel`: `Run` returns the error, then the wrapper's logger block dereferences `cache.PinnedCount()`, so callers got a panic instead. - Fold two disagreeing `queueEmpty` expressions into one method. ## Testing Differential run of the fixed `Run` against the pre-guard one over 40k configs / 2.3M steps: identical pins, `queueEmpty` and `usedBytes` at every step. The pre-guard code livelocked in 18,306 of those configs. Thanks @awskii. - `ExactBudgetFillTerminates` — the production state; hangs before the fix. - `NoPinWaveEndsStep` — both no-pin paths as two budgets one byte apart, asserting the exact resolver call count. Each case fails against exactly one of the two production changes reverted, so neither is left unpinned by the other. - `DeferWithDbHitsInSameWave` — deferral boundary with db-hits pinned in the same wave. - `StepBudgetSweepTerminates` — budgets straddling one entry's cost. Hang guards abort the binary rather than `t.Fatal`, since `Run` has no cancellation and a spinning goroutine would outlive the failure. `execution/commitment` green under `-race -count=2`; `make lint` clean. ## Scope `preload_parallel.go` is the only site with this shape: the serial `ContractTrunkPreload.Run` pops its queue head unconditionally, `OnBlockComplete` ranges a bounded set, and `execStatusList.drainDeferred` already has a progress net. `release/3.6` needs a backport; `release/3.5` does not have the feature. ## Notes (not fixed here) - `adaptive_pin.go`: `c.misses` entries are never removed, so one `sync.Map` entry accumulates per contract hash ever touched and `OnBlockComplete` ranges the whole set every block. Found by @awskii. - `commitment_trunk_preload_{bytes,duration_seconds}_total` are declared but never written — no metric signal for preload work while this was wedged. Fixed in erigontech#23067. - When `PerContractMaxBudgetBytes - usedBytes` drops below one entry's cost, `runExtensionLocked` runs every block and pins nothing. Bounded per-block work, not a hang. --------- Co-authored-by: awskii <artem.tsskiy@gmail.com>
Problem
commitment_trunk_preload_duration_seconds_totalandcommitment_trunk_preload_bytes_totalare declared intrunk_pin_metrics.gobut never written anywhere in the tree, so both read0for the life of the process.Confirmed on a live Gnosis node with 5.9 days of uptime and 68,732 recorded preload extensions:
The neighbouring counters work; only these two are dead. The result is that there is no metric signal for how much work the adaptive pin controller does or how long it spends doing it. That gap was noticed while diagnosing #23066 — a livelock inside
ContractTrunkPreloadParallel.Run— where these counters would have been the natural place to see preload time climbing.Change
Record both at the two places a preload actually runs, covering the parallel and serial paths in each:
promoteLocked— the initial view for a newly promoted contract.runExtensionLocked— the per-block extension step, which is the dominant path in a running node.A promote whose
Runfails has its pins rolled back viaInvalidate, so it contributes its duration but no bytes. That is whyrecordPreloadtakes the byte count as a parameter instead of reading it back off the preloader.No behaviour change beyond the counters; no new metric names, cardinality, or hot-path work (both call sites already run once per contract per block under
c.mu).Testing
TDD, red → green. Both tests fail on
mainwith the counters flat at0:TestAdaptivePin_PromoteRecordsPreloadMetrics— both counters advance across a promote.TestAdaptivePin_ExtendRecordsPreloadMetrics— both counters advance across an extension, with the initial view budgeted so the queue survives promotion and there is real work left to measure.Each test guards against a vacuous pass by first asserting the preload actually pinned bytes / left a non-empty queue.
Full
execution/commitment/...suite passes.make lintclean for the touched files.Relationship to #23066
Split out of #23066 review discussion to keep that fix minimal. The two branches touch disjoint files (
adaptive_pin.go/trunk_pin_metrics.gohere,preload_parallel.gothere). Verified by trial-merging the two branches: no conflicts, merged result builds and the full package suite passes. They can land in either order.