Kürzlich sah ich bei einem unserer Kunden große Mengen erzeugten Garbages, welcher viele Garbage Collections verursachte. Zudem einen erheblichen Performanceverlust in Hibernate Code. Als ich mir die von AppDynamics aufgezeichneten langsamen Transaktionen ansah, wunderte mich dass der sonst üblicherweise langsame Datenbankzugriff sehr schnell war. Der langsame Teil war also in einem anderen Teil von Hibernate. Damit hatte ich nicht gerechnet, denn Hibernate ist doch eigentlich ein sehr gut optimiertes und viel eingesetztes Framework. Nach etwas eingehender Analyse konnte ich zum Glück Hibernate entlasten. Die aufgezeichneten Daten zeigten, dass die Zeit im org.hibernate.pretty.Printer verbraucht wurden. Aha! Das erklärt also die Unmengen von Garbage und den langsamen vermeintlichen Hibernate Code: Es hat debug sql/objekt Informationen erzeugt.
Aber warum hat der Kunde dies nicht gesehen? Im Log waren tatsächlich keine Informationen vorhanden. Die Platten wären auch nach Minuten unter Produktionslast voll gewesen.
Die Antwort ist einfach, aber doch schockierend. Die folgende Log4J Konfiguration gibt bereits die ersten Hinweise.
Als Beispiel dient folgende bereits verräterisch benannte Klasse:
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}
Der Code läuft also mit Debug Level, welches in der Root-Kategorie definiert ist. Also liefert LOG.isDebugEnabled() true. Es passiert also die schwere Arbeit der Log-Erstellung. Strings werden erzeugt und Garbage produziert. Anschließend wird die Logmeldung an das arme Log4J weitergeleitet, welches wohl oder übel „debug“ für diese Kategorie akzeptieren musste. Log4J sucht nun nach einem Appender, findet einen und versucht die Logmeldung dorthin weiterzugeben. Der Appender schaut sie sich an, sagt „nein danke“ und schmeißt sie weg, da der Schwellwert auf Error gesetzt ist.
Was man daraus lernen kann: Versucht den Schwellwert der Appender als Regulator zu vermeiden. Oder stellt sicher, dass alle Kategorien maximal den detailliertesten Appender Level verwenden.
War dieser Beitrag hilfreich?
Weitere Beiträge
von Fabian Lange
26.3.2015 Dein Job bei 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-Autor*in
Fabian Lange
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.