diff options
author | MacroFake <falke.marco@gmail.com> | 2022-09-19 10:55:03 +0200 |
---|---|---|
committer | MacroFake <falke.marco@gmail.com> | 2022-09-19 11:51:34 +0200 |
commit | fabf1cdb206e368a9433abf99a5ea2762a5ed2c0 (patch) | |
tree | 96b3cc124c82a3329859c3953251c0f86aba3f62 /src/validation.cpp | |
parent | faed342a2338d6a1a26cf977671a736662debae4 (diff) | |
download | bitcoin-fabf1cdb206e368a9433abf99a5ea2762a5ed2c0.tar.xz |
Use steady clock for bench logging
Diffstat (limited to 'src/validation.cpp')
-rw-r--r-- | src/validation.cpp | 122 |
1 files changed, 79 insertions, 43 deletions
diff --git a/src/validation.cpp b/src/validation.cpp index 7660da0ac0..9ebcc4fb98 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -82,9 +82,6 @@ using node::SnapshotMetadata; using node::UndoReadFromDisk; using node::UnlinkPrunedFiles; -#define MICRO 0.000001 -#define MILLI 0.001 - /** Maximum kilobytes for transactions to store for processing during reorg */ static const unsigned int MAX_DISCONNECTED_TX_POOL_SIZE = 20000; /** Time to wait between writing blocks/block index to disk. */ @@ -1965,13 +1962,13 @@ static unsigned int GetBlockScriptFlags(const CBlockIndex& block_index, const Ch } -static int64_t time_check = 0; -static int64_t time_forks = 0; -static int64_t time_connect = 0; -static int64_t time_verify = 0; -static int64_t time_undo = 0; -static int64_t time_index = 0; -static int64_t time_total = 0; +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. @@ -1986,7 +1983,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, uint256 block_hash{block.GetHash()}; assert(*pindex->phashBlock == block_hash); - int64_t time_start = GetTimeMicros(); + const auto time_start{SteadyClock::now()}; // Check it again in case a previous version let a bad block in // NOTE: We don't currently (re-)invoke ContextualCheckBlock() or @@ -2056,9 +2053,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, } } - int64_t time_1 = GetTimeMicros(); + const auto time_1{SteadyClock::now()}; time_check += time_1 - time_start; - LogPrint(BCLog::BENCH, " - Sanity checks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (time_1 - time_start), time_check * MICRO, time_check * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Sanity checks: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_1 - time_start), + Ticks<SecondsDouble>(time_check), + Ticks<MillisecondsDouble>(time_check) / num_blocks_total); // Do not allow blocks that contain transactions which 'overwrite' older transactions, // unless those are already completely spent. @@ -2156,9 +2156,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // Get the script flags for this block unsigned int flags{GetBlockScriptFlags(*pindex, m_chainman)}; - int64_t time_2 = GetTimeMicros(); + const auto time_2{SteadyClock::now()}; time_forks += time_2 - time_1; - LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (time_2 - time_1), time_forks * MICRO, time_forks * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_2 - time_1), + Ticks<SecondsDouble>(time_forks), + Ticks<MillisecondsDouble>(time_forks) / num_blocks_total); CBlockUndo blockundo; @@ -2242,9 +2245,13 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, } UpdateCoins(tx, view, i == 0 ? undoDummy : blockundo.vtxundo.back(), pindex->nHeight); } - int64_t time_3 = GetTimeMicros(); + const auto time_3{SteadyClock::now()}; 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(), MILLI * (time_3 - time_2), MILLI * (time_3 - time_2) / block.vtx.size(), nInputs <= 1 ? 0 : MILLI * (time_3 - time_2) / (nInputs-1), time_connect * MICRO, time_connect * MILLI / num_blocks_total); + 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(), + nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_3 - time_2) / (nInputs - 1), + Ticks<SecondsDouble>(time_connect), + Ticks<MillisecondsDouble>(time_connect) / num_blocks_total); CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, m_params.GetConsensus()); if (block.vtx[0]->GetValueOut() > blockReward) { @@ -2256,9 +2263,13 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, LogPrintf("ERROR: %s: CheckQueue failed\n", __func__); return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed"); } - int64_t time_4 = GetTimeMicros(); + const auto time_4{SteadyClock::now()}; time_verify += time_4 - time_2; - LogPrint(BCLog::BENCH, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs (%.2fms/blk)]\n", nInputs - 1, MILLI * (time_4 - time_2), nInputs <= 1 ? 0 : MILLI * (time_4 - time_2) / (nInputs-1), time_verify * MICRO, time_verify * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs (%.2fms/blk)]\n", nInputs - 1, + Ticks<MillisecondsDouble>(time_4 - time_2), + nInputs <= 1 ? 0 : Ticks<MillisecondsDouble>(time_4 - time_2) / (nInputs - 1), + Ticks<SecondsDouble>(time_verify), + Ticks<MillisecondsDouble>(time_verify) / num_blocks_total); if (fJustCheck) return true; @@ -2267,9 +2278,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, return false; } - int64_t time_5 = GetTimeMicros(); + const auto time_5{SteadyClock::now()}; time_undo += time_5 - time_4; - LogPrint(BCLog::BENCH, " - Write undo data: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (time_5 - time_4), time_undo * MICRO, time_undo * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Write undo data: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_5 - time_4), + Ticks<SecondsDouble>(time_undo), + Ticks<MillisecondsDouble>(time_undo) / num_blocks_total); if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) { pindex->RaiseValidity(BLOCK_VALID_SCRIPTS); @@ -2279,9 +2293,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // add this block to the view's block chain view.SetBestBlock(pindex->GetBlockHash()); - int64_t time_6 = GetTimeMicros(); + const auto time_6{SteadyClock::now()}; time_index += time_6 - time_5; - LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (time_6 - time_5), time_index * MICRO, time_index * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_6 - time_5), + Ticks<SecondsDouble>(time_index), + Ticks<MillisecondsDouble>(time_index) / num_blocks_total); TRACE6(validation, block_connected, block_hash.data(), @@ -2596,7 +2613,7 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra return error("DisconnectTip(): Failed to read block"); } // Apply the block atomically to the chain state. - int64_t time_start = GetTimeMicros(); + const auto time_start{SteadyClock::now()}; { CCoinsViewCache view(&CoinsTip()); assert(view.GetBestBlock() == pindexDelete->GetBlockHash()); @@ -2605,7 +2622,8 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra bool flushed = view.Flush(); assert(flushed); } - LogPrint(BCLog::BENCH, "- Disconnect block: %.2fms\n", (GetTimeMicros() - time_start) * MILLI); + LogPrint(BCLog::BENCH, "- Disconnect block: %.2fms\n", + Ticks<MillisecondsDouble>(SteadyClock::now() - time_start)); { // Prune locks that began at or after the tip should be moved backward so they get a chance to reorg @@ -2645,11 +2663,11 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra return true; } -static int64_t time_read_from_disk_total = 0; -static int64_t time_connect_total = 0; -static int64_t time_flush = 0; -static int64_t time_chainstate = 0; -static int64_t time_post_connect = 0; +static SteadyClock::duration time_read_from_disk_total{}; +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; @@ -2704,7 +2722,7 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, assert(pindexNew->pprev == m_chain.Tip()); // Read block from disk. - int64_t time_1 = GetTimeMicros(); + const auto time_1{SteadyClock::now()}; std::shared_ptr<const CBlock> pthisBlock; if (!pblock) { std::shared_ptr<CBlock> pblockNew = std::make_shared<CBlock>(); @@ -2718,10 +2736,13 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, } const CBlock& blockConnecting = *pthisBlock; // Apply the block atomically to the chain state. - int64_t time_2 = GetTimeMicros(); + const auto time_2{SteadyClock::now()}; time_read_from_disk_total += time_2 - time_1; - int64_t time_3; - LogPrint(BCLog::BENCH, " - Load block from disk: %.2fms [%.2fs (%.2fms/blk)]\n", (time_2 - time_1) * MILLI, time_read_from_disk_total * MICRO, time_read_from_disk_total * MILLI / num_blocks_total); + SteadyClock::time_point time_3; + LogPrint(BCLog::BENCH, " - Load block from disk: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_2 - time_1), + Ticks<SecondsDouble>(time_read_from_disk_total), + Ticks<MillisecondsDouble>(time_read_from_disk_total) / num_blocks_total); { CCoinsViewCache view(&CoinsTip()); bool rv = ConnectBlock(blockConnecting, state, pindexNew, view); @@ -2731,23 +2752,32 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, InvalidBlockFound(pindexNew, state); return error("%s: ConnectBlock %s failed, %s", __func__, pindexNew->GetBlockHash().ToString(), state.ToString()); } - time_3 = GetTimeMicros(); + time_3 = SteadyClock::now(); time_connect_total += time_3 - time_2; assert(num_blocks_total > 0); - LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", (time_3 - time_2) * MILLI, time_connect_total * MICRO, time_connect_total * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_3 - time_2), + Ticks<SecondsDouble>(time_connect_total), + Ticks<MillisecondsDouble>(time_connect_total) / num_blocks_total); bool flushed = view.Flush(); assert(flushed); } - int64_t time_4 = GetTimeMicros(); + const auto time_4{SteadyClock::now()}; time_flush += time_4 - time_3; - LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n", (time_4 - time_3) * MILLI, time_flush * MICRO, time_flush * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_4 - time_3), + Ticks<SecondsDouble>(time_flush), + Ticks<MillisecondsDouble>(time_flush) / num_blocks_total); // Write the chain state to disk, if necessary. if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) { return false; } - int64_t time_5 = GetTimeMicros(); + const auto time_5{SteadyClock::now()}; time_chainstate += time_5 - time_4; - LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n", (time_5 - time_4) * MILLI, time_chainstate * MICRO, time_chainstate * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_5 - time_4), + Ticks<SecondsDouble>(time_chainstate), + Ticks<MillisecondsDouble>(time_chainstate) / num_blocks_total); // Remove conflicting transactions from the mempool.; if (m_mempool) { m_mempool->removeForBlock(blockConnecting.vtx, pindexNew->nHeight); @@ -2757,11 +2787,17 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, m_chain.SetTip(*pindexNew); UpdateTip(pindexNew); - int64_t time_6 = GetTimeMicros(); + const auto time_6{SteadyClock::now()}; time_post_connect += time_6 - time_5; time_total += time_6 - time_1; - LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", (time_6 - time_5) * MILLI, time_post_connect * MICRO, time_post_connect * MILLI / num_blocks_total); - LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", (time_6 - time_1) * MILLI, time_total * MICRO, time_total * MILLI / num_blocks_total); + LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_6 - time_5), + Ticks<SecondsDouble>(time_post_connect), + Ticks<MillisecondsDouble>(time_post_connect) / num_blocks_total); + LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", + Ticks<MillisecondsDouble>(time_6 - time_1), + Ticks<SecondsDouble>(time_total), + Ticks<MillisecondsDouble>(time_total) / num_blocks_total); connectTrace.BlockConnected(pindexNew, std::move(pthisBlock)); return true; |