Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from
Closed

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 10 additions & 2 deletions include/mp/proxy-io.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -136,6 +136,9 @@ struct LogOptions {
//! Maximum number of characters to use when representing
//! request and response structs as strings.
size_t max_chars{200};

//! Enable verbose logging which may affect performance
bool verbose{false};
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

@theuni theuni Sep 25, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

};

std::string LongThreadName(const char* exe_name);
Expand Down Expand Up @@ -168,8 +171,13 @@ std::string LongThreadName(const char* exe_name);
class EventLoop
{
public:
//! Construct event loop object.
EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr);
//! Construct event loop object with default logging options.
EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr)
: EventLoop(exe_name, LogOptions{std::move(log_fn)}, context){}

//! Construct event loop object with specified logging options.
EventLoop(const char* exe_name, LogOptions log_opts, void* context = nullptr);

~EventLoop();

//! Run event loop. Does not return until shutdown. This should only be
Expand Down
28 changes: 18 additions & 10 deletions include/mp/proxy-types.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -629,15 +629,19 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel
using FieldList = typename ProxyClientMethodTraits<typename Request::Params>::Fields;
invoke_context.emplace(*proxy_client.m_context.connection, thread_context);
IterateFields().handleChain(*invoke_context, request, FieldList(), typename FieldObjs::BuildParams{&fields}...);
proxy_client.m_context.loop->logPlain()
<< "{" << thread_context.thread_name << "} IPC client send "
<< TypeName<typename Request::Params>() << " " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
if (proxy_client.m_context.loop->m_log_opts.verbose) {
proxy_client.m_context.loop->logPlain()
<< "{" << thread_context.thread_name << "} IPC client send "
<< TypeName<typename Request::Params>() << " " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
}

proxy_client.m_context.loop->m_task_set->add(request.send().then(
[&](::capnp::Response<typename Request::Results>&& response) {
proxy_client.m_context.loop->logPlain()
<< "{" << thread_context.thread_name << "} IPC client recv "
<< TypeName<typename Request::Results>() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
if (proxy_client.m_context.loop->m_log_opts.verbose) {
proxy_client.m_context.loop->logPlain()
<< "{" << thread_context.thread_name << "} IPC client recv "
<< TypeName<typename Request::Results>() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
}
try {
IterateFields().handleChain(
*invoke_context, response, FieldList(), typename FieldObjs::ReadResults{&fields}...);
Expand Down Expand Up @@ -700,8 +704,10 @@ kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
using Results = typename decltype(call_context.getResults())::Builds;

int req = ++server_reqs;
server.m_context.loop->log() << "IPC server recv request #" << req << " "
<< TypeName<typename Params::Reads>() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars);
if (server.m_context.loop->m_log_opts.verbose) {
server.m_context.loop->log() << "IPC server recv request #" << req << " "
<< TypeName<typename Params::Reads>() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars);
}

try {
using ServerContext = ServerInvokeContext<Server, CallContext>;
Expand All @@ -717,8 +723,10 @@ kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); },
[&]() { return kj::Promise<CallContext>(kj::mv(call_context)); })
.then([&server, req](CallContext call_context) {
server.m_context.loop->log() << "IPC server send response #" << req << " " << TypeName<Results>()
<< " " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars);
if (server.m_context.loop->m_log_opts.verbose) {
server.m_context.loop->log() << "IPC server send response #" << req << " " << TypeName<Results>()
<< " " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars);
}
});
} catch (const std::exception& e) {
server.m_context.loop->log() << "IPC server unhandled exception: " << e.what();
Expand Down
4 changes: 2 additions & 2 deletions src/mp/proxy.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -191,13 +191,13 @@ void EventLoop::addAsyncCleanup(std::function<void()> fn)
startAsyncThread();
}

EventLoop::EventLoop(const char* exe_name, LogFn log_fn, void* context)
EventLoop::EventLoop(const char* exe_name, LogOptions log_opts, void* context)
: m_exe_name(exe_name),
m_io_context(kj::setupAsyncIo()),
m_task_set(new kj::TaskSet(m_error_handler)),
m_log_opts(std::move(log_opts)),
m_context(context)
{
m_log_opts.log_fn = log_fn;
int fds[2];
KJ_SYSCALL(socketpair(AF_UNIX, SOCK_STREAM, 0, fds));
m_wait_fd = fds[0];
Expand Down
Loading