foster/bitcoin-bitcoin-core
0
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-02-12 11:19:08 -05:00
Code Issues Activity

Use steady clock for bench logging

Browse source
This commit is contained in:
MacroFake 2022-09-19 10:55:03 +02:00
parent faed342a23
commit fabf1cdb20
No known key found for this signature in database
GPG key ID: CE2B75697E69A548
4 changed files with 92 additions and 51 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

11
src/node/miner.cpp
View file

@ -105,7 +105,7 @@ void BlockAssembler::resetBlock()
std::unique_ptr<CBlockTemplate> BlockAssembler::CreateNewBlock(const CScript& scriptPubKeyIn) std::unique_ptr<CBlockTemplate> BlockAssembler::CreateNewBlock(const CScript& scriptPubKeyIn)
{ {
int64_t time_start = GetTimeMicros(); const auto time_start{SteadyClock::now()};
resetBlock(); resetBlock();
@ -143,7 +143,7 @@ std::unique_ptr<CBlockTemplate> BlockAssembler::CreateNewBlock(const CScript& sc
addPackageTxs(*m_mempool, nPackagesSelected, nDescendantsUpdated); addPackageTxs(*m_mempool, nPackagesSelected, nDescendantsUpdated);
} }
int64_t time_1 = GetTimeMicros(); const auto time_1{SteadyClock::now()};
m_last_block_num_txs = nBlockTx; m_last_block_num_txs = nBlockTx;
m_last_block_weight = nBlockWeight; m_last_block_weight = nBlockWeight;
@ -173,9 +173,12 @@ std::unique_ptr<CBlockTemplate> BlockAssembler::CreateNewBlock(const CScript& sc
if (!TestBlockValidity(state, chainparams, m_chainstate, *pblock, pindexPrev, GetAdjustedTime, false, false)) { if (!TestBlockValidity(state, chainparams, m_chainstate, *pblock, pindexPrev, GetAdjustedTime, false, false)) {
throw std::runtime_error(strprintf("%s: TestBlockValidity failed: %s", __func__, state.ToString())); throw std::runtime_error(strprintf("%s: TestBlockValidity failed: %s", __func__, state.ToString()));
} }
int64_t time_2 = GetTimeMicros(); const auto time_2{SteadyClock::now()};
LogPrint(BCLog::BENCH, "CreateNewBlock() packages: %.2fms (%d packages, %d updated descendants), validity: %.2fms (total %.2fms)\n", 0.001 * (time_1 - time_start), nPackagesSelected, nDescendantsUpdated, 0.001 * (time_2 - time_1), 0.001 * (time_2 - time_start)); LogPrint(BCLog::BENCH, "CreateNewBlock() packages: %.2fms (%d packages, %d updated descendants), validity: %.2fms (total %.2fms)\n",
Ticks<MillisecondsDouble>(time_1 - time_start), nPackagesSelected, nDescendantsUpdated,
Ticks<MillisecondsDouble>(time_2 - time_1),
Ticks<MillisecondsDouble>(time_2 - time_start));
return std::move(pblocktemplate); return std::move(pblocktemplate);
} }

9
src/policy/fees.cpp
View file

@ -997,8 +997,9 @@ bool CBlockPolicyEstimator::Read(AutoFile& filein)
return true; return true;
} }
void CBlockPolicyEstimator::FlushUnconfirmed() { void CBlockPolicyEstimator::FlushUnconfirmed()
int64_t startclear = GetTimeMicros(); {
const auto startclear{SteadyClock::now()};
LOCK(m_cs_fee_estimator); LOCK(m_cs_fee_estimator);
size_t num_entries = mapMemPoolTxs.size(); size_t num_entries = mapMemPoolTxs.size();
// Remove every entry in mapMemPoolTxs // Remove every entry in mapMemPoolTxs
@ -1006,8 +1007,8 @@ void CBlockPolicyEstimator::FlushUnconfirmed() {
auto mi = mapMemPoolTxs.begin(); auto mi = mapMemPoolTxs.begin();
_removeTx(mi->first, false); // this calls erase() on mapMemPoolTxs _removeTx(mi->first, false); // this calls erase() on mapMemPoolTxs
} }
int64_t endclear = GetTimeMicros(); const auto endclear{SteadyClock::now()};
LogPrint(BCLog::ESTIMATEFEE, "Recorded %u unconfirmed txs from mempool in %gs\n", num_entries, (endclear - startclear)*0.000001); LogPrint(BCLog::ESTIMATEFEE, "Recorded %u unconfirmed txs from mempool in %gs\n", num_entries, Ticks<SecondsDouble>(endclear - startclear));
} }
FeeFilterRounder::FeeFilterRounder(const CFeeRate& minIncrementalFee) FeeFilterRounder::FeeFilterRounder(const CFeeRate& minIncrementalFee)

1
src/util/time.h
View file

@ -57,6 +57,7 @@ constexpr int64_t count_microseconds(std::chrono::microseconds t) { return t.cou
using HoursDouble = std::chrono::duration<double, std::chrono::hours::period>; using HoursDouble = std::chrono::duration<double, std::chrono::hours::period>;
using SecondsDouble = std::chrono::duration<double, std::chrono::seconds::period>; using SecondsDouble = std::chrono::duration<double, std::chrono::seconds::period>;
using MillisecondsDouble = std::chrono::duration<double, std::chrono::milliseconds::period>;
/** /**
* DEPRECATED * DEPRECATED

122
src/validation.cpp
View file

@ -82,9 +82,6 @@ using node::SnapshotMetadata;
using node::UndoReadFromDisk; using node::UndoReadFromDisk;
using node::UnlinkPrunedFiles; using node::UnlinkPrunedFiles;
#define MICRO 0.000001
#define MILLI 0.001
/** Maximum kilobytes for transactions to store for processing during reorg */ /** Maximum kilobytes for transactions to store for processing during reorg */
static const unsigned int MAX_DISCONNECTED_TX_POOL_SIZE = 20000; static const unsigned int MAX_DISCONNECTED_TX_POOL_SIZE = 20000;
/** Time to wait between writing blocks/block index to disk. */ /** 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 SteadyClock::duration time_check{};
static int64_t time_forks = 0; static SteadyClock::duration time_forks{};
static int64_t time_connect = 0; static SteadyClock::duration time_connect{};
static int64_t time_verify = 0; static SteadyClock::duration time_verify{};
static int64_t time_undo = 0; static SteadyClock::duration time_undo{};
static int64_t time_index = 0; static SteadyClock::duration time_index{};
static int64_t time_total = 0; static SteadyClock::duration time_total{};
static int64_t num_blocks_total = 0; 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.
@ -1986,7 +1983,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
uint256 block_hash{block.GetHash()}; uint256 block_hash{block.GetHash()};
assert(*pindex->phashBlock == block_hash); 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 // Check it again in case a previous version let a bad block in
// NOTE: We don't currently (re-)invoke ContextualCheckBlock() or // 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; 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, // Do not allow blocks that contain transactions which 'overwrite' older transactions,
// unless those are already completely spent. // 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 // Get the script flags for this block
unsigned int flags{GetBlockScriptFlags(*pindex, m_chainman)}; unsigned int flags{GetBlockScriptFlags(*pindex, m_chainman)};
int64_t time_2 = GetTimeMicros(); const auto time_2{SteadyClock::now()};
time_forks += time_2 - time_1; 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; 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); 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; 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()); CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, m_params.GetConsensus());
if (block.vtx[0]->GetValueOut() > blockReward) { 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__); LogPrintf("ERROR: %s: CheckQueue failed\n", __func__);
return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed"); 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; 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) if (fJustCheck)
return true; return true;
@ -2267,9 +2278,12 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
return false; return false;
} }
int64_t time_5 = GetTimeMicros(); const auto time_5{SteadyClock::now()};
time_undo += time_5 - time_4; 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)) { if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) {
pindex->RaiseValidity(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 // add this block to the view's block chain
view.SetBestBlock(pindex->GetBlockHash()); view.SetBestBlock(pindex->GetBlockHash());
int64_t time_6 = GetTimeMicros(); const auto time_6{SteadyClock::now()};
time_index += time_6 - time_5; 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, TRACE6(validation, block_connected,
block_hash.data(), block_hash.data(),
@ -2596,7 +2613,7 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra
return error("DisconnectTip(): Failed to read block"); return error("DisconnectTip(): Failed to read block");
} }
// Apply the block atomically to the chain state. // Apply the block atomically to the chain state.
int64_t time_start = GetTimeMicros(); const auto time_start{SteadyClock::now()};
{ {
CCoinsViewCache view(&CoinsTip()); CCoinsViewCache view(&CoinsTip());
assert(view.GetBestBlock() == pindexDelete->GetBlockHash()); assert(view.GetBestBlock() == pindexDelete->GetBlockHash());
@ -2605,7 +2622,8 @@ bool Chainstate::DisconnectTip(BlockValidationState& state, DisconnectedBlockTra
bool flushed = view.Flush(); bool flushed = view.Flush();
assert(flushed); 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 // 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; return true;
} }
static int64_t time_read_from_disk_total = 0; static SteadyClock::duration time_read_from_disk_total{};
static int64_t time_connect_total = 0; static SteadyClock::duration time_connect_total{};
static int64_t time_flush = 0; static SteadyClock::duration time_flush{};
static int64_t time_chainstate = 0; static SteadyClock::duration time_chainstate{};
static int64_t time_post_connect = 0; static SteadyClock::duration time_post_connect{};
struct PerBlockConnectTrace { struct PerBlockConnectTrace {
CBlockIndex* pindex = nullptr; CBlockIndex* pindex = nullptr;
@ -2704,7 +2722,7 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
assert(pindexNew->pprev == m_chain.Tip()); assert(pindexNew->pprev == m_chain.Tip());
// Read block from disk. // Read block from disk.
int64_t time_1 = GetTimeMicros(); const auto time_1{SteadyClock::now()};
std::shared_ptr<const CBlock> pthisBlock; std::shared_ptr<const CBlock> pthisBlock;
if (!pblock) { if (!pblock) {
std::shared_ptr<CBlock> pblockNew = std::make_shared<CBlock>(); std::shared_ptr<CBlock> pblockNew = std::make_shared<CBlock>();
@ -2718,10 +2736,13 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
} }
const CBlock& blockConnecting = *pthisBlock; const CBlock& blockConnecting = *pthisBlock;
// Apply the block atomically to the chain state. // 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; time_read_from_disk_total += time_2 - time_1;
int64_t time_3; SteadyClock::time_point 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); 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()); CCoinsViewCache view(&CoinsTip());
bool rv = ConnectBlock(blockConnecting, state, pindexNew, view); bool rv = ConnectBlock(blockConnecting, state, pindexNew, view);
@ -2731,23 +2752,32 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
InvalidBlockFound(pindexNew, state); InvalidBlockFound(pindexNew, state);
return error("%s: ConnectBlock %s failed, %s", __func__, pindexNew->GetBlockHash().ToString(), state.ToString()); 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; time_connect_total += time_3 - time_2;
assert(num_blocks_total > 0); 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(); bool flushed = view.Flush();
assert(flushed); assert(flushed);
} }
int64_t time_4 = GetTimeMicros(); const auto time_4{SteadyClock::now()};
time_flush += time_4 - time_3; 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. // Write the chain state to disk, if necessary.
if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) { if (!FlushStateToDisk(state, FlushStateMode::IF_NEEDED)) {
return false; return false;
} }
int64_t time_5 = GetTimeMicros(); const auto time_5{SteadyClock::now()};
time_chainstate += time_5 - time_4; 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.; // 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);
@ -2757,11 +2787,17 @@ bool Chainstate::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew,
m_chain.SetTip(*pindexNew); m_chain.SetTip(*pindexNew);
UpdateTip(pindexNew); UpdateTip(pindexNew);
int64_t time_6 = GetTimeMicros(); const auto time_6{SteadyClock::now()};
time_post_connect += time_6 - time_5; time_post_connect += time_6 - time_5;
time_total += time_6 - time_1; 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 postprocess: %.2fms [%.2fs (%.2fms/blk)]\n",
LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", (time_6 - time_1) * MILLI, time_total * MICRO, time_total * MILLI / num_blocks_total); 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)); connectTrace.BlockConnected(pindexNew, std::move(pthisBlock));
return true; return true;