From 1f73be19c04b75caf052a540aca118b6e4e22770 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Tue, 23 Sep 2025 20:36:06 +0000 Subject: [PATCH] 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 --- include/mp/proxy-io.h | 12 ++++++++++-- include/mp/proxy-types.h | 28 ++++++++++++++++++---------- src/mp/proxy.cpp | 4 ++-- 3 files changed, 30 insertions(+), 14 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index a0bdf137..01126509 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -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}; }; std::string LongThreadName(const char* exe_name); @@ -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 diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index 222defd9..09c0d308 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -629,15 +629,19 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel using FieldList = typename ProxyClientMethodTraits::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() << " " << 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() << " " << 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&& response) { - proxy_client.m_context.loop->logPlain() - << "{" << thread_context.thread_name << "} IPC client recv " - << TypeName() << " " << 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() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); + } try { IterateFields().handleChain( *invoke_context, response, FieldList(), typename FieldObjs::ReadResults{&fields}...); @@ -700,8 +704,10 @@ kj::Promise 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() << " " << 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() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); + } try { using ServerContext = ServerInvokeContext; @@ -717,8 +723,10 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); }, [&]() { return kj::Promise(kj::mv(call_context)); }) .then([&server, req](CallContext call_context) { - server.m_context.loop->log() << "IPC server send response #" << req << " " << TypeName() - << " " << 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() + << " " << 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(); diff --git a/src/mp/proxy.cpp b/src/mp/proxy.cpp index 06825c99..271682c8 100644 --- a/src/mp/proxy.cpp +++ b/src/mp/proxy.cpp @@ -191,13 +191,13 @@ void EventLoop::addAsyncCleanup(std::function 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];