From 2b37f368a1487f11504284e2805d373bf000b40d Mon Sep 17 00:00:00 2001
From: "Steve H. Jung" <iproudhon@gmail.com>
Date: Sat, 15 May 2021 05:56:00 +0900
Subject: [PATCH 1/2] added extra timing info regarding block generation

---
 state/execution.go | 38 +++++++++++++++++++++++++++++++-------
 1 file changed, 31 insertions(+), 7 deletions(-)

diff --git a/state/execution.go b/state/execution.go
index 44d498040..0139f1d0d 100644
--- a/state/execution.go
+++ b/state/execution.go
@@ -234,6 +234,20 @@ func (blockExec *BlockExecutor) ApplyBlock(
 
 	fail.Fail() // XXX
 
+	blockGenerationTimeMs := float64(time.Now().UnixNano()-execStartTime) / 1000000
+	numTxs := len(block.Txs)
+	tps := 0
+	if blockGenerationTimeMs > 0 {
+		tps = int(float64(numTxs) / blockGenerationTimeMs * 1000)
+	}
+	blockExec.logger.Info(
+		"block generated",
+		"height", block.Height,
+		"num_txs", numTxs,
+		"generation_time", blockGenerationTimeMs,
+		"tps", tps,
+	)
+
 	// Events are fired after everything else.
 	// NOTE: if we crash between Commit and Save, events wont be fired during replay
 	fireEvents(blockExec.logger, blockExec.eventBus, block, abciResponses, validatorUpdates)
@@ -270,12 +284,6 @@ func (blockExec *BlockExecutor) Commit(
 	}
 
 	// ResponseCommit has no error code - just data
-	blockExec.logger.Info(
-		"committed state",
-		"height", block.Height,
-		"num_txs", len(block.Txs),
-		"app_hash", fmt.Sprintf("%X", res.Data),
-	)
 
 	if stepTimes != nil {
 		stepTimes.ToCommitRechecking()
@@ -293,6 +301,15 @@ func (blockExec *BlockExecutor) Commit(
 	updateMempoolTimeMs := float64(updateMempoolEndTime-updateMempoolStartTime) / 1000000
 	blockExec.metrics.BlockUpdateMempoolTime.Set(updateMempoolTimeMs)
 
+	blockExec.logger.Info(
+		"committed state",
+		"height", block.Height,
+		"num_txs", len(block.Txs),
+		"app_hash", fmt.Sprintf("%X", res.Data),
+		"commit_time", appCommitTimeMs,
+		"update_mempool_time", updateMempoolTimeMs,
+	)
+
 	return res.Data, res.RetainHeight, err
 }
 
@@ -335,6 +352,7 @@ func execBlockOnProxyApp(
 	}
 	proxyAppConn.SetGlobalCallback(proxyCb)
 
+	execBlockStartTime := time.Now().UnixNano()
 	commitInfo := getBeginBlockValidatorInfo(block, store, initialHeight)
 
 	byzVals := make([]abci.Evidence, 0)
@@ -375,7 +393,13 @@ func execBlockOnProxyApp(
 		return nil, err
 	}
 
-	logger.Info("executed block", "height", block.Height, "num_valid_txs", validTxs, "num_invalid_txs", invalidTxs)
+	execBlockEndTime := time.Now().UnixNano()
+	execBlockTimeMs := float64(execBlockEndTime-execBlockStartTime) / 1000000
+	tps := 0
+	if execBlockTimeMs > 0 {
+		tps = int(float64(validTxs+invalidTxs) / execBlockTimeMs * 1000)
+	}
+	logger.Info("executed block", "height", block.Height, "num_valid_txs", validTxs, "num_invalid_txs", invalidTxs, "execution_time", execBlockTimeMs, "tps", tps)
 	return abciResponses, nil
 }
 

From 78d994cd7ddbb57cc2d987cda2ea584e02d7f0d4 Mon Sep 17 00:00:00 2001
From: "Steve H. Jung" <iproudhon@gmail.com>
Date: Fri, 4 Jun 2021 11:01:22 +0900
Subject: [PATCH 2/2] reformat to keep lint happy

---
 state/execution.go | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/state/execution.go b/state/execution.go
index 0139f1d0d..ecb6bcfe5 100644
--- a/state/execution.go
+++ b/state/execution.go
@@ -399,7 +399,13 @@ func execBlockOnProxyApp(
 	if execBlockTimeMs > 0 {
 		tps = int(float64(validTxs+invalidTxs) / execBlockTimeMs * 1000)
 	}
-	logger.Info("executed block", "height", block.Height, "num_valid_txs", validTxs, "num_invalid_txs", invalidTxs, "execution_time", execBlockTimeMs, "tps", tps)
+	logger.Info(
+		"executed block",
+		"height", block.Height,
+		"num_valid_txs", validTxs,
+		"num_invalid_txs", invalidTxs,
+		"execution_time", execBlockTimeMs,
+		"tps", tps)
 	return abciResponses, nil
 }