Log performance impact tuning

I have read about logging performance impact many times, but I have never seen with my own eyes. That changed once I accidentally run full set of integration tests with full logging on, which took twice as long as with no log on. That changed my look on logging and now I will never look at a logger line the same way.
The log's impact on application's performance is significant. It is definitely more than I anticipated and what is the worst part, it can be easily worsened by using a logger inappropriately.
In this post, I will demonstrate how a small variance in logging line of code can make a huge difference in application's performance.

While I am using log4j2 for my demonstration, the main principle is the same for other logging frameworks.

The wrong way

The  first code snippet shows the most common inappropriate uses of logging.

logger.info("timeConsumingObject1 " + timeConsumingObject1);
logger.warn("timeConsumingObject3 {}", timeConsumingObject3.toString());
if (logger.isDebugEnabled()){
    logger.debug("timeConsumingObject2 " + timeConsumingObject2);
}

The first line is wrong, because it always calls object's toString method and does not use curly brackets with parameter, although the latter does not affect the performance.
The second line is wrong because of the premature toString call, this causes the method to be invoked without connection to logger level set.
The last piece of the code works, yes, but at what price? You suddenly have three lines of code instead of just one, obscuring the executive code and impairing testability.

The right way

Without further adieu, this is what yours code should look like.

logger.info("timeConsumingObject1 {}", timeConsumingObject1);

This code leads to toString method invocation only when it is necessary and not when the message is going to be discarded immediately after its creation.

Configuration

I used slightly modified template log4j2.xml file, where controlled for the test purposes for the logger "cz.effy.blog". The first logger ensures that test execution time gets logged.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR">
 <Appenders>
  <Console name="Console" target="SYSTEM_OUT">
   <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
  </Console>
 </Appenders>
 <Loggers>
  <Logger name="cz.effy.blog.logging.LoggingTest" level="TRACE" additivity="false">
   <AppenderRef ref="Console"/>
  </Logger>
  <Logger name="cz.effy.blog" level="ERROR" additivity="false">
   <AppenderRef ref="Console"/>
  </Logger>
  <Root level="error">
   <AppenderRef ref="Console"/>
  </Root>
 </Loggers>
</Configuration>

Mock classes

There are three notable example classes.
The first one represents a class, whose toString method takes one second to execute. This simulates a time consuming objects we sometimes encounter, for example web service's request/response.That one second is most likely exaggerated, but it will highlight the differences in test run times.

public class TimeConsumingObject {

 final Logger logger = LogManager.getLogger(getClass());

 @Override
 public String toString() {
  logger.trace("toString invoked");
  try {
   Thread.sleep(1000l);
  } catch (InterruptedException e) {
   e.printStackTrace();
  }
  return "Object" + this.hashCode();
 }
}

The second class represents an usual quickly stringified class.

public class SimpleObject {

 @Override
 public String toString() {
  return "Object" + this.hashCode();
 }
}

The last one represents a common service with a set of methods with logging.

public class LoggingClass {
 final Logger logger = LogManager.getLogger(getClass());

 private TimeConsumingObject timeConsumingObject1;
 private TimeConsumingObject timeConsumingObject2;
 private TimeConsumingObject timeConsumingObject3;
 private SimpleObject simpleObject;

 public LoggingClass() {
  this.timeConsumingObject1 = new TimeConsumingObject();
  this.timeConsumingObject2 = new TimeConsumingObject();
  this.timeConsumingObject3 = new TimeConsumingObject();
  this.simpleObject = new SimpleObject();
 }

 public void properlyLoggedMethod() {
  logger.trace("entering properlyLoggedMethod");
  logger.info("timeConsumingObject1 {}", timeConsumingObject1);
  logger.warn("simpleObject {}", simpleObject);
  logger.debug("timeConsumingObject2 {}", timeConsumingObject2);
  logger.warn("timeConsumingObject3 {}", timeConsumingObject3);
 }

 public void poorlyLoggedMethod() {
  logger.trace("entering properlyLoggedMethod");
  logger.info("timeConsumingObject1 " + timeConsumingObject1);
  logger.warn("simpleObject " + simpleObject);
  logger.debug("timeConsumingObject2 " + timeConsumingObject2);
  logger.warn("timeConsumingObject3 {}", timeConsumingObject3.toString());
 }

 public void simpleProperlyLoggedMethod() {
  logger.warn("simpleObject {}", simpleObject);
 }

 public void simplePoorlyLoggedMethod() {
  logger.warn("simpleObject {}", simpleObject.toString());
 }
}

There are two two-methods sets, that represents in both cases the right and the wrong ways while the actual log result remains the same.
The first set logs constant message, three time consuming objects (one second sleep in toString method) and one simple object.
The second set logs only the simple object.

Test results

Although there are many variables influencing the actual numbers, the vast differences should prove, why I strongly suggest logging "the right way".

Logged method test

Level - TRACE
ProperlyLogged - 3 seconds
PoorlyLogged - 3 seconds
LEVEL - WARN
ProperlyLogged - 1 seconds
PoorlyLogged - 3 seconds
LEVEL - OFF
ProperlyLogged - 0 seconds
PoorlyLogged - 3 seconds

When the log level is set to maximum, there is no measurable difference, but once you turn it down, you instantly see the difference to appear. The largest gap is at the OFF level, because the proper way does not invoke toString method at all versus three times for the wrong way.

Simple logged method test

This test is invoked thousand times in order to make the numbers measurable.
LEVEL - WARN
ProperlyLogged - 0.06 seconds
PoorlyLogged - 0.06 seconds
LEVEL - OFF
ProperlyLogged - 0.008 seconds
PoorlyLogged - 0.01 seconds

As before, the test results are very close to each other  when everything gets logged. But once you turn off logging, there is a measurable gap. These results are the mean values from a handful of runs.

Conclusion

The next time you are writing a line of log, I suggest you consider using the method with parameters, passing objects with toString methods.
This practice leads to better performance and cleaner code.

The code for this post is available on github.