Quote from: NotATether on May 06, 2021, 09:10:06 AM

Alright, this is going to open another can of worms because I'm not sure how execution cap handles multiple cores. But on the plus side it looks like all your benchmark has to do is run bitcoin core with -reindex and then measure the time it takes to finish from debug.log and also using stuff like top to keep track of resource usage. But automatic profiling with systat where the metrics are stored in other log files is better IMO.

I don't think those cpu percentage limits are going to be useful for much-- I doubt they result in a repeatable measurement.

A better way to do a benchmark to get a tx/s figure is to use invalidateblock to roll back the chain 1000 blocks or so, then restart the process to flush the signature caches and reconsiderblock and collect data from that.

If you enable the bench debugging option you'll get data like this:

Quote

2021-05-01T19:10:02.540246Z received block 0000000000000000000922bf7fce4f900d7696f0c1c7221f97d3f367fdd9c44d peer=0
2021-05-01T19:10:02.553389Z - Load block from disk: 0.00ms [0.00s]
2021-05-01T19:10:02.553414Z - Sanity checks: 0.00ms [0.00s (0.00ms/blk)]
2021-05-01T19:10:02.553449Z - Fork checks: 0.04ms [0.00s (0.04ms/blk)]
2021-05-01T19:10:03.255699Z - Connect 2532 transactions: 702.21ms (0.277ms/tx, 0.116ms/txin) [0.70s (702.21ms/blk)]
2021-05-01T19:10:03.255837Z - Verify 6043 txins: 702.38ms (0.116ms/txin) [0.70s (702.38ms/blk)]
2021-05-01T19:10:03.265095Z - Index writing: 9.26ms [0.01s (9.26ms/blk)]
2021-05-01T19:10:03.265110Z - Callbacks: 0.02ms [0.00s (0.02ms/blk)]
2021-05-01T19:10:03.265490Z - Connect total: 712.10ms [0.71s (712.10ms/blk)]
2021-05-01T19:10:03.270861Z - Flush: 5.37ms [0.01s (5.37ms/blk)]
2021-05-01T19:10:03.270885Z - Writing chainstate: 0.03ms [0.00s (0.03ms/blk)]
2021-05-01T19:10:03.278491Z UpdateTip: new best=0000000000000000000922bf7fce4f900d7696f0c1c7221f97d3f367fdd9c44d height=681059 version=0x20800000 log2_work=92.840892 tx=637825747 date='2021-04-29T05:56:20Z' progress=0.998789 cache=2.3MiB(17699txo)
2021-05-01T19:10:03.278523Z - Connect postprocess: 7.64ms [0.01s (7.64ms/blk)]
2021-05-01T19:10:03.278540Z - Connect block: 725.14ms [0.73s (725.14ms/blk)]

Unfortunately any kind of reindex or cold cache benchmark only tells you about the performance while catching up.

During normal operation there is normally no validation of transactions at all when a block is accepted, or only a couple-- they've already been validated when they were previously relayed on the network.

This is obvious when you look at the performance of blocks after a node has been running for a while:

Quote

2021-05-09T14:11:43.013649Z received: cmpctblock (10734 bytes) peer=14002
2021-05-09T14:11:43.017889Z Initialized PartiallyDownloadedBlock for block 0000000000000000000ccd134daad627f62fbb52258fbc400220cbcd7cd38639 using a cmpctblock of size 10734
2021-05-09T14:11:43.018046Z received: blocktxn (33 bytes) peer=14002
2021-05-09T14:11:43.023885Z Successfully reconstructed block 0000000000000000000ccd134daad627f62fbb52258fbc400220cbcd7cd38639 with 1 txn prefilled, 1715 txn from mempool (incl at least 0 from extra pool) and 0 txn requested
2021-05-09T14:11:43.028245Z PeerManager::NewPoWValidBlock sending header-and-ids 0000000000000000000ccd134daad627f62fbb52258fbc400220cbcd7cd38639 to peer=4
2021-05-09T14:11:43.029259Z sending cmpctblock (10734 bytes) peer=4
[...]
2021-05-09T14:11:43.032630Z sending cmpctblock (10734 bytes) peer=31588
2021-05-09T14:11:43.044382Z - Load block from disk: 0.00ms [7.36s]
2021-05-09T14:11:43.044427Z - Sanity checks: 0.01ms [1.48s (0.80ms/blk)]
2021-05-09T14:11:43.044492Z - Fork checks: 0.07ms [0.10s (0.05ms/blk)]
2021-05-09T14:11:43.068471Z - Connect 1716 transactions: 23.96ms (0.014ms/tx, 0.004ms/txin) [157.68s (84.87ms/blk)]
2021-05-09T14:11:43.068508Z - Verify 6370 txins: 24.01ms (0.004ms/txin) [159.77s (85.99ms/blk)]
2021-05-09T14:11:43.081081Z - Index writing: 12.57ms [18.65s (10.04ms/blk)]
2021-05-09T14:11:43.081107Z - Callbacks: 0.03ms [0.05s (0.02ms/blk)]
2021-05-09T14:11:43.081346Z - Connect total: 36.97ms [177.38s (95.47ms/blk)]
2021-05-09T14:11:43.092634Z - Flush: 11.29ms [15.98s (8.60ms/blk)]
2021-05-09T14:11:43.092672Z - Writing chainstate: 0.04ms [0.09s (0.05ms/blk)]
2021-05-09T14:11:43.117336Z UpdateTip: new best=0000000000000000000ccd134daad627f62fbb52258fbc400220cbcd7cd38639 height=682762 version=0x20000004 log2_work=92.865917 tx=640740048 date='2021-05-09T14:11:34Z' progress=1.000000 cache=196.6MiB(1235174txo)
2021-05-09T14:11:43.117376Z - Connect postprocess: 24.71ms [42.18s (22.70ms/blk)]
2021-05-09T14:11:43.117393Z - Connect block: 73.01ms [242.98s (130.77ms/blk)]

So in that number you see that it spent 24.01ms verifying 6370, compared to the earlier cold cache example that spent 702.38ms verifying fewer (6043) txins.

Depending on what you're considering, that faster on-tip performance doesn't matter because a miner could fill their block we new, never before seen txn even ones constructed to be expensive to verify-- it's not the worst case. The worst case can only really be characterized by making special test blocks that intentionally trigger the most expensive costs.