More "bench" log for Dash specific parts (#2884)

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<Consensus::LLMQType, std::vector<uint256>> 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;
 }
 

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;
 }
 

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;
+    int64_t nTime5_5 = GetTimeMicros(); nTimeProcessSpecial += nTime5_5 - nTime5_4;
-    LogPrint("bench", "    - Payee and special txes: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimePayeeAndSpecial * 0.000001);
+    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