diff --git a/chain/consensus/compute_state.go b/chain/consensus/compute_state.go index 10aea006efc..bb52b4b3671 100644 --- a/chain/consensus/compute_state.go +++ b/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), diff --git a/metrics/metrics.go b/metrics/metrics.go index 6dabc610546..b05f033583d 100644 --- a/metrics/metrics.go +++ b/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,