Merge pull request #944 from onflow/mpeter/add-block-processing-time-metric

Add a metric to count the EVM block processing time during event ingestion

Author: m-Peter

metrics/collector.go

@@ -66,12 +66,20 @@ var gasEstimationIterations = prometheus.NewGauge(prometheus.GaugeOpts{
 	Help: "Number of iterations taken to estimate the gas of a EVM call/tx",
 })
 
+// Time difference between block proposal time and block indexing time
 var blockIngestionTime = prometheus.NewHistogram(prometheus.HistogramOpts{
 	Name:    prefixedName("block_ingestion_time_seconds"),
-	Help:    "Time taken to fully ingest an EVM block in the local state index",
+	Help:    "Latency from EVM block proposal time to indexing completion (wall-clock duration)",
 	Buckets: []float64{.5, 1, 2.5, 5, 10, 15, 20, 30, 45},
 })
 
+// EVM block processing time during event ingestion, including transaction replay
+// and state validation
+var blockProcessTime = prometheus.NewSummary(prometheus.SummaryOpts{
+	Name: prefixedName("block_process_time_seconds"),
+	Help: "Processing time to fully index an EVM block in the local state index",
+})
+
 var requestRateLimitedCounters = prometheus.NewCounterVec(prometheus.CounterOpts{
 	Name: prefixedName("request_rate_limited"),
 	Help: "Total number of rate limits by JSON-RPC method",
@@ -105,6 +113,7 @@ var metrics = []prometheus.Collector{
 	availableSigningKeys,
 	gasEstimationIterations,
 	blockIngestionTime,
+	blockProcessTime,
 	requestRateLimitedCounters,
 	transactionsDroppedCounter,
 	rateLimitedTransactionsCounter,
@@ -123,6 +132,7 @@ type Collector interface {
 	AvailableSigningKeys(count int)
 	GasEstimationIterations(count int)
 	BlockIngestionTime(blockCreation time.Time)
+	BlockProcessTime(start time.Time)
 	RequestRateLimited(method string)
 	TransactionsDropped(count int)
 	TransactionRateLimited()
@@ -147,6 +157,7 @@ type DefaultCollector struct {
 	availableSigningkeys           prometheus.Gauge
 	gasEstimationIterations        prometheus.Gauge
 	blockIngestionTime             prometheus.Histogram
+	blockProcessTime               prometheus.Summary
 	requestRateLimitedCounters     *prometheus.CounterVec
 	transactionsDroppedCounter     prometheus.Counter
 	rateLimitedTransactionsCounter prometheus.Counter
@@ -173,6 +184,7 @@ func NewCollector(logger zerolog.Logger) Collector {
 		availableSigningkeys:           availableSigningKeys,
 		gasEstimationIterations:        gasEstimationIterations,
 		blockIngestionTime:             blockIngestionTime,
+		blockProcessTime:               blockProcessTime,
 		requestRateLimitedCounters:     requestRateLimitedCounters,
 		transactionsDroppedCounter:     transactionsDroppedCounter,
 		rateLimitedTransactionsCounter: rateLimitedTransactionsCounter,
@@ -243,6 +255,10 @@ func (c *DefaultCollector) BlockIngestionTime(blockCreation time.Time) {
 		Observe(time.Since(blockCreation).Seconds())
 }
 
+func (c *DefaultCollector) BlockProcessTime(start time.Time) {
+	c.blockProcessTime.Observe(time.Since(start).Seconds())
+}
+
 func (c *DefaultCollector) RequestRateLimited(method string) {
 	c.requestRateLimitedCounters.With(
 		prometheus.Labels{

metrics/nop.go

@@ -22,6 +22,7 @@ func (c *nopCollector) OperatorBalance(balance uint64)             {}
 func (c *nopCollector) AvailableSigningKeys(count int)             {}
 func (c *nopCollector) GasEstimationIterations(count int)          {}
 func (c *nopCollector) BlockIngestionTime(blockCreation time.Time) {}
+func (c *nopCollector) BlockProcessTime(start time.Time)           {}
 func (c *nopCollector) RequestRateLimited(method string)           {}
 func (c *nopCollector) TransactionsDropped(count int)              {}
 func (c *nopCollector) TransactionRateLimited()                    {}

services/ingestion/engine.go

@@ -184,11 +184,14 @@ func (e *Engine) processEvents(events *models.CadenceEvents) error {
 		Int("cadence-event-length", events.Length()).
 		Msg("received new cadence evm events")
 
+	start := time.Now()
 	err := e.withBatch(
 		func(batch *pebbleDB.Batch) error {
 			return e.indexEvents(events, batch)
 		},
 	)
+	e.collector.BlockProcessTime(start)
+
 	if err != nil {
 		return fmt.Errorf("failed to index events for cadence block %d: %w", events.CadenceHeight(), err)
 	}