Java Phantom Logging verursacht schwerwiegende Performanceprobleme

1 Kommentar

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:

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";
	}
 
}

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.

Fabian Lange ist Lead Agent Engineer bei Instana und bei der codecentric als Performance Geek bekannt. Er baut leidenschaftlich gerne schnelle Software und hilft anderen dabei, das Gleiche zu tun.
Er kennt die Java Virtual Machine bis in die letzte Ecke und beherrscht verschiedenste Tools, die JVM, den JIT oder den GC zu verstehen.
Er ist beliebter Vortragender auf zahlreichen Konferenzen und wurde unter anderem mit dem JavaOne Rockstar Award ausgezeichnet.

Share on FacebookGoogle+Share on LinkedInTweet about this on TwitterShare on RedditDigg thisShare on StumbleUpon

Kommentare

  • Florian Ortner

    27. November 2010 von Florian Ortner

    Danke für das schöne Beispiel.

    Leider kann ich’s noch toppen: aus Interopgründen war der Logger native, dh: die Phatom-Log-Strings wurden von UTF-16 nach ASCII/native konvertiert bevor die „Nein danke“ Entscheidung getroffen wurde. Mittlerweile performt das „okay“ — dort war’s ein JRE 1.4 und der Conversionoverhead hat eine CPU auf der AIX/LPAR ausgelastet… dort bezahlt man nach CPU Cycles. Ein If := Jahresgehalt 🙂

    lg,
    Florian

Kommentieren

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert.