From d70bc52ee31b8c4c87ee011625e7031c2dc89c0c Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Sat, 26 Jul 2014 22:49:17 +0200 Subject: [PATCH] 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. --- src/init.cpp | 7 ++++--- src/main.cpp | 50 +++++++++++++++++++++++++++++++++++++------------- src/main.h | 1 - 3 files changed, 41 insertions(+), 17 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 3488a8bed..8b6567b5c 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -285,7 +285,6 @@ std::string HelpMessage(HelpMessageMode mode) strUsage += "\n" + _("Debugging/Testing options:") + "\n"; 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 += " -dblogsize= " + _("Flush database activity from memory pool to disk log every megabytes (default: 100)") + "\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= " + _("Output debugging information (default: 0, supplying is optional)") + "\n"; strUsage += " " + _("If is not supplied, output all debugging information.") + "\n"; strUsage += " " + _(" 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) strUsage += ", qt"; strUsage += ".\n"; @@ -599,7 +598,9 @@ bool AppInit2(boost::thread_group& threadGroup) if (GetBoolArg("-tor", false)) 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 mempool.setSanityCheck(GetBoolArg("-checkmempool", Params().DefaultCheckMemPool())); Checkpoints::fEnabled = GetBoolArg("-checkpoints", true); diff --git a/src/main.cpp b/src/main.cpp index 06ce15b5b..85e085189 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -45,7 +45,6 @@ CConditionVariable cvBlockChange; int nScriptCheckThreads = 0; bool fImporting = false; bool fReindex = false; -bool fBenchmark = false; bool fTxIndex = false; bool fIsBareMultisigStd = true; unsigned int nCoinCacheSize = 5000; @@ -1680,6 +1679,12 @@ void ThreadScriptCheck() { 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) { AssertLockHeld(cs_main); @@ -1735,7 +1740,7 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C CCheckQueueControl control(fScriptChecks && nScriptCheckThreads ? &scriptcheckqueue : NULL); - int64_t nStart = GetTimeMicros(); + int64_t nTimeStart = GetTimeMicros(); int64_t nFees = 0; int nInputs = 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)); pos.nTxOffset += ::GetSerializeSize(tx, SER_DISK, CLIENT_VERSION); } - int64_t nTime = GetTimeMicros() - nStart; - if (fBenchmark) - 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)); + int64_t nTime1 = GetTimeMicros(); nTimeConnect += nTime1 - nTimeStart; + 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); if (block.vtx[0].GetValueOut() > GetBlockValue(pindex->nHeight, nFees)) return state.DoS(100, @@ -1797,9 +1801,8 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C if (!control.Wait()) return state.DoS(100, false); - int64_t nTime2 = GetTimeMicros() - nStart; - if (fBenchmark) - LogPrintf("- Verify %u txins: %.2fms (%.3fms/txin)\n", nInputs - 1, 0.001 * nTime2, nInputs <= 1 ? 0 : 0.001 * nTime2 / (nInputs-1)); + int64_t nTime2 = GetTimeMicros(); nTimeVerify += nTime2 - nTimeStart; + 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); if (fJustCheck) return true; @@ -1840,6 +1843,9 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C ret = view.SetBestBlock(pindex->GetBlockHash()); 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 BOOST_FOREACH(const CTransaction& tx, block.vtx) g_signals.SyncTransaction(tx, &block); @@ -1849,6 +1855,9 @@ bool ConnectBlock(CBlock& block, CValidationState& state, CBlockIndex* pindex, C g_signals.UpdatedTransaction(hashPrevBestCoinBase); 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; } @@ -1928,8 +1937,7 @@ bool static DisconnectTip(CValidationState &state) { return error("DisconnectTip() : DisconnectBlock %s failed", pindexDelete->GetBlockHash().ToString()); assert(view.Flush()); } - if (fBenchmark) - LogPrintf("- Disconnect: %.2fms\n", (GetTimeMicros() - nStart) * 0.001); + LogPrint("bench", "- Disconnect block: %.2fms\n", (GetTimeMicros() - nStart) * 0.001); // Write the chain state to disk, if necessary. if (!WriteChainState(state)) return false; @@ -1953,16 +1961,25 @@ bool static DisconnectTip(CValidationState &state) { 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. bool static ConnectTip(CValidationState &state, CBlockIndex *pindexNew) { assert(pindexNew->pprev == chainActive.Tip()); mempool.check(pcoinsTip); // Read block from disk. + int64_t nTime1 = GetTimeMicros(); CBlock block; if (!ReadBlockFromDisk(block, pindexNew)) return state.Abort(_("Failed to read block")); // 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); 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()); } 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()); } - if (fBenchmark) - LogPrintf("- Connect: %.2fms\n", (GetTimeMicros() - nStart) * 0.001); + int64_t nTime4 = GetTimeMicros(); nTimeFlush += nTime4 - nTime3; + LogPrint("bench", " - Flush: %.2fms [%.2fs]\n", (nTime4 - nTime3) * 0.001, nTimeFlush * 0.000001); // Write the chain state to disk, if necessary. if (!WriteChainState(state)) 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. list 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) { 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; } diff --git a/src/main.h b/src/main.h index 5f231fa45..48ec86f6a 100644 --- a/src/main.h +++ b/src/main.h @@ -91,7 +91,6 @@ extern CWaitableCriticalSection csBestBlock; extern CConditionVariable cvBlockChange; extern bool fImporting; extern bool fReindex; -extern bool fBenchmark; extern int nScriptCheckThreads; extern bool fTxIndex; extern bool fIsBareMultisigStd;