feat(metrics): capture total gas metric from ApplyBlocks (#13037)

Author: rvagg

chain/consensus/compute_state.go

@@ -194,7 +194,7 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		}
 	}
 
-	vmEarly := partDone()
+	vmEarlyDuration := partDone()
 	earlyCronGas := cronGas
 	cronGas = 0
 	partDone = metrics.Timer(ctx, metrics.VMApplyMessages)
@@ -258,14 +258,14 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		}
 	}
 
-	vmMsg := partDone()
+	vmMsgDuration := partDone()
 	partDone = metrics.Timer(ctx, metrics.VMApplyCron)
 
 	if err := runCron(vmi, epoch); err != nil {
 		return cid.Cid{}, cid.Cid{}, err
 	}
 
-	vmCron := partDone()
+	vmCronDuration := partDone()
 	partDone = metrics.Timer(ctx, metrics.VMApplyFlush)
 
 	rectarr := blockadt.MakeEmptyArray(sm.ChainStore().ActorStore(ctx))
@@ -301,14 +301,28 @@ func (t *TipSetExecutor) ApplyBlocks(ctx context.Context,
 		return cid.Undef, cid.Undef, xerrors.Errorf("vm flush failed: %w", err)
 	}
 
-	vmFlush := partDone()
+	vmFlushDuration := 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())
+	log.Infow(
+		"ApplyBlocks stats",
+		"earlyMs", vmEarlyDuration.Milliseconds(),
+		"earlyCronGas", earlyCronGas,
+		"vmMsgMs", vmMsgDuration.Milliseconds(),
+		"msgGas", msgGas,
+		"vmCronMs", vmCronDuration.Milliseconds(),
+		"cronGas", cronGas,
+		"vmFlushMs", vmFlushDuration.Milliseconds(),
+		"totalMs", (vmEarlyDuration + vmMsgDuration + vmCronDuration + vmFlushDuration).Milliseconds(),
+		"totalGas", earlyCronGas+msgGas+cronGas,
+		"epoch", epoch,
+		"tsk", ts.Key(),
+	)
 
 	stats.Record(ctx,
 		metrics.VMSends.M(int64(atomic.LoadUint64(&vm.StatSends))),
 		metrics.VMApplied.M(int64(atomic.LoadUint64(&vm.StatApplied))),
+		metrics.VMApplyBlocksTotalGas.M(earlyCronGas+msgGas+cronGas),
 		metrics.VMApplyEarlyGas.M(earlyCronGas),
 		metrics.VMApplyMessagesGas.M(msgGas),
 		metrics.VMApplyCronGas.M(cronGas),

metrics/metrics.go

@@ -123,6 +123,7 @@ var (
 	VMApplyEarly                        = stats.Float64("vm/applyblocks_early", "Time spent in early apply-blocks (null cron, upgrades)", stats.UnitMilliseconds)
 	VMApplyCron                         = stats.Float64("vm/applyblocks_cron", "Time spent in cron", stats.UnitMilliseconds)
 	VMApplyFlush                        = stats.Float64("vm/applyblocks_flush", "Time spent flushing vm state", stats.UnitMilliseconds)
+	VMApplyBlocksTotalGas               = stats.Int64("vm/applyblocks_total_gas", "Total gas of messages and cron", stats.UnitDimensionless)
 	VMApplyMessagesGas                  = stats.Int64("vm/applyblocks_messages_gas", "Total gas of block messages", stats.UnitDimensionless)
 	VMApplyEarlyGas                     = stats.Int64("vm/applyblocks_early_gas", "Total gas of early apply-blocks (null cron, upgrades)", stats.UnitDimensionless)
 	VMApplyCronGas                      = stats.Int64("vm/applyblocks_cron_gas", "Total gas of cron", stats.UnitDimensionless)
@@ -411,6 +412,11 @@ var (
 		Aggregation: defaultMillisecondsDistribution,
 		TagKeys:     []tag.Key{Network},
 	}
+	VMApplyBlocksTotalGasView = &view.View{
+		Measure:     VMApplyBlocksTotalGas,
+		Aggregation: view.LastValue(),
+		TagKeys:     []tag.Key{Network},
+	}
 	VMApplyEarlyGasView = &view.View{
 		Measure:     VMApplyEarlyGas,
 		Aggregation: view.LastValue(),
@@ -815,6 +821,7 @@ var ChainNodeViews = append([]*view.View{
 	VMApplyEarlyView,
 	VMApplyCronView,
 	VMApplyFlushView,
+	VMApplyBlocksTotalGasView,
 	VMApplyEarlyGasView,
 	VMApplyMessagesGasView,
 	VMApplyCronGasView,