From dd3977523a2ced196c5dad71be2949ca866f7e6f Mon Sep 17 00:00:00 2001 From: UdjinM6 Date: Tue, 30 Apr 2019 15:48:49 +0300 Subject: [PATCH] More "bench" log for Dash specific parts (#2884) --- src/evo/cbtx.cpp | 54 +++++++++++++++++++++++++++++++++++++++++++ src/evo/specialtx.cpp | 19 +++++++++++++++ src/validation.cpp | 27 +++++++++++++++++++--- 3 files changed, 97 insertions(+), 3 deletions(-) diff --git a/src/evo/cbtx.cpp b/src/evo/cbtx.cpp index 9e5bd7b7e1..ffa25a2508 100644 --- a/src/evo/cbtx.cpp +++ b/src/evo/cbtx.cpp @@ -55,11 +55,20 @@ bool CheckCbTxMerkleRoots(const CBlock& block, const CBlockIndex* pindex, CValid return true; } + static int64_t nTimePayload = 0; + static int64_t nTimeMerkleMNL = 0; + static int64_t nTimeMerkleQuorum = 0; + + int64_t nTime1 = GetTimeMicros(); + CCbTx cbTx; if (!GetTxPayload(*block.vtx[0], cbTx)) { return state.DoS(100, false, REJECT_INVALID, "bad-cbtx-payload"); } + int64_t nTime2 = GetTimeMicros(); nTimePayload += nTime2 - nTime1; + LogPrint("bench", " - GetTxPayload: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimePayload * 0.000001); + if (pindex) { uint256 calculatedMerkleRoot; if (!CalcCbTxMerkleRootMNList(block, pindex->pprev, calculatedMerkleRoot, state)) { @@ -68,6 +77,10 @@ bool CheckCbTxMerkleRoots(const CBlock& block, const CBlockIndex* pindex, CValid if (calculatedMerkleRoot != cbTx.merkleRootMNList) { return state.DoS(100, false, REJECT_INVALID, "bad-cbtx-mnmerkleroot"); } + + int64_t nTime3 = GetTimeMicros(); nTimeMerkleMNL += nTime3 - nTime2; + LogPrint("bench", " - CalcCbTxMerkleRootMNList: %.2fms [%.2fs]\n", 0.001 * (nTime3 - nTime2), nTimeMerkleMNL * 0.000001); + if (cbTx.nVersion >= 2) { if (!CalcCbTxMerkleRootQuorums(block, pindex->pprev, calculatedMerkleRoot, state)) { return state.DoS(100, false, REJECT_INVALID, "bad-cbtx-quorummerkleroot"); @@ -76,6 +89,10 @@ bool CheckCbTxMerkleRoots(const CBlock& block, const CBlockIndex* pindex, CValid return state.DoS(100, false, REJECT_INVALID, "bad-cbtx-quorummerkleroot"); } } + + int64_t nTime4 = GetTimeMicros(); nTimeMerkleQuorum += nTime4 - nTime3; + LogPrint("bench", " - CalcCbTxMerkleRootQuorums: %.2fms [%.2fs]\n", 0.001 * (nTime4 - nTime3), nTimeMerkleQuorum * 0.000001); + } return true; @@ -85,23 +102,50 @@ bool CalcCbTxMerkleRootMNList(const CBlock& block, const CBlockIndex* pindexPrev { LOCK(deterministicMNManager->cs); + static int64_t nTimeDMN = 0; + static int64_t nTimeSMNL = 0; + static int64_t nTimeMerkle = 0; + + int64_t nTime1 = GetTimeMicros(); + CDeterministicMNList tmpMNList; if (!deterministicMNManager->BuildNewListFromBlock(block, pindexPrev, state, tmpMNList, false)) { return false; } + int64_t nTime2 = GetTimeMicros(); nTimeDMN += nTime2 - nTime1; + LogPrint("bench", " - BuildNewListFromBlock: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimeDMN * 0.000001); + CSimplifiedMNList sml(tmpMNList); + int64_t nTime3 = GetTimeMicros(); nTimeSMNL += nTime3 - nTime2; + LogPrint("bench", " - CSimplifiedMNList: %.2fms [%.2fs]\n", 0.001 * (nTime3 - nTime2), nTimeSMNL * 0.000001); + bool mutated = false; merkleRootRet = sml.CalcMerkleRoot(&mutated); + + int64_t nTime4 = GetTimeMicros(); nTimeMerkle += nTime4 - nTime3; + LogPrint("bench", " - CalcMerkleRoot: %.2fms [%.2fs]\n", 0.001 * (nTime4 - nTime3), nTimeMerkle * 0.000001); + return !mutated; } bool CalcCbTxMerkleRootQuorums(const CBlock& block, const CBlockIndex* pindexPrev, uint256& merkleRootRet, CValidationState& state) { + static int64_t nTimeMinedAndActive = 0; + static int64_t nTimeMined = 0; + static int64_t nTimeLoop = 0; + static int64_t nTimeMerkle = 0; + + int64_t nTime1 = GetTimeMicros(); + auto quorums = llmq::quorumBlockProcessor->GetMinedAndActiveCommitmentsUntilBlock(pindexPrev); std::map> qcHashes; size_t hashCount = 0; + + int64_t nTime2 = GetTimeMicros(); nTimeMinedAndActive += nTime2 - nTime1; + LogPrint("bench", " - GetMinedAndActiveCommitmentsUntilBlock: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimeMinedAndActive * 0.000001); + for (const auto& p : quorums) { auto& v = qcHashes[p.first]; v.reserve(p.second.size()); @@ -115,6 +159,9 @@ bool CalcCbTxMerkleRootQuorums(const CBlock& block, const CBlockIndex* pindexPre } } + int64_t nTime3 = GetTimeMicros(); nTimeMined += nTime3 - nTime2; + LogPrint("bench", " - GetMinedCommitment: %.2fms [%.2fs]\n", 0.001 * (nTime3 - nTime2), nTimeMined * 0.000001); + // now add the commitments from the current block, which are not returned by GetMinedAndActiveCommitmentsUntilBlock // due to the use of pindexPrev (we don't have the tip index here) for (size_t i = 1; i < block.vtx.size(); i++) { @@ -150,8 +197,15 @@ bool CalcCbTxMerkleRootQuorums(const CBlock& block, const CBlockIndex* pindexPre } std::sort(qcHashesVec.begin(), qcHashesVec.end()); + int64_t nTime4 = GetTimeMicros(); nTimeLoop += nTime4 - nTime3; + LogPrint("bench", " - Loop: %.2fms [%.2fs]\n", 0.001 * (nTime4 - nTime3), nTimeLoop * 0.000001); + bool mutated = false; merkleRootRet = ComputeMerkleRoot(qcHashesVec, &mutated); + + int64_t nTime5 = GetTimeMicros(); nTimeMerkle += nTime5 - nTime4; + LogPrint("bench", " - ComputeMerkleRoot: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimeMerkle * 0.000001); + return !mutated; } diff --git a/src/evo/specialtx.cpp b/src/evo/specialtx.cpp index 2f30493651..a416a0f5b5 100644 --- a/src/evo/specialtx.cpp +++ b/src/evo/specialtx.cpp @@ -88,6 +88,13 @@ bool UndoSpecialTx(const CTransaction& tx, const CBlockIndex* pindex) bool ProcessSpecialTxsInBlock(const CBlock& block, const CBlockIndex* pindex, CValidationState& state, bool fJustCheck) { + static int64_t nTimeLoop = 0; + static int64_t nTimeQuorum = 0; + static int64_t nTimeDMN = 0; + static int64_t nTimeMerkle = 0; + + int64_t nTime1 = GetTimeMicros(); + for (int i = 0; i < (int)block.vtx.size(); i++) { const CTransaction& tx = *block.vtx[i]; if (!CheckSpecialTx(tx, pindex->pprev, state)) { @@ -98,18 +105,30 @@ bool ProcessSpecialTxsInBlock(const CBlock& block, const CBlockIndex* pindex, CV } } + int64_t nTime2 = GetTimeMicros(); nTimeLoop += nTime2 - nTime1; + LogPrint("bench", " - Loop: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimeLoop * 0.000001); + if (!llmq::quorumBlockProcessor->ProcessBlock(block, pindex, state)) { return false; } + int64_t nTime3 = GetTimeMicros(); nTimeQuorum += nTime3 - nTime2; + LogPrint("bench", " - quorumBlockProcessor: %.2fms [%.2fs]\n", 0.001 * (nTime3 - nTime2), nTimeQuorum * 0.000001); + if (!deterministicMNManager->ProcessBlock(block, pindex, state, fJustCheck)) { return false; } + int64_t nTime4 = GetTimeMicros(); nTimeDMN += nTime4 - nTime3; + LogPrint("bench", " - deterministicMNManager: %.2fms [%.2fs]\n", 0.001 * (nTime4 - nTime3), nTimeDMN * 0.000001); + if (!CheckCbTxMerkleRoots(block, pindex, state)) { return false; } + int64_t nTime5 = GetTimeMicros(); nTimeMerkle += nTime5 - nTime4; + LogPrint("bench", " - CheckCbTxMerkleRoots: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimeMerkle * 0.000001); + return true; } diff --git a/src/validation.cpp b/src/validation.cpp index 8f4cd60dca..b1141dedf7 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1869,7 +1869,12 @@ static ThresholdConditionCache warningcache[VERSIONBITS_NUM_BITS]; static int64_t nTimeCheck = 0; static int64_t nTimeForks = 0; static int64_t nTimeVerify = 0; -static int64_t nTimePayeeAndSpecial = 0; +static int64_t nTimeISFilter = 0; +static int64_t nTimeSubsidy = 0; +static int64_t nTimeValueValid = 0; +static int64_t nTimePayeeValid = 0; +static int64_t nTimeProcessSpecial = 0; +static int64_t nTimeDashSpecific = 0; static int64_t nTimeConnect = 0; static int64_t nTimeIndex = 0; static int64_t nTimeCallbacks = 0; @@ -2226,28 +2231,44 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd LogPrintf("ConnectBlock(DASH): spork is off, skipping transaction locking checks\n"); } + int64_t nTime5_1 = GetTimeMicros(); nTimeISFilter += nTime5_1 - nTime4; + LogPrint("bench", " - IS filter: %.2fms [%.2fs]\n", 0.001 * (nTime5_1 - nTime4), nTimeISFilter * 0.000001); + // DASH : MODIFIED TO CHECK MASTERNODE PAYMENTS AND SUPERBLOCKS // TODO: resync data (both ways?) and try to reprocess this block later. CAmount blockReward = nFees + GetBlockSubsidy(pindex->pprev->nBits, pindex->pprev->nHeight, chainparams.GetConsensus()); std::string strError = ""; + + int64_t nTime5_2 = GetTimeMicros(); nTimeSubsidy += nTime5_2 - nTime5_1; + LogPrint("bench", " - GetBlockSubsidy: %.2fms [%.2fs]\n", 0.001 * (nTime5_2 - nTime5_1), nTimeSubsidy * 0.000001); + if (!IsBlockValueValid(block, pindex->nHeight, blockReward, strError)) { return state.DoS(0, error("ConnectBlock(DASH): %s", strError), REJECT_INVALID, "bad-cb-amount"); } + int64_t nTime5_3 = GetTimeMicros(); nTimeValueValid += nTime5_3 - nTime5_2; + LogPrint("bench", " - IsBlockValueValid: %.2fms [%.2fs]\n", 0.001 * (nTime5_3 - nTime5_2), nTimeValueValid * 0.000001); + if (!IsBlockPayeeValid(*block.vtx[0], pindex->nHeight, blockReward)) { mapRejectedBlocks.insert(std::make_pair(block.GetHash(), GetTime())); return state.DoS(0, error("ConnectBlock(DASH): couldn't find masternode or superblock payments"), REJECT_INVALID, "bad-cb-payee"); } + int64_t nTime5_4 = GetTimeMicros(); nTimePayeeValid += nTime5_4 - nTime5_3; + LogPrint("bench", " - IsBlockPayeeValid: %.2fms [%.2fs]\n", 0.001 * (nTime5_4 - nTime5_3), nTimePayeeValid * 0.000001); + if (!ProcessSpecialTxsInBlock(block, pindex, state, fJustCheck)) { return error("ConnectBlock(DASH): ProcessSpecialTxsInBlock for block %s failed with %s", pindex->GetBlockHash().ToString(), FormatStateMessage(state)); } - int64_t nTime5 = GetTimeMicros(); nTimePayeeAndSpecial += nTime5 - nTime4; - LogPrint("bench", " - Payee and special txes: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimePayeeAndSpecial * 0.000001); + int64_t nTime5_5 = GetTimeMicros(); nTimeProcessSpecial += nTime5_5 - nTime5_4; + LogPrint("bench", " - ProcessSpecialTxsInBlock: %.2fms [%.2fs]\n", 0.001 * (nTime5_5 - nTime5_4), nTimeProcessSpecial * 0.000001); + + int64_t nTime5 = GetTimeMicros(); nTimeDashSpecific += nTime5 - nTime4; + LogPrint("bench", " - Dash specific: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimeDashSpecific * 0.000001); // END DASH