feat: more prometheus metrics for monitoring performance (#146) (#175)

mempool/clist_mempool.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"sync"
 	"sync/atomic"
+	"time"
 
 	abci "github.com/tendermint/tendermint/abci/types"
 	cfg "github.com/tendermint/tendermint/config"
@@ -305,7 +306,7 @@ func (mem *CListMempool) globalCb(req *abci.Request, res *abci.Response) {
 		return
 	}
 
-	mem.metrics.RecheckTimes.Add(1)
+	mem.metrics.RecheckCount.Add(1)
 	mem.resCbRecheck(req, res)
 
 	// update metrics
@@ -610,6 +611,7 @@ func (mem *CListMempool) Update(
 
 	// Either recheck non-committed txs to see if they became invalid
 	// or just notify there're some txs left.
+	recheckStartTime := time.Now().UnixNano()
 	if mem.Size() > 0 {
 		if mem.config.Recheck {
 			mem.logger.Debug("recheck txs", "numtxs", mem.Size(), "height", height)
@@ -621,6 +623,10 @@ func (mem *CListMempool) Update(
 			mem.notifyTxsAvailable()
 		}
 	}
+	recheckEndTime := time.Now().UnixNano()
+
+	recheckTimeMs := float64(recheckEndTime-recheckStartTime) / 1000000
+	mem.metrics.RecheckTime.Set(recheckTimeMs)
 
 	// Update metrics
 	mem.metrics.Size.Set(float64(mem.Size()))

mempool/metrics.go

@@ -23,7 +23,9 @@ type Metrics struct {
 	// Number of failed transactions.
 	FailedTxs metrics.Counter
 	// Number of times transactions are rechecked in the mempool.
-	RecheckTimes metrics.Counter
+	RecheckCount metrics.Counter
+	// Time of recheck transactions in the mempool.
+	RecheckTime metrics.Gauge
 }
 
 // PrometheusMetrics returns Metrics build using Prometheus client library.
@@ -54,12 +56,18 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 			Name:      "failed_txs",
 			Help:      "Number of failed transactions.",
 		}, labels).With(labelsAndValues...),
-		RecheckTimes: prometheus.NewCounterFrom(stdprometheus.CounterOpts{
+		RecheckCount: prometheus.NewCounterFrom(stdprometheus.CounterOpts{
 			Namespace: namespace,
 			Subsystem: MetricsSubsystem,
-			Name:      "recheck_times",
+			Name:      "recheck_count",
 			Help:      "Number of times transactions are rechecked in the mempool.",
 		}, labels).With(labelsAndValues...),
+		RecheckTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "recheck_time",
+			Help:      "Time of recheck transactions in the mempool in ms.",
+		}, labels).With(labelsAndValues...),
 	}
 }
 
@@ -69,6 +77,7 @@ func NopMetrics() *Metrics {
 		Size:         discard.NewGauge(),
 		TxSizeBytes:  discard.NewHistogram(),
 		FailedTxs:    discard.NewCounter(),
-		RecheckTimes: discard.NewCounter(),
+		RecheckCount: discard.NewCounter(),
+		RecheckTime:  discard.NewGauge(),
 	}
 }

state/execution.go

@@ -136,12 +136,16 @@ func (blockExec *BlockExecutor) ApplyBlock(
 		return state, 0, ErrInvalidBlock(err)
 	}
 
-	startTime := time.Now().UnixNano()
+	execStartTime := time.Now().UnixNano()
 	abciResponses, err := execBlockOnProxyApp(
 		blockExec.logger, blockExec.proxyApp, block, blockExec.store, state.InitialHeight,
 	)
-	endTime := time.Now().UnixNano()
-	blockExec.metrics.BlockProcessingTime.Observe(float64(endTime-startTime) / 1000000)
+	execEndTime := time.Now().UnixNano()
+
+	execTimeMs := float64(execEndTime-execStartTime) / 1000000
+	blockExec.metrics.BlockProcessingTime.Observe(execTimeMs)
+	blockExec.metrics.BlockExecutionTime.Set(execTimeMs)
+
 	if err != nil {
 		return state, 0, ErrProxyAppConn(err)
 	}
@@ -177,7 +181,13 @@ func (blockExec *BlockExecutor) ApplyBlock(
 	}
 
 	// Lock mempool, commit app state, update mempoool.
+	commitStartTime := time.Now().UnixNano()
 	appHash, retainHeight, err := blockExec.Commit(state, block, abciResponses.DeliverTxs)
+	commitEndTime := time.Now().UnixNano()
+
+	commitTimeMs := float64(commitEndTime-commitStartTime) / 1000000
+	blockExec.metrics.BlockCommitTime.Set(commitTimeMs)
+
 	if err != nil {
 		return state, 0, fmt.Errorf("commit failed for application: %v", err)
 	}
@@ -225,7 +235,13 @@ func (blockExec *BlockExecutor) Commit(
 	}
 
 	// Commit block, get hash back
+	appCommitStartTime := time.Now().UnixNano()
 	res, err := blockExec.proxyApp.CommitSync()
+	appCommitEndTime := time.Now().UnixNano()
+
+	appCommitTimeMs := float64(appCommitEndTime-appCommitStartTime) / 1000000
+	blockExec.metrics.BlockAppCommitTime.Set(appCommitTimeMs)
+
 	if err != nil {
 		blockExec.logger.Error("client error during proxyAppConn.CommitSync", "err", err)
 		return nil, 0, err
@@ -240,13 +256,18 @@ func (blockExec *BlockExecutor) Commit(
 	)
 
 	// Update mempool.
+	updateMempoolStartTime := time.Now().UnixNano()
 	err = blockExec.mempool.Update(
 		block.Height,
 		block.Txs,
 		deliverTxResponses,
 		TxPreCheck(state),
 		TxPostCheck(state),
 	)
+	updateMempoolEndTime := time.Now().UnixNano()
+
+	updateMempoolTimeMs := float64(updateMempoolEndTime-updateMempoolStartTime) / 1000000
+	blockExec.metrics.BlockUpdateMempoolTime.Set(updateMempoolTimeMs)
 
 	return res.Data, res.RetainHeight, err
 }

state/metrics.go

@@ -17,6 +17,14 @@ const (
 type Metrics struct {
 	// Time between BeginBlock and EndBlock.
 	BlockProcessingTime metrics.Histogram
+	// Time gauge between BeginBlock and EndBlock.
+	BlockExecutionTime metrics.Gauge
+	// Time of commit
+	BlockCommitTime metrics.Gauge
+	// Time of app commit
+	BlockAppCommitTime metrics.Gauge
+	// Time of update mempool
+	BlockUpdateMempoolTime metrics.Gauge
 }
 
 // PrometheusMetrics returns Metrics build using Prometheus client library.
@@ -35,12 +43,40 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 			Help:      "Time between BeginBlock and EndBlock in ms.",
 			Buckets:   stdprometheus.LinearBuckets(1, 10, 10),
 		}, labels).With(labelsAndValues...),
+		BlockExecutionTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "block_execution_time",
+			Help:      "Time between BeginBlock and EndBlock in ms.",
+		}, labels).With(labelsAndValues...),
+		BlockCommitTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "block_commit_time",
+			Help:      "Time of commit in ms.",
+		}, labels).With(labelsAndValues...),
+		BlockAppCommitTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "block_app_commit_time",
+			Help:      "Time of app commit in ms.",
+		}, labels).With(labelsAndValues...),
+		BlockUpdateMempoolTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "block_update_mempool_time",
+			Help:      "Time of update mempool in ms.",
+		}, labels).With(labelsAndValues...),
 	}
 }
 
 // NopMetrics returns no-op Metrics.
 func NopMetrics() *Metrics {
 	return &Metrics{
-		BlockProcessingTime: discard.NewHistogram(),
+		BlockProcessingTime:    discard.NewHistogram(),
+		BlockExecutionTime:     discard.NewGauge(),
+		BlockCommitTime:        discard.NewGauge(),
+		BlockAppCommitTime:     discard.NewGauge(),
+		BlockUpdateMempoolTime: discard.NewGauge(),
 	}
 }