From 3443943f86678eb27d9895f3871fcf3945eb1c4f Mon Sep 17 00:00:00 2001 From: TheCharlatan Date: Wed, 19 Jun 2024 11:36:31 +0200 Subject: [PATCH] refactor: De-globalize validation benchmark timekeeping 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. --- src/validation.cpp | 84 +++++++++++++++++++--------------------------- src/validation.h | 15 +++++++++ 2 files changed, 50 insertions(+), 49 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index 939759f0dfd..812290021b4 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -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. * Validity checks that depend on the UTXO set are also done; ConnectBlock() * 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(); assert(hashPrevBlock == view.GetBestBlock()); - num_blocks_total++; + m_chainman.num_blocks_total++; // Special case for the genesis block, skipping connection of its transactions // (its coinbase is unspendable) @@ -2494,11 +2485,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, } 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", Ticks(time_1 - time_start), - Ticks(time_check), - Ticks(time_check) / num_blocks_total); + Ticks(m_chainman.time_check), + Ticks(m_chainman.time_check) / m_chainman.num_blocks_total); // Do not allow blocks that contain transactions which 'overwrite' older transactions, // 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)}; 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", Ticks(time_2 - time_1), - Ticks(time_forks), - Ticks(time_forks) / num_blocks_total); + Ticks(m_chainman.time_forks), + Ticks(m_chainman.time_forks) / m_chainman.num_blocks_total); 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); } 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(), Ticks(time_3 - time_2), Ticks(time_3 - time_2) / block.vtx.size(), nInputs <= 1 ? 0 : Ticks(time_3 - time_2) / (nInputs - 1), - Ticks(time_connect), - Ticks(time_connect) / num_blocks_total); + Ticks(m_chainman.time_connect), + Ticks(m_chainman.time_connect) / m_chainman.num_blocks_total); CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, params.GetConsensus()); 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"); } 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, Ticks(time_4 - time_2), nInputs <= 1 ? 0 : Ticks(time_4 - time_2) / (nInputs - 1), - Ticks(time_verify), - Ticks(time_verify) / num_blocks_total); + Ticks(m_chainman.time_verify), + Ticks(m_chainman.time_verify) / m_chainman.num_blocks_total); if (fJustCheck) return true; @@ -2720,11 +2711,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, } 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", Ticks(time_5 - time_4), - Ticks(time_undo), - Ticks(time_undo) / num_blocks_total); + Ticks(m_chainman.time_undo), + Ticks(m_chainman.time_undo) / m_chainman.num_blocks_total); if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) { pindex->RaiseValidity(BLOCK_VALID_SCRIPTS); @@ -2735,11 +2726,11 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, view.SetBestBlock(pindex->GetBlockHash()); 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", Ticks(time_6 - time_5), - Ticks(time_index), - Ticks(time_index) / num_blocks_total); + Ticks(m_chainman.time_index), + Ticks(m_chainman.time_index) / m_chainman.num_blocks_total); TRACE6(validation, block_connected, block_hash.data(), @@ -3097,11 +3088,6 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra 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 { CBlockIndex* pindex = nullptr; std::shared_ptr pblock; @@ -3188,31 +3174,31 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, return false; } time_3 = SteadyClock::now(); - time_connect_total += time_3 - time_2; - assert(num_blocks_total > 0); + m_chainman.time_connect_total += time_3 - time_2; + assert(m_chainman.num_blocks_total > 0); LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", Ticks(time_3 - time_2), - Ticks(time_connect_total), - Ticks(time_connect_total) / num_blocks_total); + Ticks(m_chainman.time_connect_total), + Ticks(m_chainman.time_connect_total) / m_chainman.num_blocks_total); bool flushed = view.Flush(); assert(flushed); } 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", Ticks(time_4 - time_3), - Ticks(time_flush), - Ticks(time_flush) / num_blocks_total); + Ticks(m_chainman.time_flush), + Ticks(m_chainman.time_flush) / m_chainman.num_blocks_total); // Write the chain state to disk, if necessary. if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) { return false; } 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", Ticks(time_5 - time_4), - Ticks(time_chainstate), - Ticks(time_chainstate) / num_blocks_total); + Ticks(m_chainman.time_chainstate), + Ticks(m_chainman.time_chainstate) / m_chainman.num_blocks_total); // Remove conflicting transactions from the mempool.; if (m_mempool) { m_mempool->removeForBlock(blockConnecting.vtx, pindexNew->nHeight); @@ -3223,16 +3209,16 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, UpdateTip(pindexNew); const auto time_6{SteadyClock::now()}; - time_post_connect += time_6 - time_5; - time_total += time_6 - time_1; + m_chainman.time_post_connect += time_6 - time_5; + m_chainman.time_total += time_6 - time_1; LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", Ticks(time_6 - time_5), - Ticks(time_post_connect), - Ticks(time_post_connect) / num_blocks_total); + Ticks(m_chainman.time_post_connect), + Ticks(m_chainman.time_post_connect) / m_chainman.num_blocks_total); LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", Ticks(time_6 - time_1), - Ticks(time_total), - Ticks(time_total) / num_blocks_total); + Ticks(m_chainman.time_total), + Ticks(m_chainman.time_total) / m_chainman.num_blocks_total); // 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). diff --git a/src/validation.h b/src/validation.h index 9f99ba796bf..92377aa5fc9 100644 --- a/src/validation.h +++ b/src/validation.h @@ -949,6 +949,21 @@ private: //! A queue for script verifications that have to be performed by worker threads. CCheckQueue 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: using Options = kernel::ChainstateManagerOpts;