From 51c6b64c91e100d533dc50a92b18b23050dff3fa Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?=C5=81ukasz=20Magiera?= <magik6k@gmail.com>
Date: Tue, 14 Mar 2023 13:58:36 +0100
Subject: [PATCH] feat: consensus: log ApplyBlock timing/gas stats

---
 chain/consensus/compute_state.go | 22 +++++++++++++++++++---
 metrics/metrics.go               |  5 +++--
 2 files changed, 22 insertions(+), 5 deletions(-)

diff --git a/chain/consensus/compute_state.go b/chain/consensus/compute_state.go
index cfb2cdf31..e627a62d2 100644
--- a/chain/consensus/compute_state.go
+++ b/chain/consensus/compute_state.go
@@ -3,6 +3,7 @@ package consensus
 import (
 	"context"
 	"sync/atomic"
+	"time"
 
 	"github.com/ipfs/go-cid"
 	cbor "github.com/ipfs/go-ipld-cbor"
@@ -113,6 +114,8 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		return sm.VMConstructor()(ctx, vmopt)
 	}
 
+	var cronGas int64
+
 	runCron := func(vmCron vm.Interface, epoch abi.ChainEpoch) error {
 		cronMsg := &types.Message{
 			To:         cron.Address,
@@ -130,6 +133,8 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 			return xerrors.Errorf("running cron: %w", err)
 		}
 
+		cronGas += ret.GasUsed
+
 		if em != nil {
 			if err := em.MessageApplied(ctx, ts, cronMsg.Cid(), cronMsg, ret, true); err != nil {
 				return xerrors.Errorf("callback failed on cron message: %w", err)
@@ -181,7 +186,9 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		}
 	}
 
-	partDone()
+	vmEarly := partDone()
+	earlyCronGas := cronGas
+	cronGas = 0
 	partDone = metrics.Timer(ctx, metrics.VMApplyMessages)
 
 	vmi, err := makeVm(pstate, epoch, ts.MinTimestamp())
@@ -196,6 +203,8 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		processedMsgs = make(map[cid.Cid]struct{})
 	)
 
+	var msgGas int64
+
 	for _, b := range bms {
 		penalty := types.NewInt(0)
 		gasReward := big.Zero()
@@ -210,6 +219,8 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 				return cid.Undef, cid.Undef, err
 			}
 
+			msgGas += r.GasUsed
+
 			receipts = append(receipts, &r.MessageReceipt)
 			gasReward = big.Add(gasReward, r.GasCosts.MinerTip)
 			penalty = big.Add(penalty, r.GasCosts.MinerPenalty)
@@ -239,14 +250,14 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		}
 	}
 
-	partDone()
+	vmMsg := partDone()
 	partDone = metrics.Timer(ctx, metrics.VMApplyCron)
 
 	if err := runCron(vmi, epoch); err != nil {
 		return cid.Cid{}, cid.Cid{}, err
 	}
 
-	partDone()
+	vmCron := partDone()
 	partDone = metrics.Timer(ctx, metrics.VMApplyFlush)
 
 	rectarr := blockadt.MakeEmptyArray(sm.ChainStore().ActorStore(ctx))
@@ -282,6 +293,11 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		return cid.Undef, cid.Undef, xerrors.Errorf("vm flush failed: %w", err)
 	}
 
+	vmFlush := partDone()
+	partDone = func() time.Duration { return time.Duration(0) }
+
+	log.Infow("ApplyBlocks stats", "early", vmEarly, "earlyCronGas", earlyCronGas, "vmMsg", vmMsg, "msgGas", msgGas, "vmCron", vmCron, "cronGas", cronGas, "vmFlush", vmFlush, "epoch", epoch, "tsk", ts.Key())
+
 	stats.Record(ctx, metrics.VMSends.M(int64(atomic.LoadUint64(&vm.StatSends))),
 		metrics.VMApplied.M(int64(atomic.LoadUint64(&vm.StatApplied))))
 
diff --git a/metrics/metrics.go b/metrics/metrics.go
index 149195faf..ca638ac27 100644
--- a/metrics/metrics.go
+++ b/metrics/metrics.go
@@ -775,9 +775,10 @@ func SinceInMilliseconds(startTime time.Time) float64 {
 
 // Timer is a function stopwatch, calling it starts the timer,
 // calling the returned function will record the duration.
-func Timer(ctx context.Context, m *stats.Float64Measure) func() {
+func Timer(ctx context.Context, m *stats.Float64Measure) func() time.Duration {
 	start := time.Now()
-	return func() {
+	return func() time.Duration {
 		stats.Record(ctx, m.M(SinceInMilliseconds(start)))
+		return time.Since(start)
 	}
 }