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

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.

Author: theuni

include/mp/proxy-io.h

@@ -133,9 +133,15 @@ 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};
+
+    //! Enable verbose logging which may affect performance
+    bool verbose{false};
 };
 
 std::string LongThreadName(const char* exe_name);
@@ -170,6 +176,10 @@ class EventLoop
 public:
     //! Construct event loop object.
     EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr);
+
+    //! Construct event loop object with 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
@@ -210,13 +220,13 @@ class EventLoop
     //! Check if loop should exit.
     bool done() const MP_REQUIRES(m_mutex);
 
-    Logger log()
+    Logger log(bool verbose = false)
     {
-        Logger logger(false, m_log_opts.log_fn);
+        Logger logger(false, verbose ? m_log_opts.verbose_log_fn : m_log_opts.log_fn);
         logger << "{" << LongThreadName(m_exe_name) << "} ";
         return logger;
     }
-    Logger logPlain() { return {false, m_log_opts.log_fn}; }
+    Logger logPlain(bool verbose = false) { return {false, verbose ? m_log_opts.verbose_log_fn : 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

include/mp/proxy-types.h

@@ -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(true)
+                    << "{" << 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(true)
+                        << "{" << 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}...);
@@ -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(true) << "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>;
@@ -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(true) << "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();