log: improve checkaddrman logging with duration in milliseconds #22872

pull jonatack wants to merge 3 commits into bitcoin:master from jonatack:improve-checkaddrman-logging changing 5 files +32 −17
  1. jonatack commented at 12:28 AM on September 3, 2021: contributor

    This patch:

    • updates the logging/timer.h::Timer class to allow not repeating the log message on completion
    • adds a LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro that prints the descriptive message when logging the start but not when logging the completion
    • updates the checkaddrman logging to log the duration, and renames the function like the -checkaddrman configuration option in order to prefix every log message with CheckAddrman instead of the longer, less pleasant, and different-from-checkaddrman ForceCheckAddrman (the Doxygen documentation on the function already makes clear that it is unaffected by m_consistency_check_ratio).

    before

    2021-09-21T18:42:50Z [opencon] Addrman checks started: new 64864, tried 1690, total 66554
2021-09-21T18:42:50Z [opencon] Addrman checks completed successfully

    after

    2021-09-21T18:42:50Z [opencon] CheckAddrman: new 64864, tried 1690, total 66554 started
2021-09-21T18:42:50Z [opencon] CheckAddrman: completed (76.21ms)

    To test, build and run bitcoind with -debug=addrman -checkaddrman=<n> for a value of n in the range of, say, 10 to 40.

  2. DrahtBot added the label P2P on Sep 3, 2021
  3. DrahtBot added the label Utils/log/libs on Sep 3, 2021
  4. in src/addrman.h:415 in 0b2d83944c outdated 
     412 |          }
 413 |      }
 414 |  
 415 |      //! Perform consistency check. Returns an error code or zero.
 416 | -    int Check_() const EXCLUSIVE_LOCKS_REQUIRED(cs);
 417 | +    int CheckAddrMan() const EXCLUSIVE_LOCKS_REQUIRED(cs);
    MarcoFalke commented at 7:46 AM on September 3, 2021:

    any reason for the rename here? This will just cause conflicts and increase the git history without any benefit.

    jonatack commented at 8:58 AM on September 3, 2021:

    It's to have the log print "CheckAddrMan:" instead of "Check_:"

    laanwj commented at 11:48 AM on September 9, 2021:

    All the method names seem to end with _, might want to keep that at least for consistency?

    jonatack commented at 5:52 PM on September 9, 2021:

    Done, updated the pull description

  5. practicalswift commented at 1:43 PM on September 4, 2021: contributor

    Concept ACK

  6. theStack commented at 3:33 PM on September 5, 2021: contributor

    Concept ACK

  7. laanwj commented at 11:48 AM on September 9, 2021: member

    Concept ACK

  8. jonatack force-pushed on Sep 9, 2021
  9. in src/addrman.cpp:772 in b3b4a9281f outdated 
     758 |      if (m_consistency_check_ratio == 0) return 0;
 759 |      if (insecure_rand.randrange(m_consistency_check_ratio) >= 1) return 0;
 760 |  
 761 | -    LogPrint(BCLog::ADDRMAN, "Addrman checks started: new %i, tried %i, total %u\n", nNew, nTried, vRandom.size());
 762 | +    LOG_TIME_MILLIS_WITH_CATEGORY(
 763 | +        strprintf("new %i, tried %i, total %u", nNew, nTried, vRandom.size()), BCLog::ADDRMAN);
    MarcoFalke commented at 10:45 AM on September 10, 2021:

    Looks like this will print the statistics twice, implying they would change in-between, which might be confusing.

    Not sure how to best solve this.

    jonatack commented at 12:37 PM on September 10, 2021:

    Looks like this will print the statistics twice, implying they would change in-between, which might be confusing.

    Not sure how to best solve this.

    I'll have a look.

    jonatack commented at 7:43 PM on September 11, 2021:

    Done, example on signet:

    2021-09-11T19:39:05Z [scheduler] Enter: lock contention ::cs_main, validation.cpp:4874 started
2021-09-11T19:39:05Z [opencon] CheckAddrMan_: new 442, tried 57, total 499 started
2021-09-11T19:39:05Z [opencon] CheckAddrMan_: completed (10.30ms)
2021-09-11T19:39:07Z [scheduler] Enter: lock contention ::cs_main, validation.cpp:4874 completed (2906703μs)
  10. fanquake cross-referenced this on Sep 10, 2021 from issue test: add addpeeraddress "tried", test addrman checks on restart with asmap by jonatack
  11. DrahtBot cross-referenced this on Sep 11, 2021 from issue fuzz: Reset addrman when consistency check fails by MarcoFalke
  12. DrahtBot commented at 3:33 AM on September 11, 2021: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

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

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    No conflicts as of last run.

  13. DrahtBot cross-referenced this on Sep 11, 2021 from issue addrman: Avoid crash on corrupt data, Force Check after deserialize by MarcoFalke
  14. DrahtBot cross-referenced this on Sep 11, 2021 from issue [p2p] Pimpl AddrMan to abstract implementation details by amitiuttarwar
  15. jonatack force-pushed on Sep 11, 2021
  16. Bossday cross-referenced this on Sep 21, 2021 from issue . by Bossday
  17. DrahtBot added the label Needs rebase on Sep 21, 2021
  18. jonatack force-pushed on Sep 21, 2021
  19. DrahtBot removed the label Needs rebase on Sep 21, 2021
  20. jonatack force-pushed on Sep 21, 2021
  21. jonatack commented at 7:31 PM on September 21, 2021: contributor

    Rebased and updated following the merges of #22734 and #22831.

  22. DrahtBot cross-referenced this on Sep 22, 2021 from issue p2p, rpc, test: expose tried and refcount in getnodeaddresses, update/improve tests by jonatack
  23. DrahtBot cross-referenced this on Sep 24, 2021 from issue test: avoid non-determinism in asmap-addrman test by jonatack
  24. in src/logging/timer.h:104 in ce97db1596 outdated 
      99 | @@ -91,6 +100,8 @@ class Timer
 100 |      BCLog::Timer<std::chrono::microseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
 101 |  #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
 102 |      BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
 103 | +#define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
 104 | +    BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category, /* msg_on_completion=*/false)
    MarcoFalke commented at 12:30 PM on September 24, 2021:

    unrelated idea:

    The following log could also be improved with this new macro:

    src/validation.cpp:                LogPrintf("[snapshot] flushing coins cache (%.2f MB)... ", /* Continued */
    MarcoFalke commented at 4:45 PM on November 10, 2021:

    @jonatack Let me know if you want to work on this, otherwise I might pick it up

    jonatack commented at 5:05 PM on November 10, 2021:

    Thanks Marco, will have a look and comment here.

    MarcoFalke commented at 2:24 PM on December 10, 2021:

    @jonatack

    jonatack commented at 2:32 PM on December 10, 2021:

    Oh, thanks for the ping!

    jonatack commented at 9:52 PM on December 10, 2021:

    #23738

  25. DrahtBot added the label Needs rebase on Sep 27, 2021
  26. jonatack force-pushed on Sep 27, 2021
  27. DrahtBot removed the label Needs rebase on Sep 27, 2021
  28. jonatack commented at 10:56 AM on September 28, 2021: contributor

    Rebased.

  29. DrahtBot cross-referenced this on Oct 4, 2021 from issue [fuzz] Use public methods in addrman fuzz tests by jnewbery
  30. DrahtBot added the label Needs rebase on Oct 5, 2021
  31. log, timer: allow not repeating log message on completion 325da75a53
  32. log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro
    that prints the descriptive message when logging the start
but not when logging the completion.
    ec65bed00e
  33. p2p: improve checkaddrman logging with duration in milliseconds
    and update the function name to CheckAddrman (drop "Force") for
nicer log output as it is prefixed to each of these log messages:

2021-09-21T18:42:50Z [opencon] CheckAddrman: new 64864, tried 1690, total 66554 started
2021-09-21T18:42:50Z [opencon] CheckAddrman: completed (76.21ms)

The existing Doxygen documentation on the function already makes
clear that it is unaffected by m_consistency_check_ratio.
    22b44fc696
  34. jonatack force-pushed on Oct 5, 2021
  35. jonatack commented at 4:38 PM on October 5, 2021: contributor

    Rebased!

  36. DrahtBot removed the label Needs rebase on Oct 5, 2021
  37. laanwj commented at 4:06 PM on November 10, 2021: member

    Code review ACK 22b44fc696dc1078c40d17e2d497c74c7b4ae750

    2021-11-10T16:20:35Z CheckAddrman: new 9305, tried 322, total 9627 started
2021-11-10T16:20:35Z CheckAddrman: completed (21.53ms)
  38. MarcoFalke referenced this in commit 4a8707741d on Nov 10, 2021
  39. MarcoFalke removed the label P2P on Nov 10, 2021
  40. MarcoFalke commented at 4:45 PM on November 10, 2021: member

    Merged

  41. MarcoFalke closed this on Nov 10, 2021
  42. jonatack deleted the branch on Nov 10, 2021
  43. sidhujag referenced this in commit 6562a00c37 on Nov 10, 2021
  44. jonatack cross-referenced this on Dec 10, 2021 from issue validation, log: improve logging of ChainstateManager snapshot persistance by jonatack
  45. MarcoFalke referenced this in commit 767c012665 on Dec 13, 2021
  46. sidhujag referenced this in commit 35eedd1b41 on Dec 13, 2021
  47. Fabcien referenced this in commit e58399eaf2 on Nov 11, 2022
  48. bitcoin locked this on Dec 10, 2022
Contributors
jonatackMarcoFalkelaanwjpracticalswifttheStackDrahtBot
Labels
Utils/log/libs
Linked (view graph)
#22736 log, sync: change lock contention from preprocessor directive to log category#22831 test: add addpeeraddress "tried", test addrman checks on restart with asmap#23055 .#23738 validation, log: improve logging of ChainstateManager snapshot persistance
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: 2026-05-20 06:53 UTC