diff --git a/RELEASES.md b/RELEASES.md index dd4e84d9fceb..497cc23fdd2f 100644 --- a/RELEASES.md +++ b/RELEASES.md @@ -4,11 +4,14 @@ ### Metrics -- Renamed Coreth and Subnet-EVM state-sync p2p metrics (`{vmName}` is `evm` for Coreth/C-Chain and `subnetevm` for Subnet-EVM chains): +- Added `avalanche_{vmName}_sae_last_executed_height` and `avalanche_{vmName}_sae_last_settled_height` gauges, exposing SAE async-execution and settlement heights. +- Renamed Coreth and Subnet-EVM state-sync p2p metrics: - `avalanche_{vmName}_eth_net_tracked_peers` -> `avalanche_{vmName}_sdk_sync_peer_tracker_num_tracked_peers` - `avalanche_{vmName}_eth_net_responsive_peers` -> `avalanche_{vmName}_sdk_sync_peer_tracker_num_responsive_peers` - `avalanche_{vmName}_eth_net_average_bandwidth` -> `avalanche_{vmName}_sdk_sync_peer_tracker_average_bandwidth` +NOTE: `{vmName}` is `evm` for Coreth/C-Chain and `subnetevm` for Subnet-EVM chains + ### Fixes - Updated minimum Go version from `v1.25.8` to `v1.25.10`. diff --git a/vms/saevm/sae/BUILD.bazel b/vms/saevm/sae/BUILD.bazel index 2b79af49b4ed..4dd9e41f187e 100644 --- a/vms/saevm/sae/BUILD.bazel +++ b/vms/saevm/sae/BUILD.bazel @@ -23,6 +23,7 @@ go_library( importpath = "github.com/ava-labs/avalanchego/vms/saevm/sae", visibility = ["//visibility:public"], deps = [ + "//api/metrics", "//database", "//ids", "//network/p2p", @@ -110,6 +111,7 @@ go_test( "//vms/saevm/saedb", "//vms/saevm/saetest", "//vms/saevm/saetest/escrow", + "//vms/saevm/saexec", "//vms/saevm/txgossip/txgossiptest", "//vms/saevm/types", "@com_github_arr4n_shed//testerr", @@ -140,6 +142,8 @@ go_test( "@com_github_google_go_cmp//cmp", "@com_github_google_go_cmp//cmp/cmpopts", "@com_github_holiman_uint256//:uint256", + "@com_github_prometheus_client_golang//prometheus", + "@com_github_prometheus_client_model//go", "@com_github_stretchr_testify//assert", "@com_github_stretchr_testify//require", "@org_uber_go_goleak//:goleak", @@ -195,6 +199,7 @@ go_test( "//vms/saevm/saedb", "//vms/saevm/saetest", "//vms/saevm/saetest/escrow", + "//vms/saevm/saexec", "//vms/saevm/txgossip/txgossiptest", "//vms/saevm/types", "//vms/saevm/worstcase", @@ -225,6 +230,8 @@ go_test( "@com_github_google_go_cmp//cmp", "@com_github_google_go_cmp//cmp/cmpopts", "@com_github_holiman_uint256//:uint256", + "@com_github_prometheus_client_golang//prometheus", + "@com_github_prometheus_client_model//go", "@com_github_stretchr_testify//assert", "@com_github_stretchr_testify//require", "@org_uber_go_goleak//:goleak", diff --git a/vms/saevm/sae/consensus.go b/vms/saevm/sae/consensus.go index 56f23dd6107d..2b488c9dc878 100644 --- a/vms/saevm/sae/consensus.go +++ b/vms/saevm/sae/consensus.go @@ -75,6 +75,7 @@ func (vm *VM) AcceptBlock(ctx context.Context, b *blocks.Block) error { if err := s.MarkSettled(&vm.last.settled); err != nil { return err } + vm.exec.MarkSettled(s.Height()) } // I(s ∈ S) above, before I(b ∈ A) before X(b ∈ A) diff --git a/vms/saevm/sae/vm.go b/vms/saevm/sae/vm.go index 0d616859f7ad..81391f62cd0d 100644 --- a/vms/saevm/sae/vm.go +++ b/vms/saevm/sae/vm.go @@ -25,6 +25,7 @@ import ( "github.com/ava-labs/libevm/params" "github.com/prometheus/client_golang/prometheus" + "github.com/ava-labs/avalanchego/api/metrics" "github.com/ava-labs/avalanchego/network/p2p" "github.com/ava-labs/avalanchego/network/p2p/gossip" "github.com/ava-labs/avalanchego/snow" @@ -52,10 +53,10 @@ type VM struct { Peers *p2p.Peers ValidatorPeers *p2p.Validators - hooks hook.Points - config Config - snowCtx *snow.Context - metrics *prometheus.Registry + hooks hook.Points + config Config + snowCtx *snow.Context + metricRegistry *prometheus.Registry db ethdb.Database xdb saetypes.ExecutionResults @@ -123,12 +124,16 @@ func NewVM[T hook.Transaction]( if cfg.Now == nil { cfg.Now = time.Now } + reg, err := metrics.MakeAndRegister(snowCtx.Metrics, "sae") + if err != nil { + return nil, err + } vm := &VM{ - hooks: hooks, - config: cfg, - snowCtx: snowCtx, - metrics: prometheus.NewRegistry(), - db: db, + hooks: hooks, + config: cfg, + snowCtx: snowCtx, + metricRegistry: reg, + db: db, } defer func() { if retErr != nil { @@ -136,10 +141,6 @@ func NewVM[T hook.Transaction]( } }() - if err := snowCtx.Metrics.Register("sae", vm.metrics); err != nil { - return nil, err - } - xdb, err := hooks.ExecutionResultsDB( filepath.Join(snowCtx.ChainDataDir, "sae_execution_results"), ) @@ -180,6 +181,7 @@ func NewVM[T hook.Transaction]( cfg.DBConfig, hooks, snowCtx.Log, + vm.metricRegistry, ) if err != nil { return nil, fmt.Errorf("saexec.New(...): %v", err) @@ -201,6 +203,8 @@ func NewVM[T hook.Transaction]( vm.last.settled.Store(lastSettled) vm.last.accepted.Store(head) vm.preference.Store(head) + // [saexec.New] already records the initial executed height. + vm.exec.MarkSettled(lastSettled.Height()) } { // ========== Mempool ========== @@ -214,11 +218,11 @@ func NewVM[T hook.Transaction]( } vm.toClose = append(vm.toClose, txPool) - metrics, err := bloom.NewMetrics("mempool", vm.metrics) + bloomMetrics, err := bloom.NewMetrics("mempool", vm.metricRegistry) if err != nil { return nil, err } - conf := gossip.BloomSetConfig{Metrics: metrics} + conf := gossip.BloomSetConfig{Metrics: bloomMetrics} pool, err := txgossip.NewSet(txPool, conf) if err != nil { return nil, err @@ -239,7 +243,7 @@ func NewVM[T hook.Transaction]( } { // ========== P2P Gossip ========== - network, peers, validatorPeers, err := newNetwork(snowCtx, sender, vm.metrics) + network, peers, validatorPeers, err := newNetwork(snowCtx, sender, vm.metricRegistry) if err != nil { return nil, fmt.Errorf("newNetwork(...): %v", err) } @@ -253,7 +257,7 @@ func NewVM[T hook.Transaction]( txgossip.Marshaller{}, gossip.SystemConfig{ Log: snowCtx.Log, - Registry: vm.metrics, + Registry: vm.metricRegistry, Namespace: "gossip", RequestPeriod: pullGossipPeriod, }, diff --git a/vms/saevm/sae/vm_test.go b/vms/saevm/sae/vm_test.go index 7dddf9de9787..6b38167df7a3 100644 --- a/vms/saevm/sae/vm_test.go +++ b/vms/saevm/sae/vm_test.go @@ -10,6 +10,7 @@ import ( "math/big" "net/http/httptest" "os" + "slices" "sync" "testing" "time" @@ -32,6 +33,7 @@ import ( "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" "github.com/holiman/uint256" + "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/goleak" @@ -54,12 +56,14 @@ import ( "github.com/ava-labs/avalanchego/vms/saevm/hook" "github.com/ava-labs/avalanchego/vms/saevm/hook/hookstest" "github.com/ava-labs/avalanchego/vms/saevm/saetest" + "github.com/ava-labs/avalanchego/vms/saevm/saexec" "github.com/ava-labs/avalanchego/vms/saevm/txgossip/txgossiptest" snowcommon "github.com/ava-labs/avalanchego/snow/engine/common" saeparams "github.com/ava-labs/avalanchego/vms/saevm/params" saetypes "github.com/ava-labs/avalanchego/vms/saevm/types" libevmhookstest "github.com/ava-labs/libevm/libevm/hookstest" + dto "github.com/prometheus/client_model/go" ) func TestMain(m *testing.M) { @@ -1014,6 +1018,34 @@ func TestGossip(t *testing.T) { requireNotReceiveTx(t, nonValidators[1:], tx.Hash()) } +func TestSettlementMetric(t *testing.T) { + opt, vmTime := withVMTime(t, time.Unix(saeparams.TauSeconds, 0)) + ctx, sut := newSUT(t, 1, opt) + + executed := sut.runConsensusLoop(t) + require.NoErrorf(t, executed.WaitUntilExecuted(ctx), "%T.WaitUntilExecuted()", executed) + + vmTime.advanceToSettle(ctx, t, executed) + settledBy := sut.runConsensusLoop(t) + require.NoErrorf(t, settledBy.WaitUntilExecuted(ctx), "%T.WaitUntilExecuted()", settledBy) + require.Equal(t, float64(executed.Height()), gaugeValue(t, sut.rawVM.metricRegistry, saexec.LastSettledHeightName), "last settled height") +} + +// gaugeValue returns the current value of a single-series gauge from `g` by +// name, failing the test if it is missing or has more than one series. +func gaugeValue(t *testing.T, g prometheus.Gatherer, name string) float64 { + t.Helper() + mfs, err := g.Gather() + require.NoError(t, err, "Gather()") + i := slices.IndexFunc(mfs, func(mf *dto.MetricFamily) bool { + return mf.GetName() == name + }) + require.GreaterOrEqualf(t, i, 0, "metric %q not found", name) + series := mfs[i].GetMetric() + require.Lenf(t, series, 1, "metric %q series count", name) + return series[0].GetGauge().GetValue() +} + func TestBlockSources(t *testing.T) { opt, vmTime := withVMTime(t, time.Unix(saeparams.TauSeconds, 0)) ctx, sut := newSUT(t, 1, opt) diff --git a/vms/saevm/saexec/BUILD.bazel b/vms/saevm/saexec/BUILD.bazel index 8b8788b290d8..fd9caa89d91b 100644 --- a/vms/saevm/saexec/BUILD.bazel +++ b/vms/saevm/saexec/BUILD.bazel @@ -6,6 +6,7 @@ go_library( srcs = [ "context.go", "execution.go", + "metrics.go", "receipts.go", "saexec.go", "subscription.go", @@ -32,6 +33,7 @@ go_library( "@com_github_ava_labs_libevm//libevm/eventual", "@com_github_ava_labs_libevm//params", "@com_github_holiman_uint256//:uint256", + "@com_github_prometheus_client_golang//prometheus", "@org_uber_go_zap//:zap", ], ) @@ -71,6 +73,8 @@ go_test( "@com_github_google_go_cmp//cmp", "@com_github_google_go_cmp//cmp/cmpopts", "@com_github_holiman_uint256//:uint256", + "@com_github_prometheus_client_golang//prometheus", + "@com_github_prometheus_client_golang//prometheus/testutil", "@com_github_stretchr_testify//assert", "@com_github_stretchr_testify//require", "@org_uber_go_goleak//:goleak", diff --git a/vms/saevm/saexec/execution.go b/vms/saevm/saexec/execution.go index 368b32d7fb15..157833500aa7 100644 --- a/vms/saevm/saexec/execution.go +++ b/vms/saevm/saexec/execution.go @@ -292,16 +292,18 @@ func (e *Executor) afterExecution(b *blocks.Block, r *ExecutionResults) error { // post-execution state to no longer be consensus-critical. e.Tracker.Track(root) - // The strict ordering of the next 3 calls guarantees invariants that MUST - // NOT be broken: + // The strict ordering of the following calls guarantees invariants that + // MUST NOT be broken: // // 1. [blocks.Block.MarkExecuted] guarantees disk then in-memory changes. // 2. Internal indicator of last executed MUST follow in-memory change. - // 3. External indicator of last executed MUST follow internal indicator. + // 3. Metrics indicator of last executed MUST follow internal indicator. + // 4. External indicator of last executed MUST follow internal indicator. if err := b.MarkExecuted(e.db, e.xdb, r.FinishBy.Gas.Clone(), r.FinishBy.Wall, r.BaseFee.ToBig(), r.Receipts, root, &e.lastExecuted /* (2) */); err != nil { return err } - e.sendPostExecutionEvents(b.EthBlock(), r.Receipts) // (3) + e.metrics.markExecuted(b.Height()) // (3) + e.sendPostExecutionEvents(b.EthBlock(), r.Receipts) // (4) return nil } diff --git a/vms/saevm/saexec/metrics.go b/vms/saevm/saexec/metrics.go new file mode 100644 index 000000000000..0db5fe5d143d --- /dev/null +++ b/vms/saevm/saexec/metrics.go @@ -0,0 +1,53 @@ +// Copyright (C) 2019, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + +package saexec + +import ( + "errors" + + "github.com/prometheus/client_golang/prometheus" +) + +// Exported metric names for the SAE lifecycle bucket. Cross-package callers +// (tests, alert/dashboard wiring) should reference these constants rather +// than the raw strings. +const ( + LastExecutedHeightName = "last_executed_height" + LastSettledHeightName = "last_settled_height" +) + +// metrics holds the SAE block-lifecycle gauges. Both live with [Executor] +// because it owns the execution lifecycle: [Executor.afterExecution] +// writes last_executed_height directly, and [Executor.MarkSettled] +// exposes the settled gauge for the sae VM to drive. Co-locating them +// keeps registration in one place. +type metrics struct { + lastExecutedHeight prometheus.Gauge + lastSettledHeight prometheus.Gauge +} + +func newMetrics(reg prometheus.Registerer) (*metrics, error) { + m := &metrics{ + lastExecutedHeight: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: LastExecutedHeightName, + Help: "Height of the latest block that completed async execution.", + }), + lastSettledHeight: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: LastSettledHeightName, + Help: "Height of the latest block that has settled.", + }), + } + return m, errors.Join( + reg.Register(m.lastExecutedHeight), + reg.Register(m.lastSettledHeight), + ) +} + +func (m *metrics) markExecuted(height uint64) { + m.lastExecutedHeight.Set(float64(height)) +} + +func (m *metrics) markSettled(height uint64) { + m.lastSettledHeight.Set(float64(height)) +} diff --git a/vms/saevm/saexec/saexec.go b/vms/saevm/saexec/saexec.go index 781ba2349ad0..bbfc7644eab5 100644 --- a/vms/saevm/saexec/saexec.go +++ b/vms/saevm/saexec/saexec.go @@ -8,6 +8,7 @@ package saexec import ( + "fmt" "io" "sync/atomic" @@ -18,6 +19,7 @@ import ( "github.com/ava-labs/libevm/event" "github.com/ava-labs/libevm/libevm/eventual" "github.com/ava-labs/libevm/params" + "github.com/prometheus/client_golang/prometheus" "github.com/ava-labs/avalanchego/cache/lru" "github.com/ava-labs/avalanchego/utils/logging" @@ -49,6 +51,7 @@ type Executor struct { chainConfig *params.ChainConfig db ethdb.Database xdb saetypes.ExecutionResults + metrics *metrics } // New constructs and starts a new [Executor]. Call [Executor.Close] to release @@ -66,12 +69,18 @@ func New( saedbConfig saedb.Config, hooks hook.Points, log logging.Logger, + reg prometheus.Registerer, ) (*Executor, error) { t, err := saedb.NewTracker(db, saedbConfig, lastExecuted.PostExecutionStateRoot(), log) if err != nil { return nil, err } + m, err := newMetrics(reg) + if err != nil { + return nil, fmt.Errorf("registering saexec metrics: %w", err) + } + e := &Executor{ Tracker: t, quit: make(chan struct{}), // closed by [Executor.Close] @@ -90,14 +99,22 @@ func New( chainConfig: chainConfig, db: db, xdb: xdb, + metrics: m, receipts: newSyncMap[common.Hash, eventual.Value[*Receipt]](), } e.lastExecuted.Store(lastExecuted) + e.metrics.markExecuted(lastExecuted.Height()) go e.processQueue() return e, nil } +// MarkSettled records height as the latest settled height. See [metrics] +// for why the lifecycle gauge is colocated in this package. +func (e *Executor) MarkSettled(height uint64) { + e.metrics.markSettled(height) +} + var _ io.Closer = (*Executor)(nil) // Close shuts down the [Executor], waits for the currently executing block diff --git a/vms/saevm/saexec/saexec_test.go b/vms/saevm/saexec/saexec_test.go index b0afb30c8914..75bd7da73900 100644 --- a/vms/saevm/saexec/saexec_test.go +++ b/vms/saevm/saexec/saexec_test.go @@ -13,6 +13,7 @@ import ( "slices" "sync" "testing" + "time" "github.com/arr4n/shed/testerr" "github.com/ava-labs/libevm/common" @@ -31,6 +32,8 @@ import ( "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" "github.com/holiman/uint256" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/goleak" @@ -117,7 +120,7 @@ func newSUT(tb testing.TB, opts ...sutOption) (context.Context, *SUT) { Archival: sutCfg.archival, TrieCommitInterval: sutCfg.commitInterval, } - e, err := New(genesis, src.AsHeaderSource(), config, db, xdb, saedbConfig, sutCfg.hooks, logger) + e, err := New(genesis, src.AsHeaderSource(), config, db, xdb, saedbConfig, sutCfg.hooks, logger, prometheus.NewRegistry()) require.NoError(tb, err, "New()") closeOnce := sync.OnceValue(e.Close) @@ -171,6 +174,20 @@ func TestExecutionSynchronisation(t *testing.T) { } } +func TestExecutionMetrics(t *testing.T) { + ctx, sut := newSUT(t) + b := sut.chain.NewBlock(t, nil) + + require.NoError(t, sut.Enqueue(ctx, b), "Enqueue()") + require.NoErrorf(t, b.WaitUntilExecuted(ctx), "%T.WaitUntilExecuted()", b) + // [Executor.afterExecution] updates LastExecutedHeight after + // [blocks.Block.MarkExecuted] returns, so the gauge can lag behind + // [blocks.Block.WaitUntilExecuted] unblocking for a brief period. + require.Eventually(t, func() bool { + return testutil.ToFloat64(sut.metrics.lastExecutedHeight) == float64(b.Height()) + }, time.Second, 10*time.Millisecond, "last executed height") +} + func TestReceiptPropagation(t *testing.T) { ctx, sut := newSUT(t) e, chain, wallet := sut.Executor, sut.chain, sut.wallet @@ -1036,7 +1053,7 @@ func TestArchivalStoresAll(t *testing.T) { t.Run("recover", func(t *testing.T) { // Restart the chain to remove the TrieDB cache. src := blocks.Source(chain.GetBlock) - e, err := New(chain.Last(), src.AsHeaderSource(), sut.chainConfig, sut.db, sut.xdb, sut.saedbConfig, defaultHooks(), sut.log) + e, err := New(chain.Last(), src.AsHeaderSource(), sut.chainConfig, sut.db, sut.xdb, sut.saedbConfig, defaultHooks(), sut.log, prometheus.NewRegistry()) require.NoError(t, err, "New()") t.Cleanup(func() { require.NoErrorf(t, e.Close(), "%T.Close()", e) diff --git a/vms/saevm/txgossip/txgossip_test.go b/vms/saevm/txgossip/txgossip_test.go index aa0845038d49..65ff7c19d930 100644 --- a/vms/saevm/txgossip/txgossip_test.go +++ b/vms/saevm/txgossip/txgossip_test.go @@ -83,7 +83,7 @@ func newSUT(t *testing.T, numAccounts uint) SUT { chain := blockstest.NewChainBuilder(genesis) src := blocks.Source(chain.GetBlock) - exec, err := saexec.New(genesis, src.AsHeaderSource(), config, db, xdb, saedb.Config{}, hookstest.NewStub(1e6), logger) + exec, err := saexec.New(genesis, src.AsHeaderSource(), config, db, xdb, saedb.Config{}, hookstest.NewStub(1e6), logger, prometheus.NewRegistry()) require.NoError(t, err, "saexec.New()") t.Cleanup(func() { require.NoErrorf(t, exec.Close(), "%T.Close()", exec)