multiprocess: Fix high overhead from message logging #33517

pull theuni wants to merge 2 commits into bitcoin:master from theuni:libmultiprocess-logging-bump changing 1 files +39 −5
  1. theuni commented at 10:34 pm on October 1, 2025: member

    This fixes https://github.com/bitcoin-core/libmultiprocess/issues/215 on Core’s side. It depends on https://github.com/bitcoin-core/libmultiprocess/pull/220 being merged upstream, and a PR to update our subtree. I’ve included a subtree merge from my repo here for now, but will rebase on top of the merge from upstream once it’s in. Edit: Rebased on top of #33518.

    For context: before https://github.com/bitcoin-core/libmultiprocess/pull/220, libmultiprocess serializesd every log message parameter, even if that message was ultimately going to be discarded. The upstream PR accomplished 2 main things:

    • Creates logging categories, similar to Core’s
    • Using macros, avoids serializing parameters for disabled log levels.

    That allowed the expensive serialization to be skipped, but the default log level is Trace. This PR updates our usage of libmultiprocess options to honor our log categories and levels.

    Because of the substantial unnecessary overhead (see the flamegraphs. Logging accounts for 50% of my application’s cpu time, and nearly 10% of bitcoin-node’s, both of which go to ~0% once fixed), it’d be a shame to ship the first multiprocess binaries without this fixed. So I propose that we also backport this (and the required libmultiprocess subtree merge) to v30. Sorry about the timing :(

    Edit: Didn’t make it for v30, but it would still make sense to backport for a v30.1.

  2. DrahtBot added the label interfaces on Oct 1, 2025
  3. DrahtBot commented at 10:35 pm on October 1, 2025: contributor

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

    Code Coverage & Benchmarks

    For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/33517.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK Sjors, TheCharlatan, sipa
    Concept ACK Raimo33
    Stale ACK ryanofsky

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

  4. TheCharlatan commented at 5:13 am on October 2, 2025: contributor
    Concept ACK
  5. Raimo33 commented at 9:54 am on October 2, 2025: none

    Concept ACK

    I agree with the backporting

  6. in src/ipc/capnp/protocol.cpp:91 in 7c0015d543 outdated
    61@@ -62,7 +62,10 @@ class CapnpProtocol : public Protocol
    62     {
    63         assert(!m_loop);
    64         mp::g_thread_context.thread_name = mp::ThreadName(exe_name);
    65-        m_loop.emplace(exe_name, &IpcLogFn, &m_context);
    66+        mp::LogOptions opts = {
    


    ryanofsky commented at 8:56 pm on October 3, 2025:

    In commit “multiprocess: update multiprocess EventLoop construction to use options” (7c0015d543b4a6141520a02895342b4a316b60fe)

    This is fine to keep if intentional, but could consider passing unnamed temporary like mp::LogOptions{.log_fn = IpcLogFn} to simply code and avoid need for std::move, and not keep an empty options object on the stack for the duration of the thread.


    theuni commented at 3:06 pm on October 7, 2025:

    I only did it this way because it’s more readable to me that way, and because I figured there may be more logging options for us to use in the future that would make the in-place init more complicated.

    Happy to change it if you feel strongly.


    ryanofsky commented at 1:05 pm on October 9, 2025:

    re: #33517 (review)

    Yeah just a tradeoff between having extra variables and having an extra level a nesting. I think having more variables is worse, but no strong opinion and you should follow your preference

  7. ryanofsky approved
  8. ryanofsky commented at 9:01 pm on October 3, 2025: contributor
    Partial code review ACK d6167af132febba14bd0d86d7465aef490c58fea (just reviewed the Bitcoin code changes in last two commits, not the earlier libmultiprocess changes which will disappear when rebased), but this all looks good
  9. DrahtBot requested review from TheCharlatan on Oct 3, 2025
  10. theuni force-pushed on Oct 7, 2025
  11. theuni commented at 3:03 pm on October 7, 2025: member
    Rebased on #33518 temporarily to make sure ci is happy with everything combined.
  12. in src/ipc/capnp/protocol.cpp:44 in c3f700feb6
    40+        case mp::Log::Info: return BCLog::Level::Info;
    41+        case mp::Log::Warning: return BCLog::Level::Warning;
    42+        case mp::Log::Error: return BCLog::Level::Error;
    43+        case mp::Log::Raise: return BCLog::Level::Error;
    44+    } // no default case, so the compiler can warn about missing cases
    45+    assert(false);
    


    theuni commented at 3:09 pm on October 7, 2025:

    I’m torn about what to do here, so feedback welcome. Adding another value upstream at any point would cause a crash here. But because we don’t know what that future value would be, we can’t predict how we should react to it now.

    Just commenting because this effectively freezes mp::Log, and would require adding new fields to LogMessage instead. I’m ok with that, but @ryanofsky might not be.


    Sjors commented at 7:27 am on October 8, 2025:

    In c3f700feb6f650a7ceb62714f2d8eb0d5f1cb2ae multiprocess: align our logging with libmultiprocess’s:

    Adding a level to mp::Log could be considered a breaking change, similar to changing a function signature in the .capnp file in a breaking way.

    But we don’t want to treat IPC clients as trusted (in the long run), so crashing doesn’t seem right. Maybe instead disconnect and log at the error level?


    theuni commented at 4:19 pm on October 8, 2025:

    Agreed about avoiding crashing.

    I pushed a change that does something different than what you suggested though: assume an unknown log level should only be seen at our most verbose level, which is Trace.

    I think that’s ok, as it should cause a compilation warning (missed switch value), but otherwise not much change for the user. As it would be an API break that requires downstream attention, I think that’s reasonable.


    ryanofsky commented at 1:07 pm on October 9, 2025:

    re: #33517 (review)

    Not important, but FWIW sjors suggestion makes a little more sense to me to I don’t see sending unknown log messages to the trace stream, which is effectively a black hole, as being more conservative. IMO ideal thing to do would be to return std::optional and nullopt and then log unknown messages at debug level with a prefix like “[unrecognized flags “0x%08x]”.


    theuni commented at 1:56 pm on October 9, 2025:

    By “more conservative”, I meant from a Core logging DOS pov.

    If libmp ever added a super-duper-verbose mode, imo the safer thing to do would be to black-hole those messages rather than fill the log with them. Sure that would hide issues, but it would also prevent accidental blowups. I don’t see that as likely at all, just thinking defensively by default.

    I could imagine sending a single “Unrecognized log level specified” warning, but that doesn’t really seem worth the complexity for a theoretical/unlikely future issue.

  13. Sjors approved
  14. Sjors commented at 7:29 am on October 8, 2025: member

    ACK c3f700feb6f650a7ceb62714f2d8eb0d5f1cb2ae


    Not directly related to the changes here, but it’s a bit odd that clean disconnects are logged at the info level (always visible) while new connections are logged at the debug level (requires -debug=ipc).

    Disconnect:

    02025-10-08T07:19:16Z [ipc:info] {bitcoin-node-57287/b-capnp-loop-6497836} IPC server destroy N2mp11ProxyServerIN3ipc5capnp8messages6MiningEEE
    12025-10-08T07:19:16Z [ipc:info] {bitcoin-node-57287/b-capnp-loop-6497836} IPC server: socket disconnected.
    22025-10-08T07:19:16Z [ipc:info] {bitcoin-node-57287/b-capnp-loop-6497836} IPC server destroy N2mp11ProxyServerIN3ipc5capnp8messages4InitEEE
    

    Connect (-debug=ipc):

    02025-10-08T07:19:44Z [ipc] {bitcoin-node-57788/b-capnp-loop-6502845} IPC server recv request  [#1](/bitcoin-bitcoin/1/) Init.construct$Params
    12025-10-08T07:19:44Z [ipc] {bitcoin-node-57788/b-capnp-loop-6502845} IPC server send response [#1](/bitcoin-bitcoin/1/) Init.construct$Results
    22025-10-08T07:19:44Z [ipc] {bitcoin-node-57788/b-capnp-loop-6502845} IPC server recv request  [#2](/bitcoin-bitcoin/2/) Init.makeMining$Params
    32025-10-08T07:19:44Z [ipc] {bitcoin-node-57788/b-capnp-loop-6502845} IPC server post request  [#2](/bitcoin-bitcoin/2/) {bitcoin-node-57788/6502989 (from sv2-tp-57803/6502987)}
    42025-10-08T07:19:44Z [ipc] {bitcoin-node-57788/b-capnp-loop-6502845} IPC server send response [#2](/bitcoin-bitcoin/2/) Init.makeMining$Results
    

    The former seems too chatty, the latter too quiet. Maybe only have the “socket disconnected” message be at the info level and introduce a “socket connected” message.

  15. DrahtBot requested review from ryanofsky on Oct 8, 2025
  16. theuni force-pushed on Oct 8, 2025
  17. ryanofsky approved
  18. ryanofsky commented at 1:23 pm on October 9, 2025: contributor

    Code review ACK dcaf4b736f9ddfc6a2695ce19221a7f383e43e20. Just rebased onto #33518 and changed assert(false) to log trace and since last review

    re: #33517#pullrequestreview-3313376282

    The former seems too chatty, the latter too quiet.

    Good observations, created https://github.com/bitcoin-core/libmultiprocess/issues/227 to track this

  19. DrahtBot requested review from Sjors on Oct 9, 2025
  20. fanquake referenced this in commit becf150013 on Oct 10, 2025
  21. fanquake commented at 9:48 am on October 10, 2025: member
    #33518 has gone in, so this could be rebased / undrafted.
  22. multiprocess: update multiprocess EventLoop construction to use options
    This uses the constructors recently added upstream.
    9d068225ee
  23. multiprocess: align our logging with libmultiprocess's
    Without this change, logging (even if unused) may account for a
    substantial portion of bitcoin-node's and/or client's runtime cpu usage, due
    to libmultiprocess's expensive message serialization.
    
    This (along with some recent upstream changes) avoids the overhead by opting
    out of log handling for messages that we're not interested in.
    
    Info, Warning, and Error are logged unconditionally to match our behavior
    elsewhere. See BCLog::Logger::GetCategoryLogLevel .
    0626b90f50
  24. theuni force-pushed on Oct 10, 2025
  25. theuni marked this as ready for review on Oct 10, 2025
  26. Sjors commented at 8:57 am on October 13, 2025: member
    CI doesn’t look happy. Update: seems fine again.
  27. Sjors commented at 8:16 am on October 14, 2025: member
    ACK 0626b90f507db68610a69feec86deb712dd095a1
  28. DrahtBot requested review from ryanofsky on Oct 14, 2025
  29. TheCharlatan approved
  30. TheCharlatan commented at 1:06 pm on October 14, 2025: contributor
    ACK 0626b90f507db68610a69feec86deb712dd095a1
  31. sipa commented at 1:22 pm on October 14, 2025: member
    utACK 0626b90f507db68610a69feec86deb712dd095a1
  32. glozow merged this on Oct 14, 2025
  33. glozow closed this on Oct 14, 2025

  34. fanquake added the label Needs backport (30.x) on Oct 14, 2025
  35. fanquake commented at 8:57 am on October 16, 2025: member
    Backported to 30.x in #33609.
  36. fanquake removed the label Needs backport (30.x) on Oct 16, 2025
  37. fanquake referenced this in commit f8db6f6ce7 on Oct 16, 2025
  38. fanquake referenced this in commit 729e4c2abd on Oct 16, 2025
  39. ryanofsky commented at 2:22 pm on October 22, 2025: contributor

    Just to follow up, I think it was unclear if this change was compatible with the logging RPC that allows log levels to be changed at runtime.

    I think it actually is compatible because the current RPC method only allows enabling/disabling categories without adjusting levels. If a way to adjust log levels is added though, a special case like the one added for libevent might need to be added for libmultiprocess as well.

  40. theuni commented at 7:30 am on October 23, 2025: member
    Agreed. Thanks for having a look.

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: 2025-10-31 15:13 UTC

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