From 2d0d14ecc347ecc4ec848bba2c834832490e150a Mon Sep 17 00:00:00 2001 From: Patrick O'Grady Date: Tue, 4 Apr 2023 23:23:12 -0700 Subject: [PATCH 1/4] add verify metrics --- chain/block.go | 4 ++++ chain/dependencies.go | 5 +++++ vm/metrics.go | 41 +++++++++++++++++++++++++++++++++-------- vm/resolutions.go | 8 ++++++++ 4 files changed, 50 insertions(+), 8 deletions(-) diff --git a/chain/block.go b/chain/block.go index dce91963b7..0338e5d2b8 100644 --- a/chain/block.go +++ b/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.RecordSignaturesVerified(time.Since(start)) return state, nil } diff --git a/chain/dependencies.go b/chain/dependencies.go index 690649ddf8..3abf9b09dd 100644 --- a/chain/dependencies.go +++ b/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,10 @@ type VM interface { // and false if the sync completed with the previous root. UpdateSyncTarget(*StatelessBlock) (bool, error) StateReady() bool + + // The following functions are used to record metrics about VM performance + RecordRootCalculated(t time.Duration) // only called in Verify + RecordSignaturesVerified(t time.Duration) // only called in Verify } type Mempool interface { diff --git a/vm/metrics.go b/vm/metrics.go index 370a2cd52c..3f890400bb 100644 --- a/vm/metrics.go +++ b/vm/metrics.go @@ -4,21 +4,45 @@ package vm import ( + "github.com/ava-labs/avalanchego/utils/metric" "github.com/ava-labs/avalanchego/utils/wrappers" "github.com/prometheus/client_golang/prometheus" ) type Metrics struct { - unitsVerified prometheus.Counter - unitsAccepted prometheus.Counter - txsSubmitted prometheus.Counter // includes gossip - txsVerified prometheus.Counter - txsAccepted prometheus.Counter - decisionsRPCConnections prometheus.Gauge - blocksRPCConnections prometheus.Gauge + unitsVerified prometheus.Counter + unitsAccepted prometheus.Counter + txsSubmitted prometheus.Counter // includes gossip + txsVerified prometheus.Counter + txsAccepted prometheus.Counter + decisionsRPCConnections prometheus.Gauge + blocksRPCConnections prometheus.Gauge + rootCalculationWait metric.Averager + signatureVerificationWait metric.Averager } func newMetrics() (*prometheus.Registry, *Metrics, error) { + r := prometheus.NewRegistry() + + rootCalculations, err := metric.NewAverager( + "chain", + "root_calculations", + "time spent on root calculations in verify", + r, + ) + if err != nil { + return nil, nil, err + } + signaturesVerified, err := metric.NewAverager( + "chain", + "signature_verification_wait", + "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", }), + rootCalculationWait: rootCalculations, + signatureVerificationWait: signaturesVerified, } - r := prometheus.NewRegistry() errs := wrappers.Errs{} errs.Add( r.Register(m.unitsVerified), diff --git a/vm/resolutions.go b/vm/resolutions.go index 4f06cf558d..1eaf56f3d7 100644 --- a/vm/resolutions.go +++ b/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.rootCalculationWait.Observe(float64(t)) +} + +func (vm *VM) RecordSignaturesVerified(t time.Duration) { + vm.metrics.signatureVerificationWait.Observe(float64(t)) +} From e22f633260ed39d849be7ba835c2d9865838a7a8 Mon Sep 17 00:00:00 2001 From: Patrick O'Grady Date: Tue, 4 Apr 2023 23:27:19 -0700 Subject: [PATCH 2/4] cleanup wording --- chain/block.go | 2 +- chain/dependencies.go | 6 +++--- vm/metrics.go | 32 ++++++++++++++++---------------- vm/resolutions.go | 2 +- 4 files changed, 21 insertions(+), 21 deletions(-) diff --git a/chain/block.go b/chain/block.go index 0338e5d2b8..8e1bdd08cd 100644 --- a/chain/block.go +++ b/chain/block.go @@ -611,7 +611,7 @@ func (b *StatelessBlock) innerVerify(ctx context.Context) (merkledb.TrieView, er if err := b.sigJob.Wait(); err != nil { return nil, err } - b.vm.RecordSignaturesVerified(time.Since(start)) + b.vm.RecordWaitSignatures(time.Since(start)) return state, nil } diff --git a/chain/dependencies.go b/chain/dependencies.go index 3abf9b09dd..a635c06556 100644 --- a/chain/dependencies.go +++ b/chain/dependencies.go @@ -64,9 +64,9 @@ type VM interface { UpdateSyncTarget(*StatelessBlock) (bool, error) StateReady() bool - // The following functions are used to record metrics about VM performance - RecordRootCalculated(t time.Duration) // only called in Verify - RecordSignaturesVerified(t time.Duration) // only called in Verify + // Record the duration of various operations to populate chain metrics + RecordRootCalculated(t time.Duration) // only called in Verify + RecordWaitSignatures(t time.Duration) // only called in Verify } type Mempool interface { diff --git a/vm/metrics.go b/vm/metrics.go index 3f890400bb..a8e02abad2 100644 --- a/vm/metrics.go +++ b/vm/metrics.go @@ -10,32 +10,32 @@ import ( ) type Metrics struct { - unitsVerified prometheus.Counter - unitsAccepted prometheus.Counter - txsSubmitted prometheus.Counter // includes gossip - txsVerified prometheus.Counter - txsAccepted prometheus.Counter - decisionsRPCConnections prometheus.Gauge - blocksRPCConnections prometheus.Gauge - rootCalculationWait metric.Averager - signatureVerificationWait metric.Averager + unitsVerified prometheus.Counter + unitsAccepted prometheus.Counter + txsSubmitted prometheus.Counter // includes gossip + txsVerified prometheus.Counter + txsAccepted prometheus.Counter + decisionsRPCConnections prometheus.Gauge + blocksRPCConnections prometheus.Gauge + rootCalculated metric.Averager + waitSignatures metric.Averager } func newMetrics() (*prometheus.Registry, *Metrics, error) { r := prometheus.NewRegistry() - rootCalculations, err := metric.NewAverager( + rootCalculated, err := metric.NewAverager( "chain", - "root_calculations", - "time spent on root calculations in verify", + "root_calculated", + "time spent calculating the state root in verify", r, ) if err != nil { return nil, nil, err } - signaturesVerified, err := metric.NewAverager( + waitSignatures, err := metric.NewAverager( "chain", - "signature_verification_wait", + "wait_signatures", "time spent waiting for signature verification in verify", r, ) @@ -79,8 +79,8 @@ func newMetrics() (*prometheus.Registry, *Metrics, error) { Name: "blocks_rpc_connections", Help: "number of open blocks connections", }), - rootCalculationWait: rootCalculations, - signatureVerificationWait: signaturesVerified, + rootCalculated: rootCalculated, + waitSignatures: waitSignatures, } errs := wrappers.Errs{} errs.Add( diff --git a/vm/resolutions.go b/vm/resolutions.go index 1eaf56f3d7..9dae106595 100644 --- a/vm/resolutions.go +++ b/vm/resolutions.go @@ -326,6 +326,6 @@ func (vm *VM) RecordRootCalculated(t time.Duration) { vm.metrics.rootCalculationWait.Observe(float64(t)) } -func (vm *VM) RecordSignaturesVerified(t time.Duration) { +func (vm *VM) RecordWaitSignatures(t time.Duration) { vm.metrics.signatureVerificationWait.Observe(float64(t)) } From b3acb94a1d7dc165c2bbec32fd59c1a8255fdf13 Mon Sep 17 00:00:00 2001 From: Patrick O'Grady Date: Tue, 4 Apr 2023 23:28:16 -0700 Subject: [PATCH 3/4] add more comments --- chain/dependencies.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/chain/dependencies.go b/chain/dependencies.go index a635c06556..24b9d30356 100644 --- a/chain/dependencies.go +++ b/chain/dependencies.go @@ -65,6 +65,9 @@ type VM interface { 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 } From 813e125d4d2ce11a3a3f8ef0e65808af6a89d685 Mon Sep 17 00:00:00 2001 From: Patrick O'Grady Date: Tue, 4 Apr 2023 23:30:51 -0700 Subject: [PATCH 4/4] update resolution --- vm/resolutions.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/vm/resolutions.go b/vm/resolutions.go index 9dae106595..d1e46c1387 100644 --- a/vm/resolutions.go +++ b/vm/resolutions.go @@ -323,9 +323,9 @@ func (vm *VM) StateManager() chain.StateManager { } func (vm *VM) RecordRootCalculated(t time.Duration) { - vm.metrics.rootCalculationWait.Observe(float64(t)) + vm.metrics.rootCalculated.Observe(float64(t)) } func (vm *VM) RecordWaitSignatures(t time.Duration) { - vm.metrics.signatureVerificationWait.Observe(float64(t)) + vm.metrics.waitSignatures.Observe(float64(t)) }