multiprocess: Fix high overhead from message logging

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.

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

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

That allows 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 :(

DrahtBot added the label interfaces on Oct 1, 2025

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	ryanofsky
Concept ACK	TheCharlatan, Raimo33
Stale ACK	Sjors

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

TheCharlatan commented at 5:13 am on October 2, 2025: contributor

Concept ACK

Raimo33 commented at 9:54 am on October 2, 2025: none

Concept ACK

I agree with the backporting

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

ryanofsky approved

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

DrahtBot requested review from TheCharlatan on Oct 3, 2025

Squashed 'src/ipc/libmultiprocess/' changes from 47d79db8a552..a4f929696490

a4f929696490 Merge bitcoin-core/libmultiprocess#224: doc: fix typos
f4344ae87da0 Merge bitcoin-core/libmultiprocess#222: test, ci: Fix threadsanitizer errors in mptest
1434642b3804 doc: fix typos
73d22ba2e930 test: Fix tsan race in thread busy test
b74e1bba014d ci: Use tsan-instrumented cap'n proto in sanitizers job
c332774409ad test: Fix failing exception check in new thread busy test
ca3c05d56709 test: Use KJ_LOG instead of std::cout for logging
7eb1da120ab6 ci: Use tsan-instrumented libcxx in sanitizers job
ec86e4336e98 Merge bitcoin-core/libmultiprocess#220: Add log levels and advertise them to users via logging callback
515ce93ad349 Logging: Pass LogData struct to logging callback
213574ccc43d Logging: reclassify remaining log messages
e4de0412b430 Logging: Break out expensive log messages and classify them as Trace
408874a78fdc Logging: Use new logging macros
67b092d835cd Logging: Disable logging if messsage level is less than the requested level
d0a1ba7ebf21 Logging: add log levels to mirror Core's
463a8296d188 Logging: Disable moving or copying Logger
83a2e10c0b03 Logging: Add an EventLoop constructor to allow for user-specified log options
58cf47a7fc8c Merge bitcoin-core/libmultiprocess#221: test default PassField impl handles output parameters
db03a663f514 Merge bitcoin-core/libmultiprocess#214: Fix crash on simultaneous IPC calls using the same thread
afcc40b0f1e8 Merge bitcoin-core/libmultiprocess#213: util+doc: Clearer errors when attempting to run examples + polished docs
6db669628387 test In|Out parameter
29cf2ada75ea test default PassField impl handles output parameters
1238170f68e8 test: simultaneous IPC calls using same thread
eb069ab75d83 Fix crash on simultaneous IPC calls using the same thread
ec03a9639ab5 doc: Precision and typos
2b4348193551 doc: Where possible, remove links to ryanofsky/bitcoin/
286fe469c9c9 util: Add helpful error message when failing to execute file

git-subtree-dir: src/ipc/libmultiprocess
git-subtree-split: a4f92969649018ca70f949a09148bccfeaecd99a

0f01e1577f

Merge commit '0f01e1577f7c6734eb345139a12aba329ef22a5f' into pr/subtree-6 eda91b07fd

multiprocess: update multiprocess EventLoop construction to use options

This uses the constructors recently added upstream.

6c1de3ead9

theuni force-pushed on Oct 7, 2025

theuni commented at 3:03 pm on October 7, 2025: member

Rebased on #33518 temporarily to make sure ci is happy with everything combined.

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.

Sjors approved

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.

DrahtBot requested review from ryanofsky on Oct 8, 2025

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 .

dcaf4b736f

theuni force-pushed on Oct 8, 2025

ryanofsky approved

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

DrahtBot requested review from Sjors on Oct 9, 2025

fanquake referenced this in commit becf150013 on Oct 10, 2025

fanquake commented at 9:48 am on October 10, 2025: member

#33518 has gone in, so this could be rebased / undrafted.

multiprocess: Fix high overhead from message logging #33517

Code Coverage & Benchmarks

Reviews