logs: add timing information to FlushStateToDisk() #16805

pull jamesob wants to merge 2 commits into bitcoin:master from jamesob:2019-09-flush-logs changing 5 files +168 −3
  1. jamesob commented at 8:24 pm on September 4, 2019: member

    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.

    02019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
12019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
22019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  2. jamesob force-pushed on Sep 4, 2019
  3. DrahtBot added the label Validation on Sep 4, 2019
  4. DrahtBot commented at 10:10 pm on September 4, 2019: member

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    Conflicts

    No conflicts as of last run.

  5. in src/logging.h:57 in 6fa89eda14 outdated 
    53@@ -54,6 +54,7 @@ namespace BCLog {
54         COINDB      = (1 << 18),
55         QT          = (1 << 19),
56         LEVELDB     = (1 << 20),
57+        DISKFLUSH   = (1 << 21),
    laanwj commented at 8:38 am on September 6, 2019:
    Would prefer adding this to the current BENCH category, it includes more timings like this. Adding a new category seems overkill to me.
    jamesob commented at 6:49 pm on September 9, 2019:
    Yeah, I think that makes sense. Fixed.
  6. hebasto commented at 11:00 am on September 9, 2019: member
    Concept ACK
  7. jamesob force-pushed on Sep 9, 2019
  8. promag commented at 10:48 pm on September 15, 2019: member

    Concept ACK, not so fond of the approach because you have to deal with state (assert(time_started == 0)). I think you could use RAII style, see this draft:

    0#define PROFILE(msg) Profile profile(msg)
1
2            {
3                PROFILE("write block and undo data to disk");
4                // First make sure all block and undo data is flushed to disk.
5                FlushBlockFile();
6            }
  9. jamesob force-pushed on Sep 19, 2019
  10. jamesob commented at 6:15 pm on September 19, 2019: member
    Thanks for the looks so far. I’ve taken @promag’s advice and have added a more generally useful RAII utility for logging times, BCLog::Timer.
  11. in src/logging.h:242 in cad68f59ff outdated 
    237+
238+} // namespace BCLog
239+
240+#define PASTE(x, y) x ## y
241+#define PASTE2(x, y) PASTE(x, y)
242+#define TIME_MICROS(end_msg, ...) \
    MarcoFalke commented at 6:39 pm on September 19, 2019:
    Could say BENCH_MICROS to be more specific?
    jamesob commented at 9:12 pm on September 19, 2019:
    I’ve changed to LOG_TIME_*, hope you like that.
  12. MarcoFalke commented at 6:40 pm on September 19, 2019: member
    ACK cad68f59ff9a95e6e4f7fe9cce61705563bb1409
  13. jamesob force-pushed on Sep 19, 2019
  14. jamesob force-pushed on Sep 19, 2019
  15. jamesob force-pushed on Sep 19, 2019
  16. in src/logging.h:192 in 8dbd959ca4 outdated 
    187+    //! (instead of being filtered by category).
188+    Timer(
189+        std::string prefix,
190+        std::string end_msg,
191+        BCLog::LogFlags log_category = BCLog::LogFlags::ALL) :
192+            m_prefix(prefix),
    ryanofsky commented at 3:32 pm on September 24, 2019:
    Could std::move prefix and end_msg to avoid allocations.
    jamesob commented at 3:03 pm on September 25, 2019:
    done
  17. in src/logging.h:207 in 8dbd959ca4 outdated 
    202+    void Log(const std::string& msg)
203+    {
204+        const std::string full_msg = this->LogMsg(msg);
205+
206+        if (m_log_category == BCLog::LogFlags::ALL) {
207+            LogPrintf(full_msg.c_str()); /* No newline */
    ryanofsky commented at 3:36 pm on September 24, 2019:

    Here and below should this use LogPrintf("%s", full_msg) to avoid errors if msg contains % characters? Using %s\n here would also allow dropping the newline in LogMsg and removing the “No newline” lint workarounds.

    Also can .c_str() be dropped?

    jamesob commented at 3:03 pm on September 25, 2019:
    Ah good suggestions! done
  18. in src/logging.h:239 in 8dbd959ca4 outdated 
    234+    std::chrono::microseconds m_start_t{};
235+};
236+
237+} // namespace BCLog
238+
239+#define PASTE(x, y) x ## y
    ryanofsky commented at 3:41 pm on September 24, 2019:
    I’m surprised there aren’t warnings about macro redefinitions since sync.h defines same macros. If this does turn out to be a problem could move PASTE/PASTE2 to a common location like util/preprocessor.h or util/macros.h
    laanwj commented at 9:40 am on September 25, 2019:
    Seems a good idea to factor these out in any case
    jamesob commented at 3:03 pm on September 25, 2019:
    done
  19. ryanofsky approved
  20. ryanofsky commented at 3:51 pm on September 24, 2019: member
    utACK 8dbd959ca409c632e2ffd3a2ab585be60a71d7be
  21. in src/logging.h:228 in 8dbd959ca4 outdated 
    223+        } else if (std::is_same<TimeType, std::chrono::seconds>::value) {
224+            units = "s";
225+            divisor = 1000. * 1000.;
226+        }
227+
228+        const auto end_time = GetTime<std::chrono::microseconds>() - m_start_t;
    MarcoFalke commented at 4:01 pm on September 24, 2019:
    style-nit: Could move this up to not include the (trivial) switch-case statement above in the measurement? (edit: Looks like the switch-case should be evaluated at compile time, so should be fine either way)
    jamesob commented at 3:03 pm on September 25, 2019:
    done
  22. jamesob force-pushed on Sep 25, 2019
  23. jamesob commented at 3:32 pm on September 25, 2019: member

    flushlogs.4 -> flushlogs.5 (diff)

    Thanks for all the good feedback.

  24. in src/logging.h:185 in 3a2d129282 outdated 
    180+    //! A descriptive message of what is being timed.
181+    std::string m_title{};
182+
183+    //! Forwarded on to LogPrint if specified - has the effect of only
184+    //! outputing the timing log when a particular debug= category is specified.
185+    BCLog::LogFlags m_log_category{};
    MarcoFalke commented at 5:22 pm on September 27, 2019:
    style-nit: Any reason the members are not const and private?
    jamesob commented at 5:45 pm on September 27, 2019:
    Nah, will change if rebase happens.
  25. MarcoFalke commented at 5:27 pm on September 27, 2019: member
    unsigned ACK 1cff8d23a0042ff865cfd380f8da06233b61fb2e
  26. in src/logging.h:198 in 1cff8d23a0 outdated 
    193+            m_prefix(std::move(prefix)),
194+            m_title(std::move(end_msg)),
195+            m_start_t(GetTime<std::chrono::microseconds>()),
196+            m_log_category(log_category)
197+    {
198+        this->Log(strprintf("%s started", m_title), false);
    ryanofsky commented at 5:52 pm on September 27, 2019:
    Maybe wait to initialize m_start_t until after the Log call, so the elapsed time doesn’t include the time spent logging. This would also let you eliminate the show_elapsed_time bool arguments (could just check m_start_t != 0 instead).
    jamesob commented at 6:04 pm on September 27, 2019:
    Oh that’s a good point. Will do.
  27. ryanofsky approved
  28. ryanofsky commented at 5:56 pm on September 27, 2019: member
    utACK 1cff8d23a0042ff865cfd380f8da06233b61fb2e. Since last review now logs a message at start of timing, also implements various suggestions above. I left a new suggestion, but it’s not important so feel to ignore / merge this as-is.
  29. jamesob force-pushed on Sep 27, 2019
  30. jamesob commented at 6:31 pm on September 27, 2019: member
    Thanks for the looks, have incorporated all feedback.
  31. in src/logging.h:233 in 07b8f8389c outdated 
    229@@ -240,6 +230,17 @@ class Timer
230 
231 private:
232     std::chrono::microseconds m_start_t{};
233+
    ryanofsky commented at 6:38 pm on September 27, 2019:

    In commit “logs: add timing information to FlushStateToDisk()” (07b8f8389c5ec557fbb6a7ab59a186865636d2d4)

    Note: third commit is moving lines added by the second commit.

    jamesob commented at 6:44 pm on September 27, 2019:
    Oops! Fixed, thanks.
  32. ryanofsky commented at 6:40 pm on September 27, 2019: member
    utACK 07b8f8389c5ec557fbb6a7ab59a186865636d2d4. Overall looks good, but third commit is changing code added by the second commit, so it looks like there might have been a problem squashing commits.
  33. jamesob force-pushed on Sep 27, 2019
  34. ryanofsky approved
  35. ryanofsky commented at 7:13 pm on September 27, 2019: member
    utACK e75b176e9364dd8ba2cbe9907b71b83c8d492693. No changes since last review, just squashed previous updates into the right commit.
  36. in src/logging.h:241 in e75b176e93 outdated 
    236+
237+    //! A descriptive message of what is being timed.
238+    const std::string m_title{};
239+
240+    //! Forwarded on to LogPrint if specified - has the effect of only
241+    //! outputing the timing log when a particular debug= category is specified.
    practicalswift commented at 4:39 pm on September 28, 2019:
    Should be “outputting” :)
  37. laanwj added this to the milestone 0.20.0 on Sep 30, 2019
  38. laanwj added the label Feature on Sep 30, 2019
  39. laanwj referenced this in commit 2f174498d6 on Oct 8, 2019
  40. sidhujag referenced this in commit b7ccc1cf43 on Oct 8, 2019
  41. hebasto commented at 7:37 pm on October 12, 2019: member

    Compiled and tested on ODROID-HC1 (ARMv7). Due to the #17010 issue all commits from this PR (0d86f4d3dacab38f3cd5371d0c920585c178302c, 51ab646bba9367c737fbbdb0f5cde4ae4de8b67c and e75b176e9364dd8ba2cbe9907b71b83c8d492693) were cherry-picked and applied on top of the 0.19.0rc1 tag.

    Without applied commits (on v0.19.0rc1):

     0$ time bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo
 1{
 2  "height": 599066,
 3  "bestblock": "000000000000000000153a21ef9fad22d4c2b04cee7df6da7c2ff217ad476a1c",
 4  "transactions": 36733277,
 5  "txouts": 63062142,
 6  "bogosize": 4743097104,
 7  "hash_serialized_2": "8c2d70e7e0fc6bec531b7c63806713da0526dbb4eb89242a28d93fb43743d31a",
 8  "disk_size": 3773406726,
 9  "total_amount": 17988154.82195437
10}
11
12real	5m16.144s
13user	0m0.000s
14sys	0m0.024s

    With applied commits:

     0$ git log -4 --oneline
 1e6945685f (HEAD) logs: add timing information to FlushStateToDisk()
 216875b2fb logs: add BCLog::Timer and related macros
 3732cb046b refactor: consolidate PASTE macros
 4913972944 (tag: v0.19.0rc1) doc: Update manpages
 5
 6$ time bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo
 7{
 8  "height": 599087,
 9  "bestblock": "0000000000000000000d1c471cbcf2819e59c344507fc5ce939021b23a6b932f",
10  "transactions": 36743836,
11  "txouts": 63075327,
12  "bogosize": 4744073610,
13  "hash_serialized_2": "fde22357f7ada7dbb81f7f303d66cbd543a1dda3430de664c56ea9ab0546ba8b",
14  "disk_size": 3775232343,
15  "total_amount": 17988417.32195437
16}
17
18real	60m27.968s
19user	0m0.009s
20sys	0m0.021s

    debug.log contains:

    02019-10-12T18:53:14Z FlushStateToDisk: write coins cache to disk (6260 coins, 730kB) started
12019-10-12T18:53:14Z FlushStateToDisk: write coins cache to disk (6260 coins, 730kB) completed (0.01s)

    Maybe related to #16008 and #16979.

    UPDATE: It seems the described issue does not relate to this PR directly. The root of observed behavior could be in ARM big.LITTLE architecture.

  42. laanwj commented at 12:37 pm on October 30, 2019: member
    @hebasto I do not believe the changes in this PR can have such a performance impact.
  43. hebasto commented at 12:58 pm on October 30, 2019: member

    @laanwj

    I do not believe the changes in this PR can have such a performance impact.

    You are right. The ARM big.LITTLE Heterogeneous Multi-Processing causes such a performance impact if any of threads runs on LITTLE core.

  44. laanwj commented at 1:14 pm on October 30, 2019: member
    Maybe open a new issue for that (don’t know how much control applications have over the thread affinity in that case?).
  45. in src/logging.h:12 in e75b176e93 outdated 
     7@@ -8,8 +8,11 @@
 8 
 9 #include <fs.h>
10 #include <tinyformat.h>
11+#include <util/macros.h>
12+#include <util/time.h>
    laanwj commented at 10:27 am on November 1, 2019:
    Might want to put the timer in a new header. Pulling in these extra header files in everything that uses logging.h (read: everything) might slow down the build unnecessarily.
    MarcoFalke commented at 12:57 pm on November 1, 2019:
    Last time I looked, I found that the standard library headers are generally fast to include (compared to boost and our serialize.h)
    laanwj commented at 11:15 am on November 2, 2019:
    In comparison that’s true. Still it’s good to be extra careful about introducing extra dependencies for such a common header.
  46. jamesob force-pushed on Nov 4, 2019
  47. jamesob force-pushed on Nov 4, 2019
  48. logs: add BCLog::Timer and related macros 
    Makes logging timing information about a block of code easier.
    41edaf227a
  49. logs: add timing information to FlushStateToDisk() dcef9a2922
  50. jamesob force-pushed on Nov 4, 2019
  51. jamesob commented at 7:15 pm on November 4, 2019: member

    flushlogs.8 -> flushlogs.11

    Separated BCLog::Timer out into its own header per @laanwj’s recommendation.

  52. ryanofsky approved
  53. ryanofsky commented at 8:11 pm on November 5, 2019: member
    Code review ACK dcef9a2922317cb2849f397366b6c56d755db6c9. No changes since last review other than moving code to new timer.h header
  54. laanwj commented at 8:33 pm on November 5, 2019: member
    Thanks, ACK dcef9a2922317cb2849f397366b6c56d755db6c9
  55. laanwj referenced this in commit 40b6070ad7 on Nov 5, 2019
  56. laanwj merged this on Nov 5, 2019
  57. laanwj closed this on Nov 5, 2019
  58. in src/validation.cpp:2030 in dcef9a2922 
    2024@@ -2023,15 +2025,23 @@ bool CChainState::FlushStateToDisk(
2025     static int64_t nLastFlush = 0;
2026     std::set<int> setFilesToPrune;
2027     bool full_flush_completed = false;
2028+
2029+    const size_t coins_count = CoinsTip().GetCacheSize();
2030+    const size_t coins_mem_usage = CoinsTip().DynamicMemoryUsage();
    MarcoFalke commented at 1:07 pm on November 6, 2019:
    How is this different from the existing cacheSize?
    jamesob commented at 4:08 pm on November 6, 2019:
    Ah yeah, guess it’s not. Oops.
  59. sidhujag referenced this in commit 82c9482c70 on Nov 7, 2019
  60. fanquake referenced this in commit e727c2bdca on May 4, 2020
  61. sidhujag referenced this in commit fae55b66f9 on May 5, 2020
  62. sidhujag referenced this in commit e7e6811406 on Nov 10, 2020
  63. Fabcien referenced this in commit 48b5e2d8d8 on Dec 24, 2020
  64. kittywhiskers referenced this in commit 05f6931bd4 on Jun 16, 2021
  65. kittywhiskers referenced this in commit 0206ca2dcb on Jun 17, 2021
  66. PastaPastaPasta referenced this in commit 14c631691f on Jun 21, 2021
  67. DrahtBot locked this on Dec 16, 2021


jamesob DrahtBot laanwj hebasto promag MarcoFalke ryanofsky practicalswift

Labels
Feature Validation

Milestone
0.20.0

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-03 13:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me