From 54937513ee983b07a821534a6ec3afebc84c6770 Mon Sep 17 00:00:00 2001 From: Oleksandr Lystopad Date: Thu, 6 Aug 2026 14:26:48 +0200 Subject: [PATCH 1/2] execution/commitment: record the trunk-preload duration and bytes counters 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. --- execution/commitment/adaptive_pin.go | 11 ++++ execution/commitment/adaptive_pin_test.go | 70 +++++++++++++++++++++++ execution/commitment/trunk_pin_metrics.go | 12 ++++ 3 files changed, 93 insertions(+) diff --git a/execution/commitment/adaptive_pin.go b/execution/commitment/adaptive_pin.go index 8fe3f1403c5..f444081f3ed 100644 --- a/execution/commitment/adaptive_pin.go +++ b/execution/commitment/adaptive_pin.go @@ -21,6 +21,7 @@ import ( "encoding/hex" "sync" "sync/atomic" + "time" "github.com/erigontech/erigon/common/log/v3" ) @@ -300,12 +301,15 @@ func (c *AdaptivePinController) promoteLocked( if provider != nil { dbBranches = provider(hash[:]) } + started := time.Now() if _, _, err := p.Run(c.cfg.InitialViewBudgetBytes, dbBranches, parallelResolve, c.cache, c.logger); err != nil { + recordPreload(started, 0) for _, prefix := range p.PinnedPrefixes() { c.cache.Invalidate(prefix) } return nil, err } + recordPreload(started, p.usedBytes) return &adaptiveContractState{ contractHash: hash, promotedAtTxNum: txNum, @@ -317,12 +321,15 @@ func (c *AdaptivePinController) promoteLocked( return nil, err } p.pinTxNum = txNum + started := time.Now() if _, _, err := p.Run(c.cfg.InitialViewBudgetBytes, reader, c.cache, c.logger); err != nil { + recordPreload(started, 0) for _, prefix := range p.PinnedPrefixes() { c.cache.Invalidate(prefix) } return nil, err } + recordPreload(started, p.usedBytes) return &adaptiveContractState{ contractHash: hash, promotedAtTxNum: txNum, @@ -351,11 +358,15 @@ func (c *AdaptivePinController) runExtensionLocked( dbBranches = provider(state.contractHash[:]) } state.parallel.pinTxNum = txNum + before, started := state.parallel.usedBytes, time.Now() _, _, err := state.parallel.Run(stepBudget, dbBranches, parallelResolve, c.cache, c.logger) + recordPreload(started, state.parallel.usedBytes-before) return err } 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 } diff --git a/execution/commitment/adaptive_pin_test.go b/execution/commitment/adaptive_pin_test.go index fc8bed57bcd..6e276df4efd 100644 --- a/execution/commitment/adaptive_pin_test.go +++ b/execution/commitment/adaptive_pin_test.go @@ -17,6 +17,7 @@ package commitment import ( + "context" "testing" "github.com/erigontech/erigon/common/log/v3" @@ -47,3 +48,72 @@ func TestNewAdaptivePinController_ExplicitConfigWins(t *testing.T) { t.Fatalf("explicit config was overwritten: got %+v, want %+v", c.cfg, cfg) } } + +// The trunk-preload counters are the only signal for how much work the adaptive +// pin controller is doing; a preload that pins bytes must move both of them. +func TestAdaptivePin_PromoteRecordsPreloadMetrics(t *testing.T) { + hash, tree, _ := buildSyntheticTree(t) + resolve := fakeResolver(tree, nil, 100, "") + + bytesBefore := mxPreloadBytesTotal.GetValue() + secondsBefore := mxPreloadDurationSecondsTotal.GetValue() + + c := NewAdaptivePinController(NewBranchCache(64), AdaptivePinControllerConfig{}, log.Root()) + var h [32]byte + copy(h[:], hash) + + c.mu.Lock() + state, err := c.promoteLocked(context.Background(), h, 1, resolve, nil, nil) + c.mu.Unlock() + if err != nil { + t.Fatal(err) + } + if state.usedBytes() == 0 { + t.Fatal("promote pinned nothing, so the metric assertions below would be vacuous") + } + + if got := mxPreloadBytesTotal.GetValue() - bytesBefore; got <= 0 { + t.Errorf("commitment_trunk_preload_bytes_total advanced by %v after promoting a contract, want > 0", got) + } + if got := mxPreloadDurationSecondsTotal.GetValue() - secondsBefore; got <= 0 { + t.Errorf("commitment_trunk_preload_duration_seconds_total advanced by %v after promoting a contract, want > 0", got) + } +} + +// Extensions are the dominant preload path in a running node, so they must be +// counted too, not just the one-off promote. +func TestAdaptivePin_ExtendRecordsPreloadMetrics(t *testing.T) { + hash, tree, _ := buildSyntheticTree(t) + resolve := fakeResolver(tree, nil, 100, "") + + // Budget the initial view so the queue survives promotion and an extension + // has something left to pin. + cfg := AdaptivePinControllerConfig{InitialViewBudgetBytes: minEntryBytes + 1} + c := NewAdaptivePinController(NewBranchCache(64), cfg, log.Root()) + var h [32]byte + copy(h[:], hash) + + c.mu.Lock() + defer c.mu.Unlock() + state, err := c.promoteLocked(context.Background(), h, 1, resolve, nil, nil) + if err != nil { + t.Fatal(err) + } + if state.queueRemaining() == 0 { + t.Fatal("initial view drained the queue, so there is no extension to measure") + } + + bytesBefore := mxPreloadBytesTotal.GetValue() + secondsBefore := mxPreloadDurationSecondsTotal.GetValue() + + if err := c.runExtensionLocked(context.Background(), state, 2, 1<<20, resolve, nil, nil); err != nil { + t.Fatal(err) + } + + if got := mxPreloadBytesTotal.GetValue() - bytesBefore; got <= 0 { + t.Errorf("commitment_trunk_preload_bytes_total advanced by %v after an extension, want > 0", got) + } + if got := mxPreloadDurationSecondsTotal.GetValue() - secondsBefore; got <= 0 { + t.Errorf("commitment_trunk_preload_duration_seconds_total advanced by %v after an extension, want > 0", got) + } +} diff --git a/execution/commitment/trunk_pin_metrics.go b/execution/commitment/trunk_pin_metrics.go index 3a0b956e4fc..ca9d04c80f8 100644 --- a/execution/commitment/trunk_pin_metrics.go +++ b/execution/commitment/trunk_pin_metrics.go @@ -17,6 +17,8 @@ package commitment import ( + "time" + "github.com/erigontech/erigon/diagnostics/metrics" ) @@ -37,6 +39,16 @@ var ( mxPreloadBytesTotal = metrics.GetOrCreateCounter("commitment_trunk_preload_bytes_total") ) +// recordPreload accounts one preload step: the wall time it took and the bytes +// it newly pinned. Bytes are passed in rather than read back off the preloader +// so a rolled-back step can report the time it cost without the pins it lost. +func recordPreload(started time.Time, bytesPinned int) { + mxPreloadDurationSecondsTotal.Add(time.Since(started).Seconds()) + if bytesPinned > 0 { + mxPreloadBytesTotal.AddInt(bytesPinned) + } +} + // PublishMetrics emits counter deltas (last-published tracked internally) and // sets gauges absolute. Call once per SD.Flush — once-per-batch avoids hot-path cost. func (c *BranchCache) PublishMetrics() { From fbce91ee77c636ee18c62e3366f4b67d600e8c54 Mon Sep 17 00:00:00 2001 From: Oleksandr Lystopad Date: Mon, 10 Aug 2026 11:36:43 +0200 Subject: [PATCH 2/2] execution/commitment: don't assert wall time through the preload path MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- execution/commitment/adaptive_pin_test.go | 41 ++++++++++++++++++----- 1 file changed, 33 insertions(+), 8 deletions(-) diff --git a/execution/commitment/adaptive_pin_test.go b/execution/commitment/adaptive_pin_test.go index 6e276df4efd..3335f1138d2 100644 --- a/execution/commitment/adaptive_pin_test.go +++ b/execution/commitment/adaptive_pin_test.go @@ -19,6 +19,7 @@ package commitment import ( "context" "testing" + "time" "github.com/erigontech/erigon/common/log/v3" ) @@ -50,13 +51,13 @@ func TestNewAdaptivePinController_ExplicitConfigWins(t *testing.T) { } // The trunk-preload counters are the only signal for how much work the adaptive -// pin controller is doing; a preload that pins bytes must move both of them. +// pin controller is doing, so promotion must feed them. Asserting the byte +// counter is enough to prove recordPreload ran: nothing else writes it. func TestAdaptivePin_PromoteRecordsPreloadMetrics(t *testing.T) { hash, tree, _ := buildSyntheticTree(t) resolve := fakeResolver(tree, nil, 100, "") bytesBefore := mxPreloadBytesTotal.GetValue() - secondsBefore := mxPreloadDurationSecondsTotal.GetValue() c := NewAdaptivePinController(NewBranchCache(64), AdaptivePinControllerConfig{}, log.Root()) var h [32]byte @@ -75,9 +76,6 @@ func TestAdaptivePin_PromoteRecordsPreloadMetrics(t *testing.T) { if got := mxPreloadBytesTotal.GetValue() - bytesBefore; got <= 0 { t.Errorf("commitment_trunk_preload_bytes_total advanced by %v after promoting a contract, want > 0", got) } - if got := mxPreloadDurationSecondsTotal.GetValue() - secondsBefore; got <= 0 { - t.Errorf("commitment_trunk_preload_duration_seconds_total advanced by %v after promoting a contract, want > 0", got) - } } // Extensions are the dominant preload path in a running node, so they must be @@ -104,7 +102,6 @@ func TestAdaptivePin_ExtendRecordsPreloadMetrics(t *testing.T) { } bytesBefore := mxPreloadBytesTotal.GetValue() - secondsBefore := mxPreloadDurationSecondsTotal.GetValue() if err := c.runExtensionLocked(context.Background(), state, 2, 1<<20, resolve, nil, nil); err != nil { t.Fatal(err) @@ -113,7 +110,35 @@ func TestAdaptivePin_ExtendRecordsPreloadMetrics(t *testing.T) { if got := mxPreloadBytesTotal.GetValue() - bytesBefore; got <= 0 { t.Errorf("commitment_trunk_preload_bytes_total advanced by %v after an extension, want > 0", got) } - if got := mxPreloadDurationSecondsTotal.GetValue() - secondsBefore; got <= 0 { - t.Errorf("commitment_trunk_preload_duration_seconds_total advanced by %v after an extension, want > 0", got) +} + +// The elapsed time cannot be asserted through a real preload: the work takes +// microseconds, and a coarse platform timer rounds that to zero. Drive +// recordPreload with a known elapsed time instead. +func TestRecordPreload_RecordsElapsedAndBytes(t *testing.T) { + const elapsed = 50 * time.Millisecond + + for _, tc := range []struct { + name string + bytesPinned int + wantBytes float64 + }{ + {"pinned bytes are counted", 4096, 4096}, + // A rolled-back step reports the time it cost without the pins it lost. + {"a step that pinned nothing still counts its time", 0, 0}, + } { + t.Run(tc.name, func(t *testing.T) { + bytesBefore := mxPreloadBytesTotal.GetValue() + secondsBefore := mxPreloadDurationSecondsTotal.GetValue() + + recordPreload(time.Now().Add(-elapsed), tc.bytesPinned) + + if got := mxPreloadBytesTotal.GetValue() - bytesBefore; got != tc.wantBytes { + t.Errorf("commitment_trunk_preload_bytes_total advanced by %v, want %v", got, tc.wantBytes) + } + if got := mxPreloadDurationSecondsTotal.GetValue() - secondsBefore; got < elapsed.Seconds() { + t.Errorf("commitment_trunk_preload_duration_seconds_total advanced by %v, want >= %v", got, elapsed.Seconds()) + } + }) } }