Lotus Profiling Report - Message Execution
This data was collected by preparing a new Lotus node by downloading a mainnet snapshot, then running Lotus with the pprof flag. The output was analyzed after the node ran for 10 minutes while syncing mainnet.
Overall Profiling Snapshot of Lotus Main Loop
This SVG visualizes a profiling snapshot of the entire execution loop of the Lotus function, with a focus on the top 500 nodes for more manageable visualization.
Apply Message Function Profiling
This section contains the profiling data of the ApplyMessage function, depicted in the form of a list from the profiling output.
(pprof) Total: 1364.79s
ROUTINE ======================== github.com/filecoin-project/filecoin-ffi.(*FVM).ApplyMessage in /mnt/lotus/extern/filecoin-ffi/fvm.go
0 310ms (flat, cum) 0.023% of Total
. . 119: // NOTE: we need to call KeepAlive here (and below) because go doesn't guarantee that the
. . 120: // receiver will live to the end of the function. If we don't do this, go _will_ garbage
. . 121: // collect the FVM, causing us to run the finalizer while we're in the middle of using the
. . 122: // FVM.
. . 123: defer runtime.KeepAlive(f)
. 300ms 124: resp, err := cgo.FvmMachineExecuteMessage(
. . 125: f.executor,
. . 126: cgo.AsSliceRefUint8(msgBytes),
. . 127: uint64(chainLen),
. . 128: applyExplicit,
. . 129: )
. . 130: if err != nil {
. . 131: return nil, err
. . 132: }
. . 133:
. 10ms 134: return buildResponse(resp)
. . 135:}
. . 136:
. . 137:func (f *FVM) ApplyImplicitMessage(msgBytes []byte) (*ApplyRet, error) {
. . 138: defer runtime.KeepAlive(f)
. . 139: resp, err := cgo.FvmMachineExecuteMessage(
ROUTINE ======================== github.com/filecoin-project/lotus/chain/vm.(*FVM).ApplyMessage in /mnt/lotus/chain/vm/fvm.go
10ms 400ms (flat, cum) 0.029% of Total
. . 414:
. . 415:func (vm *FVM) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet, error) {
. . 416: start := build.Clock.Now()
. . 417: defer atomic.AddUint64(&StatApplied, 1)
. . 418: vmMsg := cmsg.VMMessage()
. 30ms 419: msgBytes, err := vmMsg.Serialize()
. . 420: if err != nil {
. . 421: return nil, xerrors.Errorf("serializing msg: %w", err)
. . 422: }
. . 423:
. 350ms 424: ret, err := vm.fvm.ApplyMessage(msgBytes, uint(cmsg.ChainLength()))
. . 425: if err != nil {
. . 426: return nil, xerrors.Errorf("applying msg: %w", err)
. . 427: }
. . 428:
. 10ms 429: duration := time.Since(start)
. . 430:
. . 431: var receipt types.MessageReceipt
. . 432: if vm.nv >= network.Version18 {
. . 433: receipt = types.NewMessageReceiptV1(exitcode.ExitCode(ret.ExitCode), ret.Return, ret.GasUsed, ret.EventsRoot)
. . 434: } else {
. . 435: receipt = types.NewMessageReceiptV0(exitcode.ExitCode(ret.ExitCode), ret.Return, ret.GasUsed)
. . 436: }
. . 437:
. . 438: var aerr aerrors.ActorError
. . 439: if ret.ExitCode != 0 {
. . 440: amsg := ret.FailureInfo
. . 441: if amsg == "" {
. . 442: amsg = "unknown error"
. . 443: }
. . 444: aerr = aerrors.New(exitcode.ExitCode(ret.ExitCode), amsg)
. . 445: }
. . 446:
. . 447: var et types.ExecutionTrace
. . 448: if len(ret.ExecTraceBytes) != 0 {
. . 449: if err = et.UnmarshalCBOR(bytes.NewReader(ret.ExecTraceBytes)); err != nil {
. . 450: return nil, xerrors.Errorf("failed to unmarshal exectrace: %w", err)
. . 451: }
. . 452: }
. . 453:
. . 454: applyRet := &ApplyRet{
. . 455: MessageReceipt: receipt,
. . 456: GasCosts: &GasOutputs{
. . 457: BaseFeeBurn: ret.BaseFeeBurn,
. . 458: OverEstimationBurn: ret.OverEstimationBurn,
. . 459: MinerPenalty: ret.MinerPenalty,
. . 460: MinerTip: ret.MinerTip,
. . 461: Refund: ret.Refund,
. . 462: GasRefund: ret.GasRefund,
. . 463: GasBurned: ret.GasBurned,
. . 464: },
. . 465: ActorErr: aerr,
. . 466: ExecutionTrace: et,
. . 467: Duration: duration,
. . 468: }
. . 469:
. . 470: if vm.returnEvents && len(ret.EventsBytes) > 0 {
. . 471: applyRet.Events, err = decodeEvents(ret.EventsBytes)
. . 472: if err != nil {
. . 473: return nil, fmt.Errorf("failed to decode events returned by the FVM: %w", err)
. . 474: }
. . 475: }
. . 476:
10ms 10ms 477: return applyRet, nil
. . 478:}
. . 479:
. . 480:func (vm *FVM) ApplyImplicitMessage(ctx context.Context, cmsg *types.Message) (*ApplyRet, error) {
. . 481: start := build.Clock.Now()
. . 482: defer atomic.AddUint64(&StatApplied, 1)
ROUTINE ======================== github.com/filecoin-project/lotus/chain/vm.(*vmExecutor).ApplyMessage in /mnt/lotus/chain/vm/execution.go
0 510ms (flat, cum) 0.037% of Total
. . 39:func newVMExecutor(vmi Interface, lane ExecutionLane) Interface {
. . 40: return &vmExecutor{vmi: vmi, lane: lane}
. . 41:}
. . 42:
. . 43:func (e *vmExecutor) ApplyMessage(ctx context.Context, cmsg types.ChainMsg) (*ApplyRet, error) {
. 50ms 44: token := execution.getToken(e.lane)
. . 45: defer token.Done()
. . 46:
. 460ms 47: return e.vmi.ApplyMessage(ctx, cmsg)
. . 48:}
. . 49:
. . 50:func (e *vmExecutor) ApplyImplicitMessage(ctx context.Context, msg *types.Message) (*ApplyRet, error) {
. . 51: token := execution.getToken(e.lane)
. . 52: defer token.Done()
(pprof)
This section provides the top relative percentages of the ApplyMessage function from the profiling output.
File: lotus
Build ID: 13166a2e60aa778ec2c3f826b0e3e379ed13927d
Type: cpu
Time: Dec 24, 2023 at 12:15pm (UTC)
Duration: 602.99s, Total samples = 510ms (0.085%)
Active filters:
focus=ApplyMessage
Showing nodes accounting for 510ms, 100% of 510ms total
flat flat% sum% cum cum%
260ms 50.98% 50.98% 280ms 54.90% runtime.cgocall
80ms 15.69% 66.67% 120ms 23.53% runtime.mallocgc
20ms 3.92% 70.59% 60ms 11.76% bytes.(*Buffer).Write
20ms 3.92% 74.51% 20ms 3.92% runtime.futex
10ms 1.96% 76.47% 400ms 78.43% github.com/filecoin-project/lotus/chain/vm.(*FVM).ApplyMessage
10ms 1.96% 78.43% 40ms 7.84% go.opencensus.io/stats.Record
10ms 1.96% 80.39% 10ms 1.96% runtime.(*fixalloc).alloc
10ms 1.96% 82.35% 30ms 5.88% runtime.(*mcache).refill
10ms 1.96% 84.31% 10ms 1.96% runtime.(*mspan).init
10ms 1.96% 86.27% 10ms 1.96% runtime.cgoCheckPointer
10ms 1.96% 88.24% 10ms 1.96% runtime.duffcopy
10ms 1.96% 90.20% 20ms 3.92% runtime.exitsyscallfast
10ms 1.96% 92.16% 10ms 1.96% runtime.heapBitsSetType
10ms 1.96% 94.12% 30ms 5.88% runtime.mapassign_faststr
10ms 1.96% 96.08% 10ms 1.96% runtime.memmove
10ms 1.96% 98.04% 10ms 1.96% runtime.nanotime
10ms 1.96% 100% 10ms 1.96% runtime.pidleget
0 0% 100% 40ms 7.84% bytes.(*Buffer).grow
0 0% 100% 40ms 7.84% bytes.growSlice
0 0% 100% 310ms 60.78% github.com/filecoin-project/filecoin-ffi.(*FVM).ApplyMessage
0 0% 100% 10ms 1.96% github.com/filecoin-project/filecoin-ffi.buildResponse
0 0% 100% 10ms 1.96% github.com/filecoin-project/filecoin-ffi.reformBigInt
0 0% 100% 10ms 1.96% github.com/filecoin-project/filecoin-ffi/cgo.(*_Ctype_struct_Result_FvmMachineExecuteResponse).destroy
0 0% 100% 10ms 1.96% github.com/filecoin-project/filecoin-ffi/cgo.(*_Ctype_struct_Result_FvmMachineExecuteResponse).destroy.func1
0 0% 100% 300ms 58.82% github.com/filecoin-project/filecoin-ffi/cgo.FvmMachineExecuteMessage
0 0% 100% 280ms 54.90% github.com/filecoin-project/filecoin-ffi/cgo.FvmMachineExecuteMessage.func1
0 0% 100% 280ms 54.90% github.com/filecoin-project/filecoin-ffi/cgo._Cfunc_fvm_machine_execute_message
0 0% 100% 20ms 3.92% github.com/filecoin-project/go-state-types/big.(*Int).MarshalCBOR
0 0% 100% 10ms 1.96% github.com/filecoin-project/go-state-types/big.NewInt
0 0% 100% 510ms 100% github.com/filecoin-project/lotus/chain/consensus.(*TipSetExecutor).ApplyBlocks
0 0% 100% 510ms 100% github.com/filecoin-project/lotus/chain/consensus.(*TipSetExecutor).ExecuteTipSet
0 0% 100% 500ms 98.04% github.com/filecoin-project/lotus/chain/consensus.CommonBlkChecks.func3
0 0% 100% 10ms 1.96% github.com/filecoin-project/lotus/chain/messagepool.(*MessagePool).Add
0 0% 100% 10ms 1.96% github.com/filecoin-project/lotus/chain/messagepool.(*mpoolProvider).GetActorAfter
0 0% 100% 510ms 100% github.com/filecoin-project/lotus/chain/stmgr.(*StateManager).TipSetState
0 0% 100% 10ms 1.96% github.com/filecoin-project/lotus/chain/sub.(*MessageValidator).Validate
0 0% 100% 40ms 7.84% github.com/filecoin-project/lotus/chain/types.(*Message).ChainLength
0 0% 100% 70ms 13.73% github.com/filecoin-project/lotus/chain/types.(*Message).MarshalCBOR
0 0% 100% 70ms 13.73% github.com/filecoin-project/lotus/chain/types.(*Message).Serialize
0 0% 100% 50ms 9.80% github.com/filecoin-project/lotus/chain/vm.(*executionEnv).getToken
0 0% 100% 60ms 11.76% github.com/filecoin-project/lotus/chain/vm.(*executionEnv).putToken
0 0% 100% 60ms 11.76% github.com/filecoin-project/lotus/chain/vm.(*executionToken).Done
0 0% 100% 510ms 100% github.com/filecoin-project/lotus/chain/vm.(*vmExecutor).ApplyMessage
0 0% 100% 110ms 21.57% github.com/filecoin-project/lotus/chain/vm.metricsAdjust
0 0% 100% 500ms 98.04% github.com/filecoin-project/lotus/lib/async.Err.func1
0 0% 100% 10ms 1.96% github.com/libp2p/go-libp2p-pubsub.(*validation).doValidateTopic
0 0% 100% 10ms 1.96% github.com/libp2p/go-libp2p-pubsub.(*validation).validate.func1
0 0% 100% 10ms 1.96% github.com/libp2p/go-libp2p-pubsub.(*validation).validateSingleTopic
0 0% 100% 10ms 1.96% github.com/libp2p/go-libp2p-pubsub.(*validation).validateTopic
0 0% 100% 10ms 1.96% github.com/libp2p/go-libp2p-pubsub.(*validatorImpl).validateMsg
0 0% 100% 20ms 3.92% github.com/whyrusleeping/cbor-gen.(*CborWriter).Write
0 0% 100% 30ms 5.88% go.opencensus.io/stats/view.recordMeasurement
0 0% 100% 40ms 7.84% go.opencensus.io/tag.(*mutator).Mutate
0 0% 100% 60ms 11.76% go.opencensus.io/tag.New
0 0% 100% 40ms 7.84% go.opencensus.io/tag.Upsert.func1
0 0% 100% 10ms 1.96% go.opencensus.io/tag.createMetadatas
0 0% 100% 30ms 5.88% runtime.(*mcache).nextFree
0 0% 100% 20ms 3.92% runtime.(*mcentral).cacheSpan
0 0% 100% 20ms 3.92% runtime.(*mcentral).grow
0 0% 100% 20ms 3.92% runtime.(*mheap).alloc
0 0% 100% 20ms 3.92% runtime.(*mheap).alloc.func1
0 0% 100% 10ms 1.96% runtime.(*mheap).allocMSpanLocked
0 0% 100% 20ms 3.92% runtime.(*mheap).allocSpan
0 0% 100% 10ms 1.96% runtime.(*mheap).initSpan
0 0% 100% 30ms 5.88% runtime.chansend
0 0% 100% 30ms 5.88% runtime.chansend1
0 0% 100% 20ms 3.92% runtime.exitsyscall
0 0% 100% 10ms 1.96% runtime.exitsyscallfast.func1
0 0% 100% 10ms 1.96% runtime.exitsyscallfast_pidle
0 0% 100% 20ms 3.92% runtime.futexwakeup
0 0% 100% 20ms 3.92% runtime.goready
0 0% 100% 20ms 3.92% runtime.goready.func1
0 0% 100% 40ms 7.84% runtime.growslice
0 0% 100% 20ms 3.92% runtime.makemap_small
0 0% 100% 10ms 1.96% runtime.makeslice
0 0% 100% 50ms 9.80% runtime.newobject
0 0% 100% 20ms 3.92% runtime.notewakeup
0 0% 100% 20ms 3.92% runtime.ready
0 0% 100% 20ms 3.92% runtime.send
0 0% 100% 20ms 3.92% runtime.startm
0 0% 100% 50ms 9.80% runtime.systemstack
0 0% 100% 10ms 1.96% runtime.typedmemmove
0 0% 100% 20ms 3.92% runtime.wakep
0 0% 100% 10ms 1.96% time.Since
This SVG provides a graphical representation of the profiling data for the ApplyMessage function.