From 8efb6566c1d92ba3d81859b4092ac779b69d4844 Mon Sep 17 00:00:00 2001
From: "Kim, JinSan" <jinsan@linecorp.com>
Date: Tue, 27 Oct 2020 21:06:12 +0900
Subject: [PATCH] feat: metric for block exec, commit and tx recheck

---
 mempool/clist_mempool.go |  7 +++++++
 mempool/metrics.go       | 17 +++++++++++++----
 state/execution.go       | 16 +++++++++++++---
 state/metrics.go         | 18 ++++++++++++++++++
 4 files changed, 51 insertions(+), 7 deletions(-)

diff --git a/mempool/clist_mempool.go b/mempool/clist_mempool.go
index 7732032a4..28337e2a3 100644
--- a/mempool/clist_mempool.go
+++ b/mempool/clist_mempool.go
@@ -573,7 +573,14 @@ func (mem *CListMempool) Update(
 	if mem.Size() > 0 {
 		if mem.config.Recheck {
 			mem.logger.Info("Recheck txs", "numtxs", mem.Size(), "height", height)
+
+			recheckStartTime := time.Now().UnixNano()
 			mem.recheckTxs()
+			recheckEndTime := time.Now().UnixNano()
+
+			recheckTimeMs := float64(recheckEndTime-recheckStartTime) / 1000000
+			mem.metrics.RecheckingTime.Set(recheckTimeMs)
+
 			// At this point, mem.txs are being rechecked.
 			// mem.recheckCursor re-scans mem.txs and possibly removes some txs.
 			// Before mem.Reap(), we should wait for mem.recheckCursor to be nil.
diff --git a/mempool/metrics.go b/mempool/metrics.go
index 5e4eaf5ed..d5e09927c 100644
--- a/mempool/metrics.go
+++ b/mempool/metrics.go
@@ -24,6 +24,8 @@ type Metrics struct {
 	FailedTxs metrics.Counter
 	// Number of times transactions are rechecked in the mempool.
 	RecheckTimes metrics.Counter
+	// Time of Rechecking
+	RecheckingTime metrics.Gauge
 }
 
 // PrometheusMetrics returns Metrics build using Prometheus client library.
@@ -60,15 +62,22 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 			Name:      "recheck_times",
 			Help:      "Number of times transactions are rechecked in the mempool.",
 		}, labels).With(labelsAndValues...),
+		RecheckingTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
+			Namespace: namespace,
+			Subsystem: MetricsSubsystem,
+			Name:      "rechecking_time",
+			Help:      "Time of Rechecking in ms.",
+		}, labels).With(labelsAndValues...),
 	}
 }
 
 // NopMetrics returns no-op Metrics.
 func NopMetrics() *Metrics {
 	return &Metrics{
-		Size:         discard.NewGauge(),
-		TxSizeBytes:  discard.NewHistogram(),
-		FailedTxs:    discard.NewCounter(),
-		RecheckTimes: discard.NewCounter(),
+		Size:           discard.NewGauge(),
+		TxSizeBytes:    discard.NewHistogram(),
+		FailedTxs:      discard.NewCounter(),
+		RecheckTimes:   discard.NewCounter(),
+		RecheckingTime: discard.NewGauge(),
 	}
 }
diff --git a/state/execution.go b/state/execution.go
index cd45484ce..abbfae064 100644
--- a/state/execution.go
+++ b/state/execution.go
@@ -131,10 +131,14 @@ 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.db)
-	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)
 	}
@@ -167,7 +171,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)
 	}
diff --git a/state/metrics.go b/state/metrics.go
index bcd713f5f..65e43d94e 100644
--- a/state/metrics.go
+++ b/state/metrics.go
@@ -17,6 +17,10 @@ const (
 type Metrics struct {
 	// Time between BeginBlock and EndBlock.
 	BlockProcessingTime metrics.Histogram
+	// Time between BeginBlock and EndBlock.
+	BlockExecutionTime metrics.Gauge
+	// Time of Commit
+	BlockCommitTime metrics.Gauge
 }
 
 // PrometheusMetrics returns Metrics build using Prometheus client library.
@@ -35,6 +39,18 @@ 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...),
 	}
 }
 
@@ -42,5 +58,7 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 func NopMetrics() *Metrics {
 	return &Metrics{
 		BlockProcessingTime: discard.NewHistogram(),
+		BlockExecutionTime:  discard.NewGauge(),
+		BlockCommitTime:     discard.NewGauge(),
 	}
 }