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.

lotus cluster_L File: lotus File: lotus Build ID: 13166a2e60aa778ec2c3f826b0e3e379ed13927d Type: cpu Time: Dec 24, 2023 at 12:15pm (UTC) Duration: 602.99s, Total samples = 1364.79s (226.34%) Showing nodes accounting for 1158.69s, 84.90% of 1364.79s total Dropped 2326 nodes (cum <= 6.82s) See https://git.io/JfYMW for how to read the graph N1 badger (*DB) View 0.81s (0.059%) of 340.16s (24.92%) N46 badger (*Blockstore) View func1 0.05s (0.0037%) of 44.82s (3.28%) N1->N46 44.82s N56 badger (*Blockstore) Get func1 0.07s (0.0051%) of 41.52s (3.04%) N1->N56 41.52s N91 badger (*DB) newTransaction 1.19s (0.087%) of 17.24s (1.26%) N1->N91 17.22s N161 badger (*Txn) Discard 0.47s (0.034%) of 10.37s (0.76%) N1->N161 10.37s N169 splitstore (*BadgerMarkSet) tryDB func1 0.12s (0.0088%) of 202.17s (14.81%) N1->N169 202.17s N185 badger (*Blockstore) Has func1 0.03s (0.0022%) of 12.75s (0.93%) N1->N185 12.75s N205 badger (*Blockstore) PutMany func2 0 of 10.47s (0.77%) N1->N205 10.47s N2 runtime _ExternalCode 0.02s (0.0015%) of 454.48s (33.30%) N4 [lotus] 238.45s (17.47%) N2->N4 238.45s N10 <unknown> 173.80s (12.73%) N2->N10 173.80s N36 [libc.so.6] 31.99s (2.34%) N2->N36 31.99s N94 runtime rtsigprocmask 9.83s (0.72%) N2->N94 9.60s N3 async Err func1 0 of 199.25s (14.60%) N122 filcns (*FilecoinEC) ValidateBlock func2 0 of 7.57s (0.55%) N3->N122 7.57s N124 store (*ChainStore) MessagesForBlock 0 of 9.35s (0.69%) N3->N124 4.30s N183 consensus CommonBlkChecks func1 0 of 112s (8.21%) N3->N183 112s N208 consensus CommonBlkChecks func3 0 of 16.46s (1.21%) N3->N208 16.46s N209 filcns (*FilecoinEC) ValidateBlock func6 0 of 45.72s (3.35%) N3->N209 45.72s N5 badger (*Txn) Get 1.20s (0.088%) of 276.67s (20.27%) N11 badger (*DB) get 3.41s (0.25%) of 262.41s (19.23%) N5->N11 262.41s N15 runtime newobject 1.61s (0.12%) of 38.67s (2.83%) N5->N15 4.57s N66 runtime makeslicecopy 2.94s (0.22%) of 10.40s (0.76%) N5->N66 8s N6 splitstore (*SplitStore) walkObject 0.80s (0.059%) of 372.72s (27.31%) N12 splitstore (*BadgerMarkSet) Visit 2.50s (0.18%) of 268.58s (19.68%) N6->N12 268.58s N6->N15 1.41s N23 splitstore (*SplitStore) doWarmup func1 0.55s (0.04%) of 62.52s (4.58%) N6->N23 62.52s N63 splitstore (*SplitStore) view 0.11s (0.0081%) of 39.09s (2.86%) N6->N63 39.09s N7 runtime mallocgc 40.19s (2.94%) of 82.28s (6.03%) N34 runtime memclrNoHeapPointers 19.45s (1.43%) N7->N34 5.98s N108 runtime heapBitsSetType 4.53s (0.33%) of 12.30s (0.9%) N7->N108 12.30s N132 runtime deductAssistCredit 2.80s (0.21%) of 7.69s (0.56%) N7->N132 7.69s N163 runtime (*mcache) nextFree 0.38s (0.028%) of 11.71s (0.86%) N7->N163 11.71s N8 errgroup (*Group) Go func1 0 of 373.52s (27.37%) N207 splitstore (*SplitStore) walkChain func4 0 of 372.72s (27.31%) N8->N207 372.72s N9 badger (*levelHandler) get 4.95s (0.36%) of 163.33s (11.97%) N9->N15 1.51s N27 badger (*levelHandler) getTableForKey 10.34s (0.76%) of 30.42s (2.23%) N9->N27 30.42s N47 table (*Table) DoesNotHave 8.63s (0.63%) of 71.33s (5.23%) N9->N47 71.33s N93 table (*Iterator) next 0.60s (0.044%) of 10.11s (0.74%) N9->N93 4.85s N105 expvar (*Map) Add 3.63s (0.27%) of 20.79s (1.52%) N9->N105 20.79s N196 table (*Iterator) Seek 0 of 20.04s (1.47%) N9->N196 20.04s N61 badger (*levelsController) get 4.23s (0.31%) of 167.56s (12.28%) N11->N61 167.56s N90 badger (*DB) getMemTables 3.20s (0.23%) of 9.46s (0.69%) N11->N90 9.46s N141 skl (*Skiplist) Get 0.90s (0.066%) of 81.15s (5.95%) N11->N141 81.15s N45 splitstore (*BadgerMarkSet) write 0.26s (0.019%) of 28.01s (2.05%) N12->N45 28.01s N55 runtime mapassign_faststr 1.72s (0.13%) of 13.91s (1.02%) N12->N55 7.30s N83 runtime slicebytetostring 0.64s (0.047%) of 7.30s (0.53%) N12->N83 2.78s N165 splitstore (*BadgerMarkSet) tryDB 0.20s (0.015%) of 220.19s (16.13%) N12->N165 220.19s N13 runtime cgocall 111.83s (8.19%) of 116.13s (8.51%) N168 runtime cgocallback 0.03s (0.0022%) of 8.30s (0.61%) N13->N168 4.22s N14 runtime systemstack 0.17s (0.012%) of 72.99s (5.35%) N99 runtime wakep 0.36s (0.026%) of 19.29s (1.41%) N14->N99 5.72s N213 runtime gcBgMarkWorker func2 0 of 50.63s (3.71%) N14->N213 50.63s N15->N7 37.05s N16 runtime memmove 27.96s (2.05%) N17 z Bloom Has 62.69s (4.59%) of 62.70s (4.59%) N18 skl (*Skiplist) findNear 60.34s (4.42%) of 80.09s (5.87%) N20 y CompareKeys 8.51s (0.62%) of 42.38s (3.11%) N18->N20 19.75s N19 consensus checkBlockMessages 0.01s (0.00073%) of 111.97s (8.20%) N50 sigs Verify 0.01s (0.00073%) of 17.69s (1.30%) N19->N50 3.39s N72 consensus checkBlockMessages func1 0 of 25.27s (1.85%) N19->N72 25.27s N189 consensus VerifyBlsAggregate 0 of 81.36s (5.96%) N19->N189 81.36s N35 cmpbody 32.41s (2.37%) N20->N35 32.40s N21 runtime scanobject 12.78s (0.94%) of 46.20s (3.39%) N53 runtime greyobject 17.75s (1.30%) of 18.02s (1.32%) N21->N53 17.83s N74 runtime findObject 10.80s (0.79%) N21->N74 9.90s N22 badger (*DB) doWrites func1 0 of 89.09s (6.53%) N26 badger (*DB) writeRequests 0 of 89.09s (6.53%) N22->N26 89.09s N81 blockstore (*discardstore) Get 0.06s (0.0044%) of 42.42s (3.11%) N23->N81 36.88s N85 badger (*Blockstore) PutMany 0.06s (0.0044%) of 13.68s (1.00%) N23->N85 9.80s N147 badger (*Blockstore) Has 0.07s (0.0051%) of 15.83s (1.16%) N23->N147 14.34s N24 bytes (*Buffer) Write 3.65s (0.27%) of 25.64s (1.88%) N24->N16 4.05s N78 bytes (*Buffer) grow 0.56s (0.041%) of 21.98s (1.61%) N24->N78 17.94s N25 rle EncodeRuns 3.76s (0.28%) of 32.64s (2.39%) N76 rle (*addIt) NextRun 1.75s (0.13%) of 16.83s (1.23%) N25->N76 16.64s N117 rle (*andIter) NextRun 4.23s (0.31%) of 9.62s (0.7%) N25->N117 9.62s N92 badger (*valueLog) write 1.01s (0.074%) of 19.52s (1.43%) N26->N92 19.52s N129 badger (*DB) writeToLSM 1.44s (0.11%) of 68.18s (5.00%) N26->N129 68.18s N27->N15 6.68s N38 runtime makeslice 0.96s (0.07%) of 16.03s (1.17%) N27->N38 3.42s N39 sort Search 1.69s (0.12%) of 19.94s (1.46%) N27->N39 4.55s N89 sync (*RWMutex) RUnlock 7.29s (0.53%) N27->N89 5.36s N28 skl (*Skiplist) findSpliceForLevel 35.37s (2.59%) of 49.15s (3.60%) N28->N20 13.75s N29 badger (*Blockstore) View 0.12s (0.0088%) of 51.01s (3.74%) N29->N1 48.70s N30 skl (*Skiplist) Put 3.97s (0.29%) of 66.51s (4.87%) N30->N28 49.15s N116 skl newNode 0.15s (0.011%) of 13.08s (0.96%) N30->N116 13.08s N31 runtime futex 24.89s (1.82%) N32 go-ipld-cbor (*BasicIpldStore) Get 0.03s (0.0022%) of 34.68s (2.54%) N118 splitstore (*SplitStore) Get 0.09s (0.0066%) of 11.97s (0.88%) N32->N118 11.97s N136 go-ipld-cbor (*BasicIpldStore) decode 0.01s (0.00073%) of 22.68s (1.66%) N32->N136 22.68s N33 y (*WaterMark) process 1.45s (0.11%) of 30.37s (2.23%) N77 runtime selectgo 8.11s (0.59%) of 20.34s (1.49%) N33->N77 19.14s N123 y (*WaterMark) process func1 2.08s (0.15%) of 9.75s (0.71%) N33->N123 9.75s N37 runtime mcall 0.14s (0.01%) of 59.36s (4.35%) N174 runtime park_m 0.11s (0.0081%) of 59.04s (4.33%) N37->N174 59.04s N38->N7 15.04s N113 table (*Iterator) seekFrom func1 5.56s (0.41%) of 10.41s (0.76%) N39->N113 10.41s N40 badger (*levelsController) compactBuildTables 3.14s (0.23%) of 38.17s (2.80%) N59 table (*MergeIterator) Next 1.99s (0.15%) of 15.26s (1.12%) N40->N59 15.26s N60 table (*Builder) Add 0.46s (0.034%) of 21.72s (1.59%) N40->N60 14.18s N41 filecoin-ffi HashVerify 0 of 95.62s (7.01%) N201 cgo _Cfunc_hash_verify 0 of 95.60s (7.00%) N41->N201 95.60s N42 runtime findRunnable 2.22s (0.16%) of 42.34s (3.10%) N65 runtime stealWork 6.98s (0.51%) of 26.30s (1.93%) N42->N65 26.30s N159 runtime stopm 0.46s (0.034%) of 9.62s (0.7%) N42->N159 9.61s N43 runtime schedule 0.69s (0.051%) of 58.40s (4.28%) N43->N42 42.34s N155 runtime resetspinning 0.54s (0.04%) of 14.10s (1.03%) N43->N155 14.10s N44 runtime gcBgMarkWorker 0 of 50.72s (3.72%) N44->N14 50.67s N45->N15 2.18s N45->N66 2.19s N82 runtime stringtoslicebyte 0.29s (0.021%) of 8.33s (0.61%) N45->N82 5s N128 badger (*WriteBatch) SetEntry 0.98s (0.072%) of 14.78s (1.08%) N45->N128 13.77s N46->N5 21.28s N84 badger (*Item) Value 0.10s (0.0073%) of 23.29s (1.71%) N46->N84 23.29s N47->N17 62.70s N48 runtime growslice 1.09s (0.08%) of 11.10s (0.81%) N48->N7 8.43s N49 miner AllPartSectors 0 of 42.98s (3.15%) N167 go-bitfield MultiMerge 0 of 18.15s (1.33%) N49->N167 18.15s N176 miner (*state12) ForEachDeadline 0 of 24.83s (1.82%) N49->N176 24.83s N212 bls blsSigner Verify 0 of 14.28s (1.05%) N50->N212 14.28s N51 badger (*levelsController) runCompactor 0 of 37.80s (2.77%) N195 badger (*levelsController) doCompact 0 of 39s (2.86%) N51->N195 37.68s N52 cbor-gen ScanForLinks 1.75s (0.13%) of 18.34s (1.34%) N52->N48 1.43s N73 cbor-gen CborReadHeaderBuf 6.26s (0.46%) of 13.32s (0.98%) N52->N73 10.19s N52->N83 1.45s N54 table (*Table) block 3.31s (0.24%) of 10.94s (0.8%) N54->N15 1.53s N54->N38 2.23s N140 syscall RawSyscall6 0.01s (0.00073%) of 10.48s (0.77%) N54->N140 2.13s N55->N7 1.58s N178 runtime growWork_faststr 0.07s (0.0051%) of 9.50s (0.7%) N55->N178 9.50s N56->N5 30.13s N115 badger (*Item) ValueCopy 0.22s (0.016%) of 11.29s (0.83%) N56->N115 11.29s N57 aeshashbody 9.61s (0.7%) N58 badger (*Blockstore) Get 0.20s (0.015%) of 48.46s (3.55%) N58->N1 46.18s N59->N20 1.62s N114 table (*node) next 0.61s (0.045%) of 12.23s (0.9%) N59->N114 12.23s N80 table (*Builder) addHelper 2.24s (0.16%) of 18.13s (1.33%) N60->N80 18.13s N61->N9 163.33s N62 runtime gcDrain 3.56s (0.26%) of 50.63s (3.71%) N62->N21 42.15s N63->N29 8.20s N131 blockstore (*discardstore) View 0.04s (0.0029%) of 32.04s (2.35%) N63->N131 30.24s N64 bytes growSlice 0.18s (0.013%) of 20.74s (1.52%) N64->N16 3.88s N64->N34 12.05s N64->N48 4.59s N152 runtime runqsteal 0.63s (0.046%) of 17.92s (1.31%) N65->N152 17.92s N66->N7 4.19s N66->N16 3.07s N67 splitstore (*SplitStore) View 0.03s (0.0022%) of 13.29s (0.97%) N67->N29 11s N67->N131 1.80s N68 syscall Syscall6 11.55s (0.85%) N69 go-hamt-ipld (*Node) Find 0.02s (0.0015%) of 27.98s (2.05%) N164 go-hamt-ipld (*Node) getValue 0.11s (0.0081%) of 27.80s (2.04%) N69->N164 27.80s N70 go-hamt-ipld (*Pointer) UnmarshalCBOR 0.28s (0.021%) of 18.17s (1.33%) N70->N38 2.13s N125 go-hamt-ipld (*KV) UnmarshalCBOR 0.22s (0.016%) of 11.24s (0.82%) N70->N125 11.24s N71 runtime usleep 13.74s (1.01%) N87 state (*StateTree) GetActor 0.04s (0.0029%) of 16.21s (1.19%) N72->N87 11.76s N157 state (*StateTree) LookupID 0 of 13.72s (1.01%) N72->N157 13.17s N75 cbor-gen (*Deferred) UnmarshalCBOR 0.62s (0.045%) of 9.41s (0.69%) N75->N73 1.51s N75->N78 3.72s N96 rle (*addIt) prep 5.30s (0.39%) of 16.78s (1.23%) N76->N96 16.73s N78->N64 20.74s N79 table (*Builder) Finish 5.17s (0.38%) of 10.85s (0.79%) N79->N24 4.68s N80->N24 10.16s N80->N48 1.47s N181 blockstore (*idstore) Get 0.04s (0.0029%) of 42.36s (3.10%) N81->N181 42.36s N82->N7 2.99s N82->N16 4.09s N83->N7 5.59s N166 splitstore (*SplitStore) walkObject func1 0.02s (0.0015%) of 17.88s (1.31%) N84->N166 17.88s N85->N1 10.49s N86 rle (*addIt) prep func1 7.56s (0.55%) of 16.53s (1.21%) N86->N76 16.11s N186 adt (*Map) Get 0.01s (0.00073%) of 15.75s (1.15%) N87->N186 15.75s N88 go-bitfield SubtractBitField 0.01s (0.00073%) of 19.79s (1.45%) N88->N25 15.73s N90->N15 2.51s N90->N38 2.01s N90->N89 1.71s N91->N15 4.74s N103 badger (*oracle) readTs 5.55s (0.41%) of 11.30s (0.83%) N91->N103 11.30s N107 badger (*logFile) encodeEntry 0.91s (0.067%) of 14.18s (1.04%) N92->N107 14.18s N120 syscall Syscall 0 of 8.25s (0.6%) N92->N120 4.22s N93->N54 6.69s N95 badger (*Txn) modify 0.66s (0.048%) of 13.32s (0.98%) N95->N55 6.22s N95->N83 1.44s N96->N86 16.53s N97 table (*Iterator) seekFrom 0.04s (0.0029%) of 20.04s (1.47%) N97->N39 10.92s N135 table (*Iterator) seekHelper 0.06s (0.0044%) of 9.06s (0.66%) N97->N135 9.06s N98 badger buildL0Table 0.88s (0.064%) of 17.29s (1.27%) N98->N60 7.54s N98->N79 1.96s N162 runtime startm 0.33s (0.024%) of 17.89s (1.31%) N99->N162 17.87s N100 miner (*Partition) ActiveSectors 0.01s (0.00073%) of 19.80s (1.45%) N100->N88 12.24s N204 miner (*Partition) LiveSectors 0 of 7.55s (0.55%) N100->N204 7.55s N101 badger Open func5 0 of 18.90s (1.38%) N194 badger (*DB) flushMemtable 0 of 18.90s (1.38%) N101->N194 18.90s N102 runtime mapaccess2 4.99s (0.37%) of 14.35s (1.05%) N102->N57 2.46s N106 runtime chansend1 0.24s (0.018%) of 15.25s (1.12%) N103->N106 5.16s N104 go-hamt-ipld loadNode 0.40s (0.029%) of 29.68s (2.17%) N104->N32 29s N109 sync (*Map) Load 3.15s (0.23%) of 17.46s (1.28%) N105->N109 17.16s N111 runtime chansend 1.84s (0.13%) of 15.21s (1.11%) N106->N111 15.01s N107->N15 2.55s N107->N24 7.92s N109->N102 14.31s N110 consensus (*TipSetExecutor) ApplyBlocks 0.02s (0.0015%) of 16.20s (1.19%) N211 vm (*vmExecutor) Flush 0 of 12.61s (0.92%) N110->N211 12.61s N171 runtime send 0.06s (0.0044%) of 7.40s (0.54%) N111->N171 7.34s N112 runtime runqgrab 3.55s (0.26%) of 17.29s (1.27%) N112->N71 13.74s N113->N20 4.57s N114->N59 8.64s N114->N93 5.26s N115->N16 4.77s N115->N48 1.41s N116->N7 2.64s N130 skl (*Arena) putVal 5.47s (0.4%) of 7.05s (0.52%) N116->N130 7.05s N118->N58 6.10s N118->N81 5.53s N119 runtime evacuate_faststr 2.96s (0.22%) of 9.43s (0.69%) N119->N57 5.41s N120->N140 8.18s N121 go-hamt-ipld (*Node) UnmarshalCBOR 0.12s (0.0088%) of 20.90s (1.53%) N121->N15 1.95s N121->N70 18.17s N122->N87 1.63s N139 filcns VerifyVRF 0 of 8.54s (0.63%) N122->N139 4.29s N123->N7 1.91s N193 store (*ChainStore) LoadMessagesFromCids 0.01s (0.00073%) of 7.91s (0.58%) N124->N193 7.89s N125->N75 8.48s N126 badger (*levelsController) compactBuildTables func2 0 of 11.79s (0.86%) N142 badger (*levelsController) compactBuildTables func2 1 0 of 11.79s (0.86%) N126->N142 11.79s N127 runtime cgocallbackg1 0 of 7.96s (0.58%) N127->N67 3.55s N127->N85 3.55s N179 badger (*WriteBatch) handleEntry 0.06s (0.0044%) of 13.37s (0.98%) N128->N179 13.37s N129->N30 66.51s N177 blockstore (*idstore) View 0.06s (0.0044%) of 32s (2.34%) N131->N177 32s N132->N14 4.40s N133 miner (*deadline12) ForEachPartition 0 of 23.15s (1.70%) N133->N32 1.86s N184 adt (*Array) ForEach 0.03s (0.0022%) of 21.18s (1.55%) N133->N184 21.18s N134 filcns (*FilecoinEC) VerifyWinningPoStProof 0 of 45.72s (3.35%) N134->N13 1.57s N145 stmgr GetSectorsForWinningPoSt 0.01s (0.00073%) of 44.12s (3.23%) N134->N145 44.12s N135->N39 4.47s N135->N54 4.25s N136->N121 20.90s N137 runtime sweepone 1.82s (0.13%) of 6.84s (0.5%) N137->N14 1.85s N138 miner (*Deadlines) ForEach 0 of 24.75s (1.81%) N188 miner (*state12) ForEachDeadline func1 0 of 23.18s (1.70%) N138->N188 23.18s N139->N50 8.54s N140->N68 10.47s N141->N18 80.09s N142->N79 8.89s N143 init (*State) ResolveAddress 0.01s (0.00073%) of 12.67s (0.93%) N146 adt (*Map) Get 0.01s (0.00073%) of 12.27s (0.9%) N143->N146 11.08s N144 runtime bgsweep 0.04s (0.0029%) of 6.91s (0.51%) N144->N137 6.84s N145->N49 42.98s N146->N69 12.26s N147->N1 14.86s N148 badger (*levelsController) runCompactDef 0 of 39s (2.86%) N148->N40 38.17s N149 state (*StateTree) lookupIDinternal 0 of 13.66s (1.00%) N190 init (*state12) ResolveAddress 0.01s (0.00073%) of 12.70s (0.93%) N149->N190 12.70s N150 badger (*DB) handleFlushTask 0 of 18.90s (1.38%) N150->N98 17.29s N151 runtime (*mcentral) cacheSpan 0.73s (0.053%) of 7.82s (0.57%) N151->N14 5.28s N152->N112 17.29s N153 adt (*Array) ForEach func1 0.01s (0.00073%) of 20.59s (1.51%) N180 miner (*deadline12) ForEachPartition func1 0.01s (0.00073%) of 19.88s (1.46%) N153->N180 19.88s N154 consensus (*TipSetExecutor) ExecuteTipSet 0 of 16.85s (1.23%) N154->N110 16.20s N155->N99 13.56s N156 go-amt-ipld (*node) forEachAt 0.01s (0.00073%) of 21.15s (1.55%) N156->N153 20.59s N157->N149 13.66s N158 runtime (*mcache) refill 0.43s (0.032%) of 10.72s (0.79%) N158->N151 7.82s N160 runtime notesleep 0.54s (0.04%) of 8.29s (0.61%) N159->N160 8.29s N170 runtime futexsleep 0.20s (0.015%) of 7.75s (0.57%) N160->N170 7.75s N161->N106 9.90s N172 runtime notewakeup 0.09s (0.0066%) of 17.50s (1.28%) N162->N172 17.45s N163->N158 10.72s N203 go-hamt-ipld (*Pointer) loadChild 0 of 27.42s (2.01%) N164->N203 27.42s N165->N1 219.89s N166->N52 17.56s N202 go-bitfield NewFromIter 0 of 16.91s (1.24%) N167->N202 16.91s N192 runtime cgocallbackg 0.01s (0.00073%) of 7.99s (0.59%) N168->N192 7.99s N169->N5 202.05s N170->N31 7.55s N171->N14 6.52s N173 runtime futexwakeup 0.10s (0.0073%) of 17.44s (1.28%) N172->N173 17.41s N173->N31 17.34s N174->N43 58.27s N175 store (*ChainStore) GetMessage 0.03s (0.0022%) of 7.90s (0.58%) N175->N67 7.76s N176->N138 24.75s N177->N29 31.81s N178->N119 9.43s N179->N95 13.31s N187 miner AllPartSectors func1 1 0.02s (0.0015%) of 19.82s (1.45%) N180->N187 19.82s N181->N58 42.28s N182 stmgr (*StateManager) TipSetState 0 of 16.91s (1.24%) N182->N154 16.85s N183->N19 111.97s N184->N156 21.15s N185->N5 12.72s N186->N69 15.72s N187->N100 19.80s N191 miner AllPartSectors func1 0 of 23.16s (1.70%) N188->N191 23.16s N189->N41 81.34s N190->N143 12.67s N191->N133 23.15s N192->N127 7.96s N193->N175 7.90s N194->N150 18.90s N195->N148 39s N196->N97 20.04s N197 filecoin-ffi (*FVM) Flush 0 of 12.61s (0.92%) N198 cgo FvmMachineFlush 0 of 12.61s (0.92%) N197->N198 12.61s N199 cgo FvmMachineFlush func1 0 of 12.61s (0.92%) N198->N199 12.61s N200 cgo _Cfunc_fvm_machine_flush 0 of 12.61s (0.92%) N199->N200 12.61s N200->N13 12.61s N201->N13 95.60s N202->N25 16.91s N203->N104 27.42s N204->N88 7.55s N205->N5 10.46s N206 splitstore (*SplitStore) walkChain func3 0 of 372.72s (27.31%) N206->N6 372.72s N207->N206 372.72s N208->N182 16.46s N209->N134 45.72s N210 vm (*FVM) Flush 0 of 12.61s (0.92%) N210->N197 12.61s N211->N210 12.61s N212->N41 14.28s N213->N62 50.63s

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.

lotus cluster_L File: lotus 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 Showing top 80 nodes out of 84 See https://git.io/JfYMW for how to read the graph N1 async Err func1 0 of 500ms (98.04%) N45 consensus CommonBlkChecks func3 0 of 500ms (98.04%) N1->N45 500ms N2 vm (*vmExecutor) ApplyMessage 0 of 510ms (100%) N3 vm (*FVM) ApplyMessage 10ms (1.96%) of 400ms (78.43%) N2->N3 400ms N50 vm (*executionEnv) getToken 0 of 50ms (9.80%) N2->N50 50ms N52 vm (*executionToken) Done 0 of 60ms (11.76%) N2->N52 60ms N13 types (*Message) Serialize 0 of 70ms (13.73%) N3->N13 30ms N14 filecoin-ffi (*FVM) ApplyMessage 0 of 310ms (60.78%) N3->N14 310ms N30 runtime nanotime 10ms (1.96%) N3->N30 10ms N49 types (*Message) ChainLength 0 of 40ms (7.84%) N3->N49 40ms N4 runtime mallocgc 80ms (15.69%) of 120ms (23.53%) N28 runtime heapBitsSetType 10ms (1.96%) N4->N28 10ms N61 runtime (*mcache) nextFree 0 of 30ms (5.88%) N4->N61 30ms N5 runtime cgocall 260ms (50.98%) of 280ms (54.90%) N69 runtime exitsyscall 0 of 20ms (3.92%) N5->N69 20ms N6 vm metricsAdjust 0 of 110ms (21.57%) N11 runtime newobject 0 of 50ms (9.80%) N6->N11 10ms N15 tag New 0 of 60ms (11.76%) N6->N15 60ms N16 stats Record 10ms (1.96%) of 40ms (7.84%) N6->N16 40ms N7 runtime systemstack 0 of 50ms (9.80%) N65 runtime (*mheap) alloc func1 0 of 20ms (3.92%) N7->N65 20ms N70 runtime exitsyscallfast func1 0 of 10ms (1.96%) N7->N70 10ms N74 runtime goready func1 0 of 20ms (3.92%) N7->N74 20ms N8 bytes (*Buffer) Write 20ms (3.92%) of 60ms (11.76%) N33 bytes (*Buffer) grow 0 of 40ms (7.84%) N8->N33 40ms N9 cgo FvmMachineExecuteMessage 0 of 300ms (58.82%) N27 runtime duffcopy 10ms (1.96%) N9->N27 10ms N37 cgo (*_Ctype_struct_Result_FvmMachineExecuteResponse) destroy 0 of 10ms (1.96%) N9->N37 10ms N39 cgo FvmMachineExecuteMessage func1 0 of 280ms (54.90%) N9->N39 280ms N10 types (*Message) MarshalCBOR 0 of 70ms (13.73%) N10->N8 40ms N41 big (*Int) MarshalCBOR 0 of 20ms (3.92%) N10->N41 20ms N77 runtime makeslice 0 of 10ms (1.96%) N10->N77 10ms N11->N4 50ms N12 stmgr (*StateManager) TipSetState 0 of 510ms (100%) N44 consensus (*TipSetExecutor) ExecuteTipSet 0 of 510ms (100%) N12->N44 510ms N13->N10 70ms N14->N9 300ms N35 filecoin-ffi buildResponse 0 of 10ms (1.96%) N14->N35 10ms N59 tag (*mutator) Mutate 0 of 40ms (7.84%) N15->N59 40ms N76 runtime makemap_small 0 of 20ms (3.92%) N15->N76 20ms N58 view recordMeasurement 0 of 30ms (5.88%) N16->N58 30ms N17 runtime futex 20ms (3.92%) N18 runtime (*mcache) refill 10ms (1.96%) of 30ms (5.88%) N62 runtime (*mcentral) cacheSpan 0 of 20ms (3.92%) N18->N62 20ms N19 runtime mapassign_faststr 10ms (1.96%) of 30ms (5.88%) N19->N4 20ms N20 tag Upsert func1 0 of 40ms (7.84%) N20->N19 30ms N60 tag createMetadatas 0 of 10ms (1.96%) N20->N60 10ms N21 runtime exitsyscallfast 10ms (1.96%) of 20ms (3.92%) N21->N7 10ms N22 runtime chansend 0 of 30ms (5.88%) N29 runtime memmove 10ms (1.96%) N22->N29 10ms N80 runtime send 0 of 20ms (3.92%) N22->N80 20ms N23 runtime (*fixalloc) alloc 10ms (1.96%) N24 runtime (*mheap) allocSpan 0 of 20ms (3.92%) N66 runtime (*mheap) allocMSpanLocked 0 of 10ms (1.96%) N24->N66 10ms N67 runtime (*mheap) initSpan 0 of 10ms (1.96%) N24->N67 10ms N25 runtime (*mspan) init 10ms (1.96%) N26 runtime cgoCheckPointer 10ms (1.96%) N31 runtime pidleget 10ms (1.96%) N32 go-libp2p-pubsub (*validation) validate func1 0 of 10ms (1.96%) N53 go-libp2p-pubsub (*validation) doValidateTopic 0 of 10ms (1.96%) N32->N53 10ms N34 bytes growSlice 0 of 40ms (7.84%) N33->N34 40ms N75 runtime growslice 0 of 40ms (7.84%) N34->N75 40ms N36 filecoin-ffi reformBigInt 0 of 10ms (1.96%) N35->N36 10ms N42 big NewInt 0 of 10ms (1.96%) N36->N42 10ms N38 cgo (*_Ctype_struct_Result_FvmMachineExecuteResponse) destroy func1 0 of 10ms (1.96%) N37->N38 10ms N38->N26 10ms N40 cgo _Cfunc_fvm_machine_execute_message 0 of 280ms (54.90%) N39->N40 280ms N40->N5 280ms N57 cbor-gen (*CborWriter) Write 0 of 20ms (3.92%) N41->N57 20ms N42->N11 10ms N43 consensus (*TipSetExecutor) ApplyBlocks 0 of 510ms (100%) N43->N2 510ms N44->N43 510ms N45->N12 500ms N46 messagepool (*MessagePool) Add 0 of 10ms (1.96%) N47 messagepool (*mpoolProvider) GetActorAfter 0 of 10ms (1.96%) N46->N47 10ms N47->N12 10ms N48 sub (*MessageValidator) Validate 0 of 10ms (1.96%) N48->N46 10ms N49->N13 40ms N50->N6 50ms N51 vm (*executionEnv) putToken 0 of 60ms (11.76%) N51->N6 60ms N52->N51 60ms N55 go-libp2p-pubsub (*validation) validateTopic 0 of 10ms (1.96%) N53->N55 10ms N54 go-libp2p-pubsub (*validation) validateSingleTopic 0 of 10ms (1.96%) N56 go-libp2p-pubsub (*validatorImpl) validateMsg 0 of 10ms (1.96%) N54->N56 10ms N55->N54 10ms N56->N48 10ms N57->N8 20ms N68 runtime chansend1 0 of 30ms (5.88%) N58->N68 30ms N59->N20 40ms N60->N11 10ms N61->N18 30ms N63 runtime (*mcentral) grow 0 of 20ms (3.92%) N62->N63 20ms N64 runtime (*mheap) alloc 0 of 20ms (3.92%) N63->N64 20ms N64->N7 20ms N65->N24 20ms N66->N23 10ms N67->N25 10ms N68->N22 30ms N69->N21 20ms N71 runtime exitsyscallfast_pidle 0 of 10ms (1.96%) N70->N71 10ms N71->N31 10ms N72 runtime futexwakeup 0 of 20ms (3.92%) N72->N17 20ms N73 runtime goready 0 of 20ms (3.92%) N73->N7 20ms N79 runtime ready 0 of 20ms (3.92%) N74->N79 20ms N75->N4 40ms N76->N11 20ms N77->N4 10ms N78 runtime notewakeup 0 of 20ms (3.92%) N78->N72 20ms N79->N78 20ms N80->N73 20ms