From 0206ca2dcb3f1292f35ba8abfa1d534c1afcc321 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kittywhiskers@users.noreply.github.com> Date: Thu, 19 Sep 2019 13:59:49 -0400 Subject: [PATCH] bitcoin#16805: add timing information to FlushStateToDisk() --- src/Makefile.am | 1 + src/Makefile.test.include | 1 + src/logging/timer.h | 104 +++++++++++++++++++++++++++++++++++++ src/test/logging_tests.cpp | 36 +++++++++++++ src/validation.cpp | 28 +++++++++- 5 files changed, 168 insertions(+), 2 deletions(-) create mode 100644 src/logging/timer.h create mode 100644 src/test/logging_tests.cpp diff --git a/src/Makefile.am b/src/Makefile.am index f2f6ddc879..7c9aba61eb 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -199,6 +199,7 @@ BITCOIN_CORE_H = \ llmq/quorums_signing_shares.h \ llmq/quorums_utils.h \ logging.h \ + logging/timer.h \ masternode/activemasternode.h \ masternode/masternode-meta.h \ masternode/masternode-payments.h \ diff --git a/src/Makefile.test.include b/src/Makefile.test.include index 4d3c6f4d6f..3b1759af0b 100644 --- a/src/Makefile.test.include +++ b/src/Makefile.test.include @@ -69,6 +69,7 @@ BITCOIN_TESTS =\ test/key_tests.cpp \ test/lcg.h \ test/limitedmap_tests.cpp \ + test/logging_tests.cpp \ test/dbwrapper_tests.cpp \ test/main_tests.cpp \ test/mempool_tests.cpp \ diff --git a/src/logging/timer.h b/src/logging/timer.h new file mode 100644 index 0000000000..ca34aa08ac --- /dev/null +++ b/src/logging/timer.h @@ -0,0 +1,104 @@ +// Copyright (c) 2009-2010 Satoshi Nakamoto +// Copyright (c) 2009-2018 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#ifndef BITCOIN_LOGGING_TIMER_H +#define BITCOIN_LOGGING_TIMER_H + +#include +#include +#include + +#include +#include + + +namespace BCLog { + +//! RAII-style object that outputs timing information to logs. +template +class Timer +{ +public: + //! If log_category is left as the default, end_msg will log unconditionally + //! (instead of being filtered by category). + Timer( + std::string prefix, + std::string end_msg, + BCLog::LogFlags log_category = BCLog::LogFlags::ALL) : + m_prefix(std::move(prefix)), + m_title(std::move(end_msg)), + m_log_category(log_category) + { + this->Log(strprintf("%s started", m_title)); + m_start_t = GetTime(); + } + + ~Timer() + { + this->Log(strprintf("%s completed", m_title)); + } + + void Log(const std::string& msg) + { + const std::string full_msg = this->LogMsg(msg); + + if (m_log_category == BCLog::LogFlags::ALL) { + LogPrintf("%s\n", full_msg); + } else { + LogPrint(m_log_category, "%s\n", full_msg); + } + } + + std::string LogMsg(const std::string& msg) + { + const auto end_time = GetTime() - m_start_t; + if (m_start_t.count() <= 0) { + return strprintf("%s: %s", m_prefix, msg); + } + + std::string units = ""; + float divisor = 1; + + if (std::is_same::value) { + units = "μs"; + } else if (std::is_same::value) { + units = "ms"; + divisor = 1000.; + } else if (std::is_same::value) { + units = "s"; + divisor = 1000. * 1000.; + } + + const float time_ms = end_time.count() / divisor; + return strprintf("%s: %s (%.2f%s)", m_prefix, msg, time_ms, units); + } + +private: + std::chrono::microseconds m_start_t{}; + + //! Log prefix; usually the name of the function this was created in. + const std::string m_prefix{}; + + //! A descriptive message of what is being timed. + const std::string m_title{}; + + //! Forwarded on to LogPrint if specified - has the effect of only + //! outputing the timing log when a particular debug= category is specified. + const BCLog::LogFlags m_log_category{}; + +}; + +} // namespace BCLog + + +#define LOG_TIME_MICROS(end_msg, ...) \ + BCLog::Timer PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__) +#define LOG_TIME_MILLIS(end_msg, ...) \ + BCLog::Timer PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__) +#define LOG_TIME_SECONDS(end_msg, ...) \ + BCLog::Timer PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__) + + +#endif // BITCOIN_LOGGING_TIMER_H diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp new file mode 100644 index 0000000000..8ed9d3aa98 --- /dev/null +++ b/src/test/logging_tests.cpp @@ -0,0 +1,36 @@ +// Copyright (c) 2019 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#include +#include +#include + +#include + +#include + +BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) + +BOOST_AUTO_TEST_CASE(logging_timer) +{ + + SetMockTime(1); + auto sec_timer = BCLog::Timer("tests", "end_msg"); + SetMockTime(2); + BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); + + SetMockTime(1); + auto ms_timer = BCLog::Timer("tests", "end_msg"); + SetMockTime(2); + BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)"); + + SetMockTime(1); + auto micro_timer = BCLog::Timer("tests", "end_msg"); + SetMockTime(2); + BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000.00μs)"); + + SetMockTime(0); +} + +BOOST_AUTO_TEST_SUITE_END() diff --git a/src/validation.cpp b/src/validation.cpp index df3ffbf83e..e387f05972 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -19,6 +19,8 @@ #include #include #include +#include +#include #include #include #include @@ -2464,6 +2466,10 @@ bool static FlushStateToDisk(const CChainParams& chainparams, CValidationState & static int64_t nLastFlush = 0; std::set setFilesToPrune; bool full_flush_completed = false; + + const size_t coins_count = pcoinsTip->GetCacheSize(); + const size_t coins_mem_usage = pcoinsTip->DynamicMemoryUsage(); + try { { bool fFlushForPrune = false; @@ -2471,8 +2477,12 @@ bool static FlushStateToDisk(const CChainParams& chainparams, CValidationState & LOCK(cs_LastBlockFile); if (fPruneMode && (fCheckForPruning || nManualPruneHeight > 0) && !fReindex) { if (nManualPruneHeight > 0) { + LOG_TIME_MILLIS("find files to prune (manual)", BCLog::BENCHMARK); + FindFilesToPruneManual(setFilesToPrune, nManualPruneHeight); } else { + LOG_TIME_MILLIS("find files to prune", BCLog::BENCHMARK); + FindFilesToPrune(setFilesToPrune, chainparams.PruneAfterHeight()); fCheckForPruning = false; } @@ -2512,9 +2522,17 @@ bool static FlushStateToDisk(const CChainParams& chainparams, CValidationState & if (!CheckDiskSpace(0, true)) return state.Error("out of disk space"); // First make sure all block and undo data is flushed to disk. - FlushBlockFile(); + { + LOG_TIME_MILLIS("write block and undo data to disk", BCLog::BENCHMARK); + + // 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::BENCHMARK); + std::vector > vFiles; vFiles.reserve(setDirtyFileInfo.size()); for (std::set::iterator it = setDirtyFileInfo.begin(); it != setDirtyFileInfo.end(); ) { @@ -2532,12 +2550,18 @@ bool static FlushStateToDisk(const CChainParams& chainparams, CValidationState & } } // Finally remove any pruned files - if (fFlushForPrune) + if (fFlushForPrune) { + LOG_TIME_MILLIS("unlink pruned files", BCLog::BENCHMARK); + 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 && !pcoinsTip->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