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

[theuni]

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]

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]

Here is a commit which hooks up usage in Core.

[Sjors]

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]

Code review ACK e50802f. 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:

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

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

#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]

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:

MP_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:

enum class LogLevel {
    Trace = 0,
    Debug,
    Info,
    Warning,
    Error,
};

...

template <typename Callable>
void log(LogLevel log_level, Callable&& log_callback)
{
    logPlain(log_level, [this, &log_callback](auto& logger) {
        logger << "{" << LongThreadName(m_exe_name) << "} ";
        std::invoke(log_callback, logger);
    });
}

template <typename Callable>
void logPlain(LogLevel log_level, Callable&& log_callback)
{
    if (log_level >= m_log_opts.log_level) {
        Logger logger(false, m_log_opts.log_fn);
        std::invoke(log_callback, logger);
    }
}

With macros like:

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

and usage like:

MP_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]

Hmm, maybe I read too quickly.

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

[ismaelsadeeq]

nice Concept ACK

[theuni]

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]

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:

diff

--- a/include/mp/proxy-io.h
+++ b/include/mp/proxy-io.h
@@ -133,9 +133,6 @@ struct LogOptions {
     //! External logging callback.
     LogFn log_fn;
 
-    //! External verbose logging callback.
-    LogFn verbose_log_fn{nullptr};
-
     //! Maximum number of characters to use when representing
     //! request and response structs as strings.
     size_t max_chars{200};
@@ -220,13 +217,13 @@ public:
     //! Check if loop should exit.
     bool done() const MP_REQUIRES(m_mutex);
 
-    Logger log(bool verbose = false)
+    Logger log()
     {
-        Logger logger(false, verbose ? m_log_opts.verbose_log_fn : m_log_opts.log_fn);
+        Logger logger(false, m_log_opts.log_fn);
         logger << "{" << LongThreadName(m_exe_name) << "} ";
         return logger;
     }
-    Logger logPlain(bool verbose = false) { return {false, verbose ? m_log_opts.verbose_log_fn : m_log_opts.log_fn}; }
+    Logger logPlain() { return {false, m_log_opts.log_fn}; }
     Logger raise() { return {true, m_log_opts.log_fn}; }
 
     //! 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]

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]

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

[ryanofsky]

Code review ACK 8f9baf7. 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.

[ryanofsky]

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]

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]

re: #216 (comment)

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]

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.

[theuni]

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]

Addressed @ryanofsky's feedback.

[ryanofsky]

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

[ryanofsky]

re: #216 (comment)

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.

[ismaelsadeeq]

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 bitcoin/bitcoin#33463 (comment)), 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.

[ismaelsadeeq]

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

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

[  6%] Building CXX object CMakeFiles/multiprocess.dir/src/mp/proxy.cpp.o
In file included from /Users/abubakarismail/Desktop/Work/bitcoin-dev/libmultiprocess/src/mp/proxy.cpp:7:
/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'
        : EventLoop(exe_name, LogOptions(std::move(log_fn)), context){}
                              ^~~~~~~~~~~~~~~~~~~~~~~~~~~~
/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
struct LogOptions {
       ^
/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
struct LogOptions {
       ^
/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
1 error generated.
make[3]: *** [CMakeFiles/multiprocess.dir/src/mp/proxy.cpp.o] Error 1
make[2]: *** [CMakeFiles/multiprocess.dir/all] Error 2
make[1]: *** [example/CMakeFiles/mpexamples.dir/rule] Error 2
make: *** [mpexamples] Error 2

Suggested change

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

[ismaelsadeeq]

ACK 1f73be1

Last forced push from ef0f363 to 1f73be1
diff fixes #216 (comment)

[theuni]

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]

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]

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!

[theuni]

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]

Closing in favor of #220.