Add metrics for root calculation and signature wait

chain/block.go

@@ -589,10 +589,12 @@ func (b *StatelessBlock) innerVerify(ctx context.Context) (merkledb.TrieView, er
 	}
 
 	// Compute state root
+	start := time.Now()
 	computedRoot, err := state.GetMerkleRoot(ctx)
 	if err != nil {
 		return nil, err
 	}
+	b.vm.RecordRootCalculated(time.Since(start))
 	if b.StateRoot != computedRoot {
 		return nil, fmt.Errorf(
 			"%w: expected=%s found=%s",
@@ -605,9 +607,11 @@ func (b *StatelessBlock) innerVerify(ctx context.Context) (merkledb.TrieView, er
 	// Ensure signatures are verified
 	_, sspan := b.vm.Tracer().Start(ctx, "StatelessBlock.Verify.WaitSignatures")
 	defer sspan.End()
+	start = time.Now()
 	if err := b.sigJob.Wait(); err != nil {
 		return nil, err
 	}
+	b.vm.RecordWaitSignatures(time.Since(start))
 	return state, nil
 }
 

chain/dependencies.go

@@ -5,6 +5,7 @@ package chain
 
 import (
 	"context"
+	"time"
 
 	"github.com/ava-labs/avalanchego/ids"
 	"github.com/ava-labs/avalanchego/snow/engine/snowman/block"
@@ -62,6 +63,13 @@ type VM interface {
 	// and false if the sync completed with the previous root.
 	UpdateSyncTarget(*StatelessBlock) (bool, error)
 	StateReady() bool
+
+	// Record the duration of various operations to populate chain metrics
+	//
+	// If there was a long-lived [Chain] struct, we would store metrics for chain
+	// there.
+	RecordRootCalculated(t time.Duration) // only called in Verify
+	RecordWaitSignatures(t time.Duration) // only called in Verify
 }
 
 type Mempool interface {

vm/metrics.go

@@ -4,6 +4,7 @@
 package vm
 
 import (
+	"github.com/ava-labs/avalanchego/utils/metric"
 	"github.com/ava-labs/avalanchego/utils/wrappers"
 	"github.com/prometheus/client_golang/prometheus"
 )
@@ -16,9 +17,32 @@ type Metrics struct {
 	txsAccepted             prometheus.Counter
 	decisionsRPCConnections prometheus.Gauge
 	blocksRPCConnections    prometheus.Gauge
+	rootCalculated          metric.Averager
+	waitSignatures          metric.Averager
 }
 
 func newMetrics() (*prometheus.Registry, *Metrics, error) {
+	r := prometheus.NewRegistry()
+
+	rootCalculated, err := metric.NewAverager(
+		"chain",
+		"root_calculated",
+		"time spent calculating the state root in verify",
+		r,
+	)
+	if err != nil {
+		return nil, nil, err
+	}
+	waitSignatures, err := metric.NewAverager(
+		"chain",
+		"wait_signatures",
+		"time spent waiting for signature verification in verify",
+		r,
+	)
+	if err != nil {
+		return nil, nil, err
+	}
+
 	m := &Metrics{
 		unitsVerified: prometheus.NewCounter(prometheus.CounterOpts{
 			Namespace: "chain",
@@ -55,8 +79,9 @@ func newMetrics() (*prometheus.Registry, *Metrics, error) {
 			Name:      "blocks_rpc_connections",
 			Help:      "number of open blocks connections",
 		}),
+		rootCalculated: rootCalculated,
+		waitSignatures: waitSignatures,
 	}
-	r := prometheus.NewRegistry()
 	errs := wrappers.Errs{}
 	errs.Add(
 		r.Register(m.unitsVerified),

vm/resolutions.go

@@ -321,3 +321,11 @@ func (vm *VM) StateSyncEnabled(ctx context.Context) (bool, error) {
 func (vm *VM) StateManager() chain.StateManager {
 	return vm.c.StateManager()
 }
+
+func (vm *VM) RecordRootCalculated(t time.Duration) {
+	vm.metrics.rootCalculated.Observe(float64(t))
+}
+
+func (vm *VM) RecordWaitSignatures(t time.Duration) {
+	vm.metrics.waitSignatures.Observe(float64(t))
+}