Put lock contention logging behind DEBUG_LOCKCONTENTION preprocessor directive #24734

pull jonatack wants to merge 4 commits into bitcoin:master from jonatack:change-lock-logging-to-DEBUG_LOCKCONTENTION changing 8 files +43 −10
  1. jonatack commented at 11:02 am on April 1, 2022: member

    PRs #22736, #22904 and #23223 changed lock contention logging from a DEBUG_LOCKCONTENTION compile-time preprocessor directive to a runtime lock log category and improved the logging output. This changed the locking from using lock() to try_lock():

    • void Mutex::UniqueLock::lock() acquires the mutex and blocks until it gains access to it

    • bool Mutex::UniqueLock::try_lock() doesn’t block but instead immediately returns whether it acquired the mutex; it may be used by lock() internally as part of the deadlock-avoidance algorithm

    In theory the cost of try_lock might be essentially the same relative to lock. The test-and-set logic of these calls is purported to be ~ constant time, optimised and light/quick if used carefully (i.e. no mutex convoying), compared to system calls, memory/cache coherency and fences, wait queues, and (particularly) lock contentions. See the discussion around #22736 (comment) and after with respect to performance/cost aspects. However, there are reasonable concerns (see here and here) that Base::try_lock() may be potentially costly or risky compared to Base::lock() in this very frequently called code.

    One alternative to keep the run-time lock logging would be to gate the try_lock call behind the logging conditional, for example as proposed in https://github.com/bitcoin/bitcoin/commit/ccd73de1dd969097d34634c2be2fc32b03fbd09e and ACKed here. However, this would add the cost of if (LogAcceptCategory(BCLog::LOCK)) to the hotspot, instead of replacing lock with try_lock, for the most frequent happy path (non-contention).

    It turns out we can keep the advantages of the runtime lock contention logging (the ability to turn it on/off at runtime) while out of prudence putting the try_lock() call and lock logging category behind a DEBUG_LOCKCONTENTION compile-time preprocessor directive, and also still retain the lock logging enhancements of the mentioned PRs, as suggested in #24734 (comment) by W. J. van der Laan, in #22736 (review), and in the linked IRC discussion.

    Proposed here and for backport to v23.

  2. in src/sync.h:141 in 0d1248bf26 outdated
    135@@ -136,9 +136,14 @@ class SCOPED_LOCKABLE UniqueLock : public Base
    136     void Enter(const char* pszName, const char* pszFile, int nLine)
    137     {
    138         EnterCritical(pszName, pszFile, nLine, Base::mutex());
    139-        if (Base::try_lock()) return;
    140-        LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
    141-        Base::lock();
    142+#ifdef DEBUG_LOCKCONTENTION
    143+        if (!Base::try_lock()) {
    144+            LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
    


    jonatack commented at 11:06 am on April 1, 2022:
    0            LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine));
    

    ajtowns commented at 11:11 am on April 1, 2022:
    0#ifdef DEBUG_LOCKCONTENTION
    1        if (Base::try_lock()) return;
    2        LOG_TIME_MICROS(....);
    3#endif
    4        Base::lock();
    

    jonatack commented at 11:44 am on April 1, 2022:
    Agree, more like the current code and cleaner.

    jonatack commented at 12:51 pm on April 1, 2022:
    Done, thanks
  3. laanwj commented at 11:28 am on April 1, 2022: member

    Alternatively, we could keep the lock category only when DEBUG_LOCKCONTENTION is set. This still has the intended effect of making lock contention run-time switchable for people that want it enabled. No strong opinion though. This is definitely simpler.

    Obvious concept ACK.

  4. jonatack commented at 11:43 am on April 1, 2022: member

    Alternatively, we could keep the lock category only when DEBUG_LOCKCONTENTION is set. This still has the intended effect of making lock contention run-time switchable for people that want it enabled. No strong opinion though.

    Agree! This would allow leaving the flag defined for development while being able to switch it off at runtime. All the benefits without the drawbacks. Will update.

  5. DrahtBot added the label Tests on Apr 1, 2022
  6. jonatack renamed this:
    sync: revert lock contention from log category to preprocessor directive
    Put lock contention logging behind `DEBUG_LOCKCONTENTION` preprocessor directive
    on Apr 1, 2022
  7. jonatack commented at 12:54 pm on April 1, 2022: member

    Updated code and PR title/description per @laanwj’s and @ajtowns suggestion. This is now a much smaller change, too.

    Edit: overlooked updating the commit title, will do after CI feedback.

  8. jonatack force-pushed on Apr 1, 2022
  9. shaavan approved
  10. shaavan commented at 1:16 pm on April 1, 2022: contributor

    ACK 73759f88537e472dc443318a16545d63e6c22024

    Let me summarize how I understood this PR:

    • This PR introduced (back) the DEBUG_LOCKCONTENTION compile-time processor directive to allow the user to opt-out of potentially costly and dangerous run time locking log using Base::try_lock().

    If my understanding of this PR is correct, I agree with its concept of it:

    • I like the prudent approach in case we find out using Base::try_lock() was not the efficient way of logging.
    • This keeps the earlier benefits introduced with run-time logging, so we are not losing a beneficial feature.

    Considering the comments of @laanwj and @ajtowns

    • The reduced diff looks much cleaner than the earlier version of this PR.
    • As per @laanwj suggestion, the updated code keeps the benefits of run-time logging instead of completely reverting them, which I agree with.
  11. jonatack commented at 1:17 pm on April 1, 2022: member
    Mind that updating the checkqueue_tests setup doesn’t seem needed, but can do if people prefer. -> Edit: done, as the test without DEBUG_LOCKCONTENTION defined would generate warnings.
  12. DrahtBot commented at 1:24 pm on April 1, 2022: member

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

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #24757 (build, ci: add DEBUG_LOCKCONTENTION to –enable-debug and CI by jonatack)
    • #23443 (p2p: Erlay support signaling by naumenkogs)
    • #21603 (log: Mitigate disk filling attacks by rate limiting LogPrintf by dergoegge)

    If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

  13. in test/functional/rpc_misc.py:60 in 73759f8853 outdated
    56@@ -57,7 +57,7 @@ def run_test(self):
    57         self.log.info("test logging rpc and help")
    58 
    59         # Test logging RPC returns the expected number of logging categories.
    60-        assert_equal(len(node.logging()), 27)
    61+        assert 26 <= len(node.logging()) <= 27
    


    MarcoFalke commented at 1:29 pm on April 1, 2022:
    What is the point of this other than causing merge conflicts? Might be best to remove.

    jonatack commented at 1:33 pm on April 1, 2022:
    Considered removing, done
  14. jonatack commented at 2:00 pm on April 1, 2022: member

    With this change, if lock logging is requested and DEBUG_LOCKCONTENTION is not defined:

    0$ bitcoind -debug=lock
    1Warning: Unsupported logging category -debug=lock.
    22022-04-01T13:57:44Z [init] Bitcoin Core version v23.99.0-73759f88537e (debug build)
    32022-04-01T13:57:44Z [init] Warning: Unsupported logging category -debug=lock.
    
    0$ bitcoin-cli logging '["lock"]'
    1error code: -8
    2error message:
    3unknown logging category lock
    

    which is better than being silently inactive.

  15. jonatack force-pushed on Apr 1, 2022
  16. MarcoFalke commented at 2:17 pm on April 1, 2022: member

    So this will be disabled for all CI tasks? If yes, could enable it for some, or by default in --enable-debug? See also #24709.

    Otherwise the code is never compiled, which makes me wonder if it ever was compiled before the changes?

  17. jonatack commented at 2:22 pm on April 1, 2022: member

    So this will be disabled for all CI tasks? If yes, could enable it for some, or by default in --enable-debug? See also #24709.

    I was thinking about that, as personally I would always want to define DEBUG_LOCKCONTENTION for debug building. Can add here to --enable-debug the same as DDEBUG_LOCKORDER and mention in the developer notes.

  18. MarcoFalke commented at 2:26 pm on April 1, 2022: member
    If it was never enabled previously, it can also be done as a follow-up. Just wanted to raise the point.
  19. jonatack commented at 2:32 pm on April 1, 2022: member
    Follow-up SGTM. Right, the previous situation AFAIK was that it was only compiled if manually defined by the user.
  20. jonatack force-pushed on Apr 1, 2022
  21. jonatack commented at 3:41 pm on April 1, 2022: member
    Made the src/sync.h logging include headers conditional on DEBUG_LOCKCONTENTION as well, added missing includes in src/net.{h,cpp} that this revealed and moved a method from the header to the implementation to not include logging in the header file.
  22. jonatack force-pushed on Apr 1, 2022
  23. jonatack force-pushed on Apr 1, 2022
  24. net: add missing include headers to src/net.{h,cpp}
    Among these includes, src/net.{h,cpp} is relying on src/sync.h for <logging.h>
    and in turn on src/logging.h for <list>.  The compiler raises when they are
    removed from src/sync.h in the last commit of this PR, so they need to be added.
    6e56589bcb
  25. refactor: move StartExtraBlockRelayPeers from net.h to net.cpp
    which allows dropping `#include <logging>` in the header file.
    e1437e1f5d
  26. jonatack force-pushed on Apr 1, 2022
  27. jonatack commented at 9:48 am on April 4, 2022: member
    Added developer notes documentation.
  28. in test/functional/rpc_misc.py:59 in 2623fb4ff2 outdated
    55@@ -56,9 +56,6 @@ def run_test(self):
    56 
    57         self.log.info("test logging rpc and help")
    58 
    59-        # Test logging RPC returns the expected number of logging categories.
    


    laanwj commented at 10:05 am on April 4, 2022:
    ACK on removing this test, it seems kind of unnecessary (just checks that the code is the code, not any kind of correctness).

    jonatack commented at 8:42 am on April 5, 2022:
    Agree
  29. laanwj commented at 10:07 am on April 4, 2022: member

    Concept and code review ACK 2623fb4ff235b199e167695fe304a689b072c560

    (reasoning for adding backport label is that it removes the try_locklock sequence overhead for every locking in the application, which adds some overhead and is potentially risky)

  30. laanwj added the label Needs backport (23.x) on Apr 4, 2022
  31. jonatack commented at 10:33 am on April 4, 2022: member

    (reasoning for adding backport label is that it removes the try_locklock sequence overhead for every locking in the application, which adds some overhead and is potentially risky)

    Agree, really happy that this change avoids unnecessary risk while preserving the benefits of the recent improvements.

  32. MarcoFalke added this to the milestone 23.0 on Apr 4, 2022
  33. MarcoFalke removed the label Tests on Apr 4, 2022
  34. MarcoFalke added the label Utils/log/libs on Apr 4, 2022
  35. jonatack commented at 11:36 am on April 4, 2022: member

    So this will be disabled for all CI tasks? If yes, could enable it for some, or by default in --enable-debug? See also #24709.

    Done in #24757.

  36. jonatack force-pushed on Apr 5, 2022
  37. jonatack commented at 8:38 am on April 5, 2022: member
    Updated per git diff 2623fb4 7ea951d to avoid Unsupported logging category -debugexclude=lock warnings when running the checkqueue tests without DEBUG_LOCKCONTENTION defined. Edit: re-pushed to appease linter.
  38. jonatack force-pushed on Apr 5, 2022
  39. Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive 236dbd1265
  40. Add DEBUG_LOCKCONTENTION documentation to the developer notes 7ea951d607
  41. jonatack force-pushed on Apr 5, 2022
  42. in src/net.cpp:55 in 7ea951d607
    51@@ -51,8 +52,12 @@
    52 #include <array>
    53 #include <cstdint>
    54 #include <functional>
    55+#include <list>
    


    fanquake commented at 9:37 am on April 5, 2022:

    In 6e56589bcbe2d04ee1b9018baf5a9d1dc958e68d

    The compiler raises when they are removed from src/sync.h in the last commit of this PR, so they need to be added.

    If they need to be added, they should be added in the commit where they become required. If this PR is going to be backported, the number of commits, and potential for conflicts should be kept at a minimum, so we should avoid things like additional commits doing include fixups.


    jonatack commented at 9:54 am on April 5, 2022:
    These are different changes; kept them separate to ease review. If the goal is to squash this down, then we could not conditionally do the two includes in the 3rd commit and backport only that one.

    jonatack commented at 10:23 am on April 5, 2022:
    Done in #24770.
  43. in src/net.cpp:1865 in e1437e1f5d outdated
    1861@@ -1862,6 +1862,12 @@ void CConnman::SetTryNewOutboundPeer(bool flag)
    1862     LogPrint(BCLog::NET, "net: setting try another outbound peer=%s\n", flag ? "true" : "false");
    1863 }
    1864 
    1865+void CConnman::StartExtraBlockRelayPeers()
    


    fanquake commented at 9:42 am on April 5, 2022:

    In e1437e1f5d3fb9ae95b1ca503893ff0ffb2e8c8d

    which allows dropping #include <logging> in the header file.

    is this the only reason for this change? I’m not sure that doing this is required right now, and it seems to just be what necessitates the changes in the prior commit.


    jonatack commented at 9:51 am on April 5, 2022:
    No; see explanation in the first commit message.
  44. jonatack commented at 9:45 am on April 5, 2022: member

    ACK 73759f8 @shaavan mind having another look? (thanks!)

  45. fanquake commented at 9:49 am on April 5, 2022: member
    I think you could just drop the first two commits, and add 2 missing includes to the 3rd commit, i.e https://github.com/fanquake/bitcoin/tree/simplfied_24734. That would seem to achieve the same outcome with less code changes, and is simpler if this is meant to be backported.
  46. MarcoFalke removed the label Needs backport (23.x) on Apr 5, 2022
  47. MarcoFalke removed this from the milestone 23.0 on Apr 5, 2022
  48. shaavan commented at 12:26 pm on April 5, 2022: contributor

    Changes since my last review:

    1. Added documentation for DEBUG_LOCKCONTENTION in developer notes.
    2. Added missing include headers.
    3. Moved StartExtraBlockRelayPeers from net.h to the net.cpp

    I like the added developer documentation for its clear and concise writing. It explains the purpose of the DEBUG_LOCKCONTENTION macro and describes how to use it effectively.

    However, I am not able to reason with the following added changes:

    • Keeping all the included headers into a separate commit.
      • Though it makes reviewing easier. I don’t feel it needs to be in a separate commit.
    • Moving StartExtraBlockRelayPeers from net.h to the net.cpp
      • Though it is mentioned in this comment to refer to the first commit message, I can still not completely understand the reasoning. Hence, for now, I am concept 0 on this particular change.

    I took a look into #24770, which has all the changes I agree with from this PR, and hence I think we can focus on getting that merged first.

  49. jonatack commented at 1:28 pm on April 5, 2022: member

    @shaavan thanks for having a look.

    * **Keeping all the included headers into a separate commit.**
      
      * Though it makes reviewing easier. I don’t feel it needs to be in a separate commit.
    

    The missing headers are an unrelated issue, apart from needing to be fixed for the object of this pull. Missing headers are generally done in a separate commit, see https://github.com/bitcoin/bitcoin/pull/24740/commits for a recent example.

    * **Moving `StartExtraBlockRelayPeers` from net.h to the net.cpp**
      
      * Though it is mentioned in [this](https://github.com/bitcoin/bitcoin/pull/24734#discussion_r842591735) comment to refer to the first commit message, I can still not completely understand the reasoning. Hence, for now, I am concept 0 on this particular change.
    

    Moving the function definition into the implementation (cpp) allows dropping an include header. Doing so can speed up compilation for the many files that include net.h. It’s not strictly needed for backport but is trivial to review.

  50. ajtowns commented at 8:44 am on April 6, 2022: member
    This should be closed or rebased on top of #24770 if that’s what you’re now intending to get merged…
  51. jonatack commented at 8:49 am on April 6, 2022: member
    Yes, this is my preferred version and plan to update or close whichever ones aren’t merged.
  52. shaavan approved
  53. shaavan commented at 11:27 am on April 8, 2022: contributor

    ACK 7ea951d607846f21c262aca950c393cc150ca7ab

    Missing headers are generally done in a separate commit.

    Though I am not 100% convinced, I cannot think of any blocking points for this change. Hence I am Concept 0 on this and will allow fellow reviewers to decide the optimal way forward on this particular change.

    Moving the function definition into the implementation (cpp) allows dropping an include header. Doing so can speed up compilation for the many files that include the net.h.

    That is acceptable reasoning, and I find it to be logically sound. Hence, I agree with this change.

  54. fanquake referenced this in commit c1059c9fef on Apr 8, 2022
  55. MarcoFalke commented at 10:11 am on April 9, 2022: member
    Closing as this has been merged
  56. MarcoFalke closed this on Apr 9, 2022

  57. jonatack commented at 11:53 am on April 12, 2022: member
    Thank you for revewing, @shaavan. I moved the remaining changes here to #24757.
  58. DrahtBot locked this on Apr 12, 2023

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-12-22 12:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me