2

Although in some tutorials, for example here (Parametrized logging section), said that Logback message {} parametrization help us to avoid unnecessary calculation in logging data (if logging level is not DEBUG):

logger.debug("The bonus for employee {} is {}", 
   employee.getName(), employeeService.calculateBonus(employee));

I tested (on logback version 1.2.3) that this optimization works only for unnecessary toString() of parameter object - as this works for log4j.

Logback documentation doesn't cover this detail.

So, we have to use isDebugEnabled() for all 'expensive' logging, do we?

Dan Brandt
  • 605
  • 1
  • 7
  • 21
  • 1
    The linked article doesn't say "unnecessary calculation" anywhere. The `{}` construct help prevent the **string concatenation** needed to insert values into the log text. That's all. – Andreas Jan 14 '20 at 16:44
  • @Andreas, you are absolutely right about string concatenation - but the [article](https://stackify.com/logging-logback/) says: `...This format ensures that the logger will first verify is the log level is enabled, and only afterward will it determine and use the value of the parameters in the log message.` -- **determine and use**. If you say about this article, of course – Dan Brandt Jan 14 '20 at 16:52
  • 2
    Yup, the author of that article phrased that a bit misleading. `calculateBonus()` is called even when not logging at the debug level. The *value* passed as a *parameter* to the `debug()` method is only *determined* (ahh, it's a number) and *used* (converted to string and concatenated) when logging at the debug level. – Andreas Jan 14 '20 at 17:07

2 Answers2

7

Take a look at the example here

Since 2.4, methods have been added to the Logger interface to support lambda expressions. The new methods allow client code to lazily log messages without explicitly checking if the requested log level is enabled. For example, previously one would write:

// pre-Java 8 style optimization: explicitly check the log level
// to make sure the expensiveOperation() method is only called if necessary
 if (logger.isTraceEnabled()) {
     logger.trace("Some long-running operation returned {}", expensiveOperation());
 }

With Java 8, the same effect can be achieved with a lambda expression:

// Java-8 style optimization: no need to explicitly check the log level:
// the lambda expression is not evaluated if the TRACE level is not enabled
logger.trace("Some long-running operation returned {}", () -> expensiveOperation());
Dorian Gray
  • 2,913
  • 1
  • 9
  • 25
  • thanks for good info. This approach works for me when i use `spring-boot` (2.2.2), `slf4j-api:2.0.0-alpha1` and `log4j` implementation (`slf4j-log4j12:2.0.0-alpha1`). – Dan Brandt Jan 15 '20 at 16:48
  • But it fails when i try to use Logback (`logback-classic:1.3.0-alpha5`) with error: `java.lang.ClassNotFoundException: org.slf4j.impl.StaticLoggerBinder` and only works with older logback versions, that don't support `Supplier>` in log message. May be you used newer Logback with Spring boot and solved such problem? – Dan Brandt Jan 15 '20 at 16:49
  • I just posted the example from log4j to emphasize the problem with expansive methods. I don't know the logback api. – Dorian Gray Jan 15 '20 at 20:11
2

When you make a method call, e.g. employeeService.calculateBonus(employee), you're calling that method. Simple as that. So you are calculating the employee bonus every time this line is hit. There is no lazy evaluation here.

Whether or not to use log.isDebugEnabled() depends on the situation. In this situation, if that method call is expensive, you should wrap that in a debug enabled check.

In the case of getters, this isn't usually necessary. So, for instance, I would not wrap this in an isDebugEnabled check:

log.debug("Calculating bonus for employee {} {}", employee.firstName(), employee.lastName());

These are simple getters that return a String, so no expensive calculations are done.

Christopher Schneider
  • 3,745
  • 2
  • 24
  • 38