Logging Tips

Any non-trivial system is going to have some kind of a logging framework in place. In multi-threaded code, this is often the best way to track down exactly what’s happening, and in what order. Unfortunately, there are a number of common misuses that I run across time and time again. This advice is specifically for using slf4j, though it applies to any similarly crafted logging framework.

Let’s take a look at a them!

Explicitly calling toString

Here’s something I’ve run across more than a few times:

public class Foo {
  // Lots and lots of state
  @Override
  public String toString() {
    // Really expensive concatenation of the state bits
  }
}

Then later in the code:

public void missionCriticalCode() {
  logger.debug("Have some debug info: {}", fooInstance.toString());
}

By explicitly calling the toString method on the fooInstance, we are forcing the string to be calculated, even if it is thrown away because the log level is too high. Instead, just provide the object as-is. The logging framework will only call the toString method if the log level is reached, saving some wasteful calculations.

Not Checking The Log Level

The previous tip may have been obvious to some, as you must go out of your way to fall victim to it. This one is a little more insidious. Consider the following:

public class Foo {
  public List<Bar> reallyExpensiveMethodToGatherBars() { 
    // ... 
  }
}

Then later:

public void missionCriticalCode() {
  logger.debug("Behold the bars: {}", fooInstance.reallyExpensiveMethodToGatherBars());
}

In the above, the ‘reallyExpensiveMethodToGatherBars’ method will be invoked regardless of whether the debug log level is set or not. Initiate level followers of The Way of the Log may not know that there’s a way to avoid this:

public void missionCriticalCode() {
  if (logger.isDebugEnabled()) {
    logger.debug(
      "Behold the bars: {}", 
      fooInstance.reallyExpensiveMethodToGatherBars()
    );
  }
}

With the ‘isDebugEnabled’ guard in place, the expensive Bar gathering will only occur when we care about the result!

Improper use of Log Levels

Many times, developers will determine a level that is most comfortable to them, and use this for all monitoring logging. It’s usually pretty easy to determine when something should be logged as SEVERE, or ERROR, or FATAL, but when logging events to track logic flow or aid in debugging, I often see that a developer will pick (for instance) DEBUG and use this level for every statement they want to note. This can quickly make the difference between TRACE and DEBUG meaningless and flood the log files with noise. Check your logger’s docs about the different levels available, often there will be tips about what the intent is. For instance, slf4j says the following about the different levels:

  • TRACE The TRACE Level designates finer-grained informational events than the DEBUG
  • DEBUG The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
  • INFO The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
  • WARN The WARN level designates potentially harmful situations.
  • ERROR The ERROR level designates error events that might still allow the application to continue running.
  • FATAL The FATAL level designates very severe error events that will presumably lead the application to abort.

Even with these pointers, the distinction between TRACE and DEBUG is a bit ambiguous. Develop some internal guidelines to determine at what level various application events should be logged - you’ll thank yourself later when digging through the log files!

System.out.println Statements

Even when a logger is in place, developers sometimes find it helpful to use STDOUT when developing or debugging something. Unfortunately, these don’t always get removed before code is committed. Be sure to periodically grep through the codebase for these!