Browse Source

Rework block processing benchmark code

* Replace -benchmark (and the related fBenchmark) with a regular debug option, -debug=bench.
* Increase coverage and granularity of individual block processing steps.
* Add cummulative times.
0.10
Pieter Wuille 11 years ago
parent
commit
d70bc52ee3
  1. 7
      src/init.cpp
  2. 50
      src/main.cpp
  3. 1
      src/main.h

7
src/init.cpp

@ -285,7 +285,6 @@ std::string HelpMessage(HelpMessageMode mode)
strUsage += "\n" + _("Debugging/Testing options:") + "\n"; strUsage += "\n" + _("Debugging/Testing options:") + "\n";
if (GetBoolArg("-help-debug", false)) if (GetBoolArg("-help-debug", false))
{ {
strUsage += " -benchmark " + _("Show benchmark information (default: 0)") + "\n";
strUsage += " -checkpoints " + _("Only accept block chain matching built-in checkpoints (default: 1)") + "\n"; strUsage += " -checkpoints " + _("Only accept block chain matching built-in checkpoints (default: 1)") + "\n";
strUsage += " -dblogsize=<n> " + _("Flush database activity from memory pool to disk log every <n> megabytes (default: 100)") + "\n"; strUsage += " -dblogsize=<n> " + _("Flush database activity from memory pool to disk log every <n> megabytes (default: 100)") + "\n";
strUsage += " -disablesafemode " + _("Disable safemode, override a real safe mode event (default: 0)") + "\n"; strUsage += " -disablesafemode " + _("Disable safemode, override a real safe mode event (default: 0)") + "\n";
@ -298,7 +297,7 @@ std::string HelpMessage(HelpMessageMode mode)
strUsage += " -debug=<category> " + _("Output debugging information (default: 0, supplying <category> is optional)") + "\n"; strUsage += " -debug=<category> " + _("Output debugging information (default: 0, supplying <category> is optional)") + "\n";
strUsage += " " + _("If <category> is not supplied, output all debugging information.") + "\n"; strUsage += " " + _("If <category> is not supplied, output all debugging information.") + "\n";
strUsage += " " + _("<category> can be:"); strUsage += " " + _("<category> can be:");
strUsage += " addrman, alert, coindb, db, lock, rand, rpc, selectcoins, mempool, net"; // Don't translate these and qt below strUsage += " addrman, alert, bench, coindb, db, lock, rand, rpc, selectcoins, mempool, net"; // Don't translate these and qt below
if (mode == HMM_BITCOIN_QT) if (mode == HMM_BITCOIN_QT)
strUsage += ", qt"; strUsage += ", qt";
strUsage += ".\n"; strUsage += ".\n";
@ -599,7 +598,9 @@ bool AppInit2(boost::thread_group& threadGroup)
if (GetBoolArg("-tor", false)) if (GetBoolArg("-tor", false))
return InitError(_("Error: Unsupported argument -tor found, use -onion.")); return InitError(_("Error: Unsupported argument -tor found, use -onion."));
fBenchmark = GetBoolArg("-benchmark", false); if (GetBoolArg("-benchmark", false))
InitWarning(_("Warning: Unsupported argument -benchmark ignored, use -debug=bench."));
// Checkmempool defaults to true in regtest mode // Checkmempool defaults to true in regtest mode
mempool.setSanityCheck(GetBoolArg("-checkmempool", Params().DefaultCheckMemPool())); mempool.setSanityCheck(GetBoolArg("-checkmempool", Params().DefaultCheckMemPool()));
Checkpoints::fEnabled = GetBoolArg("-checkpoints", true); Checkpoints::fEnabled = GetBoolArg("-checkpoints", true);

50
src/main.cpp

@ -45,7 +45,6 @@ CConditionVariable cvBlockChange;
int nScriptCheckThreads = 0; int nScriptCheckThreads = 0;
bool fImporting = false; bool fImporting = false;
bool fReindex = false; bool fReindex = false;
bool fBenchmark = false;
bool fTxIndex = false; bool fTxIndex = false;
bool fIsBareMultisigStd = true; bool fIsBareMultisigStd = true;
unsigned int nCoinCacheSize = 5000; unsigned int nCoinCacheSize = 5000;
@ -1680,6 +1679,12 @@ void ThreadScriptCheck() {
scriptcheckqueue.Thread(); scriptcheckqueue.Thread();
} }
static int64_t nTimeVerify = 0;
static int64_t nTimeConnect = 0;
static int64_t nTimeIndex = 0;
static int64_t nTimeCallbacks = 0;
static int64_t nTimeTotal = 0;
bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, CCoinsViewCache& view, bool fJustCheck) bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, CCoinsViewCache& view, bool fJustCheck)
{ {
AssertLockHeld(cs_main); AssertLockHeld(cs_main);
@ -1735,7 +1740,7 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C
CCheckQueueControl<CScriptCheck> control(fScriptChecks && nScriptCheckThreads ? &scriptcheckqueue : NULL); CCheckQueueControl<CScriptCheck> control(fScriptChecks && nScriptCheckThreads ? &scriptcheckqueue : NULL);
int64_t nStart = GetTimeMicros(); int64_t nTimeStart = GetTimeMicros();
int64_t nFees = 0; int64_t nFees = 0;
int nInputs = 0; int nInputs = 0;
unsigned int nSigOps = 0; unsigned int nSigOps = 0;
@ -1785,9 +1790,8 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C
vPos.push_back(std::make_pair(tx.GetHash(), pos)); vPos.push_back(std::make_pair(tx.GetHash(), pos));
pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION); pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION);
} }
int64_t nTime = GetTimeMicros() - nStart; int64_t nTime1 = GetTimeMicros(); nTimeConnect += nTime1 - nTimeStart;
if (fBenchmark) LogPrint("bench", " - Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin) [%.2fs]\n", (unsigned)block.vtx.size(), 0.001 * (nTime1 - nTimeStart), 0.001 * (nTime1 - nTimeStart) / block.vtx.size(), nInputs <= 1 ? 0 : 0.001 * (nTime1 - nTimeStart) / (nInputs-1), nTimeConnect * 0.000001);
LogPrintf("- Connect %u transactions: %.2fms (%.3fms/tx, %.3fms/txin)\n", (unsigned)block.vtx.size(), 0.001 * nTime, 0.001 * nTime / block.vtx.size(), nInputs <= 1 ? 0 : 0.001 * nTime / (nInputs-1));
if (block.vtx[0].GetValueOut() > GetBlockValue(pindex->nHeight, nFees)) if (block.vtx[0].GetValueOut() > GetBlockValue(pindex->nHeight, nFees))
return state.DoS(100, return state.DoS(100,
@ -1797,9 +1801,8 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C
if (!control.Wait()) if (!control.Wait())
return state.DoS(100, false); return state.DoS(100, false);
int64_t nTime2 = GetTimeMicros() - nStart; int64_t nTime2 = GetTimeMicros(); nTimeVerify += nTime2 - nTimeStart;
if (fBenchmark) LogPrint("bench", " - Verify %u txins: %.2fms (%.3fms/txin) [%.2fs]\n", nInputs - 1, 0.001 * (nTime2 - nTimeStart), nInputs <= 1 ? 0 : 0.001 * (nTime2 - nTimeStart) / (nInputs-1), nTimeVerify * 0.000001);
LogPrintf("- Verify %u txins: %.2fms (%.3fms/txin)\n", nInputs - 1, 0.001 * nTime2, nInputs <= 1 ? 0 : 0.001 * nTime2 / (nInputs-1));
if (fJustCheck) if (fJustCheck)
return true; return true;
@ -1840,6 +1843,9 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C
ret = view.SetBestBlock(pindex->GetBlockHash()); ret = view.SetBestBlock(pindex->GetBlockHash());
assert(ret); assert(ret);
int64_t nTime3 = GetTimeMicros(); nTimeIndex += nTime3 - nTime2;
LogPrint("bench", " - Index writing: %.2fms [%.2fs]\n", 0.001 * (nTime3 - nTime2), nTimeIndex * 0.000001);
// Watch for transactions paying to me // Watch for transactions paying to me
BOOST_FOREACH(const CTransaction& tx, block.vtx) BOOST_FOREACH(const CTransaction& tx, block.vtx)
g_signals.SyncTransaction(tx, &block); g_signals.SyncTransaction(tx, &block);
@ -1849,6 +1855,9 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C
g_signals.UpdatedTransaction(hashPrevBestCoinBase); g_signals.UpdatedTransaction(hashPrevBestCoinBase);
hashPrevBestCoinBase = block.vtx[0].GetHash(); hashPrevBestCoinBase = block.vtx[0].GetHash();
int64_t nTime4 = GetTimeMicros(); nTimeCallbacks += nTime4 - nTime3;
LogPrint("bench", " - Callbacks: %.2fms [%.2fs]\n", 0.001 * (nTime4 - nTime3), nTimeCallbacks * 0.000001);
return true; return true;
} }
@ -1928,8 +1937,7 @@ bool static DisconnectTip(CValidationState &state) {
return error("DisconnectTip() : DisconnectBlock %s failed", pindexDelete->GetBlockHash().ToString()); return error("DisconnectTip() : DisconnectBlock %s failed", pindexDelete->GetBlockHash().ToString());
assert(view.Flush()); assert(view.Flush());
} }
if (fBenchmark) LogPrint("bench", "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * 0.001);
LogPrintf("- Disconnect: %.2fms\n", (GetTimeMicros() - nStart) * 0.001);
// Write the chain state to disk, if necessary. // Write the chain state to disk, if necessary.
if (!WriteChainState(state)) if (!WriteChainState(state))
return false; return false;
@ -1953,16 +1961,25 @@ bool static DisconnectTip(CValidationState &state) {
return true; return true;
} }
static int64_t nTimeReadFromDisk = 0;
static int64_t nTimeConnectTotal = 0;
static int64_t nTimeFlush = 0;
static int64_t nTimeChainState = 0;
static int64_t nTimePostConnect = 0;
// Connect a new block to chainActive. // Connect a new block to chainActive.
bool static ConnectTip(CValidationState &state, CBlockIndex *pindexNew) { bool static ConnectTip(CValidationState &state, CBlockIndex *pindexNew) {
assert(pindexNew->pprev == chainActive.Tip()); assert(pindexNew->pprev == chainActive.Tip());
mempool.check(pcoinsTip); mempool.check(pcoinsTip);
// Read block from disk. // Read block from disk.
int64_t nTime1 = GetTimeMicros();
CBlock block; CBlock block;
if (!ReadBlockFromDisk(block, pindexNew)) if (!ReadBlockFromDisk(block, pindexNew))
return state.Abort(_("Failed to read block")); return state.Abort(_("Failed to read block"));
// Apply the block atomically to the chain state. // Apply the block atomically to the chain state.
int64_t nStart = GetTimeMicros(); int64_t nTime2 = GetTimeMicros(); nTimeReadFromDisk += nTime2 - nTime1;
int64_t nTime3;
LogPrint("bench", " - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * 0.001, nTimeReadFromDisk * 0.000001);
{ {
CCoinsViewCache view(*pcoinsTip, true); CCoinsViewCache view(*pcoinsTip, true);
CInv inv(MSG_BLOCK, pindexNew->GetBlockHash()); CInv inv(MSG_BLOCK, pindexNew->GetBlockHash());
@ -1972,13 +1989,17 @@ bool static ConnectTip(CValidationState &state, CBlockIndex *pindexNew) {
return error("ConnectTip() : ConnectBlock %s failed", pindexNew->GetBlockHash().ToString()); return error("ConnectTip() : ConnectBlock %s failed", pindexNew->GetBlockHash().ToString());
} }
mapBlockSource.erase(inv.hash); mapBlockSource.erase(inv.hash);
nTime3 = GetTimeMicros(); nTimeConnectTotal += nTime3 - nTime2;
LogPrint("bench", " - Connect total: %.2fms [%.2fs]\n", (nTime3 - nTime2) * 0.001, nTimeConnectTotal * 0.000001);
assert(view.Flush()); assert(view.Flush());
} }
if (fBenchmark) int64_t nTime4 = GetTimeMicros(); nTimeFlush += nTime4 - nTime3;
LogPrintf("- Connect: %.2fms\n", (GetTimeMicros() - nStart) * 0.001); LogPrint("bench", " - Flush: %.2fms [%.2fs]\n", (nTime4 - nTime3) * 0.001, nTimeFlush * 0.000001);
// Write the chain state to disk, if necessary. // Write the chain state to disk, if necessary.
if (!WriteChainState(state)) if (!WriteChainState(state))
return false; return false;
int64_t nTime5 = GetTimeMicros(); nTimeChainState += nTime5 - nTime4;
LogPrint("bench", " - Writing chainstate: %.2fms [%.2fs]\n", (nTime5 - nTime4) * 0.001, nTimeChainState * 0.000001);
// Remove conflicting transactions from the mempool. // Remove conflicting transactions from the mempool.
list<CTransaction> txConflicted; list<CTransaction> txConflicted;
mempool.removeForBlock(block.vtx, pindexNew->nHeight, txConflicted); mempool.removeForBlock(block.vtx, pindexNew->nHeight, txConflicted);
@ -1994,6 +2015,9 @@ bool static ConnectTip(CValidationState &state, CBlockIndex *pindexNew) {
BOOST_FOREACH(const CTransaction &tx, block.vtx) { BOOST_FOREACH(const CTransaction &tx, block.vtx) {
SyncWithWallets(tx, &block); SyncWithWallets(tx, &block);
} }
int64_t nTime6 = GetTimeMicros(); nTimePostConnect += nTime6 - nTime5; nTimeTotal += nTime6 - nTime1;
LogPrint("bench", " - Connect postprocess: %.2fms [%.2fs]\n", (nTime6 - nTime5) * 0.001, nTimePostConnect * 0.000001);
LogPrint("bench", "- Connect block: %.2fms [%.2fs]\n", (nTime6 - nTime1) * 0.001, nTimeTotal * 0.000001);
return true; return true;
} }

1
src/main.h

@ -91,7 +91,6 @@ extern CWaitableCriticalSection csBestBlock;
extern CConditionVariable cvBlockChange; extern CConditionVariable cvBlockChange;
extern bool fImporting; extern bool fImporting;
extern bool fReindex; extern bool fReindex;
extern bool fBenchmark;
extern int nScriptCheckThreads; extern int nScriptCheckThreads;
extern bool fTxIndex; extern bool fTxIndex;
extern bool fIsBareMultisigStd; extern bool fIsBareMultisigStd;

Loading…
Cancel
Save