Parameterized logging

Given that loggers in logback-classic implement the SLF4J's Logger interface, certain printing methods admit more than one parameter. These printing method variants are mainly intended to improve performance while minimizing the impact on the readability of the code.

For some Logger logger, writing,

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

incurs the cost of constructing the message parameter, that is converting both integer i and entry[i] to a String, and concatenating intermediate strings. This is regardless of whether the message will be logged or not.

One possible way to avoid the cost of parameter construction is by surrounding the log statement with a test. Here is an example.

if(logger.isDebugEnabled()) { 
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

This way you will not incur the cost of parameter construction if debugging is disabled for logger. On the other hand, if the logger is enabled for the DEBUG level, you will incur the cost of evaluating whether the logger is enabled or not, twice: once in debugEnabled and once in debug. In practice, this overhead is insignificant because evaluating a logger takes less than 1% of the time it takes to actually log a request.

Better alternative

There exists a convenient alternative based on message formats. Assuming entry is an object, you can write:

Object entry = new SomeObject(); 
logger.debug("The entry is {}.", entry);

Only after evaluating whether to log or not, and only if the decision is positive, will the logger implementation format the message and replace the '{}' pair with the string value of entry. In other words, this form does not incur the cost of parameter construction when the log statement is disabled.

The following two lines will yield the exact same output. However, in case of a disabled logging statement, the second variant will outperform the first variant by a factor of at least 30.

logger.debug("The new entry is "+entry+".");
logger.debug("The new entry is {}.", entry);

A two argument variant is also available. For example, you can write:

logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry);

If three or more arguments need to be passed, an Object[] variant is also available. For example, you can write:

Object[] paramArray = {newVal, below, above};
logger.debug("Value {} was inserted between {} and {}.", paramArray);