In log4j, does checking isDebugEnabled before logg

Question

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.

Answer 1

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

Answer 2

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.

Answer 3

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());
    }
}

Answer 4

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());
}

Answer 5

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);
}

Answer 6

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.