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.
1<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"> 2 <appender name="console" class="org.apache.log4j.ConsoleAppender"> 3 <param name="Threshold" value="Error"/> 4 <param name="Target" value="System.out"/> 5 <layout class="org.apache.log4j.PatternLayout"> 6 <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/> 7 </layout> 8 </appender> 9 10 <root> 11 <priority value ="debug" /> 12 <appender-ref ref="console" /> 13 </root> 14</log4j:configuration>
Now have a look at the following strangely named class.
1package de.codecentric;
2
3import org.apache.log4j.Logger;
4
5public class PhantomLogger {
6
7 private static final Logger LOG = Logger.getLogger(PhantomLogger.class);
8
9 public static void main(String[] args) {
10 System.out.println("Doing stuff");
11 if (LOG.isDebugEnabled()) {
12 LOG.debug(getDebugMessage());
13 }
14
15 }
16
17 private static String getDebugMessage() {
18 System.out.println("Expensive log generation here");
19 return "Debug message";
20 }
21
22}
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.
Was this post helpful?
More articles
fromFabian Lange
26.3.2015 Your job at codecentric?
Jobs
Agile Developer und Consultant (w/d/m)
Alle Standorte
Gemeinsam bessere Projekte umsetzen.
Wir helfen deinem Unternehmen.
Du stehst vor einer großen IT-Herausforderung? Wir sorgen für eine maßgeschneiderte Unterstützung. Informiere dich jetzt.
Hilf uns, noch besser zu werden.
Wir sind immer auf der Suche nach neuen Talenten. Auch für dich ist die passende Stelle dabei.
Blog author
Fabian Lange
Do you still have questions? Just send me a message.
Do you still have questions? Just send me a message.