15.6 The Performance Impact of log4j

The potential performance impact of logging in an application is significant. For a typical production application, thousands or even hundreds of thousands of log messages can be logged every day, depending on the logging threshold that's configured. The consequences might be even worse if exception stack traces are logged due to errors in the application.

The log4j documentation states that much attention has been given to minimizing the performance impact of logging using log4j. Nothing is free, however, and there is an additional cost associated with generating log messages. The question is, does that cost outweigh the benefits gained from the additional logging information?

The time cost of creating a log message using log4j depends on several factors:

• The type of appender being used

• The log4j layout being used to format the messages

• The parameter construction time to create the log message

• The depth of the logger hierarchy and where the log threshold is assigned

The type of appender has much to do with how long it will take to create a log message. Logging a message using an SMTP appender will take a different amount of time than logging to the filesystem. On a typical machine using Java 1.3, logging a message to the filesystem will take anywhere from 20 microseconds to upwards of 300 microseconds, depending on which layout you use. While this is a very small number, over time it can add up.

Probably the most significant impact on logging is what information you attempt to log and how you format that information. log4j uses a subclass of org.apache.log4j.Layout to determine how the message should be formatted in the output destination. Using the SimpleLayout class is the fastest, as it logs only the log level and the message. On the other hand, the PatternLayout class allows for a great amount of flexibility in the format of the message; you can log all sorts of information, including the class creating the message, the line number, and even the Java thread that is generating the message. However, all of this additional information comes at a severe price in terms of performance. The log4j documentation contains several warning messages in the JavaDocs for the PatternLayout class stating that performance may suffer greatly if certain information is written out with the log message.

You must be very particular about what information you need in the log message. You should be able to get by with the class, the level, and the message. The other information is nice to have, but in most cases it's superfluous.

Creating the message that goes into the log statement can also impact the time and performance. Creating a message using values such as:

logger.debug("Session id is: " + sessId + " for user " + user.getFullName( ) );

can add significant time to logging. This isn't related to log4j, but rather to the cost associated with making Java method calls and concatenating the strings together before the actual log statement can be generated.

Finally, as mentioned earlier, loggers can be connected together in a parent/child relationship. Because the logging threshold can be assigned at any level, the log4j environment may have to search up the hierarchy to determine whether the log message should be written. If this hierarchy is very deep, this traversal can add significant time to the log statement creation.

Generally, in the development stages of your application, logging costs are less important. The performance of logging shouldn't matter that much while you're still developing and debugging the application; in fact, this is typically where you want as much logging as the application can generate. When it's time to go to QA or production, turn down the logging levels.

With other languages, the logging code might not ever make it into the compiled binaries. Preprocessors might remove the logging code to keep the binary size smaller and prevent the log messages from showing up. However, this is not necessary using log4j you have the flexibility of controlling how much logging is done just by changing the configuration file. (Of course, the log statements are still present in the binary code once it's compiled.)