From 41edaf227a69bc4846d5996675e8763fdfe0f367 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Thu, 19 Sep 2019 13:59:49 -0400 Subject: [PATCH 1/2] logs: add BCLog::Timer and related macros Makes logging timing information about a block of code easier. --- src/Makefile.am | 1 + src/Makefile.test.include | 1 + src/logging/timer.h | 104 +++++++++++++++++++++++++++++++++++++ src/test/logging_tests.cpp | 36 +++++++++++++ 4 files changed, 142 insertions(+) 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 7af04148cc..798fab1b02 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -146,6 +146,7 @@ BITCOIN_CORE_H = \ dbwrapper.h \ limitedmap.h \ logging.h \ + logging/timer.h \ memusage.h \ merkleblock.h \ miner.h \ diff --git a/src/Makefile.test.include b/src/Makefile.test.include index d3fe138133..8a0fa1bdc5 100644 --- a/src/Makefile.test.include +++ b/src/Makefile.test.include @@ -110,6 +110,7 @@ BITCOIN_TESTS =\ test/key_io_tests.cpp \ test/key_tests.cpp \ test/limitedmap_tests.cpp \ + test/logging_tests.cpp \ test/dbwrapper_tests.cpp \ test/validation_tests.cpp \ test/mempool_tests.cpp \ diff --git a/src/logging/timer.h b/src/logging/timer.h new file mode 100644 index 0000000000..34dbb942c5 --- /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..eb1826ae8d --- /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() From dcef9a2922317cb2849f397366b6c56d755db6c9 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Wed, 21 Aug 2019 12:03:39 -0400 Subject: [PATCH 2/2] logs: add timing information to FlushStateToDisk() --- src/validation.cpp | 29 ++++++++++++++++++++++++++--- 1 file changed, 26 insertions(+), 3 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index a8ebbc1b96..0135521653 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -18,6 +18,8 @@ #include #include #include +#include +#include #include #include #include @@ -2023,6 +2025,10 @@ bool CChainState::FlushStateToDisk( static int64_t nLastFlush = 0; std::set 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; @@ -2030,8 +2036,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; } @@ -2070,10 +2080,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 > vFiles; vFiles.reserve(setDirtyFileInfo.size()); for (std::set::iterator it = setDirtyFileInfo.begin(); it != setDirtyFileInfo.end(); ) { @@ -2091,12 +2108,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