cerc-io/lotus
16
0
Fork 0
Code Issues Pull Requests Packages Projects Releases 27 Wiki Activity

Merge pull request #10470 from filecoin-project/feat/applyblock-timing-log

Browse Source 
feat: consensus: log ApplyBlock timing/gas stats
This commit is contained in:
Łukasz Magiera 2023-03-14 15:25:31 +01:00 committed by GitHub
commit 162e07fc95
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 22 additions and 5 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

22
chain/consensus/compute_state.go
View File

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

5
metrics/metrics.go
View File

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