Add a verbose logging option and put expensive debug output behind it

theuni commented at 8:55 pm on September 23, 2025: contributor

Fixes #215. It’s rather naive, but demonstrates a fix for the problem.

Logging every send/receive/request/response is very expensive for structs due to the way they’re stringified by capnproto.

Introduce the concept of verbose logging, and expose it to clients by adding a new constructor for EventLoop which accepts LogOptions.

For backwards compatibility, the existing constructor is unchanged. Additionally for back compat, a new callback function is added rather than adding a parameter to the existing one.

The usage is somewhat awkward due to the fact that the data should only be stringified if verbose logging has been requested. This could be less awkward by changing the logger to take a callback which is only called if verbosity is enabled instead, that way the slow serialization only happens in that case. Additionally, a more complete solution would introduce actual log levels rather than a binary option

But those suggestions would be rather invasive and presumably out of scope for simply fixing the linked issue.

DrahtBot commented at 8:55 pm on September 23, 2025: none

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

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	ismaelsadeeq, ryanofsky
Concept ACK	TheCharlatan

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#220 (Add log levels and advertise them to users via logging callback by theuni)
#218 (Better error and log messages by ryanofsky)

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.

theuni commented at 9:07 pm on September 23, 2025: contributor

Here is a commit which hooks up usage in Core.

Sjors commented at 8:01 am on September 24, 2025: member

For backwards compatibility, the existing constructor is unchanged.

As probably the only user outside of Bitcoin Core (https://github.com/sjors/sv2-tp), I’m not too worried about backwards compatibility.

ryanofsky commented at 12:34 pm on September 24, 2025: collaborator

Code review ACK e50802f31e3cfc12f9447ea9dcb951e0123788d0. I think this is a good fix, and the backwards compatibility is helpful for avoiding version mismatch errors during development, and for avoiding the need to modify bitcoin core code in a PR bumping the ilbmultiprocess subtree (which should make it a little easier to review).

I think this PR could be simplified a little by dropping new LogFn verbose_log_fn struct member and just using the existing log callback for logging everything. This would also allow dropping new bool verbose=false logging arguments.

Longer run, it might make sense to introduce a macro to make logging less cumbersome like:

0MP_LOG(loop, level) << "IPC client recv" << request;

where MP_LOG macro just uses an mp::Logger class:

0#define MP_LOG(...) if (mp::Logger logger{__VA_ARGS__}; logger) logger

and mp::Logger class can:

Decide whether the rest of the log statement is evaluated by providing operator bool
Control log formatting by providing operator <<
Accept log level levels or other context by providing different constructors

theuni commented at 2:28 pm on September 24, 2025: contributor

I think this PR could be simplified a little by dropping new LogFn verbose_log_fn struct member and just using the existing log callback for logging everything. This would also allow dropping new bool verbose=false logging arguments.

This would be my preference as well, but that leaves the log function unable to tell whether this is a “verbose” message or not. In Core’s case, we’d want treat that differently (as shown here: #216 (comment)). In order to tell them apart, we’d need to add a bool verbose param to the log function, which I was hesitant to do for back compat reasons.

Longer run, it might make sense to introduce a macro to make logging less cumbersome like:
0MP_LOG(loop, level) << "IPC client recv" << request;

I think we’d want to take that one step further and do what Core does: encapsulating the arguments in the macro as well to avoid their evaluation at unrequested log levels.

But since the codebase is still rather young and flexible, my suggestion would be a callback. Something like:

 0
 1enum class LogLevel {
 2    Trace = 0,
 3    Debug,
 4    Info,
 5    Warning,
 6    Error,
 7};
 8
 9...
10
11template <typename Callable>
12void log(LogLevel log_level, Callable&& log_callback)
13{
14    logPlain(log_level, [this, &log_callback](auto& logger) {
15        logger << "{" << LongThreadName(m_exe_name) << "} ";
16        std::invoke(log_callback, logger);
17    });
18}
19
20template <typename Callable>
21void logPlain(LogLevel log_level, Callable&& log_callback)
22{
23    if (log_level >= m_log_opts.log_level) {
24        Logger logger(false, m_log_opts.log_fn);
25        std::invoke(log_callback, logger);
26    }
27}

With macros like:

0#define MP_LOGINFO(loop, logger, code) loop.log(LogLevel::Info, [&](auto& logger) { code; })
1#define MP_LOGDEBUG(loop, logger, code) loop.log(LogLevel::Debug, [&](auto& logger) { code; })

and usage like:

0MP_LOGDEBUG(loop, logger, logger << "foo" << 3; logger << bar.makeExpensiveString());

That way, in the example above, makeExpensiveString() won’t be called unless debugging is enabled.

theuni commented at 2:45 pm on September 24, 2025: contributor

Hmm, maybe I read too quickly.

Looking again, your approach is clever and I believe keeps the arguments unevaluated as necessary as well?

ismaelsadeeq commented at 3:04 pm on September 24, 2025: member

nice Concept ACK

theuni commented at 3:07 pm on September 24, 2025: contributor

Hmm, maybe I read too quickly.

Looking again, your approach is clever and I believe keeps the arguments unevaluated as necessary as well?

Ok, yeah, neat. Let’s do that :)

But I think that’s probably out of scope for fixing #215 for v30.

Another quick fix would be to simply remove the expensive logging calls for now (or hide them behind an ifdef) and re-add them along with a more comprehensive logging refactor. Since they’re only useful for developing/debugging anyway, that would be perfectly reasonable imo.

ryanofsky commented at 3:27 pm on September 24, 2025: collaborator

Thanks I do like this PR as a simple fix and I think it would be good to merge. I’d just suggest simplifying it a little with:

 0--- a/include/mp/proxy-io.h
 1+++ b/include/mp/proxy-io.h
 2@@ -133,9 +133,6 @@ struct LogOptions {
 3     //! External logging callback.
 4     LogFn log_fn;
 5 
 6-    //! External verbose logging callback.
 7-    LogFn verbose_log_fn{nullptr};
 8-
 9     //! Maximum number of characters to use when representing
10     //! request and response structs as strings.
11     size_t max_chars{200};
12@@ -220,13 +217,13 @@ public:
13     //! Check if loop should exit.
14     bool done() const MP_REQUIRES(m_mutex);
15 
16-    Logger log(bool verbose = false)
17+    Logger log()
18     {
19-        Logger logger(false, verbose ? m_log_opts.verbose_log_fn : m_log_opts.log_fn);
20+        Logger logger(false, m_log_opts.log_fn);
21         logger << "{" << LongThreadName(m_exe_name) << "} ";
22         return logger;
23     }
24-    Logger logPlain(bool verbose = false) { return {false, verbose ? m_log_opts.verbose_log_fn : m_log_opts.log_fn}; }
25+    Logger logPlain() { return {false, m_log_opts.log_fn}; }
26     Logger raise() { return {true, m_log_opts.log_fn}; }
27 
28     //! Process name included in thread names so combined debug output from

But not very important, so feel free to keep verbose_log_fn if useful.

theuni commented at 4:16 pm on September 24, 2025: contributor

Ok. That means that Core can’t make the distinction between verbose and non-verbose messages.

For the sake of this issue, that’s fine. And assuming libmp eventually gains log levels, we’ll need an API break anyway.

Will push that change. But imo it makes sense to revisit logging and change the api asap before there are too many downstreams.

theuni force-pushed on Sep 24, 2025

theuni commented at 4:39 pm on September 24, 2025: contributor

Pushed. Also added the missed changes to the constructors in the last push.

theuni renamed this:
~~RFC: Add a verbose logging option and put expensive debug output behind it~~
Add a verbose logging option and put expensive debug output behind it
on Sep 24, 2025

in src/mp/proxy.cpp:198 in 8f9baf7f4d

190@@ -191,13 +191,13 @@ void EventLoop::addAsyncCleanup(std::function<void()> fn)
191     startAsyncThread();
192 }
193 
194-EventLoop::EventLoop(const char* exe_name, LogFn log_fn, void* context)
195+EventLoop::EventLoop(const char* exe_name, LogOptions log_opts, void* context)
196     : m_exe_name(exe_name),
197       m_io_context(kj::setupAsyncIo()),
198       m_task_set(new kj::TaskSet(m_error_handler)),
199+      m_log_opts{log_opts},

ryanofsky commented at 9:51 pm on September 24, 2025:

In commit “Add a verbose logging option and put expensive debug output behind it” (8f9baf7f4dad61188f6c3b81f13fe989efa8bae8)

May be good to use std::move here (in case the log_fn or potential future options are expensive to copy)

theuni commented at 10:50 pm on September 24, 2025:

Hah, I had them originally but got rid of them since they’re currently trivial. Will do.

in include/mp/proxy-io.h:176 in 8f9baf7f4d

170@@ -168,8 +171,13 @@ std::string LongThreadName(const char* exe_name);
171 class EventLoop
172 {
173 public:
174-    //! Construct event loop object.
175-    EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr);
176+    //! Construct event loop object with default logging options.
177+    EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr)
178+        : EventLoop(exe_name, LogOptions(log_fn), context){}

ryanofsky commented at 9:52 pm on September 24, 2025:

In commit “Add a verbose logging option and put expensive debug output behind it” (8f9baf7f4dad61188f6c3b81f13fe989efa8bae8)

May be good to use std::move for log_fn here as well

in include/mp/proxy-io.h:141 in 8f9baf7f4d outdated

135@@ -136,6 +136,9 @@ struct LogOptions {
136     //! Maximum number of characters to use when representing
137     //! request and response structs as strings.
138     size_t max_chars{200};
139+
140+    //! Enable verbose logging which may affect performance
141+    bool verbose{false};

ryanofsky commented at 10:10 pm on September 24, 2025:

In commit “Add a verbose logging option and put expensive debug output behind it” (8f9baf7):

Setting default to false is ok, but would be good to update commit message to make clear this PR turns off most IPC logging by default. E.g. when merged into bitcoin core this will make the -debug=ipc option less useful. Could leave the default to true to be conservative. But I’m also fine with keeping the default false since probably -debug=ipc should be less spammy and verbose logs should require -loglevel=ipc:trace

theuni commented at 10:57 pm on September 24, 2025:

I’d rather just change the default if you’re ok with that. It’s so expensive (for my application, anyway) that it’s harmful to the default experience. When that’s the case, I think it’s reasonable to require the user to change the default.

For Core, I can PR a change to add the logging either to debug or trace, whichever is your preference. The thing that matters most to me is that the super-slow stringification does not happen when logging is not even enabled, as is the case currently.

ryanofsky commented at 2:14 pm on September 25, 2025:

re: #216 (review)

Yes can sort it out later. I do think default for bitcoin core debug IPC logs should be to not include individual method calls and those should go into trace level instead. So this change is a step in that direction.

For the libmultiprocess library itself, I would want default output try to be helpful to new developers as opposed to developers writing high performance applications. I don’t think this is a super transparent or easy to use library and I wouldn’t want someone to struggle with it just because there was a better logging option they didn’t know about. By contrast, I’d assume developers optimizing for performance should not have too much trouble looking at a flamegraph as you did and tuning appropriately.

theuni commented at 3:47 pm on September 25, 2025:

Sorry to keep repeating myself, I just want to be clear about my concern and make sure we’re on the same page.

Whether or not Core or other users of the library show the individual function calls in their debug/trace logs is not a big issue imo – if someone has logging on, they would expect performance to suffer for it.

What’s unexpected, and my primary concern here, is that the user pays the very heavy cost of the stringification even if logging is disabled (either via a null callback, or in Core’s case, by not setting -debug=ipc). At the moment, using master, it’s not possible to avoid this overhead. That majorly violates the principle of least surprise.

Indeed this is a stopgap fix. A more robust change to add the log levels as you proposed above would also fix my concern as a side-effect, as with that you’d only pay for the logging you use. I think that would also address your onboarding concern because trace logging could be the default, and setting a quieter log level would remove the overhead.

ryanofsky commented at 10:13 pm on September 24, 2025: collaborator

Code review ACK 8f9baf7f4dad61188f6c3b81f13fe989efa8bae8. This is a simple and clean change that’s backwards compatible at API level, though not at behavior level since it disables most logging.

But imo it makes sense to revisit logging and change the api asap before there are too many downstreams.

Yes technically the changes to the internal logging interface and external logging interface can be separate, but it makes sense to do them at the same time. I’m pretty clear on what I think the internal logging interface should look like (as sketched above) but less clear on what external interface should be. Maybe it can be as simple as declaring a LogLevel enum to replace bool verbose option, and passing the LogLevel value as an argument to the logging callback function.

DrahtBot requested review from ismaelsadeeq on Sep 24, 2025

theuni commented at 10:50 pm on September 24, 2025: contributor

Maybe it can be as simple as declaring a LogLevel enum to replace bool verbose option, and passing the LogLevel value as an argument to the logging callback function.

That’s exactly what I had in mind as well.

theuni force-pushed on Sep 24, 2025

theuni commented at 11:02 pm on September 24, 2025: contributor

Addressed @ryanofsky’s feedback.

theuni force-pushed on Sep 24, 2025

ryanofsky approved

ryanofsky commented at 2:16 pm on September 25, 2025: collaborator

Code review ACK ef0f363d4d6a5002a60d4373c6ddadeb276a8ae5. Just added std::move and updated commit message since last review

in include/mp/proxy-io.h:176 in ef0f363d4d

170@@ -168,8 +171,13 @@ std::string LongThreadName(const char* exe_name);
171 class EventLoop
172 {
173 public:
174-    //! Construct event loop object.
175-    EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr);
176+    //! Construct event loop object with default logging options.
177+    EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr)
178+        : EventLoop(exe_name, LogOptions(std::move(log_fn)), context){}

ismaelsadeeq commented at 3:36 pm on September 25, 2025:

In “Add a verbose logging option and put expensive debug output behind it by default” ef0f363d4d6a5002a60d4373c6ddadeb276a8ae5

This causes a compilation error for me, using list initialization fixes it for me

 0[  6%] Building CXX object CMakeFiles/multiprocess.dir/src/mp/proxy.cpp.o
 1In file included from /Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/src/mp/proxy.cpp:7:
 2/Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/include/mp/proxy-io.h:176:31: error: no matching conversion for functional-style cast from '__libcpp_remove_reference_t<function<void (bool, string)> &>' (aka 'std::function<void (bool, std::string)>') to 'LogOptions'
 3        : EventLoop(exe_name, LogOptions(std::move(log_fn)), context){}
 4                              ^~~~~~~~~~~~~~~~~~~~~~~~~~~~
 5/Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/include/mp/proxy-io.h:131:8: note: candidate constructor (the implicit copy constructor) not viable: no known conversion from '__libcpp_remove_reference_t<function<void (bool, string)> &>' (aka 'std::function<void (bool, std::string)>') to 'const mp::LogOptions' for 1st argument
 6struct LogOptions {
 7       ^
 8/Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/include/mp/proxy-io.h:131:8: note: candidate constructor (the implicit move constructor) not viable: no known conversion from '__libcpp_remove_reference_t<function<void (bool, string)> &>' (aka 'std::function<void (bool, std::string)>') to 'mp::LogOptions' for 1st argument
 9struct LogOptions {
10       ^
11/Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/include/mp/proxy-io.h:131:8: note: candidate constructor (the implicit default constructor) not viable: requires 0 arguments, but 1 was provided
121 error generated.
13make[3]: *** [CMakeFiles/multiprocess.dir/src/mp/proxy.cpp.o] Error 1
14make[2]: *** [CMakeFiles/multiprocess.dir/all] Error 2
15make[1]: *** [example/CMakeFiles/mpexamples.dir/rule] Error 2
16make: *** [mpexamples] Error 2

0        : EventLoop(exe_name, LogOptions{std::move(log_fn)}, context){}

ismaelsadeeq commented at 4:03 pm on September 25, 2025: member

It seems to me this does not effectively solve the expensive debug logs but rather hides the log at all. I try running the examples binary and can’t see any logs at all. ~~For anyone who uses this, they will effectively have empty IPC logs~~ They can turn it on by passing verbose as true.

If I understand correccly verbose debug is supposed to have more information, which should perhaps increase the max_structs to some big value rather than turning off logs.

For verbose users (In this context users that want to see logs which is almost all the projects experimenting with the IPC interface the log might help in detecting issues e.g https://github.com/bitcoin/bitcoin/issues/33463#issuecomment-3328278574), wont see this if this is pulled to bitcoin core and we did not make -debug option or some log level add the verbose option they also won’t see logs at all, and if a log level is added the slow down is their anyway.

I would prefer if we had something like the approach suggested at #216 (comment)

Edit: I modified the example to turn it on, and also my point here is just that we have to pull this changes and enable passing verbose to true when the node is started with debug=ipc on bitcoin core. And then reduce the overhead for verbose users as well.

DrahtBot requested review from ismaelsadeeq on Sep 25, 2025

Add a verbose logging option and put expensive debug output behind it by default

Logging every send/receive/request/response is very expensive for structs
due to the way they're stringified by capnproto.

Introduce the concept of verbose logging, and expose it to clients by adding
a new constructor for EventLoop which accepts LogOptions. For backwards
compatibility, the existing constructor is unchanged.

This is a behavioral change; users are not required to explicitly opt-in to
expensive logging explicitly

1f73be19c0

theuni force-pushed on Sep 25, 2025

ismaelsadeeq commented at 10:24 am on September 26, 2025: member

ACK 1f73be19c04b75caf052a540aca118b6e4e22770

Last forced push from ef0f363d4d6a5002a60d4373c6ddadeb276a8ae5 to 1f73be19c04b75caf052a540aca118b6e4e22770 diff fixes #216 (review)

DrahtBot requested review from ryanofsky on Sep 26, 2025

theuni commented at 6:37 pm on September 26, 2025: contributor

It seems to me this does not effectively solve the expensive debug logs but rather hides the log at all. I try running the examples binary and can’t see any logs at all. ~~For anyone who uses this, they will effectively have empty IPC logs~~ They can turn it on by passing verbose as true.

I have a local branch which implements @ryanofsky’s suggested changes above. It’s more invasive and would require a change to Core to update the logging callback, but it is more robust. I will PR it on Monday.

TheCharlatan commented at 9:39 am on September 29, 2025: collaborator

Concept ACK

By the reported amount of latency eliminated by this change, I think this should be backported if possible. Or at least for a mining use case, that magnitude of latency for just logging seems unacceptable. Maybe I missed something in the conversation here, but surely it should be possible to hookup whatever severity variable is introduced here to the severity levels in core.

ryanofsky commented at 2:59 pm on September 29, 2025: collaborator

Code review ACK 1f73be19c04b75caf052a540aca118b6e4e22770, just replacing () with {} since last review. Happy to merge this as is, or wait for another update or an alternative PR. Just let me know what you prefer!

DrahtBot requested review from TheCharlatan on Sep 29, 2025

theuni commented at 9:20 pm on September 29, 2025: contributor

Code review ACK 1f73be1, just replacing () with {} since last review. Happy to merge this as is, or wait for another update or an alternative PR. Just let me know what you prefer!

See #220. If that one’s uncontroversial and can go in relatively soon, I’d prefer to go that route to go ahead and get the API break out of the way. We could backport that to Core for v30 (if there’s still time 🤞) , so there wouldn’t be any confusion between versions. But if it’s going to slow things down, I’d rather have this than nothing for v30.

Pinging @fanquake for his input/preference.

theuni commented at 7:36 pm on October 1, 2025: contributor

Closing in favor of #220.

theuni closed this on Oct 1, 2025

ryanofsky referenced this in commit ec86e4336e on Oct 2, 2025

Add a verbose logging option and put expensive debug output behind it #216

Reviews

Conflicts