[java] In log4j, does checking isDebugEnabled before logging improve performance?

I am using Log4J in my application for logging. Previously I was using debug call like:

Option 1:

logger.debug("some debug text");

but some links suggest that it is better to check isDebugEnabled() first, like:

Option 2:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text");
}

So my question is "Does option 2 improve performance any way?".

Because in any case Log4J framework have same check for debugEnabled. For option 2 it might be beneficial if we are using multiple debug statement in single method or class, where the framework does not need to call isDebugEnabled() method multiple times (on each call); in this case it calls isDebugEnabled() method only once, and if Log4J is configured to debug level then actually it calls isDebugEnabled() method twice:

1. In case of assigning value to debugEnabled variable, and
2. Actually called by logger.debug() method.

I don't think that if we write multiple logger.debug() statement in method or class and calling debug() method according to option 1 then it is overhead for Log4J framework in comparison with option 2. Since isDebugEnabled() is a very small method (in terms of code), it might be good candidate for inlining.

As of 2.x, Apache Log4j has this check built in, so having isDebugEnabled() isn't necessary anymore. Just do a debug() and the messages will be suppressed if not enabled.

As others have mentioned using the guard statement is only really useful if creating the string is a time consuming call. Specific examples of this are when creating the string will trigger some lazy loading.

It is worth noting that this problem can be completed avoided by using Simple Logging Facade for Java or (SLF4J) - http://www.slf4j.org/manual.html . This allows method calls such as:

logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);

This will only convert the passed in parameters to strings if debug is enabled. SLF4J as its name suggests is only a facade and the logging calls can be passed to log4j.

You could also very easily "roll your own" version of this.

Hope this helps.

Option 2 is better.

Per se it does not improve performance. But it ensures performance does not degrade. Here's how.

Normally we expect logger.debug(someString);

But usually, as the application grows, changes many hands, esp novice developers, you could see

logger.debug(str1 + str2 + str3 + str4);

and the like.

Even if log level is set to ERROR or FATAL, the concatenation of strings do happen ! If the application contains lots of DEBUG level messages with string concatenations, then it certainly takes a performance hit especially with jdk 1.4 or below. (Iam not sure if later versions of jdk internall do any stringbuffer.append()).

Thats why Option 2 is safe. Even the string concatenations dont happen.

Since in option 1 the message string is a constant, there is absolutely no gain in wrapping the logging statement with a condition, on the contrary, if the log statement is debug enabled, you will be evaluating twice, once in the isDebugEnabled() method and once in debug() method. The cost of invoking isDebugEnabled() is in the order of 5 to 30 nanoseconds which should be negligible for most practical purposes. Thus, option 2 is not desirable because it pollutes your code and provides no other gain.

I would recommend using Option 2 as de facto for most as it's not super expensive.

Case 1: log.debug("one string")

Case2: log.debug("one string" + "two string" + object.toString + object2.toString)

At the time either of these are called, the parameter string within log.debug (be it CASE 1 or Case2) HAS to be evaluated. That's what everyone means by 'expensive.' If you have a condition before it, 'isDebugEnabled()', these don't have to be evaluated which is where the performance is saved.

Since many people are probably viewing this answer when searching for log4j2 and nearly all current answers do not consider log4j2 or recent changes in it, this should hopefully answer the question.

log4j2 supports Suppliers (currently their own implementation, but according to the documentation it is planned to use Java's Supplier interface in version 3.0). You can read a little bit more about this in the manual. This allows you to put expensive log message creation into a supplier which only creates the message if it is going to be logged:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());

Like @erickson it depends. If I recall, isDebugEnabled is already build in the debug() method of Log4j.
As long as you're not doing some expensive computations in your debug statements, like loop on objects, perform computations and concatenate strings, you're fine in my opinion.

StringBuilder buffer = new StringBuilder();
for(Object o : myHugeCollection){
  buffer.append(o.getName()).append(":");
  buffer.append(o.getResultFromExpensiveComputation()).append(",");
}
log.debug(buffer.toString());

would be better as

if (log.isDebugEnabled(){
  StringBuilder buffer = new StringBuilder();
  for(Object o : myHugeCollection){
    buffer.append(o.getName()).append(":");
    buffer.append(o.getResultFromExpensiveComputation()).append(",");
  }
  log.debug(buffer.toString());
}

In Java 8, you don't have to use isDebugEnabled() to improve the performance.

https://logging.apache.org/log4j/2.0/manual/api.html#Java_8_lambda_support_for_lazy_logging

import java.util.logging.Logger;
...
Logger.getLogger("hello").info(() -> "Hello " + name);

Using the isDebugEnabled() is reserved for when you're building up log messages by concatenating Strings:

Var myVar = new MyVar();
log.debug("My var is " + myVar + ", value:" + myVar.someCall());

However, in your example there is no speed gain as you're just logging a String and not performing operations such as concatenation. Therefore you're just adding bloat to your code and making it harder to read.

I personally use the Java 1.5 format calls in the String class like this:

Var myVar = new MyVar();
log.debug(String.format("My var is '%s', value: '%s'", myVar, myVar.someCall()));

I doubt there's much optimisation but it's easier to read.

Do note though that most logging APIs offer formatting like this out of the box: slf4j for example provides the following:

logger.debug("My var is {}", myVar);

which is even easier to read.

Short Version: You might as well do the boolean isDebugEnabled() check.

Reasons:
1- If complicated logic / string concat. is added to your debug statement you will already have the check in place.
2- You don't have to selectively include the statement on "complex" debug statements. All statements are included that way.
3- Calling log.debug executes the following before logging:

if(repository.isDisabled(Level.DEBUG_INT))
return;

This is basically the same as calling log. or cat. isDebugEnabled().

HOWEVER! This is what the log4j developers think (as it is in their javadoc and you should probably go by it.)

This is the method

public
  boolean isDebugEnabled() {
     if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }

This is the javadoc for it

/**
*  Check whether this category is enabled for the <code>DEBUG</code>
*  Level.
*
*  <p> This function is intended to lessen the computational cost of
*  disabled log debug statements.
*
*  <p> For some <code>cat</code> Category object, when you write,
*  <pre>
*      cat.debug("This is entry number: " + i );
*  </pre>
*
*  <p>You incur the cost constructing the message, concatenatiion in
*  this case, regardless of whether the message is logged or not.
*
*  <p>If you are worried about speed, then you should write
*  <pre>
*    if(cat.isDebugEnabled()) {
*      cat.debug("This is entry number: " + i );
*    }
*  </pre>
*
*  <p>This way you will not incur the cost of parameter
*  construction if debugging is disabled for <code>cat</code>. On
*  the other hand, if the <code>cat</code> is debug enabled, you
*  will incur the cost of evaluating whether the category is debug
*  enabled twice. Once in <code>isDebugEnabled</code> and once in
*  the <code>debug</code>.  This is an insignificant overhead
*  since evaluating a category takes about 1%% of the time it
*  takes to actually log.
*
*  @return boolean - <code>true</code> if this category is debug
*  enabled, <code>false</code> otherwise.
*   */

Log4j2 lets you format parameters into a message template, similar to String.format(), thus doing away with the need to do isDebugEnabled().

Logger log = LogManager.getFormatterLogger(getClass());
log.debug("Some message [myField=%s]", myField);

Sample simple log4j2.properties:

filter.threshold.type = ThresholdFilter
filter.threshold.level = debug
appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d %-5p: %c - %m%n
appender.console.filter.threshold.type = ThresholdFilter
appender.console.filter.threshold.level = debug
rootLogger.level = info
rootLogger.appenderRef.stdout.ref = STDOUT

If you use option 2 you are doing a Boolean check which is fast. In option one you are doing a method call (pushing stuff on the stack) and then doing a Boolean check which is still fast. The problem I see is consistency. If some of your debug and info statements are wrapped and some are not it is not a consistent code style. Plus someone later on could change the debug statement to include concatenate strings, which is still pretty fast. I found that when we wrapped out debug and info statement in a large application and profiled it we saved a couple of percentage points in performance. Not much, but enough to make it worth the work. I now have a couple of macros setup in IntelliJ to automatically generate wrapped debug and info statements for me.

Since Log4j version 2.4 (orslf4j-api 2.0.0-alpha1) it's much better to use fluent API (or Java 8 lambda support for lazy logging), supporting Supplier<?> for log message argument, that can be given by lambda:

log.debug("Debug message with expensive data : {}", 
           () -> doExpensiveCalculation());

OR with slf4j API:

log.atDebug()
            .addArgument(() -> doExpensiveCalculation())
            .log("Debug message with expensive data : {}");

It improves the speed because it's common to concatenate strings in the debug text which is expensive eg:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text" + someState);
}

For a single line, I use a ternary inside of logging message, In this way I don't do the concatenation:

ej:

logger.debug(str1 + str2 + str3 + str4);

I do:

logger.debug(logger.isDebugEnable()?str1 + str2 + str3 + str4:null);

But for multiple lines of code

ej.

for(Message mess:list) {
    logger.debug("mess:" + mess.getText());
}

I do:

if(logger.isDebugEnable()) {
    for(Message mess:list) {
         logger.debug("mess:" + mess.getText());
    }
}