In log4j, does checking isDebugEnabled before logging improve performance?

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

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 2

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.

Answer 3

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.

Answer 4

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.

Answer 5

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 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.

Answer 7

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.