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.