Merge #10303: [bench] Include ms/blk stats in Connect* benchmarks.
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
This commit is contained in:
commit
f088a1bb39
1 changed files with 20 additions and 14 deletions
|
@ -53,6 +53,9 @@
|
||||||
# error "Bitcoin cannot be compiled without assertions."
|
# error "Bitcoin cannot be compiled without assertions."
|
||||||
#endif
|
#endif
|
||||||
|
|
||||||
|
#define MICRO 0.000001
|
||||||
|
#define MILLI 0.001
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Global state
|
* Global state
|
||||||
*/
|
*/
|
||||||
|
@ -1623,6 +1626,7 @@ static int64_t nTimeConnect = 0;
|
||||||
static int64_t nTimeIndex = 0;
|
static int64_t nTimeIndex = 0;
|
||||||
static int64_t nTimeCallbacks = 0;
|
static int64_t nTimeCallbacks = 0;
|
||||||
static int64_t nTimeTotal = 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.
|
/** 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()
|
* Validity checks that depend on the UTXO set are also done; ConnectBlock()
|
||||||
|
@ -1653,6 +1657,8 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
return true;
|
return true;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
nBlocksTotal++;
|
||||||
|
|
||||||
bool fScriptChecks = true;
|
bool fScriptChecks = true;
|
||||||
if (!hashAssumeValid.IsNull()) {
|
if (!hashAssumeValid.IsNull()) {
|
||||||
// We've been configured with the hash of a block which has been externally verified to have a valid history.
|
// We've been configured with the hash of a block which has been externally verified to have a valid history.
|
||||||
|
@ -1680,7 +1686,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
}
|
}
|
||||||
|
|
||||||
int64_t nTime1 = GetTimeMicros(); nTimeCheck += nTime1 - nTimeStart;
|
int64_t nTime1 = GetTimeMicros(); nTimeCheck += nTime1 - nTimeStart;
|
||||||
LogPrint(BCLog::BENCH, " - Sanity checks: %.2fms [%.2fs]\n", 0.001 * (nTime1 - nTimeStart), nTimeCheck * 0.000001);
|
LogPrint(BCLog::BENCH, " - 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,
|
// Do not allow blocks that contain transactions which 'overwrite' older transactions,
|
||||||
// unless those are already completely spent.
|
// unless those are already completely spent.
|
||||||
|
@ -1729,7 +1735,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
unsigned int flags = GetBlockScriptFlags(pindex, chainparams.GetConsensus());
|
unsigned int flags = GetBlockScriptFlags(pindex, chainparams.GetConsensus());
|
||||||
|
|
||||||
int64_t nTime2 = GetTimeMicros(); nTimeForks += nTime2 - nTime1;
|
int64_t nTime2 = GetTimeMicros(); nTimeForks += nTime2 - nTime1;
|
||||||
LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs]\n", 0.001 * (nTime2 - nTime1), nTimeForks * 0.000001);
|
LogPrint(BCLog::BENCH, " - Fork checks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime2 - nTime1), nTimeForks * MICRO, nTimeForks * MILLI / nBlocksTotal);
|
||||||
|
|
||||||
CBlockUndo blockundo;
|
CBlockUndo blockundo;
|
||||||
|
|
||||||
|
@ -1803,7 +1809,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION);
|
pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION);
|
||||||
}
|
}
|
||||||
int64_t nTime3 = GetTimeMicros(); nTimeConnect += nTime3 - nTime2;
|
int64_t nTime3 = GetTimeMicros(); nTimeConnect += nTime3 - nTime2;
|
||||||
LogPrint(BCLog::BENCH, " - 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::BENCH, " - 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);
|
||||||
|
|
||||||
CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, chainparams.GetConsensus());
|
CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, chainparams.GetConsensus());
|
||||||
if (block.vtx[0]->GetValueOut() > blockReward)
|
if (block.vtx[0]->GetValueOut() > blockReward)
|
||||||
|
@ -1815,7 +1821,7 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
if (!control.Wait())
|
if (!control.Wait())
|
||||||
return state.DoS(100, error("%s: CheckQueue failed", __func__), REJECT_INVALID, "block-validation-failed");
|
return state.DoS(100, error("%s: CheckQueue failed", __func__), REJECT_INVALID, "block-validation-failed");
|
||||||
int64_t nTime4 = GetTimeMicros(); nTimeVerify += nTime4 - nTime2;
|
int64_t nTime4 = GetTimeMicros(); nTimeVerify += nTime4 - nTime2;
|
||||||
LogPrint(BCLog::BENCH, " - 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::BENCH, " - 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);
|
||||||
|
|
||||||
if (fJustCheck)
|
if (fJustCheck)
|
||||||
return true;
|
return true;
|
||||||
|
@ -1847,10 +1853,10 @@ static bool ConnectBlock(const CBlock& block, CValidationState& state, CBlockInd
|
||||||
view.SetBestBlock(pindex->GetBlockHash());
|
view.SetBestBlock(pindex->GetBlockHash());
|
||||||
|
|
||||||
int64_t nTime5 = GetTimeMicros(); nTimeIndex += nTime5 - nTime4;
|
int64_t nTime5 = GetTimeMicros(); nTimeIndex += nTime5 - nTime4;
|
||||||
LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs]\n", 0.001 * (nTime5 - nTime4), nTimeIndex * 0.000001);
|
LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime5 - nTime4), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);
|
||||||
|
|
||||||
int64_t nTime6 = GetTimeMicros(); nTimeCallbacks += nTime6 - nTime5;
|
int64_t nTime6 = GetTimeMicros(); nTimeCallbacks += nTime6 - nTime5;
|
||||||
LogPrint(BCLog::BENCH, " - Callbacks: %.2fms [%.2fs]\n", 0.001 * (nTime6 - nTime5), nTimeCallbacks * 0.000001);
|
LogPrint(BCLog::BENCH, " - Callbacks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeCallbacks * MICRO, nTimeCallbacks * MILLI / nBlocksTotal);
|
||||||
|
|
||||||
return true;
|
return true;
|
||||||
}
|
}
|
||||||
|
@ -2075,7 +2081,7 @@ bool static DisconnectTip(CValidationState& state, const CChainParams& chainpara
|
||||||
bool flushed = view.Flush();
|
bool flushed = view.Flush();
|
||||||
assert(flushed);
|
assert(flushed);
|
||||||
}
|
}
|
||||||
LogPrint(BCLog::BENCH, "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * 0.001);
|
LogPrint(BCLog::BENCH, "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * MILLI);
|
||||||
// Write the chain state to disk, if necessary.
|
// Write the chain state to disk, if necessary.
|
||||||
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
|
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
|
||||||
return false;
|
return false;
|
||||||
|
@ -2196,7 +2202,7 @@ bool static ConnectTip(CValidationState& state, const CChainParams& chainparams,
|
||||||
// Apply the block atomically to the chain state.
|
// Apply the block atomically to the chain state.
|
||||||
int64_t nTime2 = GetTimeMicros(); nTimeReadFromDisk += nTime2 - nTime1;
|
int64_t nTime2 = GetTimeMicros(); nTimeReadFromDisk += nTime2 - nTime1;
|
||||||
int64_t nTime3;
|
int64_t nTime3;
|
||||||
LogPrint(BCLog::BENCH, " - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * 0.001, nTimeReadFromDisk * 0.000001);
|
LogPrint(BCLog::BENCH, " - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * MILLI, nTimeReadFromDisk * MICRO);
|
||||||
{
|
{
|
||||||
CCoinsViewCache view(pcoinsTip);
|
CCoinsViewCache view(pcoinsTip);
|
||||||
bool rv = ConnectBlock(blockConnecting, state, pindexNew, view, chainparams);
|
bool rv = ConnectBlock(blockConnecting, state, pindexNew, view, chainparams);
|
||||||
|
@ -2207,17 +2213,17 @@ bool static ConnectTip(CValidationState& state, const CChainParams& chainparams,
|
||||||
return error("ConnectTip(): ConnectBlock %s failed", pindexNew->GetBlockHash().ToString());
|
return error("ConnectTip(): ConnectBlock %s failed", pindexNew->GetBlockHash().ToString());
|
||||||
}
|
}
|
||||||
nTime3 = GetTimeMicros(); nTimeConnectTotal += nTime3 - nTime2;
|
nTime3 = GetTimeMicros(); nTimeConnectTotal += nTime3 - nTime2;
|
||||||
LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs]\n", (nTime3 - nTime2) * 0.001, nTimeConnectTotal * 0.000001);
|
LogPrint(BCLog::BENCH, " - Connect total: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime3 - nTime2) * MILLI, nTimeConnectTotal * MICRO, nTimeConnectTotal * MILLI / nBlocksTotal);
|
||||||
bool flushed = view.Flush();
|
bool flushed = view.Flush();
|
||||||
assert(flushed);
|
assert(flushed);
|
||||||
}
|
}
|
||||||
int64_t nTime4 = GetTimeMicros(); nTimeFlush += nTime4 - nTime3;
|
int64_t nTime4 = GetTimeMicros(); nTimeFlush += nTime4 - nTime3;
|
||||||
LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs]\n", (nTime4 - nTime3) * 0.001, nTimeFlush * 0.000001);
|
LogPrint(BCLog::BENCH, " - Flush: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime4 - nTime3) * MILLI, nTimeFlush * MICRO, nTimeFlush * MILLI / nBlocksTotal);
|
||||||
// Write the chain state to disk, if necessary.
|
// Write the chain state to disk, if necessary.
|
||||||
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
|
if (!FlushStateToDisk(chainparams, state, FLUSH_STATE_IF_NEEDED))
|
||||||
return false;
|
return false;
|
||||||
int64_t nTime5 = GetTimeMicros(); nTimeChainState += nTime5 - nTime4;
|
int64_t nTime5 = GetTimeMicros(); nTimeChainState += nTime5 - nTime4;
|
||||||
LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs]\n", (nTime5 - nTime4) * 0.001, nTimeChainState * 0.000001);
|
LogPrint(BCLog::BENCH, " - Writing chainstate: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime5 - nTime4) * MILLI, nTimeChainState * MICRO, nTimeChainState * MILLI / nBlocksTotal);
|
||||||
// Remove conflicting transactions from the mempool.;
|
// Remove conflicting transactions from the mempool.;
|
||||||
mempool.removeForBlock(blockConnecting.vtx, pindexNew->nHeight);
|
mempool.removeForBlock(blockConnecting.vtx, pindexNew->nHeight);
|
||||||
disconnectpool.removeForBlock(blockConnecting.vtx);
|
disconnectpool.removeForBlock(blockConnecting.vtx);
|
||||||
|
@ -2225,8 +2231,8 @@ bool static ConnectTip(CValidationState& state, const CChainParams& chainparams,
|
||||||
UpdateTip(pindexNew, chainparams);
|
UpdateTip(pindexNew, chainparams);
|
||||||
|
|
||||||
int64_t nTime6 = GetTimeMicros(); nTimePostConnect += nTime6 - nTime5; nTimeTotal += nTime6 - nTime1;
|
int64_t nTime6 = GetTimeMicros(); nTimePostConnect += nTime6 - nTime5; nTimeTotal += nTime6 - nTime1;
|
||||||
LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs]\n", (nTime6 - nTime5) * 0.001, nTimePostConnect * 0.000001);
|
LogPrint(BCLog::BENCH, " - Connect postprocess: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime6 - nTime5) * MILLI, nTimePostConnect * MICRO, nTimePostConnect * MILLI / nBlocksTotal);
|
||||||
LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs]\n", (nTime6 - nTime1) * 0.001, nTimeTotal * 0.000001);
|
LogPrint(BCLog::BENCH, "- Connect block: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime6 - nTime1) * MILLI, nTimeTotal * MICRO, nTimeTotal * MILLI / nBlocksTotal);
|
||||||
|
|
||||||
connectTrace.BlockConnected(pindexNew, std::move(pthisBlock));
|
connectTrace.BlockConnected(pindexNew, std::move(pthisBlock));
|
||||||
return true;
|
return true;
|
||||||
|
@ -4367,7 +4373,7 @@ void DumpMempool(void)
|
||||||
file.fclose();
|
file.fclose();
|
||||||
RenameOver(GetDataDir() / "mempool.dat.new", GetDataDir() / "mempool.dat");
|
RenameOver(GetDataDir() / "mempool.dat.new", GetDataDir() / "mempool.dat");
|
||||||
int64_t last = GetTimeMicros();
|
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) {
|
} catch (const std::exception& e) {
|
||||||
LogPrintf("Failed to dump mempool: %s. Continuing anyway.\n", e.what());
|
LogPrintf("Failed to dump mempool: %s. Continuing anyway.\n", e.what());
|
||||||
}
|
}
|
||||||
|
|
Loading…
Reference in a new issue