Execution Timing Metric & Code Comments (#111)

internal/engine/manager.go

@@ -5,6 +5,7 @@ package engine
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/base-org/pessimism/internal/core"
 	"github.com/base-org/pessimism/internal/engine/invariant"
@@ -153,7 +154,7 @@ func (em *engineManager) DeployInvariantSession(cfg *invariant.DeployConfig) (co
 		return core.NilSUUID(), err
 	}
 
-	// Shared subsytem state management
+	// Shared subsystem state management
 	if cfg.Stateful {
 		err = em.addresser.Insert(cfg.InvParams.Address(), cfg.PUUID, sUUID)
 		if err != nil {
@@ -269,9 +270,12 @@ func (em *engineManager) executeNonAddressInvariants(ctx context.Context, data c
 func (em *engineManager) executeInvariant(ctx context.Context, data core.InvariantInput, inv invariant.Invariant) {
 	logger := logging.WithContext(ctx)
 
+	start := time.Now()
 	// Execute invariant using risk engine and return alert if invalidation occurs
 	outcome, invalidated := em.engine.Execute(ctx, data.Input, inv)
+
 	em.metrics.RecordInvariantRun(inv)
+	em.metrics.RecordInvExecutionTime(inv, float64(time.Since(start).Nanoseconds()))
 
 	if invalidated {
 		// Generate & send alert

internal/engine/registry/balance.go

@@ -53,6 +53,7 @@ func NewBalanceInvariant(cfg *BalanceInvConfig) (invariant.Invariant, error) {
 func (bi *BalanceInvariant) Invalidate(td core.TransitData) (*core.InvalOutcome, bool, error) {
 	logging.NoContext().Debug("Checking invalidation for balance invariant", zap.String("data", fmt.Sprintf("%v", td)))
 
+	// 1. Validate and extract balance input
 	err := bi.ValidateInput(td)
 	if err != nil {
 		return nil, false, err
@@ -65,18 +66,19 @@ func (bi *BalanceInvariant) Invalidate(td core.TransitData) (*core.InvalOutcome,
 
 	invalidated := false
 
-	// balance > upper bound
+	// 2. Invalidate if balance > upper bound
 	if bi.cfg.UpperBound != nil &&
 		*bi.cfg.UpperBound < balance {
 		invalidated = true
 	}
 
-	// balance < lower bound
+	// 3. Invalidate if balance < lower bound
 	if bi.cfg.LowerBound != nil &&
 		*bi.cfg.LowerBound > balance {
 		invalidated = true
 	}
 
+	/// 4. Generate invalidation outcome if invalidated
 	if invalidated {
 		var upper, lower string
 

internal/engine/registry/fault_detector.go

@@ -117,6 +117,7 @@ func (fd *faultDetectorInv) Invalidate(td core.TransitData) (*core.InvalOutcome,
 	logging.NoContext().Debug("Checking invalidation for fault detector invariant",
 		zap.String("data", fmt.Sprintf("%v", td)))
 
+	// 1. Validate and extract data input
 	err := fd.ValidateInput(td)
 	if err != nil {
 		return nil, false, err
@@ -131,25 +132,29 @@ func (fd *faultDetectorInv) Invalidate(td core.TransitData) (*core.InvalOutcome,
 		return nil, false, fmt.Errorf(couldNotCastErr, "types.Log")
 	}
 
+	// 2. Convert raw log to structured output proposal type
 	output, err := fd.l2OutputOracleFilter.ParseOutputProposed(log)
 	if err != nil {
 		fd.stats.RecordNodeError(core.Layer2)
 		return nil, false, err
 	}
 
+	// 3. Fetch the L2 block with the corresponding block height of the state output
 	outputBlock, err := fd.l2Client.BlockByNumber(context.Background(), output.L2BlockNumber)
 	if err != nil {
 		fd.stats.RecordNodeError(core.Layer2)
 		return nil, false, err
 	}
 
+	// 4. Fetch the withdrawal state root of the L2ToL1MessagePasser contract on L2
 	proofResp, err := fd.l2GethClient.GetProof(context.Background(),
 		fd.l2tol1MessagePasser, []string{}, output.L2BlockNumber)
 	if err != nil {
 		fd.stats.RecordNodeError(core.Layer2)
 		return nil, false, err
 	}
 
+	// 5. Compute the expected state root of the L2 block using the rollup node software
 	asInfo := blockToInfo(outputBlock)
 	expectedStateRoot, err := rollup.ComputeL2OutputRootV0(asInfo, proofResp.StorageHash)
 	if err != nil {
@@ -158,6 +163,7 @@ func (fd *faultDetectorInv) Invalidate(td core.TransitData) (*core.InvalOutcome,
 
 	actualStateRoot := output.OutputRoot
 
+	// 6. Compare the expected state root with the actual state root; if they are not equal, then invalidate
 	if expectedStateRoot != actualStateRoot {
 		return &core.InvalOutcome{
 			TimeStamp: time.Now(),

internal/engine/registry/withdrawal_enforce.go

@@ -91,6 +91,7 @@ func (wi *WithdrawalEnforceInv) Invalidate(td core.TransitData) (*core.InvalOutc
 	logging.NoContext().Debug("Checking invalidation for withdrawal enforcement invariant",
 		zap.String("data", fmt.Sprintf("%v", td)))
 
+	// 1. Validate and extract data input
 	if td.Type != wi.InputType() {
 		return nil, false, fmt.Errorf("invalid type supplied")
 	}
@@ -104,17 +105,20 @@ func (wi *WithdrawalEnforceInv) Invalidate(td core.TransitData) (*core.InvalOutc
 		return nil, false, fmt.Errorf(couldNotCastErr, "types.Log")
 	}
 
+	// 2. Parse the log to a WithdrawalProven structured type
 	provenWithdrawal, err := wi.l1PortalFilter.ParseWithdrawalProven(log)
 	if err != nil {
 		return nil, false, err
 	}
 
+	// 3. Check if the withdrawal exists in the message outbox of the L2ToL1MessagePasser contract
 	exists, err := wi.l2tol1MessagePasser.SentMessages(nil, provenWithdrawal.WithdrawalHash)
 	if err != nil {
 		return nil, false, err
 	}
 
-	if !exists { // Proven withdrawal does not exist on L1
+	// 4. If the withdrawal does not exist, invalidate
+	if !exists {
 		return &core.InvalOutcome{
 			TimeStamp: time.Now(),
 			Message: fmt.Sprintf(withdrawalEnforceMsg,

internal/metrics/metrics.go

@@ -38,6 +38,7 @@ type Metricer interface {
 	RecordAlertGenerated(alert core.Alert)
 	RecordNodeError(network core.Network)
 	RecordPipelineLatency(pUUID core.PUUID, latency float64)
+	RecordInvExecutionTime(inv invariant.Invariant, latency float64)
 	RecordUp()
 	Start()
 	Shutdown(ctx context.Context) error
@@ -53,6 +54,7 @@ type Metrics struct {
 	NodeErrors       *prometheus.CounterVec
 	BlockLatency     *prometheus.GaugeVec
 	PipelineLatency  *prometheus.GaugeVec
+	InvExecutionTime *prometheus.GaugeVec
 
 	registry *prometheus.Registry
 	factory  Factory
@@ -122,15 +124,20 @@ func New(ctx context.Context, cfg *Config) (Metricer, func(), error) {
 		}, []string{"node"}),
 		BlockLatency: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Name:      "block_latency",
-			Help:      "Latency of block processing",
+			Help:      "Millisecond latency of block processing",
 			Namespace: metricsNamespace,
 		}, []string{"network"}),
 
 		PipelineLatency: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Name:      "pipeline_latency",
-			Help:      "Latency of pipeline processing",
+			Help:      "Millisecond latency of pipeline processing",
 			Namespace: metricsNamespace,
 		}, []string{"puuid"}),
+		InvExecutionTime: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Name:      "invariant_execution_time",
+			Help:      "Nanosecond time of invariant execution",
+			Namespace: metricsNamespace,
+		}, []string{"invariant"}),
 
 		registry: registry,
 		factory:  factory,
@@ -156,6 +163,11 @@ func (m *Metrics) RecordUp() {
 	m.Up.Set(1)
 }
 
+func (m *Metrics) RecordInvExecutionTime(inv invariant.Invariant, latency float64) {
+	invType := inv.SUUID().PID.InvType().String()
+	m.InvExecutionTime.WithLabelValues(invType).Set(latency)
+}
+
 // IncActiveInvariants ... Increments the number of active invariants
 func (m *Metrics) IncActiveInvariants(invType core.InvariantType, network core.Network,
 	pipelineType core.PipelineType) {
@@ -220,13 +232,14 @@ var NoopMetrics Metricer = new(noopMetricer)
 func (n *noopMetricer) RecordUp() {}
 func (n *noopMetricer) IncActiveInvariants(_ core.InvariantType, _ core.Network, _ core.PipelineType) {
 }
-func (n *noopMetricer) IncActivePipelines(_ core.PipelineType, _ core.Network) {}
-func (n *noopMetricer) DecActivePipelines(_ core.PipelineType, _ core.Network) {}
-func (n *noopMetricer) RecordInvariantRun(_ invariant.Invariant)               {}
-func (n *noopMetricer) RecordAlertGenerated(_ core.Alert)                      {}
-func (n *noopMetricer) RecordNodeError(_ core.Network)                         {}
-func (n *noopMetricer) RecordBlockLatency(_ core.Network, _ float64)           {}
-func (n *noopMetricer) RecordPipelineLatency(_ core.PUUID, _ float64)          {}
+func (n *noopMetricer) RecordInvExecutionTime(_ invariant.Invariant, _ float64) {}
+func (n *noopMetricer) IncActivePipelines(_ core.PipelineType, _ core.Network)  {}
+func (n *noopMetricer) DecActivePipelines(_ core.PipelineType, _ core.Network)  {}
+func (n *noopMetricer) RecordInvariantRun(_ invariant.Invariant)                {}
+func (n *noopMetricer) RecordAlertGenerated(_ core.Alert)                       {}
+func (n *noopMetricer) RecordNodeError(_ core.Network)                          {}
+func (n *noopMetricer) RecordBlockLatency(_ core.Network, _ float64)            {}
+func (n *noopMetricer) RecordPipelineLatency(_ core.PUUID, _ float64)           {}
 
 func (n *noopMetricer) Shutdown(_ context.Context) error {
 	return nil