Better Performing Non-Logging Logger Calls in Log4j2

gowebing

Using logging guards is a common practice when using Log4j 1.x and wanting to avoid the additional performance impact that can occur on some occasions even if the message is not actually logged. One of the most attractive features that Simple Logging Facade for Java (SLF4J) brought to Java logging was the ability to reduce the number of circumstances in which these log level checks are necessary. In this post, I look at how one can use Log4j 2.x's logging API changes to achieve a similar benefit.

The next code listing demonstrates logging long-running operations. The first example implicitly calls totoString() method on an instance whose name is "slow". The second logging example invokes a method that is long-running.

Traditional, Unguarded Logging

// Will implicitly invoke slow's toString() method  
logger.debug("NORMAL: " + slow);  
// Will explicitly invoke the long-running method expensiveOperation()  
logger.debug(expensiveOperation());

In the previous example, both logging operations will take a long time even when no logging is actually performed. The logging statements in the previous code listing will only actually log when the logging level is DEBUG or a less specific log level such as TRACE, but their expensive operations will be run even when nothing is logged.

There are two ways to deal with this in Log4j 1.x. One approach, and often the best approach, is to try to re-write the log statement so that no long-running operations are involved. When that is impractical (such as when one needs the context associated with the long-running operation for the log message to be useful), logging guards can be used. This approach that works in Log4j 1.x is demonstrated next.

Traditional, Guarded Logging

if (logger.isDebugEnabled())  
{  
   logger.debug("GUARDED: " + slow);  
   logger.debug(expensiveOperation());  
}

Logging guards, as shown in the previous code listing, are effective in preventing long-running operations from being called even when no message would have been logged anyway. However, using logging guards does introduce some disadvantages. Perhaps the most significant disadvantage is the extra (some would say bloated) code that is introduced. Another potential disadvantage is much less common, but much more serious: with the extra scope introduced by the conditional and associated block, it's more susceptible to errant code being introduced in the conditional that could potentially even introduce side effects in a logging-level-dependent block of code.

One of the most common situations in which log calls that do not actually log anything but significantly impact performance is when an object's toString() method is explicitly or implicitly called when an object is passed to the logger call or concatenated with a string passed to the logger call. This situation was demonstrated in the two above code listings with the string passed to the logger call by concatenating the string literal "GUARDED: " to the implicitly invoked toString() method of the variable named "slow".

SLF4J has popularized the concept of parameterized logging calls and Log4j 2 provides similar support in its logging API. The code that follows demonstrates how this is used.

Parameterized Logging

logger.debug("PARAMETERIZED: {}", slow);  
logger.debug("{}", expensiveOperation());

When the parameterized logging example above is executed with a log level more specific than DEBUG, the implicit toString() on the "slow" variable will not be attempted thanks to the parameterized logging. However, parameterized logging cannot help the other logging situation as the methodexpensiveOperation() will be invoked despite the parameterized logging. Note also that while parameterized logging helps in the case of implicit toString() calls, it does not help with explicittoString() calls. Even if the logging level is more specific than DEBUG, a call to slow.toString() in a logger statement would still incur a performance hit.

Log4j 2.4 introduces a Lambda-based mechanism that can be used to defer invocation of methods passed to a logger call such that they don't need to be executed at all if the statement is being logged at a level less specific than the current log level. This is demonstrated in the next code listing where the toString()method is explicitly called on the "slow" variable's object via lambda expression and theexpensiveOperation method is invoked via method reference.

Lambda Expression Logging

logger.debug("LAMBDA: ", () -> slow.toString());  
logger.debug("{}", this::expensiveOperation);

When the above code is executed with a log level set to a level more specific than DEBUG, neither the "slow" object's toString() method nor the expensiveOperation method will be invoked thanks to the lambda expression based lazy loading. In other words, similar to how the example worked with guards, the use of lambda expressions prevents unnecessary execution of potentially long-running methods unless their results are really going to be logged. This lambda expression support was added to Log4j with version 2.4 and, of course, requires Java 8.

Summary

Log4j 2 (2.4) provides multiple approaches for avoiding the performance impact of log statements when the messages aren't actually logged.

  1. Log statements can be re-written such that expensive methods (including expensive toString()calls) are not logged at all.
  2. Logging guards can be used to ensure that a log statement's long-running methods invocations are only executed if the message is to actually be logged.
  3. Log4j 2's parameterized (formatted) logger API can be used to eliminate the invocation of implicittoString() methods unless the message is really being logged.
  4. Log4j 2.4's lambda expression logger API can be used to to eliminate the invocation of any operations (implicit or explicit) needed for the logged message unless the message is really being logged.

 

 

 

 

Top