Skip to content

Commit

Permalink
Merge bitcoin#10303: [bench] Include ms/blk stats in Connect* benchma…
Browse files Browse the repository at this point in the history 
…rks.

a473eff [bench] Replace 0.00(000)1 with MICRO/MILLI #defines in validation.cpp. (Karl-Johan Alm)
5f850b0 [bench] Include ms/blk stats in Connect* benchmarks. (Karl-Johan Alm)

Pull request description:

  Display the average per block runtime for the various benchmarked times in the block connect functions to give an overview of long(er) term time distribution statistics.

Tree-SHA512: 3d6f24f6b9e3dbb448a647e2cda8e7b90ad6a16d4821f49f426a8e1ebc3ce5a0cf0a8cde82213e293affba441615702dfe50822c8c818e282af03bfe383d83e0

More of 10303
  • Loading branch information
@laanwj @PastaPastaPasta
laanwj authored and PastaPastaPasta committed Jan 2, 2020
1 parent 6f36208 commit 73c57aa
Showing 1 changed file with 26 additions and 20 deletions.
46 changes: 26 additions & 20 deletions src/validation.cpp
View file
Expand Up @@ -64,6 +64,9 @@
# error "Dash Core cannot be compiled without assertions."
#endif

#define MICRO 0.000001
#define MILLI 0.001

/**
* Global state
*/
Expand Down Expand Up @@ -1809,6 +1812,7 @@ static int64_t nTimeConnect = 0;
static int64_t nTimeIndex = 0;
static int64_t nTimeCallbacks = 0;
static int64_t nTimeTotal = 0;
static int64_t nBlocksTotal = 0;

/** Apply the effects of this block (with given index) on the UTXO set represented by coins.
* Validity checks that depend on the UTXO set are also done; ConnectBlock()
Expand Down Expand Up @@ -1853,6 +1857,8 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
return true;
}

nBlocksTotal++;

bool fScriptChecks = true;
if (!hashAssumeValid.IsNull()) {
// We've been configured with the hash of a block which has been externally verified to have a valid history.
Expand Down Expand Up @@ -1880,7 +1886,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
}

int64_t nTime1 = GetTimeMicros(); nTimeCheck += nTime1 - nTimeStart;
LogPrint(BCLog::BENCHMARK, " - Sanity checks: %.2fms [%.2fs]\n", 0.001 * (nTime1 - nTimeStart), nTimeCheck * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Sanity checks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime1 - nTimeStart), nTimeCheck * MICRO, nTimeCheck * MILLI / nBlocksTotal);

// Do not allow blocks that contain transactions which 'overwrite' older transactions,
// unless those are already completely spent.
Expand Down Expand Up @@ -1940,7 +1946,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
unsigned int flags = GetBlockScriptFlags(pindex, chainparams.GetConsensus());

int64_t nTime2 = GetTimeMicros(); nTimeForks += nTime2 - nTime1;
LogPrint(BCLog::BENCHMARK, " - Fork checks: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimeForks * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime2 - nTime1), nTimeForks * MICRO, nTimeForks * MILLI / nBlocksTotal);

CBlockUndo blockundo;

Expand Down Expand Up @@ -2100,12 +2106,12 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION);
}
int64_t nTime3 = GetTimeMicros(); nTimeConnect += nTime3 - nTime2;
LogPrint(BCLog::BENCHMARK, " - Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin) [%.2fs]\n", (unsigned)block.vtx.size(), 0.001 * (nTime3 - nTime2), 0.001 * (nTime3 - nTime2) / block.vtx.size(), nInputs <= 1 ? 0 : 0.001 * (nTime3 - nTime2) / (nInputs-1), nTimeConnect * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin) [%.2fs (%.2fms/blk)]\n", (unsigned)block.vtx.size(), MILLI * (nTime3 - nTime2), MILLI * (nTime3 - nTime2) / block.vtx.size(), nInputs <= 1 ? 0 : MILLI * (nTime3 - nTime2) / (nInputs-1), nTimeConnect * MICRO, nTimeConnect * MILLI / nBlocksTotal);

if (!control.Wait())
return state.DoS(100, error("%s: CheckQueue failed", __func__), REJECT_INVALID, "block-validation-failed");
int64_t nTime4 = GetTimeMicros(); nTimeVerify += nTime4 - nTime2;
LogPrint(BCLog::BENCHMARK, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs]\n", nInputs - 1, 0.001 * (nTime4 - nTime2), nInputs <= 1 ? 0 : 0.001 * (nTime4 - nTime2) / (nInputs-1), nTimeVerify * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs (%.2fms/blk)]\n", nInputs - 1, MILLI * (nTime4 - nTime2), nInputs <= 1 ? 0 : MILLI * (nTime4 - nTime2) / (nInputs-1), nTimeVerify * MICRO, nTimeVerify * MILLI / nBlocksTotal);


// DASH
Expand Down Expand Up @@ -2143,7 +2149,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
}

int64_t nTime5_1 = GetTimeMicros(); nTimeISFilter += nTime5_1 - nTime4;
LogPrint(BCLog::BENCHMARK, " - IS filter: %.2fms [%.2fs]\n", 0.001 * (nTime5_1 - nTime4), nTimeISFilter * 0.000001);
LogPrint(BCLog::BENCHMARK, " - IS filter: %.2fms [%.2fs]\n", MICRO * (nTime5_1 - nTime4), nTimeISFilter * MICRO, nTimeISFilter * MILLI / nBlocksTotal);

// DASH : MODIFIED TO CHECK MASTERNODE PAYMENTS AND SUPERBLOCKS

Expand All @@ -2152,33 +2158,33 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
std::string strError = "";

int64_t nTime5_2 = GetTimeMicros(); nTimeSubsidy += nTime5_2 - nTime5_1;
LogPrint(BCLog::BENCHMARK, " - GetBlockSubsidy: %.2fms [%.2fs]\n", 0.001 * (nTime5_2 - nTime5_1), nTimeSubsidy * 0.000001);
LogPrint(BCLog::BENCHMARK, " - GetBlockSubsidy: %.2fms [%.2fs (%.2fms/blk)]\n", MICRO * (nTime5_2 - nTime5_1), nTimeSubsidy * MICRO, nTimeSubsidy * MILLI / nBlocksTotal);

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(BCLog::BENCHMARK, " - IsBlockValueValid: %.2fms [%.2fs]\n", 0.001 * (nTime5_3 - nTime5_2), nTimeValueValid * 0.000001);
LogPrint(BCLog::BENCHMARK, " - IsBlockValueValid: %.2fms [%.2fs (%.2fms/blk)]\n", MICRO * (nTime5_3 - nTime5_2), nTimeValueValid * MICRO, nTimeValueValid * MILLI / nBlocksTotal);

if (!IsBlockPayeeValid(*block.vtx[0], pindex->nHeight, blockReward)) {
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(BCLog::BENCHMARK, " - IsBlockPayeeValid: %.2fms [%.2fs]\n", 0.001 * (nTime5_4 - nTime5_3), nTimePayeeValid * 0.000001);
LogPrint(BCLog::BENCHMARK, " - IsBlockPayeeValid: %.2fms [%.2fs (%.2fms/blk)]\n", MICRO * (nTime5_4 - nTime5_3), nTimePayeeValid * MICRO, nTimePayeeValid * MILLI / nBlocksTotal);

if (!ProcessSpecialTxsInBlock(block, pindex, state, fJustCheck, fScriptChecks)) {
return error("ConnectBlock(DASH): ProcessSpecialTxsInBlock for block %s failed with %s",
pindex->GetBlockHash().ToString(), FormatStateMessage(state));
}

int64_t nTime5_5 = GetTimeMicros(); nTimeProcessSpecial += nTime5_5 - nTime5_4;
LogPrint(BCLog::BENCHMARK, " - ProcessSpecialTxsInBlock: %.2fms [%.2fs]\n", 0.001 * (nTime5_5 - nTime5_4), nTimeProcessSpecial * 0.000001);
LogPrint(BCLog::BENCHMARK, " - ProcessSpecialTxsInBlock: %.2fms [%.2fs (%.2fms/blk)]\n", MICRO * (nTime5_5 - nTime5_4), nTimeProcessSpecial * MICRO, nTimeProcessSpecial * MILLI / nBlocksTotal);

int64_t nTime5 = GetTimeMicros(); nTimeDashSpecific += nTime5 - nTime4;
LogPrint(BCLog::BENCHMARK, " - Dash specific: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimeDashSpecific * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Dash specific: %.2fms [%.2fs (%.2fms/blk)]\n", MICRO * (nTime5 - nTime4), nTimeDashSpecific * MICRO, nTimeDashSpecific * MILLI / nBlocksTotal);

// END DASH

Expand Down Expand Up @@ -2230,12 +2236,12 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
view.SetBestBlock(pindex->GetBlockHash());

int64_t nTime6 = GetTimeMicros(); nTimeIndex += nTime6 - nTime5;
LogPrint(BCLog::BENCHMARK, " - Index writing: %.2fms [%.2fs]\n", 0.001 * (nTime6 - nTime5), nTimeIndex * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);

evoDb->WriteBestBlock(pindex->GetBlockHash());

int64_t nTime7 = GetTimeMicros(); nTimeCallbacks += nTime7 - nTime6;
LogPrint(BCLog::BENCHMARK, " - Callbacks: %.2fms [%.2fs]\n", 0.001 * (nTime7 - nTime6), nTimeCallbacks * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Callbacks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime7 - nTime6), nTimeCallbacks * MICRO, nTimeCallbacks * MILLI / nBlocksTotal);

return true;
}
Expand Down Expand Up @@ -2467,7 +2473,7 @@ bool static DisconnectTip(CValidationState& state, const CChainParams& chainpara
assert(flushed);
dbTx->Commit();
}
LogPrint(BCLog::BENCHMARK, "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * 0.001);
LogPrint(BCLog::BENCHMARK, "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * MILLI);
// Write the chain state to disk, if necessary.
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
return false;
Expand Down Expand Up @@ -2588,7 +2594,7 @@ bool static ConnectTip(CValidationState& state, const CChainParams& chainparams,
// Apply the block atomically to the chain state.
int64_t nTime2 = GetTimeMicros(); nTimeReadFromDisk += nTime2 - nTime1;
int64_t nTime3;
LogPrint(BCLog::BENCHMARK, " - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * 0.001, nTimeReadFromDisk * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * MILLI, nTimeReadFromDisk * MICRO);
{
auto dbTx = evoDb->BeginTransaction();

Expand All @@ -2601,27 +2607,27 @@ bool static ConnectTip(CValidationState& state, const CChainParams& chainparams,
return error("ConnectTip(): ConnectBlock %s failed with %s", pindexNew->GetBlockHash().ToString(), FormatStateMessage(state));
}
nTime3 = GetTimeMicros(); nTimeConnectTotal += nTime3 - nTime2;
LogPrint(BCLog::BENCHMARK, " - Connect total: %.2fms [%.2fs]\n", (nTime3 - nTime2) * 0.001, nTimeConnectTotal * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime3 - nTime2) * MILLI, nTimeConnectTotal * MICRO, nTimeConnectTotal * MILLI / nBlocksTotal);
bool flushed = view.Flush();
assert(flushed);
dbTx->Commit();
}
int64_t nTime4 = GetTimeMicros(); nTimeFlush += nTime4 - nTime3;
LogPrint(BCLog::BENCHMARK, " - Flush: %.2fms [%.2fs]\n", (nTime4 - nTime3) * 0.001, nTimeFlush * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime4 - nTime3) * MILLI, nTimeFlush * MICRO, nTimeFlush * MILLI / nBlocksTotal);
// Write the chain state to disk, if necessary.
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
return false;
int64_t nTime5 = GetTimeMicros(); nTimeChainState += nTime5 - nTime4;
LogPrint(BCLog::BENCHMARK, " - Writing chainstate: %.2fms [%.2fs]\n", (nTime5 - nTime4) * 0.001, nTimeChainState * 0.000001);
LogPrint(BCLog::BENCHMARK, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime5 - nTime4) * MILLI, nTimeChainState * MICRO, nTimeChainState * MILLI / nBlocksTotal);
// Remove conflicting transactions from the mempool.;
mempool.removeForBlock(blockConnecting.vtx, pindexNew->nHeight);
disconnectpool.removeForBlock(blockConnecting.vtx);
// Update chainActive & related variables.
UpdateTip(pindexNew, chainparams);

int64_t nTime6 = GetTimeMicros(); nTimePostConnect += nTime6 - nTime5; nTimeTotal += nTime6 - nTime1;
LogPrint(BCLog::BENCHMARK, " - Connect postprocess: %.2fms [%.2fs]\n", (nTime6 - nTime5) * 0.001, nTimePostConnect * 0.000001);
LogPrint(BCLog::BENCHMARK, "- Connect block: %.2fms [%.2fs]\n", (nTime6 - nTime1) * 0.001, nTimeTotal * 0.000001);
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);

connectTrace.BlockConnected(pindexNew, std::move(pthisBlock));
return true;
Expand Down Expand Up @@ -4754,7 +4760,7 @@ void DumpMempool(void)
file.fclose();
RenameOver(GetDataDir() / "mempool.dat.new", GetDataDir() / "mempool.dat");
int64_t last = GetTimeMicros();
LogPrintf("Dumped mempool: %gs to copy, %gs to dump\n", (mid-start)*0.000001, (last-mid)*0.000001);
LogPrintf("Dumped mempool: %gs to copy, %gs to dump\n", (mid-start)*MICRO, (last-mid)*MICRO);
} catch (const std::exception& e) {
LogPrintf("Failed to dump mempool: %s. Continuing anyway.\n", e.what());
}
Expand Down

0 comments on commit 73c57aa

Please sign in to comment.