Merge #16805: logs: add timing information to FlushStateToDisk()

dcef9a2922 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf227a logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

ACKs for top commit:
  laanwj:
    Thanks, ACK dcef9a2922
  ryanofsky:
    Code review ACK dcef9a2922. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d
This commit is contained in:
Wladimir J. van der Laan
2019-11-05 23:44:54 +01:00
5 changed files with 168 additions and 3 deletions

View File

@@ -18,6 +18,8 @@
#include <flatfile.h>
#include <hash.h>
#include <index/txindex.h>
#include <logging.h>
#include <logging/timer.h>
#include <policy/fees.h>
#include <policy/policy.h>
#include <policy/settings.h>
@@ -2199,6 +2201,10 @@ bool CChainState::FlushStateToDisk(
static int64_t nLastFlush = 0;
std::set<int> setFilesToPrune;
bool full_flush_completed = false;
const size_t coins_count = CoinsTip().GetCacheSize();
const size_t coins_mem_usage = CoinsTip().DynamicMemoryUsage();
try {
{
bool fFlushForPrune = false;
@@ -2206,8 +2212,12 @@ bool CChainState::FlushStateToDisk(
LOCK(cs_LastBlockFile);
if (fPruneMode && (fCheckForPruning || nManualPruneHeight > 0) && !fReindex) {
if (nManualPruneHeight > 0) {
LOG_TIME_MILLIS("find files to prune (manual)", BCLog::BENCH);
FindFilesToPruneManual(setFilesToPrune, nManualPruneHeight);
} else {
LOG_TIME_MILLIS("find files to prune", BCLog::BENCH);
FindFilesToPrune(setFilesToPrune, chainparams.PruneAfterHeight());
fCheckForPruning = false;
}
@@ -2246,10 +2256,17 @@ bool CChainState::FlushStateToDisk(
if (!CheckDiskSpace(GetBlocksDir())) {
return AbortNode(state, "Disk space is too low!", _("Error: Disk space is too low!").translated, CClientUIInterface::MSG_NOPREFIX);
}
// First make sure all block and undo data is flushed to disk.
FlushBlockFile();
{
LOG_TIME_MILLIS("write block and undo data to disk", BCLog::BENCH);
// First make sure all block and undo data is flushed to disk.
FlushBlockFile();
}
// Then update all block file information (which may refer to block and undo files).
{
LOG_TIME_MILLIS("write block index to disk", BCLog::BENCH);
std::vector<std::pair<int, const CBlockFileInfo*> > vFiles;
vFiles.reserve(setDirtyFileInfo.size());
for (std::set<int>::iterator it = setDirtyFileInfo.begin(); it != setDirtyFileInfo.end(); ) {
@@ -2267,12 +2284,18 @@ bool CChainState::FlushStateToDisk(
}
}
// Finally remove any pruned files
if (fFlushForPrune)
if (fFlushForPrune) {
LOG_TIME_MILLIS("unlink pruned files", BCLog::BENCH);
UnlinkPrunedFiles(setFilesToPrune);
}
nLastWrite = nNow;
}
// Flush best chain related state. This can only be done if the blocks / block index write was also done.
if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) {
LOG_TIME_SECONDS(strprintf("write coins cache to disk (%d coins, %.2fkB)",
coins_count, coins_mem_usage / 1000));
// Typical Coin structures on disk are around 48 bytes in size.
// Pushing a new one to the database can cause it to be written
// twice (once in the log, and once in the tables). This is already