From b6d184b2b2e4d90367d0cb90165b60d791f066f6 Mon Sep 17 00:00:00 2001 From: "James C. Owens" Date: Sun, 31 Mar 2024 14:18:02 -0400 Subject: [PATCH] Instrument ProcessBlock and PushGetBlocks --- src/gridcoin/staking/spam.h | 5 ++++ src/main.cpp | 56 ++++++++++++++++++++++++++++++++++++- src/net.cpp | 27 ++++++++++++++++++ 3 files changed, 87 insertions(+), 1 deletion(-) diff --git a/src/gridcoin/staking/spam.h b/src/gridcoin/staking/spam.h index 84918e8eeb..dc408e9a89 100644 --- a/src/gridcoin/staking/spam.h +++ b/src/gridcoin/staking/spam.h @@ -145,6 +145,11 @@ class SeenStakes } } + size_t OrphanProofsSeenSize() + { + return m_orphan_proofs_seen.size(); + } + private: //! //! \brief A hash table of recently-observed kernel proof hashes. diff --git a/src/main.cpp b/src/main.cpp index f20773b226..18e8e576b3 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -1460,6 +1460,10 @@ bool AskForOutstandingBlocks(uint256 hashStart) bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_LOCKS_REQUIRED(cs_main) { + std::string function = __func__; + + g_timer.InitTimer(function, LogInstance().WillLogCategory(BCLog::LogFlags::MISC)); + AssertLockHeld(cs_main); // Check for duplicate @@ -1469,6 +1473,8 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_ if (mapOrphanBlocks.count(hash)) return error("ProcessBlock() : already have block (orphan) %s", hash.ToString().c_str()); + g_timer.GetTimes("Check for duplicate", function); + if (pblock->hashPrevBlock != hashBestChain) { // Extra checks to prevent "fill up memory by spamming with bogus blocks" @@ -1484,10 +1490,14 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_ } } + g_timer.GetTimes("Checkpoint check", function); + // Preliminary checks if (!CheckBlock(*pblock, pindexBest->nHeight + 1)) return error("ProcessBlock() : CheckBlock FAILED"); + g_timer.GetTimes("CheckBlock", function); + // If don't already have its previous block, shunt it off to holding area until we get it if (!pblock->hashPrevBlock.IsNull() && !mapBlockIndex.count(pblock->hashPrevBlock)) { @@ -1512,18 +1522,34 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_ } } + g_timer.GetTimes("Orphan processing: proof of stake duplicate check", function); + CBlock* pblock2 = new CBlock(*pblock); mapOrphanBlocks.insert(make_pair(hash, pblock2)); + g_timer.GetTimes("Orphan processing: mapOrphanBlocks.insert", function); + mapOrphanBlocksByPrev.insert(make_pair(pblock->hashPrevBlock, pblock2)); + g_timer.GetTimes("Orphan processing: mapOrphanBlocksByPrev.insert", function); // Ask this guy to fill in what we're missing const CBlock* const pblock_root = GetOrphanRoot(pblock2); + g_timer.GetTimes("Orphan processing: GetOrphanRoot", function); + pfrom->PushGetBlocks(pindexBest, pblock_root->GetHash(true)); + + LogPrint(BCLog::LogFlags::MISC, "INFO: %s: pfrom->PushGetBlocks(%s, %s)", + __func__, + pindexBest->GetBlockHash().GetHex(), + pblock_root->GetHash(true).GetHex()); + + g_timer.GetTimes("Orphan processing: pfrom->PushGetBlocks", function); + // ppcoin: getblocks may not obtain the ancestor block rejected // earlier by duplicate-stake check so we ask for it again directly if (!IsInitialBlockDownload()) { const CInv ancestor_request(MSG_BLOCK, pblock_root->hashPrevBlock); + g_timer.GetTimes(function + " orphan processing: ancestor_request", function); // Ensure that this request is not deferred. CNode::AskFor() bumps // the earliest time for a message by two minutes for each call. A @@ -1535,8 +1561,11 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_ // mapAlreadyAskedFor[ancestor_request] = 0; pfrom->AskFor(ancestor_request); + g_timer.GetTimes("Orphan processing: pfrom->AskFor", function); } + g_timer.GetTimes("Request missing blocks complete", function); + return true; } @@ -1544,26 +1573,51 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock, bool generated_by_me) EXCLUSIVE_ if (!AcceptBlock(*pblock, generated_by_me)) return error("ProcessBlock() : AcceptBlock FAILED"); + g_timer.GetTimes("AcceptBlock", function); + // Recursively process any orphan blocks that depended on this one vector vWorkQueue; vWorkQueue.push_back(hash); for (unsigned int i = 0; i < vWorkQueue.size(); i++) { uint256 hashPrev = vWorkQueue[i]; + + LogPrint(BCLog::LogFlags::VERBOSE, "INFO: %s: vWorkQueue.size() = %u, vWorkQueue[%u] = %s", + __func__, + vWorkQueue.size(), + i, + hashPrev.GetHex()); + + unsigned int j = 0; + for (multimap::iterator mi = mapOrphanBlocksByPrev.lower_bound(hashPrev); mi != mapOrphanBlocksByPrev.upper_bound(hashPrev); - ++mi) + ++mi, ++j) { CBlock* pblockOrphan = mi->second; + + LogPrint(BCLog::LogFlags::VERBOSE, "INFO: %s: mapOrphanBlocksbyPrev match element %u, pblockOrphan hash = %s", + __func__, + j, + pblockOrphan->GetHash(true).GetHex()); + if (AcceptBlock(*pblockOrphan, generated_by_me)) vWorkQueue.push_back(pblockOrphan->GetHash(true)); mapOrphanBlocks.erase(pblockOrphan->GetHash(true)); g_seen_stakes.ForgetOrphan(pblockOrphan->vtx[1]); + + LogPrint(BCLog::LogFlags::VERBOSE, "INFO: %s: mapOrphanBlocks.size() = %u, g_seen_stakes.size() = %u", + __func__, + mapOrphanBlocks.size(), + g_seen_stakes.OrphanProofsSeenSize()); + delete pblockOrphan; } mapOrphanBlocksByPrev.erase(hashPrev); } + g_timer.GetTimes("Dependent orphan processing on accepted block complete", function); + return true; } diff --git a/src/net.cpp b/src/net.cpp index 0f1f87cf0d..b3ed168f23 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -131,17 +131,44 @@ unsigned short GetListenPort() void CNode::PushGetBlocks(CBlockIndex* pindexBegin, uint256 hashEnd) { + LogPrint(BCLog::LogFlags::MISC, "INFO: %s: pnode = %" PRId64 ", id = %" PRId64 ", address = %s", + __func__, + (uint64_t) this, + id, + addr.ToString()); + + std::string function = {__func__}; + + g_timer.InitTimer(function, LogInstance().WillLogCategory(BCLog::LogFlags::MISC)); + if (pindexBegin == pindexLastGetBlocksBegin && hashEnd == hashLastGetBlocksEnd) return; // Filter out duplicate requests pindexLastGetBlocksBegin = pindexBegin; hashLastGetBlocksEnd = hashEnd; + g_timer.GetTimes("Before caching check", __func__); + if (pindexBegin != g_getblocks_pindex_begin) { + LogPrint(BCLog::LogFlags::MISC, "INFO: %s: pindexBegin->GetBlockHash() = %s, pindexBegin = %" PRId64 ", " + "g_getblocks_pindex_begin->GetBlockHash() = %s, g_getblocks_pindex_begin = %" PRId64, + __func__, + pindexBegin ? pindexBegin->GetBlockHash().GetHex() : (uint256 {}).GetHex(), + (uint64_t) pindexBegin, + g_getblocks_pindex_begin ? g_getblocks_pindex_begin->GetBlockHash().GetHex() : (uint256 {}).GetHex(), + (uint64_t) g_getblocks_pindex_begin); + g_getblocks_pindex_begin = pindexBegin; g_getblocks_locator = CBlockLocator(pindexBegin); + + g_timer.GetTimes("After CBlockLocator(pindexBegin) call - cache miss", function); } + g_timer.GetTimes("Post cache check", function); + PushMessage(NetMsgType::GETBLOCKS, g_getblocks_locator, hashEnd); + + g_timer.GetTimes("PushMessage - PushGetBlocks complete", function); + } // find 'best' local address for a particular peer