Merge bitcoin/bitcoin#22736: log, sync: change lock contention from preprocessor directive to log category

7e69873283 sync: remove DEBUG_LOCKCONTENTION preprocessor directives (Jon Atack)
9b08006bc5 log, sync: improve lock contention logging and add time duration (Jon Atack)
3f4c6b87f1 log, timer: add timing macro in usec LOG_TIME_MICROS_WITH_CATEGORY (Jon Atack)
b7a17444e0 log, sync: add LOCK logging category, apply it to lock contention (Jon Atack)

Pull request description:

  To enable lock contention logging, `DEBUG_LOCKCONTENTION` has to be defined at compilation. Once built, the logging is not limited to a category and is high frequency, verbose and in all-caps. With these factors combined, it seems likely to be rarely used.

  This patch:
  - adds a `lock` logging category
  - adds a timing macro in microseconds, `LOG_TIME_MICROS_WITH_CATEGORY`
  - updates `BCLog::LogMsg()` to omit irrelevant decimals for microseconds and skip unneeded code and math
  - improves the lock contention logging, drops the all-caps, and displays the duration in microseconds
  - removes the conditional compilation directives
  - allows lock contentions to be logged on startup with `-debug=lock` or at run time with `bitcoin-cli logging '["lock"]'`

  ```
  $ bitcoind -signet -debug=lock
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1920 started
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1920 completed (4μs)
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1302 started
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1302 completed (4μs)
  2021-09-01T12:40:02Z LockContention: cs_vNodes, net.cpp:2242 started
  2021-09-01T12:40:02Z LockContention: cs_vNodes, net.cpp:2242 completed (20μs)
  2021-09-01T12:43:04Z LockContention: ::cs_main, validation.cpp:4980 started
  2021-09-01T12:43:04Z LockContention: ::cs_main, validation.cpp:4980 completed (3μs)

  $ bitcoin-cli -signet logging
    "lock": true,

  $ bitcoin-cli -signet logging [] '["lock"]'
    "lock": false,

  $ bitcoin-cli -signet logging '["lock"]'
    "lock": true,
  ```

  I've tested this with Clang 13 and GCC 10.2.1, on Debian, with and without `--enable-debug`.

ACKs for top commit:
  hebasto:
    re-ACK 7e69873283, added a contention duration to the log message since my [previous](https://github.com/bitcoin/bitcoin/pull/22736#pullrequestreview-743764606) review.
  theStack:
    re-ACK 7e69873283 🔏 ⏲️

Tree-SHA512: c4b5eb88d3a2c051acaa842b3055ce30efde1f114f61da6e55fcaa27476c1c33a60bc419f7f5ccda532e1bdbe70815222ec2b2b6d9226f29c8e94e598aacfee7
This commit is contained in:
MarcoFalke
2021-09-06 10:31:05 +02:00
7 changed files with 22 additions and 26 deletions

View File

@@ -27,7 +27,7 @@ BOOST_AUTO_TEST_CASE(logging_timer)
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)");
BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000μs)");
}
BOOST_AUTO_TEST_SUITE_END()