Unnecessary allocations in ZerologWrapper

[jhernandezb]

Summary of Bug

While debugging a tendermint performance issue (see informalsystems/tendermint#4) I noticed that even if the log level in config.toml is set to error only, the Debug method in https://github.com/public-awesome/cosmos-sdk/blob/release/v0.45.x/server/logger.go#L33 appears consistently in profiles with a significant amount, and this is due to getLogFields methods being evaluated regardless of log level.

Debug is used in different code paths of tendermint adding up some unnecessary computations.

I'm currently running the same node but with an extra check as in https://github.com/public-awesome/cosmos-sdk/blob/3a862e03d4177ccff3927cac2d2a5aaf36d5b367/server/logger.go#L46-L51

Which seems to help, although not sure if the extra check it's actually worth the troubles but CPU did decrease in some % after applying the patch.

Profile comparison

Version

0.45.11

Steps to Reproduce

Run any node with log level set to error

[tac0turtle]

This logger was deleted actually. We use Tendermint's logger now with filtering.

[alexanderbez]

Yeah it's a shame really. Zerolog is so fast. We just couldn't use it the way it was meant to be used because Tendermint's logger interface is very limited.

[tac0turtle]

how is the interface limiting? we swapped back cause there was no filtering and logs became impossible to read

[alexanderbez]

how is the interface limiting? we swapped back cause there was no filtering and logs became impossible to read

Because zerolog provides structured typed logging -- that's the entire point and reason why it's so efficient. Tendermint's interface does not, as it only allows you to provide any pairs. We were trying to put Ferrari decals on a Toyota.

[tac0turtle]

Okay I have a plan on how to get use there.

In regards to this issue it should actually live in comet. Looking at the profile the logger is from us but the log is comets. It is most likely because they are logging an interface which causes zero log to use reflection. I ran into this a few times on comet. Let's close this and open an issue on tendermint to stop logging interfaces.

[alexanderbez]

Awesome. Looking forward to seeing what your idea is.