Phantom java logger causing major performance problems - codecentric AG Blog

:

Recently at a customer, I saw massive amounts of garbage generated, causing many garbage collections, as well as a huge slowdown inside Hibernate code. I browsed through the slow transactions recorded in production by AppDynamics, and was wondering why the DB access was super fast, while some other code in Hibernate was slow. I actually didn’t expect that a well used framework like Hibernate could be so slow in some unrelated code. But when I looked closer and drilled down into the snapshot data, I noticed that the time was actually spent in org.hibernate.pretty.Printer.
Oh! So that explains the tons of garbage produced and massive slowdowns in hibernate: It was generating debug sql/object information.
But why did the customer not see that before. No log did show the information at all. The disc also must have been full after minutes under production load.

The answer is simple, and quite shocking. The following sample Log4J config might already reveal it.

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Threshold" value="Error"/> 
    <param name="Target" value="System.out"/> 
    <layout class="org.apache.log4j.PatternLayout"> 
      <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/> 
    </layout> 
  </appender> 
 
  <root> 
    <priority value ="debug" /> 
    <appender-ref ref="console" /> 
  </root>  
</log4j:configuration>

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"> <appender name="console" class="org.apache.log4j.ConsoleAppender"> <param name="Threshold" value="Error"/> <param name="Target" value="System.out"/> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/> </layout> </appender><root> <priority value ="debug" /> <appender-ref ref="console" /> </root> </log4j:configuration>

Now have a look at the following strangely named class.

package de.codecentric;
 
import org.apache.log4j.Logger;
 
public class PhantomLogger {
 
	private static final Logger LOG = Logger.getLogger(PhantomLogger.class);
 
	public static void main(String[] args) {
		System.out.println("Doing stuff");
		if (LOG.isDebugEnabled()) {
			LOG.debug(getDebugMessage());
		}
 
	}
 
	private static String getDebugMessage() {
		System.out.println("Expensive log generation here");
		return "Debug message";
	}
 
}

package de.codecentric;import org.apache.log4j.Logger;public class PhantomLogger {private static final Logger LOG = Logger.getLogger(PhantomLogger.class); public static void main(String[] args) { System.out.println("Doing stuff"); if (LOG.isDebugEnabled()) { LOG.debug(getDebugMessage()); }}private static String getDebugMessage() { System.out.println("Expensive log generation here"); return "Debug message"; }}

The code was running with debug logging defined by the root category – so LOG.isDebugEnabled() also returned true. The heavy lifting did occur. Strings were mashed, garbage produced. Then passed on to the poor Log4J which knew that debug logging had to be accepted. It looked for the appender, found it and sent it there.
The appender itself took the debug information, said “No thanks” and threw it away, as its threshold was not met which was set to Error.

The lesson learnt from this is: Try to avoid using the threshold of the appender, or make sure that all categories are at maximum at the lowest level used by an appender they are appending to.