execution/commitment: record the trunk-preload duration and bytes counters

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
 }
 

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)
+	}
+}

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() {