Parameterized logging in slf4j - how does it compare to scala's by-name parameters?

Question

Here are two statements that seem to be generally accepted, but that I can't really get over:

1) Scala's by-name params gracefully replace the ever-so-annoying log4j usage pattern:

if (l.isDebugEnabled() ) { 
      logger.debug("expensive string representation, eg: godObject.toString()") 
   }

because the by-name-parameter (a Scala-specific language feature) doesn't get evaluated before the method invocation.

2) However, this problem is solved by parametrized logging in slf4f:

logger.debug("expensive string representation, eg {}:", godObject[.toString()]);

So, how does this work? Is there some low-level magic involved in the slf4j library that prevents the evaluation of the parameter before the "debug" method execution? (is that even possible? Can a library impact such a fundamental aspect of the language?)

Or is it just the simple fact that an object is passed to the method - rather than a String? (and maybe the toString() of that object is invoked in the debug( ) method itself, if applicable).

But then, isn't that true for log4j as well? (it does have methods with Object params). And wouldn't this mean that if you pass a string - as in the code above - it would behave identically to log4j?

I'd really love to have some light shed on this matter.

Thanks!

Answer 1

There is no magic in slf4j. The problem with logging used to be that if you wanted to log let's say

logger.debug("expensive string representation: " + godObject)

then no matter if the debug level was enabled in the logger or not, you always evaluated godObject.toString()which can be an expensive operation, and then also string concatenation. This comes simply from the fact that in Java (and most languages) arguments are evaluated before they're passed to a function.

That's why slf4j introduced logger.debug(String msg, Object arg) (and other variants for more arguments). The whole idea is that you pass cheap arguments to the debug function and it calls toString on them and combines them into a message only if the debug level is on.

Note that by calling

logger.debug("expensive string representation, eg: {}", godObject.toString());

you drastically reduce this advantage, as this way you convert godObject all the time, before you pass it to debug, no matter what debug level is on. You should use only

logger.debug("expensive string representation, eg: {}", godObject);

---

However, this still isn't ideal. It only spares calling toString and string concatenation. But if your logging message requires some other expensive processing to create the message, it won't help. Like if you need to call some expensiveMethod to create the message:

logger.debug("expensive method, eg: {}",
    godObject.expensiveMethod());

then expensiveMethod is always evaluated before being passed to logger. To make this work efficiently with slf4j, you still have to resort back to

if (logger.isDebugEnabled())
    logger.debug("expensive method, eg: {}",
        godObject.expensiveMethod());

Scala's call-by-name helps a lot in this matter, because it allows you to wrap arbitrary piece of code into a function object and evaluate that code only when needed. This is exactly what we need. Let's have a look at slf4s, for example. This library exposes methods like

def debug(msg: => String) { ... }

Why no arguments like in slf4j's Logger? Because we don't need them any more. We can write just

logger.debug("expensive representation, eg: " +
    godObject.expensiveMethod())

We don't pass a message and its arguments, we pass directly a piece of code that is evaluated to the message. But only if the logger decides to do so. If the debug level isn't on, nothing that's within logger.debug(...) is ever evaluated, the whole thing is just skipped. Neither expensiveMethod is called nor any toString calls or string concatenation happen. So this approach is most general and most flexible. You can pass any expression that evaluates to a String to debug, no matter how complex it is.