log: improve checkaddrman logging with duration in milliseconds #22872

jonatack · 2021-09-03T00:28:50Z

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.

src/addrman.h

practicalswift · 2021-09-04T13:43:17Z

Concept ACK

theStack · 2021-09-05T15:33:33Z

Concept ACK

laanwj · 2021-09-09T11:48:31Z

Concept ACK

src/addrman.cpp

DrahtBot · 2021-09-11T03:33:39Z

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

Conflicts

No conflicts as of last run.

jonatack · 2021-09-21T19:31:55Z

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

maflcko · 2021-09-24T12:30:57Z

src/logging/timer.h

@@ -91,6 +100,8 @@ class Timer
    BCLog::Timer<std::chrono::microseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
 #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
    BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
+#define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
+    BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category, /* msg_on_completion=*/false)


unrelated idea:

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

src/validation.cpp: LogPrintf("[snapshot] flushing coins cache (%.2f MB)... ", /* Continued */

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

Thanks Marco, will have a look and comment here.

Oh, thanks for the ping!

jonatack · 2021-09-28T10:56:12Z

Rebased.

that prints the descriptive message when logging the start but not when logging the completion.

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.

jonatack · 2021-10-05T16:38:48Z

Rebased!

laanwj · 2021-11-10T16:06:13Z

Code review ACK 22b44fc

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

…uration in milliseconds 22b44fc p2p: improve checkaddrman logging with duration in milliseconds (Jon Atack) ec65bed log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro (Jon Atack) 325da75 log, timer: allow not repeating log message on completion (Jon Atack) Pull request description: 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. ACKs for top commit: laanwj: Code review ACK 22b44fc Tree-SHA512: 658c0dfaaa9d07092e2418f2d05007c58cc35be6593f22b3c592ce793334a885dd92dacc46bdeddc9d37939cf11174660a094c07c0fa117fbb282953aa45a94d

maflcko · 2021-11-10T16:45:17Z

Merged

…in milliseconds 22b44fc p2p: improve checkaddrman logging with duration in milliseconds (Jon Atack) ec65bed log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro (Jon Atack) 325da75 log, timer: allow not repeating log message on completion (Jon Atack) Pull request description: 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. ACKs for top commit: laanwj: Code review ACK 22b44fc Tree-SHA512: 658c0dfaaa9d07092e2418f2d05007c58cc35be6593f22b3c592ce793334a885dd92dacc46bdeddc9d37939cf11174660a094c07c0fa117fbb282953aa45a94d

…nstateManager snapshot persistance 50209a4 validation, doc: remove TODO comment (Jon Atack) 8e37fa8 validation, log: improve logging in FlushSnapshotToDisk() (Jon Atack) 271252c validation, log: extract FlushSnapshotToDisk() function (Jon Atack) Pull request description: Use the `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro to improve the logging of ChainstateManager snapshot persistance, log task start and completion separately and no longer manually track the duration, as suggested by Marco Falke in bitcoin/bitcoin#22872 (comment). Extract the flushing into one function, which clarifies the logic, extends the improved logging to both flushing call sites, and allows logging the prefix `FlushSnapshotToDisk`, which is similar to `FlushStateToDisk`. before ``` [snapshot] flushing coins cache (0 MB)... done (0.00ms) [snapshot] flushing snapshot chainstate to disk ``` after ``` FlushSnapshotToDisk: flushing coins cache (0 MB) started ... FlushSnapshotToDisk: completed (0.00ms) FlushSnapshotToDisk: saving snapshot chainstate (0 MB) started ... FlushSnapshotToDisk: completed (0.00ms) ``` The logging can be observed in the output of ``` ./src/test/test_bitcoin -t validation_chainstate_tests -- DEBUG_LOG_OUT ``` Top commit has no ACKs. Tree-SHA512: 5d954cd8c7455f8625152a43663a237f04717bb834aed62925a56e17c711fca6ccfc03783970b6b0bde44f64617d804b423a7048287c06ee816db36247acf272

…nager snapshot persistance 50209a4 validation, doc: remove TODO comment (Jon Atack) 8e37fa8 validation, log: improve logging in FlushSnapshotToDisk() (Jon Atack) 271252c validation, log: extract FlushSnapshotToDisk() function (Jon Atack) Pull request description: Use the `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro to improve the logging of ChainstateManager snapshot persistance, log task start and completion separately and no longer manually track the duration, as suggested by Marco Falke in bitcoin#22872 (comment). Extract the flushing into one function, which clarifies the logic, extends the improved logging to both flushing call sites, and allows logging the prefix `FlushSnapshotToDisk`, which is similar to `FlushStateToDisk`. before ``` [snapshot] flushing coins cache (0 MB)... done (0.00ms) [snapshot] flushing snapshot chainstate to disk ``` after ``` FlushSnapshotToDisk: flushing coins cache (0 MB) started ... FlushSnapshotToDisk: completed (0.00ms) FlushSnapshotToDisk: saving snapshot chainstate (0 MB) started ... FlushSnapshotToDisk: completed (0.00ms) ``` The logging can be observed in the output of ``` ./src/test/test_bitcoin -t validation_chainstate_tests -- DEBUG_LOG_OUT ``` Top commit has no ACKs. Tree-SHA512: 5d954cd8c7455f8625152a43663a237f04717bb834aed62925a56e17c711fca6ccfc03783970b6b0bde44f64617d804b423a7048287c06ee816db36247acf272

Summary: > log, timer: allow not repeating log message on completion > 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. > 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. > This is a backport of [[bitcoin/bitcoin#22872 | core#22872]] Test Plan: `ninja all check-all` `src/bitcoind -debug=addrman -checkaddrman=10` Reviewers: #bitcoin_abc, Fabien Reviewed By: #bitcoin_abc, Fabien Differential Revision: https://reviews.bitcoinabc.org/D12469

DrahtBot added P2P Utils/log/libs labels Sep 3, 2021

maflcko reviewed Sep 3, 2021

View reviewed changes

src/addrman.h Outdated Show resolved Hide resolved

jonatack force-pushed the improve-checkaddrman-logging branch from 0b2d839 to b3b4a92 Compare September 9, 2021 17:53

maflcko reviewed Sep 10, 2021

View reviewed changes

src/addrman.cpp Outdated Show resolved Hide resolved

fanquake mentioned this pull request Sep 10, 2021

test: add addpeeraddress "tried", test addrman checks on restart with asmap #22831

Merged

DrahtBot mentioned this pull request Sep 11, 2021

fuzz: Reset addrman when consistency check fails #22939

Closed

This was referenced Sep 11, 2021

addrman: Avoid crash on corrupt data, Force Check after deserialize #22734

Merged

[p2p] Pimpl AddrMan to abstract implementation details #22950

Merged

jonatack force-pushed the improve-checkaddrman-logging branch from b3b4a92 to 3e23496 Compare September 11, 2021 19:42

Bossday mentioned this pull request Sep 21, 2021

. #23055

Closed

DrahtBot added the Needs rebase label Sep 21, 2021

jonatack force-pushed the improve-checkaddrman-logging branch from 3e23496 to 8112122 Compare September 21, 2021 18:46

DrahtBot removed the Needs rebase label Sep 21, 2021

jonatack force-pushed the improve-checkaddrman-logging branch from 8112122 to ce97db1 Compare September 21, 2021 19:30

This was referenced Sep 22, 2021

p2p, rpc, test: expose tried and refcount in getnodeaddresses, update/improve tests #23035

Closed

test: avoid non-determinism in asmap-addrman test #23084

Merged

maflcko reviewed Sep 24, 2021

View reviewed changes

DrahtBot added the Needs rebase label Sep 27, 2021

jonatack force-pushed the improve-checkaddrman-logging branch from ce97db1 to 1920f63 Compare September 27, 2021 18:17

DrahtBot removed the Needs rebase label Sep 27, 2021

DrahtBot mentioned this pull request Oct 4, 2021

[fuzz] Use public methods in addrman fuzz tests #23053

Merged

DrahtBot added the Needs rebase label Oct 5, 2021

log, timer: allow not repeating log message on completion

325da75

jonatack added 2 commits October 5, 2021 17:28

log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro

ec65bed

that prints the descriptive message when logging the start but not when logging the completion.

jonatack force-pushed the improve-checkaddrman-logging branch from 1920f63 to 22b44fc Compare October 5, 2021 16:38

DrahtBot removed the Needs rebase label Oct 5, 2021

maflcko removed the P2P label Nov 10, 2021

maflcko closed this Nov 10, 2021

jonatack deleted the improve-checkaddrman-logging branch November 10, 2021 17:03

jonatack mentioned this pull request Dec 10, 2021

validation, log: improve logging of ChainstateManager snapshot persistance #23738

Merged

bitcoin locked and limited conversation to collaborators Dec 10, 2022

log: improve checkaddrman logging with duration in milliseconds #22872

log: improve checkaddrman logging with duration in milliseconds #22872

Uh oh!

Conversation

jonatack commented Sep 3, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

practicalswift commented Sep 4, 2021

Uh oh!

theStack commented Sep 5, 2021

Uh oh!

laanwj commented Sep 9, 2021

Uh oh!

Uh oh!

DrahtBot commented Sep 11, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

jonatack commented Sep 21, 2021

Uh oh!

maflcko Sep 24, 2021

Choose a reason for hiding this comment

Uh oh!

maflcko Nov 10, 2021

Choose a reason for hiding this comment

Uh oh!

jonatack Nov 10, 2021

Choose a reason for hiding this comment

Uh oh!

maflcko Dec 10, 2021

Choose a reason for hiding this comment

Uh oh!

jonatack Dec 10, 2021

Choose a reason for hiding this comment

Uh oh!

jonatack Dec 10, 2021

Choose a reason for hiding this comment

Uh oh!

jonatack commented Sep 28, 2021

Uh oh!

jonatack commented Oct 5, 2021

Uh oh!

laanwj commented Nov 10, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Nov 10, 2021

Uh oh!

Uh oh!

jonatack commented Sep 3, 2021 •

edited

Loading

DrahtBot commented Sep 11, 2021 •

edited

Loading

laanwj commented Nov 10, 2021 •

edited

Loading