Node profiling results

[pavitthrap]

In the branch profiling-work, I added logs and a python program to parse those logs in order to generate some stats for the stacks node. In this post, I will

• post the results of the python program for a run of the stacks-node (where it is running as a mock miner) as well as the raw data that was used to compute the answers to each overall question.
• include information on how data was logged / how the answer was computed.

You can see the branch here.

Answers

Q1: What is the average time (in ms) a synchronized miner takes to broadcast a block commitment?

5th percentile: 5115.8
50th percentile: 17727.5
95th percentile: 40806.34999999995
Num values: 114
Link to data: https://drive.google.com/file/d/1yc0Z1-9iB1gW0VBmEEyWHqJg3q1Ss7ae/view?usp=sharing

Q2: What is the average time (in ms) a synchronized miner takes to broadcast their first good block commitment?

5th percentile: 22443.45
50th percentile: 69520.0
95th percentile: 118487.84999999992
Num values: 102
Link to data: https://drive.google.com/file/d/1RBshQ9Bxlfyx10H-GsszU1unHCdbX4mD/view?usp=sharing

Q3: Determine distribution of transactions limited by each cost dimension.

runtime 81.20298724758028
read_count 18.79431668059637
write_count 0.002696071823353374
37091 out of 46548 transactions had singularly large cost dimension. 79.68333762997337 %.
Link to data: https://drive.google.com/file/d/1dOHG56BtGUyfymAahIHXoBlLAK9NcFa0/view?usp=sharing

Q4: stats on all blocks

Average number of events per block: 34.9283201407212
Total event map: defaultdict(<class 'int'>, {'contract_event:SP000000000000000000002Q6VF78.bns': 1602, 'contract_event:SPN4Y5QPGQA8882ZXW90ADC2DHYXMSTN8VAR8C3X.friedger-token-v1': 1321, 'ft_transfer_event': 4134, 'nft_mint_event': 12098, 'nft_transfer_event': 9584, 'stx_transfer_event': 36679, 'contract_event:SP466FNC0P7JWTNM2R9T199QRZN1MYEDTAR0KP27.miamicoin-token': 648, 'ft_mint_event': 2305, 'stx_burn_event': 1366, 'contract_event:SPJW1XE278YMCEYMXB8ZFGJMH8ZVAAEDP2S2PJYG.stacks-art-market': 4569, 'stx_lock_event': 760, 'contract_event:SP3QSAJQ4EA8WXEDSRRKMZZ29NH91VZ6C5X88FGZQ.thisisnumberone-v2': 763, 'contract_event:SP3FBR2AGK5H9QBDH3EEN6DF8EK8JY7RX8QJ5SVTE.send-many-memo': 2883, 'contract_event:SP3QSAJQ4EA8WXEDSRRKMZZ29NH91VZ6C5X88FGZQ.appmap-v1': 1, 'contract_event:SP1JSH2FPE8BWNTP228YZ1AZZ0HE0064PS6RXRAY4.fpwr-v04': 3, 'nft_burn_event': 2, 'contract_event:SP1Z92MPDQEWZXW36VX71Q25HKF5K2EPCJ304F275.liquidity-token-v4a': 13, 'contract_event:SP1Z92MPDQEWZXW36VX71Q25HKF5K2EPCJ304F275.stackswap-swap-v4c': 8, 'contract_event:SP3QSAJQ4EA8WXEDSRRKMZZ29NH91VZ6C5X88FGZQ.loopbomb-stx-001': 299, 'contract_event:SP3QSAJQ4EA8WXEDSRRKMZZ29NH91VZ6C5X88FGZQ.ruma-v1': 31, 'contract_event:SP2507VNQZC9VBXM7X7KB4SF4QJDJRSWHG4V39WPY.stxswap_v7': 20, 'contract_event:SP16DBHWYYHG94R4JFZVZMP5BZ3BPNKV8QNGXDTG2.power-ball': 4, 'contract_event:SPNWZ5V2TPWGQGVDR6T7B6RQ4XMGZ4PXTEE0VQ0S.marketplace-v1': 5, 'contract_event:SP2KAF9RF86PVX3NEE27DFV1CQX0T4WGR41X3S45C.byzantion-market-v1': 2, 'contract_event:SP2KAF9RF86PVX3NEE27DFV1CQX0T4WGR41X3S45C.byzantion-market-v2': 208, 'contract_event:SP3DX3H4FEYZJZ586MFBS25ZW3HZDMEW92260R2PR.Wrapped-Bitcoin': 1, 'contract_event:SPXVRSEH2BKSXAEJ00F1BY562P45D5ERPSKR4Q33.xverse-pool-v2': 75, 'contract_event:SP213KNHB5QD308TEESY1ZMX1BP8EZDPG4JWD0MEA.fari-token-mn': 33, 'contract_event:SP33DJWC4AN72WWEPCW0H8C9N5YEYTB2VD5MS19PE.wise-chocolate-piranha': 1, 'contract_event:SP37H4NY7YSVCSYEX01JEBC2CJQ1GS4SFN2GP70A9.claim-v0b': 8, 'ft_burn_event': 1})
Link to data: https://drive.google.com/file/d/1QDoBzA6ZHgxBB8ft1j6rujXvEP6vwFK2/view?usp=sharing

Q5a: stats on full blocks

Num of full blocks: 123
Num of total blocks: 455
Percent breakdown of which limit is hit: {'ReadCount': 14.346895074946467, 'Runtime': 85.65310492505354}
Link to data: https://drive.google.com/file/d/1L19nrFMODIXRnDYiSHY4ltK3j6uxR9G4/view?usp=sharing

Q5b: stats on full microblocks

Num of full microblocks: 0
Percent breakdown of which limit is hit: {}

Q6: Amount of time (in ms) it takes to process a block

5th percentile: 507.3
50th percentile: 1593.0
95th percentile: 5035.049999999996
Num values: 2274
Link to data: https://drive.google.com/file/d/1speFZg1MWUDM72JBkdD5LCRocLrKbCEe/view?usp=sharing

Q7: amount of time (in secs) to start a node/ sync to burnchain tip

Elapsed time (secs): 8865
Link to data: https://drive.google.com/file/d/1dT4_N8yo-AFqtbXE6jE2ZbwI0y0A0HIl/view?usp=sharing

Q8: amount of time (in ms) to mine a block

5th percentile: 1237.2
50th percentile: 3787.0
95th percentile: 6893.299999999981
Num values: 455
Correlation of mempool size to mining time:
m: 1.4501218972694103
b: 2072.70722761262
Link to data: https://drive.google.com/file/d/1jJ_0_WN75xEF3r2exKXIXOKZ_g7qoi7r/view?usp=sharing
Link to graph relating mempool size to mining time: https://drive.google.com/file/d/18C05uWctFLc9tK3Wm9s-GrVe6VphN1Je/view?usp=sharing

More information for each question

Q1: How long does it take an already-synchronized miner to broadcast their commitment to a new block?

Generation of data:

• Record newly inserted bitcoin header in write_block_headers in `src/burnchains/bitcoin/spv.rs”
• Record block commitment at the end of the RunTenure path in spawn_miner_relayer in testnet/stacks-node/src/neon_node.rs

Data analysis: https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L234

Q2: How long does it take an already-synchronized miner to broadcast their first good commitment to a new block (i.e., one that builds on the previous winner)?

Generation of data:

• Record newly inserted bitcoin header in write_block_headers in `src/burnchains/bitcoin/spv.rs”
• Record block commitment at the end of the RunTenure path in spawn_miner_relayer in testnet/stacks-node/src/neon_node.rs
• Determine whether commitment is a good commitment by checking if parent of the block being built has a burn height equal to the burn height of the burn chain tip. If the burn chain tip had no sortition (a flash block), we make the simplifying assumption that the newest block is being built off of the latest winner.

Data analysis: https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L234

Q3: What distribution of transactions are limited by runtime, read count, write count, etc.?

Generation of data:

• Data recorded in log_transactions_processed, which is called at the end of append_block in src/chainstate/stacks/db/blocks.rs

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L275

Q4: What are the relative frequencies of different event types? (this breaks down by contract)

Generation of data:

• Data recorded in log_transactions_processed, which is called at the end of append_block in src/chainstate/stacks/db/blocks.rs

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L322

Q5: (a) If an anchored block's cost limit is hit during mining, this logs which dimension it was.

Generation of data:

• In build_anchored_block in src/chainstate/stacks/miner.rs, in the clause for Error::BlockTooBigError

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L362

(b) Same analysis done for microblocks.
Generation of data:

• In build_anchored_block in src/chainstate/stacks/miner.rs, in the clause for Error::BlockTooBigError

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L402

Q6: How long does it take a follower to process an epoch? (logs time in append_block)

Generation of data:

• Data collected at the end of append_block in src/chainstate/stacks/db/blocks.rs.
• The start timestamp is recorded at the beginning of the same function.

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L427

Q7: No logging - how long does it take to start a non-sidecar follower from genesis?

Generation of data:

• Start timestamp collected in beginning of start in testnet/stacks-node/src/run_loop/neon.rs
• End timestamp collected in start in testnet/stacks-node/src/run_loop/neon.rs, after full burnchain is synchronized

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L449

Q8: How long does it take a miner to assemble a block? How does that change as the size of the mempool grows?

Generation of data:

• Data collected at end of build_anchored_block in src/chainstate/stacks/miner.rs. The start timestamp is recorded near the beginning of the same function

Data analysis:
https://github.com/blockstack/stacks-blockchain/blob/58c1fcd797246075062f07c56b58cd4269e600d1/parse_profile.py#L461