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. 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.

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	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.

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

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

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: update multiprocess EventLoop construction to use options

This uses the constructors recently added upstream.

9d068225ee

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

theuni force-pushed on Oct 10, 2025

theuni marked this as ready for review on Oct 10, 2025

Sjors commented at 8:57 am on October 13, 2025: member

CI doesn’t look happy. Update: seems fine again.

Sjors commented at 8:16 am on October 14, 2025: member

ACK 0626b90f507db68610a69feec86deb712dd095a1

DrahtBot requested review from ryanofsky on Oct 14, 2025

TheCharlatan approved

TheCharlatan commented at 1:06 pm on October 14, 2025: contributor

ACK 0626b90f507db68610a69feec86deb712dd095a1

sipa commented at 1:22 pm on October 14, 2025: member

utACK 0626b90f507db68610a69feec86deb712dd095a1

glozow merged this on Oct 14, 2025

glozow closed this on Oct 14, 2025

fanquake added the label Needs backport (30.x) on Oct 14, 2025

fanquake commented at 8:57 am on October 16, 2025: member

Backported to 30.x in #33609.

fanquake removed the label Needs backport (30.x) on Oct 16, 2025

fanquake referenced this in commit f8db6f6ce7 on Oct 16, 2025

fanquake referenced this in commit 729e4c2abd on Oct 16, 2025

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.

theuni commented at 7:30 am on October 23, 2025: member

Agreed. Thanks for having a look.

multiprocess: Fix high overhead from message logging #33517

Code Coverage & Benchmarks

Reviews