Make use of logging APIs | Jonathan Giles

Having a good logging story in all Java applications can be a real lifesaver when something goes wrong. The challenge is learning what to log and how to use the logging frameworks to their full potential to spread log output across the numerous logging levels (e.g. info, verbose, warning, etc), as well as to not impact the performance of the application with all the extra logging code.

Java has a plethora of logging frameworks, so it can often be confusing how to get started, but it is important to make a start so as to not be caught flat-footed when logging could have been useful.

Choosing a logging framework

As noted in the best practice on minimizing dependencies, sometimes the decision about which dependency we should use is made for us by the fact that one of our dependencies has a dependency (directly or transitively) on a particular type of framework, and this is especially the case with logging frameworks! If we already find a logging framework on our dependency classpath, we should try our best to use it.

It's a good idea to not depend on a specific logger whenever possible, and instead rely on a facade. This means we do not need to directly concern ourselves with which particular logging implementation we use, and that gives us some flexibility to change as appropriate.

For users on Java 8 and earlier, a good choice is to use SLF4J. For users who can baseline on Java 9 or later, it is preferable to minimize our dependencies and make use of the platform logging APIs that shipped in Java 9.

Understanding logging levels

The value in logging is the ability to look back after an event and discern why that event happened. Often we can find ourselves underwhelmed or overwhelmed by our log output, with not enough useful data to determine the issue, or with so much information it is impossible to find the needle within the haystack. Logging frameworks all have the concept of logging levels, and it is critical to understand how to put these to best use.

SLF4J, for example, offers TRACE, DEBUG, INFO, WARN, and ERROR levels. A summary of each of these levels is below:

TRACE: The most fine-grained level and therefore extremely verbose. At this level it is ok to log each step of an algorithm or each query going to a web service.
DEBUG: Not as fine-grained as TRACE, but this level should be used to log information needed to diagnose issues that isn't ordinarily needing to be presented to viewers of the log output.
INFO: This should be considered the default logging level for when something expected happens that is noteworthy. People should not need to output INFO logging output regularly as it represents purely informative status information.
WARN: This log level is for when something unexpected has happened that may have been recovered from or is non-critical.
ERROR: This log level is used to indicate that some functionality has failed to perform some critical function.

If all we did was log everything in the INFO level, we are making the lives of future log file reviewers much harder. It is important that we spread our logging out over all available levels, and critically, we make use of the TRACE and DEBUG levels appropriately, so that we do not become 'top-heavy', with most of our logging only going into INFO, WARN, and ERROR.

Logging performance considerations

There are so many ways to have great intentions with logging and then fail when it comes time to implement it. Normally the failure relates to a performance hit that is taken when logging is included. I have over many years observed many such logging failure, such as the ones noted below:

Eager concatenation of objects when logging may not even occur. For example:
```
// Example 1: Critical performance code path
public void criticalPath(CoreStrategy strategy) {
  // BAD! Performing toString() on CoreStrategy example class may be slow
  LOGGER.info("Entering critical code path with strategy " + strategy);
}
```
There is the likelihood that calling strategy.toString() may be an expensive and slow operation, but it is called regardless of the logging level, which means we pay the price every time. Additionally, we are also performing string concatenation, again potentially without need. A better approach is to use the overloads in SLF4J (and other frameworks) to pass the argument to the logger and have it only perform the concatenation if the log level is enabled. For example:
```
// Example 2: Critical performance code path
public void criticalPath(CoreStrategy strategy) {
  // GOOD! Not eagerly implicitly calling toString on strategy
  LOGGER.info("Entering critical code path with strategy {}", strategy);
}
```
SLF4J has overloads for each logging level with the following forms:
```
info(String msg)
info(String format, Object arg)
info(String format, Object arg1, Object arg2)
info(String format, Object... args)
```
It is important to note that we can put as many {} into our strings as we have arguments, but only the one-arg and two-arg calls will be of the very fastest form. For more than two args, there is the implicit creation of an Object[] to contain all the args. Whilst this is a non-free cost, it is neglible and should nto be of major concern in most cases.

Whilst this may seem all very academic, it is claimed that the performance of the {} bracket approach is 30x faster than the String concatenation approach. I would recommend not wasting CPU cycles needlessly!

Lack of familiarity with Supplier-based APIs. Many logging APIs in recent years have introduced APIs that use the Java Supplier interface that allows for deferred computation of logger output. For example:

// Example 3: Slow logging computation deferred until (and only if) required
public void criticalPath(CoreStrategy strategy) {
  // GOOD! Not eagerly implicitly calling toString on strategy
  LOGGER.atInfo().addArgument(() -> computeComplexLoggingOutput().log("Entering critical code path with strategy {}");
}

private String computeComplexLoggingOutput() {
  // very slow computation method used only in log output
  int hash = 0;
  while (true) {
    hash += ...;
    if (...) {
      break;
    }
  }

  return Integer.toString(hash);
}

The benefit of this approach is that this method is only called if the logging framework deems the output necessary. It avoids the eagerness of the code examples in the first tip above.