feat: consensus: log ApplyBlock timing/gas stats

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))))
 

chain/stmgr/execute.go

@@ -53,6 +53,16 @@ func (sm *StateManager) TipSetState(ctx context.Context, ts *types.TipSet) (st c
 
 	sm.stlk.Unlock()
 
+	if ts.Height() == 0 {
+		// NB: This is here because the process that executes blocks requires that the
+		// block miner reference a valid miner in the state tree. Unless we create some
+		// magical genesis miner, this won't work properly, so we short circuit here
+		// This avoids the question of 'who gets paid the genesis block reward'.
+		// This also makes us not attempt to lookup the tipset state with
+		// tryLookupTipsetState, which would cause a very long, very slow walk.
+		return ts.Blocks()[0].ParentStateRoot, ts.Blocks()[0].ParentMessageReceipts, nil
+	}
+
 	// First, try to find the tipset in the current chain. If found, we can avoid re-executing
 	// it.
 	if st, rec, found := tryLookupTipsetState(ctx, sm.cs, ts); found {

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)
 	}
 }