Merge bitcoin/bitcoin#33517: multiprocess: Fix high overhead from message logging

0626b90f50 multiprocess: align our logging with libmultiprocess's (Cory Fields)
9d068225ee multiprocess: update multiprocess EventLoop construction to use options (Cory Fields)

Pull request description:

  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](https://github.com/bitcoin-core/libmultiprocess/issues/215). 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.

ACKs for top commit:
  Sjors:
    ACK 0626b90f50
  TheCharlatan:
    ACK 0626b90f50
  sipa:
    utACK 0626b90f50

Tree-SHA512: 70b63b62d1f6de547f4d4775538d7bcaf32f57d8a72c5b26762b57755810c8be6942d9dfebab43cf1c1d8d025a555f72a48e9ebf3d84f8d40d6592ca801cda5d
This commit is contained in:
merge-script
2025-10-14 16:18:13 -04:00

View File

@@ -30,10 +30,36 @@
namespace ipc {
namespace capnp {
namespace {
void IpcLogFn(bool raise, std::string message)
BCLog::Level ConvertIPCLogLevel(mp::Log level)
{
LogDebug(BCLog::IPC, "%s\n", message);
if (raise) throw Exception(message);
switch (level) {
case mp::Log::Trace: return BCLog::Level::Trace;
case mp::Log::Debug: return BCLog::Level::Debug;
case mp::Log::Info: return BCLog::Level::Info;
case mp::Log::Warning: return BCLog::Level::Warning;
case mp::Log::Error: return BCLog::Level::Error;
case mp::Log::Raise: return BCLog::Level::Error;
} // no default case, so the compiler can warn about missing cases
// Be conservative and assume that if MP ever adds a new log level, it
// should only be shown at our most verbose level.
return BCLog::Level::Trace;
}
mp::Log GetRequestedIPCLogLevel()
{
if (LogAcceptCategory(BCLog::IPC, BCLog::Level::Trace)) return mp::Log::Trace;
if (LogAcceptCategory(BCLog::IPC, BCLog::Level::Debug)) return mp::Log::Debug;
// Info, Warning, and Error are logged unconditionally
return mp::Log::Info;
}
void IpcLogFn(mp::LogMessage message)
{
LogPrintLevel(BCLog::IPC, ConvertIPCLogLevel(message.level), "%s\n", message.message);
if (message.level == mp::Log::Raise) throw Exception(message.message);
}
class CapnpProtocol : public Protocol
@@ -62,7 +88,11 @@ public:
{
assert(!m_loop);
mp::g_thread_context.thread_name = mp::ThreadName(exe_name);
m_loop.emplace(exe_name, &IpcLogFn, &m_context);
mp::LogOptions opts = {
.log_fn = IpcLogFn,
.log_level = GetRequestedIPCLogLevel()
};
m_loop.emplace(exe_name, std::move(opts), &m_context);
if (ready_fn) ready_fn();
mp::ServeStream<messages::Init>(*m_loop, fd, init);
m_parent_connection = &m_loop->m_incoming_connections.back();
@@ -90,7 +120,11 @@ public:
std::promise<void> promise;
m_loop_thread = std::thread([&] {
util::ThreadRename("capnp-loop");
m_loop.emplace(exe_name, &IpcLogFn, &m_context);
mp::LogOptions opts = {
.log_fn = IpcLogFn,
.log_level = GetRequestedIPCLogLevel()
};
m_loop.emplace(exe_name, std::move(opts), &m_context);
m_loop_ref.emplace(*m_loop);
promise.set_value();
m_loop->loop();