Substantial overhead caused by encoding messages for logging

[theuni]

I'm working on a multiprocess branch that passes a lot of data back and forth between server and client.

When looking at a flamegraph, it's clear that >50% of my client's cpu time is spent on logging (encoding) sends. Likewise for the server with responses.

The culprit is toString() from the params/results/request/response, which ends up in kj::_::encodeCEscapeImpl(), which is horribly slow.

Current master:

Fixed:

As you can see, before removing the logging, 52% of my thread's runtime is spent in serverInvoke (which calls foo.toString(), which calls structString(), which calls kj::_::encodeCEscapeImpl(). With the debug lines removed, serverInvoke is no longer visible in the flamegraph at all.

I would imagine the sv2 implementation suffers from this as well, though I'm not sure how chatty it is, so I can't speak to the potential impact.

I'll open a RFC PR which fixes the issue rather naively. A more robust solution would introduce logging categories similar to Bitcoin Core's.

Edit: See #216.
Also, toned down the original title :)

[theuni]

Ping @Sjors, you might be seeing this as well.

[Sjors]

Do I understand correctly that this "only" impacts Bitcoin Core when running with -debug=ipc?

[theuni]

@Sjors No, that's the issue I'm afraid.

The stringification happens in Core regardless of the selected logging level, and on the client even if no log callback is set.

[Sjors]

Ah, ok that sounds more urgent then. I'll go and review your fix.