Skip to content

Commit

Permalink
perf: don't use boost time in validation.cpp
Browse files Browse the repository at this point in the history 
(over a 13 minute segment of reindex) boost time took about 9+9+9 = 27%!! of total cycles!!!

During the same time segment, GetTimeMicros() used roughly 0.2% of total cycles! (even though it's used a lot more)

Over my entire roughly 40 minute profiling session, boost time appears to use about 6% of cycles; still too much, while GetTimeMicros used about 0.4%
  • Loading branch information
@PastaPastaPasta
PastaPastaPasta committed Oct 16, 2023
1 parent 13b99e2 commit 4f34cfa
Showing 1 changed file with 29 additions and 35 deletions.
64 changes: 29 additions & 35 deletions src/validation.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -68,8 +68,6 @@
#include <optional>
#include <string>

#include <boost/date_time/posix_time/posix_time.hpp>

#define MICRO 0.000001
#define MILLI 0.001

Expand Down Expand Up @@ -944,7 +942,7 @@ bool MemPoolAccept::Finalize(ATMPArgs& args, Workspace& ws)

bool MemPoolAccept::AcceptSingleTransaction(const CTransactionRef& ptx, ATMPArgs& args)
{
boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();
AssertLockHeld(cs_main);
LOCK(m_pool.cs); // mempool "read lock" (held through GetMainSignals().TransactionAddedToMempool())

Expand All @@ -971,9 +969,9 @@ bool MemPoolAccept::AcceptSingleTransaction(const CTransactionRef& ptx, ATMPArgs
GetMainSignals().TransactionAddedToMempool(ptx, nAcceptTime);

const CTransaction& tx = *ptx;
boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("AcceptToMemoryPool_ms", diff.total_milliseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("AcceptToMemoryPool_ms", diff, 1.0f);
statsClient.inc("transactions.accepted", 1.0f);
statsClient.count("transactions.inputs", tx.vin.size(), 1.0f);
statsClient.count("transactions.outputs", tx.vout.size(), 1.0f);
Expand Down Expand Up @@ -1498,7 +1496,7 @@ void InitScriptExecutionCache() {
*/
bool CheckInputScripts(const CTransaction& tx, TxValidationState &state, const CCoinsViewCache &inputs, unsigned int flags, bool cacheSigStore, bool cacheFullScriptStore, PrecomputedTransactionData& txdata, std::vector<CScriptCheck> *pvChecks) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
{
boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();
if (tx.IsCoinBase()) return true;

if (pvChecks) {
Expand Down Expand Up @@ -1575,9 +1573,9 @@ bool CheckInputScripts(const CTransaction& tx, TxValidationState &state, const C
g_scriptExecutionCache.insert(hashCacheEntry);
}

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("CheckInputScripts_ms", diff.total_milliseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("CheckInputScripts_ms", diff, 1.0f);
return true;
}

Expand Down Expand Up @@ -1694,7 +1692,7 @@ DisconnectResult CChainState::DisconnectBlock(const CBlock& block, const CBlockI
return DISCONNECT_FAILED;
}

boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();

bool fClean = true;

Expand Down Expand Up @@ -1829,9 +1827,9 @@ DisconnectResult CChainState::DisconnectBlock(const CBlock& block, const CBlockI
view.SetBestBlock(pindex->pprev->GetBlockHash());
m_evoDb.WriteBestBlock(pindex->pprev->GetBlockHash());

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("DisconnectBlock_ms", diff.total_milliseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("DisconnectBlock_ms", diff, 1.0f);

return fClean ? DISCONNECT_OK : DISCONNECT_UNCLEAN;
}
Expand Down Expand Up @@ -2015,7 +2013,7 @@ static int64_t nBlocksTotal = 0;
bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state, CBlockIndex* pindex,
CCoinsViewCache& view, bool fJustCheck)
{
boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
int64_t nTimeStart = GetTimeMicros();

AssertLockHeld(cs_main);
assert(pindex);
Expand All @@ -2026,7 +2024,6 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
assert(m_clhandler);
assert(m_isman);
assert(m_quorum_block_processor);
int64_t nTimeStart = GetTimeMicros();

// Check it again in case a previous version let a bad block in
// NOTE: We don't currently (re-)invoke ContextualCheckBlock() or
Expand Down Expand Up @@ -2455,9 +2452,8 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
int64_t nTime8 = GetTimeMicros(); nTimeCallbacks += nTime8 - nTime5;
LogPrint(BCLog::BENCHMARK, " - Callbacks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime8 - nTime5), nTimeCallbacks * MICRO, nTimeCallbacks * MILLI / nBlocksTotal);

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("ConnectBlock_ms", diff.total_milliseconds(), 1.0f);
auto diff = nTime8 - nTime1;
statsClient.timing("ConnectBlock_ms", diff, 1.0f);
statsClient.gauge("blocks.tip.SizeBytes", ::GetSerializeSize(block, PROTOCOL_VERSION), 1.0f);
statsClient.gauge("blocks.tip.Height", m_chain.Height(), 1.0f);
statsClient.gauge("blocks.tip.Version", block.nVersion, 1.0f);
Expand Down Expand Up @@ -2841,7 +2837,7 @@ class ConnectTrace {
*/
bool CChainState::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew, const std::shared_ptr<const CBlock>& pblock, ConnectTrace& connectTrace, DisconnectedBlockTransactions& disconnectpool)
{
boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
int64_t start = GetTimeMicros();
AssertLockHeld(cs_main);
if (m_mempool) AssertLockHeld(m_mempool->cs);

Expand Down Expand Up @@ -2903,9 +2899,7 @@ bool CChainState::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew
LogPrint(BCLog::BENCHMARK, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime6 - nTime5) * MILLI, nTimePostConnect * MICRO, nTimePostConnect * MILLI / nBlocksTotal);
LogPrint(BCLog::BENCHMARK, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime6 - nTime1) * MILLI, nTimeTotal * MICRO, nTimeTotal * MILLI / nBlocksTotal);

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("ConnectTip_ms", diff.total_milliseconds(), 1.0f);
statsClient.timing("ConnectTip_ms", nTime6 - start, 1.0f);

connectTrace.BlockConnected(pindexNew, std::move(pthisBlock));
return true;
Expand Down Expand Up @@ -3124,7 +3118,7 @@ bool CChainState::ActivateBestChain(BlockValidationState& state, std::shared_ptr
// we use m_cs_chainstate to enforce mutual exclusion so that only one caller may execute this function at a time
LOCK(m_cs_chainstate);

boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();

CBlockIndex *pindexMostWork = nullptr;
CBlockIndex *pindexNewTip = nullptr;
Expand Down Expand Up @@ -3205,9 +3199,9 @@ bool CChainState::ActivateBestChain(BlockValidationState& state, std::shared_ptr
} while (pindexNewTip != pindexMostWork);
CheckBlockIndex();

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("ActivateBestChain_ms", diff.total_milliseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("ActivateBestChain_ms", diff, 1.0f);

// Write changes periodically to disk, after relay.
if (!FlushStateToDisk(state, FlushStateMode::PERIODIC)) {
Expand Down Expand Up @@ -3758,7 +3752,7 @@ bool CheckBlock(const CBlock& block, BlockValidationState& state, const Consensu
{
// These are checks that are independent of context.

boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();

if (block.fChecked)
return true;
Expand Down Expand Up @@ -3821,9 +3815,9 @@ bool CheckBlock(const CBlock& block, BlockValidationState& state, const Consensu
if (fCheckPOW && fCheckMerkleRoot)
block.fChecked = true;

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("CheckBlock_us", diff.total_microseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("CheckBlock_us", diff, 1.0f);

return true;
}
Expand Down Expand Up @@ -4128,7 +4122,7 @@ bool ChainstateManager::ProcessNewBlockHeaders(const std::vector<CBlockHeader>&
/** Store block on disk. If dbp is non-nullptr, the file is known to already reside on disk */
bool CChainState::AcceptBlock(const std::shared_ptr<const CBlock>& pblock, BlockValidationState& state, CBlockIndex** ppindex, bool fRequested, const FlatFilePos* dbp, bool* fNewBlock)
{
boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
auto start = GetTimeMicros();

const CBlock& block = *pblock;

Expand Down Expand Up @@ -4210,9 +4204,9 @@ bool CChainState::AcceptBlock(const std::shared_ptr<const CBlock>& pblock, Block

CheckBlockIndex();

boost::posix_time::ptime finish = boost::posix_time::microsec_clock::local_time();
boost::posix_time::time_duration diff = finish - start;
statsClient.timing("AcceptBlock_us", diff.total_microseconds(), 1.0f);
auto finish = GetTimeMicros();
auto diff = finish - start;
statsClient.timing("AcceptBlock_us", diff, 1.0f);

return true;
}
Expand Down

0 comments on commit 4f34cfa

Please sign in to comment.