log: improve checkaddrman logging with duration in milliseconds

jonatack commented at 0:28 am on September 3, 2021: member

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

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

after

02021-09-21T18:42:50Z [opencon] CheckAddrman: new 64864, tried 1690, total 66554 started
12021-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.

DrahtBot added the label P2P on Sep 3, 2021

DrahtBot added the label Utils/log/libs on Sep 3, 2021

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

practicalswift commented at 1:43 pm on September 4, 2021: contributor

Concept ACK

theStack commented at 3:33 pm on September 5, 2021: member

Concept ACK

laanwj commented at 11:48 am on September 9, 2021: member

Concept ACK

jonatack force-pushed on Sep 9, 2021

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:

02021-09-11T19:39:05Z [scheduler] Enter: lock contention ::cs_main, validation.cpp:4874 started
12021-09-11T19:39:05Z [opencon] CheckAddrMan_: new 442, tried 57, total 499 started
22021-09-11T19:39:05Z [opencon] CheckAddrMan_: completed (10.30ms)
32021-09-11T19:39:07Z [scheduler] Enter: lock contention ::cs_main, validation.cpp:4874 completed (2906703μs)

DrahtBot commented at 3:33 am on September 11, 2021: member

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

Conflicts

No conflicts as of last run.

jonatack force-pushed on Sep 11, 2021

DrahtBot added the label Needs rebase on Sep 21, 2021

jonatack force-pushed on Sep 21, 2021

DrahtBot removed the label Needs rebase on Sep 21, 2021

jonatack force-pushed on Sep 21, 2021

jonatack commented at 7:31 pm on September 21, 2021: member

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

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:

0src/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

DrahtBot added the label Needs rebase on Sep 27, 2021

jonatack force-pushed on Sep 27, 2021

DrahtBot removed the label Needs rebase on Sep 27, 2021

jonatack commented at 10:56 am on September 28, 2021: member

Rebased.

DrahtBot added the label Needs rebase on Oct 5, 2021

log, timer: allow not repeating log message on completion 325da75a53

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

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

jonatack force-pushed on Oct 5, 2021

jonatack commented at 4:38 pm on October 5, 2021: member

Rebased!

DrahtBot removed the label Needs rebase on Oct 5, 2021

laanwj commented at 4:06 pm on November 10, 2021: member

Code review ACK 22b44fc696dc1078c40d17e2d497c74c7b4ae750

02021-11-10T16:20:35Z CheckAddrman: new 9305, tried 322, total 9627 started
12021-11-10T16:20:35Z CheckAddrman: completed (21.53ms)

MarcoFalke referenced this in commit 4a8707741d on Nov 10, 2021

MarcoFalke removed the label P2P on Nov 10, 2021

MarcoFalke commented at 4:45 pm on November 10, 2021: member

Merged

MarcoFalke closed this on Nov 10, 2021

jonatack deleted the branch on Nov 10, 2021

sidhujag referenced this in commit 6562a00c37 on Nov 10, 2021

MarcoFalke referenced this in commit 767c012665 on Dec 13, 2021

sidhujag referenced this in commit 35eedd1b41 on Dec 13, 2021

Fabcien referenced this in commit e58399eaf2 on Nov 11, 2022

DrahtBot locked this on Dec 10, 2022

log: improve checkaddrman logging with duration in milliseconds #22872

Conflicts