Skip to content

Commit

Permalink
More "bench" log for Dash specific parts (#2884)
Browse files Browse the repository at this point in the history
  • Loading branch information
UdjinM6 committed Apr 30, 2019
1 parent 8ffdcbf commit dd39775
Show file tree
Hide file tree
Showing 3 changed files with 97 additions and 3 deletions.
54 changes: 54 additions & 0 deletions src/evo/cbtx.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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)) {
Expand All @@ -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");
Expand All @@ -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;
Expand All @@ -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());
Expand All @@ -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++) {
Expand Down Expand Up @@ -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;
}

Expand Down
19 changes: 19 additions & 0 deletions src/evo/specialtx.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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)) {
Expand All @@ -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;
}

Expand Down
27 changes: 24 additions & 3 deletions src/validation.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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

Expand Down

0 comments on commit dd39775

Please sign in to comment.