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

dcef9a2922317cb2849f397366b6c56d755db6c9 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf227a69bc4846d5996675e8763fdfe0f367 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 dcef9a2922317cb2849f397366b6c56d755db6c9
  ryanofsky:
    Code review ACK dcef9a2922317cb2849f397366b6c56d755db6c9. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d

1 files changed, 36 insertions, 0 deletions

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 <logging.h>
+#include <logging/timer.h>
+#include <test/setup_common.h>
+
+#include <chrono>
+
+#include <boost/test/unit_test.hpp>
+
+BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
+
+BOOST_AUTO_TEST_CASE(logging_timer)
+{
+
+    SetMockTime(1);
+    auto sec_timer = BCLog::Timer<std::chrono::seconds>("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<std::chrono::milliseconds>("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<std::chrono::microseconds>("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()