Sorrounding Logger with an If clause to avoid redundant String construction.

Question

Hi,

I got a recommendation to use this syntax when logging in java:

if (logger.isLoggable(Log.FINE))
{
    logger.fine("bla"+" bla"+" bla");
}

The reason for this is to avoid the redundant construction of the parameter string incase the logging level is lower than "FINE". (in the example above - 5 redundant string object. (" bla"X3, " bla bla" and "bla bla bla").

I'd like to hear what others are doing about this or if you think that this is necessary at all.

Thanks!!

Answer 1

Some newer logging frameworks allow you to specify arguments as parameters, and won't evaluate them if there's no logging.

The example I found is LogBack, the successor to Log4j. Here's the info: http://www.infoq.com/news/2007/08/logback

This gives you the best of both worlds, so to speak. Elegant syntax yet good performance.

---

Log4j code example:

if( logger.isDebugEnabled() ) {
  logger.debug( "User with account " + 
    user.getAccount() + " failed authentication; " +
    "supplied crypted password " + user.crypt(password) +
    " does not match." );
}

Equivalent LogBack code:

logger.debug( "User with account {} failed authentication; " +
    "supplied crypted password {} does not match.",
    user.getAccount(), user.crypt(password) );

This defers the cost of message assembly until LOGBack has ascertained whether or not this message will be viewed. It doesn't defer the cost of retrieving expensive parameters, such as the password crypting in the above example.

Answer 2

String objects are immutable, and repeated concatenation is therefore an expensive operation. It requires repeated memory allocation, object creation and iteration. Considering that some logging calls at the finer log levels can be invoked thousands or millions of times per minute, it might be a considerable performance gain to do as you illustrate. Though, for a smaller application, it might not be worth the extra effort.

As a side note: You can save even more performance, where this is truly critical by using a constant such as this:

public static final boolean DEBUG = false;

If you now wrap the logging code in an if-block such as this, the JVM will be able to completely optimize away the debug calls when running in product mode. This is as close as you get to a C #ifdef.

if (Globals.DEBUG) {
    // Logging call
}

Answer 3

Absolutely necessary for debug type logging. It something like 10x quicker to check the log level first than create the string and throw it away.

Answer 4

This is an improvement (good) but it can be improved on a little.

Set up final flags for each logging level (FINE, etc) in a global object used as config, then use a StringBuffer to build up your debugging output -- you can even format numbers into the stream at the same time.

public class MyAppConfig {
  public final boolean FINE=true;
  // ... other fields
}

public class MyApp {
  void someFunction() {
    ...
    int imagesProcessed;
    imagesProcessed = processImages();

    if (MyAppConfig.FINE) logger.fine(new StringBuffer(35).
      append("Count of images processed: ").append(imagesProcessed).toString());

    ...
  }
}

Here the string buffer is set up with an 'initial capacity' of 35 characters. If you know how many characters are going to be generated you can provide hints to StringBuffer.