Monday, February 8, 2021

SLF4j Logging performance: lazy argument evaluation

Sometimes we need to log a dynamically generated expressions that are very expensive to compute. For instance I had to log an object to yaml format only when debug was enabled. Serializing an object to yaml is an expensive operation especially when you need to scale up to thousands of calls per second.

(As reference, I am using java 8 with slf4j-1.7.25)

If I had directly used

 log.debug("The message is:{}", toYamlString(myObject));

then the message generating method would be called every time even if debug as disabled on the logger. This is because of the java argument evaluation mechanism.

The obvious choice here is:

if(log.isDebugEnabled()){
  log.debug("The message is:{}", toYamlString(myObject);
} 

but, apart of adding unpleasing code on top of your method, this is also doubling the call on if(log.isDebugEnabled()) that is also performed in the logging framework itself.So I took some time to see if it could be done in a better way.

At some point I found this post that was nicely solving this. I liked it and wrote my code accordingly. Then I realised it could be even simpler!

So I simplified it to only this:

  private static Object lazyString(final Supplier<?> stringSupplier) {
    return new Object() {
      @Override
      public String toString() {
        return String.valueOf(stringSupplier.get());
    }
  }

Then in my logging call:

  log.debug("The message is:{}",lazyString(() -> toYamlString(myObject)));

or, if your method take no arguments, you can use method reference:

  log.debug("The message is:{}",lazyString(this::toYamlString));

That's it! Simple and elegant.

The good news is that more and more logging frameworks added or are adding native support for deferred evaluation of arguments.

Until then we can use simple nice workarounds like this.

Have a nice day,

Dikran.