Enclosing calls to debug() in if isDebugEnabled(): a good policy?

Question

Our team has the policy of doing logging like

if (LOGGER.isDebugEnabled()) {  
  LOGGER.debug("model[" + model + "]");
}

instead of simply calling the logging method like this:

LOGGER.debug("model[" + model + "]");

This practice is capable of leading to some performance improvement, but on the other hand it makes the codebase more complex. Our application has no performance problems, probably never will, the argument for the introduction of the policy was simply that it's a good practice, so it shall be used every time we are doing logging.

Do you think it's a good policy?

Answer 1

I agree with the famous quote of Michael A. Jackson:

The First Rule of Program Optimization: Don't do it.

The Second Rule of Program Optimization – For experts only: Don't do it yet.

I think that in the majority of cases it's not worth making the codebase more complex without being sure that the performance gain will be noticable / significant.

I'm aware of the performance improvement, but I think it shall be the responsibility of the individual programmer to decide whether it's worth to add those extra lines of code in a particular case. In most cases the extra lines are just adding complexity without any noticable gain on the performance side.

Answer 2

It's a good policy for those occasions where the log string you're building up is actually going to affect performance significantly. This could be for two reasons:

• A lot of work needs to go into building the string (e.g. it's got to do lookups, or build a very large string from lots of very small pieces)
• It's in a loop which isn't doing much other work (but is called very often), so the proportion of the time spent building up even a simple log string is higher

It shouldn't be a blanket rule, and I'd expect both of these situations to be relatively rare.

Of course, what we really want is to be able to say, "Call the debug method, passing in an argument which isn't the debug string itself, but is something which knows how to build the debug string, if and only if it's necessary." This would be ugly in Java without concise closures. (Even in a language with closures in the form of lambda expressions, capturing the relevant variables could be significant in some situations, depending on how the language handles the capture.)

Answer 3

If "model" is already known, just logging it is not so expensive. But, if the "model" should be fetched just for logging as below, simplicity can be compromised.

LOGGER.debug("model[" + proxy.getModel() + "]");

Answer 4

I think it makes sence to put the isDebugEnabled() call before you write your log message. Than you easily can update your log message later. We use the following code to make the log messages more flexible.

if (LOGGER.isDebugEnabled()) {  
  String msg = "A Message {0} you can put {1} differet Objects in {2}"; //$NON-NLS-1$
  Object[] args = new Object[] {file1.toString(),new Integer(23),anObject};
  LOGGER.debug(MessageFormat.format(msg,args));
}

When you would not have the if statement you would lose time. Remember... your project becomes bigger and your log messages too.

Log messages should slow your code!

Answer 5

You should use SLF4J and make log4j your implementation. With SLF4J, you can eliminate isDebugEnabled() altogether by using parameterized messages. See

http://www.slf4j.org/faq.html#logging_performance

Answer 6

I cannot find the reference online (perhaps I read it in a book) but there was an example of some BIOS call that wrote a String to the screen.

The code the wrote the string to the screen checked to make sure that the String wasn't going to go off of the screen and then called a function to write out a char to the screen.

The function that wrote the char to the screen checked to make sure that the character would not be written off of the screen.

Removing the checking code from the function that wrote the character to the screen resulted in a massive speed boost. The was because printing each character happened very often. They also provided a method that did the check for the cases when the screen position was not checked before the call.

So, if you can check at a high level and avoid the checks at the low level you can speed things up significantly.

In the case you provide, if the code is in a loop or if there are a lot of logging statements then there would be a clear benefit since you would:

• remove the string creation (and the associated GC)
• reduce the number of if statements (though hotspote very likely optimizes them out).

I would say that, in general, you should not add anything that is known to be costly if there is an easy work around. This clearly falls into that case - the addition of the if statement is not hard to do, it is a pain to put in later, and it provides a definite speed/memory improvement.

I think the difference between this and premature optimization is that this is known to be always costly,so the issue comes down to is it a cumulative cost you want to add to the program or not? The cost is pretty much constant and it is known at the point of writing the code.