mirrors/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-02-22 06:52:36 +01:00
Code Issues Projects Releases Wiki Activity

refactor: De-globalize validation benchmark timekeeping

Browse source 
In future, users of the kernel library might run multiple chainstates in
parallel, or create and destroy multiple chainstates over the lifetime
of a process. Having static, mutable variables could lead to state
inconsistencies in these scenarios.
This commit is contained in:
TheCharlatan 2024-06-19 11:36:31 +02:00
parent 1f9d30744d
commit 3443943f86
No known key found for this signature in database
GPG key ID: 9B79B45691DB4173
2 changed files with 50 additions and 49 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

84
src/validation.cpp
View file

@ -2399,15 +2399,6 @@ static unsigned int GetBlockScriptFlags(const CBlockIndex& block_index, const Ch
} }
static SteadyClock::duration time_check{};
static SteadyClock::duration time_forks{};
static SteadyClock::duration time_connect{};
static SteadyClock::duration time_verify{};
static SteadyClock::duration time_undo{};
static SteadyClock::duration time_index{};
static SteadyClock::duration time_total{};
static int64_t num_blocks_total = 0;
/** Apply the effects of this block (with given index) on the UTXO set represented by coins. /** Apply the effects of this block (with given index) on the UTXO set represented by coins.
* Validity checks that depend on the UTXO set are also done; ConnectBlock() * Validity checks that depend on the UTXO set are also done; ConnectBlock()
* can fail if those validity checks fail (among other reasons). */ * can fail if those validity checks fail (among other reasons). */
@ -2452,7 +2443,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
uint256 hashPrevBlock = pindex->pprev == nullptr ? uint256() : pindex->pprev->GetBlockHash(); uint256 hashPrevBlock = pindex->pprev == nullptr ? uint256() : pindex->pprev->GetBlockHash();
assert(hashPrevBlock == view.GetBestBlock()); assert(hashPrevBlock == view.GetBestBlock());
num_blocks_total++; m_chainman.num_blocks_total++;
// Special case for the genesis block, skipping connection of its transactions // Special case for the genesis block, skipping connection of its transactions
// (its coinbase is unspendable) // (its coinbase is unspendable)
@ -2494,11 +2485,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
} }
const auto time_1{SteadyClock::now()}; const auto time_1{SteadyClock::now()};
time_check += time_1 - time_start; m_chainman.time_check += time_1 - time_start;
LogPrint(BCLog::BENCH, " - Sanity checks: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Sanity checks: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_1 - time_start), Ticks<MillisecondsDouble>(time_1 - time_start),
Ticks<SecondsDouble>(time_check), Ticks<SecondsDouble>(m_chainman.time_check),
Ticks<MillisecondsDouble>(time_check) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_check) / m_chainman.num_blocks_total);
// Do not allow blocks that contain transactions which 'overwrite' older transactions, // Do not allow blocks that contain transactions which 'overwrite' older transactions,
// unless those are already completely spent. // unless those are already completely spent.
@ -2596,11 +2587,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
unsigned int flags{GetBlockScriptFlags(*pindex, m_chainman)}; unsigned int flags{GetBlockScriptFlags(*pindex, m_chainman)};
const auto time_2{SteadyClock::now()}; const auto time_2{SteadyClock::now()};
time_forks += time_2 - time_1; m_chainman.time_forks += time_2 - time_1;
LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_2 - time_1), Ticks<MillisecondsDouble>(time_2 - time_1),
Ticks<SecondsDouble>(time_forks), Ticks<SecondsDouble>(m_chainman.time_forks),
Ticks<MillisecondsDouble>(time_forks) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_forks) / m_chainman.num_blocks_total);
CBlockUndo blockundo; CBlockUndo blockundo;
@ -2687,12 +2678,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
UpdateCoins(tx, view, i == 0 ? undoDummy : blockundo.vtxundo.back(), pindex->nHeight); UpdateCoins(tx, view, i == 0 ? undoDummy : blockundo.vtxundo.back(), pindex->nHeight);
} }
const auto time_3{SteadyClock::now()}; const auto time_3{SteadyClock::now()};
time_connect += time_3 - time_2; m_chainman.time_connect += time_3 - time_2;
LogPrint(BCLog::BENCH, " - Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin) [%.2fs (%.2fms/blk)]\n", (unsigned)block.vtx.size(), LogPrint(BCLog::BENCH, " - Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin) [%.2fs (%.2fms/blk)]\n", (unsigned)block.vtx.size(),
Ticks<MillisecondsDouble>(time_3 - time_2), Ticks<MillisecondsDouble>(time_3 - time_2) / block.vtx.size(), Ticks<MillisecondsDouble>(time_3 - time_2), Ticks<MillisecondsDouble>(time_3 - time_2) / block.vtx.size(),
nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_3 - time_2) / (nInputs - 1), nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_3 - time_2) / (nInputs - 1),
Ticks<SecondsDouble>(time_connect), Ticks<SecondsDouble>(m_chainman.time_connect),
Ticks<MillisecondsDouble>(time_connect) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_connect) / m_chainman.num_blocks_total);
CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, params.GetConsensus()); CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, params.GetConsensus());
if (block.vtx[0]->GetValueOut() > blockReward) { if (block.vtx[0]->GetValueOut() > blockReward) {
@ -2705,12 +2696,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed"); return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed");
} }
const auto time_4{SteadyClock::now()}; const auto time_4{SteadyClock::now()};
time_verify += time_4 - time_2; m_chainman.time_verify += time_4 - time_2;
LogPrint(BCLog::BENCH, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs (%.2fms/blk)]\n", nInputs - 1, LogPrint(BCLog::BENCH, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs (%.2fms/blk)]\n", nInputs - 1,
Ticks<MillisecondsDouble>(time_4 - time_2), Ticks<MillisecondsDouble>(time_4 - time_2),
nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_4 - time_2) / (nInputs - 1), nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_4 - time_2) / (nInputs - 1),
Ticks<SecondsDouble>(time_verify), Ticks<SecondsDouble>(m_chainman.time_verify),
Ticks<MillisecondsDouble>(time_verify) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_verify) / m_chainman.num_blocks_total);
if (fJustCheck) if (fJustCheck)
return true; return true;
@ -2720,11 +2711,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
} }
const auto time_5{SteadyClock::now()}; const auto time_5{SteadyClock::now()};
time_undo += time_5 - time_4; m_chainman.time_undo += time_5 - time_4;
LogPrint(BCLog::BENCH, " - Write undo data: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Write undo data: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_5 - time_4), Ticks<MillisecondsDouble>(time_5 - time_4),
Ticks<SecondsDouble>(time_undo), Ticks<SecondsDouble>(m_chainman.time_undo),
Ticks<MillisecondsDouble>(time_undo) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_undo) / m_chainman.num_blocks_total);
if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) { if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) {
pindex->RaiseValidity(BLOCK_VALID_SCRIPTS); pindex->RaiseValidity(BLOCK_VALID_SCRIPTS);
@ -2735,11 +2726,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
view.SetBestBlock(pindex->GetBlockHash()); view.SetBestBlock(pindex->GetBlockHash());
const auto time_6{SteadyClock::now()}; const auto time_6{SteadyClock::now()};
time_index += time_6 - time_5; m_chainman.time_index += time_6 - time_5;
LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_6 - time_5), Ticks<MillisecondsDouble>(time_6 - time_5),
Ticks<SecondsDouble>(time_index), Ticks<SecondsDouble>(m_chainman.time_index),
Ticks<MillisecondsDouble>(time_index) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_index) / m_chainman.num_blocks_total);
TRACE6(validation, block_connected, TRACE6(validation, block_connected,
block_hash.data(), block_hash.data(),
@ -3097,11 +3088,6 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra
return true; return true;
} }
static SteadyClock::duration time_connect_total{};
static SteadyClock::duration time_flush{};
static SteadyClock::duration time_chainstate{};
static SteadyClock::duration time_post_connect{};
struct PerBlockConnectTrace { struct PerBlockConnectTrace {
CBlockIndex* pindex = nullptr; CBlockIndex* pindex = nullptr;
std::shared_ptr<const CBlock> pblock; std::shared_ptr<const CBlock> pblock;
@ -3188,31 +3174,31 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
return false; return false;
} }
time_3 = SteadyClock::now(); time_3 = SteadyClock::now();
time_connect_total += time_3 - time_2; m_chainman.time_connect_total += time_3 - time_2;
assert(num_blocks_total > 0); assert(m_chainman.num_blocks_total > 0);
LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_3 - time_2), Ticks<MillisecondsDouble>(time_3 - time_2),
Ticks<SecondsDouble>(time_connect_total), Ticks<SecondsDouble>(m_chainman.time_connect_total),
Ticks<MillisecondsDouble>(time_connect_total) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_connect_total) / m_chainman.num_blocks_total);
bool flushed = view.Flush(); bool flushed = view.Flush();
assert(flushed); assert(flushed);
} }
const auto time_4{SteadyClock::now()}; const auto time_4{SteadyClock::now()};
time_flush += time_4 - time_3; m_chainman.time_flush += time_4 - time_3;
LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_4 - time_3), Ticks<MillisecondsDouble>(time_4 - time_3),
Ticks<SecondsDouble>(time_flush), Ticks<SecondsDouble>(m_chainman.time_flush),
Ticks<MillisecondsDouble>(time_flush) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_flush) / m_chainman.num_blocks_total);
// Write the chain state to disk, if necessary. // Write the chain state to disk, if necessary.
if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) { if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) {
return false; return false;
} }
const auto time_5{SteadyClock::now()}; const auto time_5{SteadyClock::now()};
time_chainstate += time_5 - time_4; m_chainman.time_chainstate += time_5 - time_4;
LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_5 - time_4), Ticks<MillisecondsDouble>(time_5 - time_4),
Ticks<SecondsDouble>(time_chainstate), Ticks<SecondsDouble>(m_chainman.time_chainstate),
Ticks<MillisecondsDouble>(time_chainstate) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_chainstate) / m_chainman.num_blocks_total);
// Remove conflicting transactions from the mempool.; // Remove conflicting transactions from the mempool.;
if (m_mempool) { if (m_mempool) {
m_mempool->removeForBlock(blockConnecting.vtx, pindexNew->nHeight); m_mempool->removeForBlock(blockConnecting.vtx, pindexNew->nHeight);
@ -3223,16 +3209,16 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
UpdateTip(pindexNew); UpdateTip(pindexNew);
const auto time_6{SteadyClock::now()}; const auto time_6{SteadyClock::now()};
time_post_connect += time_6 - time_5; m_chainman.time_post_connect += time_6 - time_5;
time_total += time_6 - time_1; m_chainman.time_total += time_6 - time_1;
LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_6 - time_5), Ticks<MillisecondsDouble>(time_6 - time_5),
Ticks<SecondsDouble>(time_post_connect), Ticks<SecondsDouble>(m_chainman.time_post_connect),
Ticks<MillisecondsDouble>(time_post_connect) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_post_connect) / m_chainman.num_blocks_total);
LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n",
Ticks<MillisecondsDouble>(time_6 - time_1), Ticks<MillisecondsDouble>(time_6 - time_1),
Ticks<SecondsDouble>(time_total), Ticks<SecondsDouble>(m_chainman.time_total),
Ticks<MillisecondsDouble>(time_total) / num_blocks_total); Ticks<MillisecondsDouble>(m_chainman.time_total) / m_chainman.num_blocks_total);
// If we are the background validation chainstate, check to see if we are done // If we are the background validation chainstate, check to see if we are done
// validating the snapshot (i.e. our tip has reached the snapshot's base block). // validating the snapshot (i.e. our tip has reached the snapshot's base block).

15
src/validation.h
View file

@ -949,6 +949,21 @@ private:
//! A queue for script verifications that have to be performed by worker threads. //! A queue for script verifications that have to be performed by worker threads.
CCheckQueue<CScriptCheck> m_script_check_queue; CCheckQueue<CScriptCheck> m_script_check_queue;
//! Timers and counters used for benchmarking validation in both background
//! and active chainstates.
SteadyClock::duration GUARDED_BY(::cs_main) time_check{};
SteadyClock::duration GUARDED_BY(::cs_main) time_forks{};
SteadyClock::duration GUARDED_BY(::cs_main) time_connect{};
SteadyClock::duration GUARDED_BY(::cs_main) time_verify{};
SteadyClock::duration GUARDED_BY(::cs_main) time_undo{};
SteadyClock::duration GUARDED_BY(::cs_main) time_index{};
SteadyClock::duration GUARDED_BY(::cs_main) time_total{};
int64_t GUARDED_BY(::cs_main) num_blocks_total{0};
SteadyClock::duration GUARDED_BY(::cs_main) time_connect_total{};
SteadyClock::duration GUARDED_BY(::cs_main) time_flush{};
SteadyClock::duration GUARDED_BY(::cs_main) time_chainstate{};
SteadyClock::duration GUARDED_BY(::cs_main) time_post_connect{};
public: public:
using Options = kernel::ChainstateManagerOpts; using Options = kernel::ChainstateManagerOpts;