Pitfall - The overheads of creating log messages

TRACE and DEBUG log levels are there to be able to convey high detail about the operation of the given code at runtime. Setting the log level above these is usually recommended, however some care must be taken for these statements to not affect performance even when seemingly “turned off”.

Consider this log statement:

// Processing a request of some kind, logging the parameters
LOG.debug("Request coming from " + myInetAddress.toString() 
          + " parameters: " + Arrays.toString(veryLongParamArray));

Even when the log level is set to INFO, arguments passed to debug() will be evaluated on each execution of the line. This makes it unnecessarily consuming on several counts:

• String concatenation: multiple String instances will be created
• InetAddress might even do a DNS lookup.
• the veryLongParamArray might be very long - creating a String out of it consumes memory, takes time

Solution

Most logging framework provide means to create log messages using fix strings and object references. The log message will be evaluated only if the message is actually logged. Example:

// No toString() evaluation, no string concatenation if debug is disabled
LOG.debug("Request coming from {} parameters: {}", myInetAddress, parameters));

This works very well as long as all parameters can be converted to strings using String.valueOf(Object). If the log message compuation is more complex, the log level can be checked before logging:

if (LOG.isDebugEnabled()) {
    // Argument expression evaluated only when DEBUG is enabled
    LOG.debug("Request coming from {}, parameters: {}", myInetAddress,
              Arrays.toString(veryLongParamArray);
}

Here, LOG.debug() with the costly Arrays.toString(Obect[]) computation is processed only when DEBUG is actually enabled.