Aufspüren eines Problems mit Speicherverlust / Speicherbereinigung in Java

Dies ist ein Problem, das ich seit einigen Monaten aufzuspüren versuche. Ich habe eine Java-App ausgeführt, die XML-Feeds verarbeitet und das Ergebnis in einer Datenbank speichert. Es gab zeitweise Ressourcenprobleme, die nur sehr schwer aufzuspüren sind.

Hintergrund: Auf der Produktionsbox (wo das Problem am deutlichsten auftritt) habe ich keinen besonders guten Zugriff auf die Box und konnte Jprofiler nicht zum Laufen bringen. Diese Box ist eine 64-Bit-Quad-Core-Maschine mit 8 GB und Centos 5.2, Tomcat6 und Java 1.6.0.11. Es beginnt mit diesen Java-Optionen

JAVA_OPTS="-server -Xmx5g -Xms4g -Xss256k -XX:MaxPermSize=256m -XX:+PrintGCDetails -
XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -XX:+UseParNewGC"

Der Technologie-Stack lautet wie folgt:

• Centos 64-Bit 5.2
• Java 6u11
• Kater 6
• Spring / WebMVC 2.5
• Ruhezustand 3
• Quarz 1.6.1
• DBCP 1.2.1
• MySQL 5.0.45
• Ehcache 1.5.0
• (und natürlich eine Vielzahl anderer Abhängigkeiten, insbesondere die Jakarta-Commons-Bibliotheken)

Das Problem, das ich am ehesten reproduzieren kann, ist ein 32-Bit-Computer mit geringerem Speicherbedarf. Dass ich die Kontrolle habe. Ich habe es mit JProfiler zu Tode geprüft und viele Leistungsprobleme behoben (Synchronisationsprobleme, Vorkompilieren / Zwischenspeichern von xpath-Abfragen, Reduzieren des Threadpools und Entfernen unnötigen Vorabrufs im Ruhezustand und übereifriges "Cache-Erwärmen" während der Verarbeitung).

In jedem Fall zeigte der Profiler, dass diese aus dem einen oder anderen Grund große Mengen an Ressourcen in Anspruch nahmen und dass es sich nach den Änderungen nicht mehr um primäre Ressourcenfresser handelte.

Das Problem: Die JVM scheint die Einstellungen für die Speichernutzung vollständig zu ignorieren, füllt den gesamten Speicher und reagiert nicht mehr. Dies ist ein Problem für den Kunden, der eine regelmäßige Umfrage erwartet (5-Minuten-Basis und 1-Minuten-Wiederholungsversuch), sowie für unsere Betriebsteams, die ständig benachrichtigt werden, dass eine Box nicht mehr reagiert und neu gestartet werden muss. Auf dieser Box läuft nichts anderes.

Das Problem scheint die Speicherbereinigung zu sein. Wir verwenden den ConcurrentMarkSweep-Kollektor (wie oben angegeben), da der ursprüngliche STW-Kollektor JDBC-Timeouts verursachte und zunehmend langsamer wurde. Die Protokolle zeigen, dass mit zunehmender Speichernutzung cms-Fehler auftreten und der ursprüngliche Stop-the-World-Kollektor wiederhergestellt wird, der dann anscheinend nicht richtig erfasst wird.

Wenn Sie jedoch mit jprofiler arbeiten, scheint die Schaltfläche "GC ausführen" den Speicher gut zu bereinigen, anstatt einen zunehmenden Platzbedarf anzuzeigen. Da ich jprofiler jedoch nicht direkt mit der Produktionsbox verbinden kann und das Auflösen bewährter Hotspots anscheinend nicht funktioniert, bin ich es links mit dem Voodoo der Garbage Collection blind zu tunen.

Was ich versucht habe:

• Profilerstellung und Behebung von Hotspots.
• Verwenden von STW-, Parallel- und CMS-Garbage Collectors.
• Laufen mit minimalen / maximalen Heap-Größen in Schritten von 1 / 2,2 / 4,4 / 5,6 / 6.
• Laufen mit Permgen-Speicherplatz in Schritten von 256 MB bis zu 1 GB.
• Viele Kombinationen der oben genannten.
• Ich habe auch die JVM [Tuning-Referenz] konsultiert (http://java.sun.com/javase/technologies/hotspot/gc/gc_tuning_6.html), kann aber nichts finden, was dieses Verhalten erklärt, oder Beispiele für die Optimierung Parameter, die in einer solchen Situation verwendet werden sollen.
• Ich habe auch (erfolglos) versucht, jprofiler im Offline-Modus mit jconsole, visualvm zu verbinden, aber ich kann anscheinend nichts finden, was meine gc-Protokolldaten stören könnte.

Leider tritt das Problem auch sporadisch auf, es scheint unvorhersehbar zu sein, es kann tagelang oder sogar eine Woche lang ohne Probleme laufen oder es kann 40 Mal am Tag ausfallen, und das einzige, was ich konsequent zu fangen scheint, ist Diese Speicherbereinigung wirkt.

Kann jemand einen Rat geben zu:
a) Warum eine JVM 8 physische Gigs und 2 GB Swap Space verwendet, wenn sie so konfiguriert ist, dass sie maximal 6 beträgt.
B) Ein Verweis auf die GC-Optimierung, der tatsächlich erklärt oder vernünftige Beispiele gibt von wann und mit welcher Einstellung die erweiterten Sammlungen verwendet werden sollen.
c) Ein Verweis auf die häufigsten Java-Speicherlecks (ich verstehe nicht beanspruchte Verweise, aber ich meine auf Bibliotheks- / Framework-Ebene oder etwas, das in Datenstrukturen inhärenter ist, wie z. B. Hashmaps).

Vielen Dank für alle Einblicke, die Sie gewähren können.

EDIT
Emil H:
1) Ja, mein Entwicklungscluster ist ein Spiegel der Produktionsdaten bis hinunter zum Medienserver. Der Hauptunterschied ist das 32/64-Bit und die verfügbare RAM-Größe, die ich nicht so einfach replizieren kann, aber der Code sowie die Abfragen und Einstellungen sind identisch.

2) Es gibt einen Legacy-Code, der auf JaxB basiert. Bei der Neuordnung der Jobs, um Planungskonflikte zu vermeiden, wird diese Ausführung jedoch im Allgemeinen eliminiert, da sie einmal am Tag ausgeführt wird. Der primäre Parser verwendet XPath-Abfragen, die das Paket java.xml.xpath aufrufen. Dies war die Quelle einiger Hotspots, zum einen wurden die Abfragen nicht vorkompiliert, und zum anderen befanden sich die Verweise auf sie in fest codierten Zeichenfolgen. Ich habe einen threadsicheren Cache (Hashmap) erstellt und die Verweise auf die xpath-Abfragen als endgültige statische Zeichenfolgen berücksichtigt, wodurch der Ressourcenverbrauch erheblich gesenkt wurde. Die Abfrage ist immer noch ein großer Teil der Verarbeitung, aber es sollte sein, dass dies die Hauptverantwortung der Anwendung ist.

3) Ein weiterer Hinweis: Der andere Hauptverbraucher sind Bildoperationen von JAI (Wiederaufbereitung von Bildern aus einem Feed). Ich bin mit den Grafikbibliotheken von Java nicht vertraut, aber soweit ich festgestellt habe, sind sie nicht besonders undicht.

(Danke für die bisherigen Antworten, Leute!)

UPDATE:
Ich konnte mit VisualVM eine Verbindung zur Produktionsinstanz herstellen, aber die Option GC-Visualisierung / Run-GC wurde deaktiviert (obwohl ich sie lokal anzeigen konnte). Das Interessante: Die Heap-Zuordnung der VM entspricht JAVA_OPTS, und der tatsächlich zugewiesene Heap sitzt bequem bei 1-1,5 Gigs und scheint nicht zu lecken, aber die Überwachung auf Box-Ebene zeigt immer noch ein Leckmuster, aber es ist wird in der VM-Überwachung nicht berücksichtigt. Es läuft nichts anderes auf dieser Box, also bin ich ratlos.

Nun, ich habe endlich das Problem gefunden, das dies verursacht hat, und ich veröffentliche eine detaillierte Antwort, falls jemand anderes diese Probleme hat.

Ich habe jmap ausprobiert, während der Prozess ausgeführt wurde, aber dies führte normalerweise dazu, dass das jvm weiter hängen blieb und ich es mit --force ausführen musste. Dies führte zu Heap-Dumps, denen anscheinend viele Daten oder zumindest die Referenzen zwischen ihnen fehlten. Für die Analyse habe ich jhat ausprobiert, das viele Daten enthält, aber nicht viel in Bezug auf die Interpretation. Zweitens habe ich das Eclipse-basierte Speicheranalysetool ( http://www.eclipse.org/mat/ ) ausprobiert , das zeigte, dass es sich bei dem Heap hauptsächlich um Klassen handelt, die sich auf Tomcat beziehen.

Das Problem war, dass jmap nicht den tatsächlichen Status der Anwendung meldete und nur die Klassen beim Herunterfahren abfing, bei denen es sich hauptsächlich um Tomcat-Klassen handelte.

Ich habe es noch einige Male versucht und festgestellt, dass es einige sehr viele Modellobjekte gab (tatsächlich 2-3x mehr als in der Datenbank als öffentlich markiert).

Auf diese Weise analysierte ich die langsamen Abfrageprotokolle und einige nicht verwandte Leistungsprobleme. Ich habe versucht, extra faul zu laden ( http://docs.jboss.org/hibernate/core/3.3/reference/en/html/performance.html ) und einige Operationen im Ruhezustand durch direkte JDBC-Abfragen zu ersetzen (meistens dort, wo es ist befasste sich mit dem Laden und Bearbeiten großer Sammlungen (die JDBC-Ersetzungen funktionierten nur direkt in den Join-Tabellen) und ersetzte einige andere ineffiziente Abfragen, die MySQL protokollierte.

Diese Schritte verbesserten die Leistung des Frontends, behandelten jedoch immer noch nicht das Problem des Lecks. Die App war immer noch instabil und verhielt sich unvorhersehbar.

Schließlich fand ich die Option: -XX: + HeapDumpOnOutOfMemoryError. Dies erzeugte schließlich eine sehr große (~ 6,5 GB) hprof-Datei, die den Status der Anwendung genau zeigte. Ironischerweise war die Datei so groß, dass sie selbst auf einer Box mit 16 GB RAM nicht analysiert werden konnte. Glücklicherweise konnte MAT einige gut aussehende Grafiken erstellen und zeigte einige bessere Daten.

Diesmal nahm ein einzelner Quarz-Thread 4,5 GB der 6 GB Heap auf, und der Großteil davon war ein StatefulPersistenceContext im Ruhezustand ( https://www.hibernate.org/hib_docs/v3/api/org/hibernate) /engine/StatefulPersistenceContext.html ). Diese Klasse wird vom Ruhezustand intern als primärer Cache verwendet (ich hatte die von EHCache unterstützten Caches der zweiten Ebene und der Abfrage deaktiviert).

Diese Klasse wird verwendet, um die meisten Funktionen des Ruhezustands zu aktivieren, sodass sie nicht direkt deaktiviert werden kann (Sie können sie direkt umgehen, aber Spring unterstützt keine zustandslose Sitzung), und ich wäre sehr überrascht, wenn dies eine solche wäre großer Speicherverlust in einem ausgereiften Produkt. Warum leckte es jetzt?

Nun, es war eine Kombination von Dingen: Der Quarz-Thread-Pool wird instanziiert, wobei bestimmte Dinge threadLocal sind. Spring injizierte eine Sitzungsfabrik, die zu Beginn des Lebenszyklus der Quarz-Threads eine Sitzung erstellte, die dann zum Ausführen des Threads wiederverwendet wurde verschiedene Quarzjobs, die die Ruhezustandssitzung verwendeten. Der Ruhezustand wurde dann in der Sitzung zwischengespeichert, was das erwartete Verhalten ist.

Das Problem ist dann, dass der Thread-Pool die Sitzung nie freigegeben hat, sodass der Ruhezustand resident blieb und den Cache für den Lebenszyklus der Sitzung verwaltet. Da hierfür die Unterstützung für Spring-Ruhezustandsvorlagen verwendet wurde, wurden die Sitzungen nicht explizit verwendet (wir verwenden eine Dao -> Manager -> Treiber -> Quarz-Job-Hierarchie, dem Dao werden bis zum Frühjahr Ruhezustandskonfigurationen injiziert, sodass die Operationen so sind direkt auf den Vorlagen gemacht).

Die Sitzung wurde also nie geschlossen, im Ruhezustand wurden Verweise auf die Cache-Objekte beibehalten, sodass sie nie als Müll gesammelt wurden. Jedes Mal, wenn ein neuer Job ausgeführt wurde, füllte er den Cache lokal im Thread weiter aus, sodass nicht einmal vorhanden war jegliche Aufteilung zwischen den verschiedenen Jobs. Da dies ein schreibintensiver Job ist (sehr wenig Lesen), wurde der Cache größtenteils verschwendet, sodass die Objekte immer wieder erstellt wurden.

Die Lösung: Erstellen Sie eine Dao-Methode, die explizit session.flush () und session.clear () aufruft, und rufen Sie diese Methode zu Beginn jedes Jobs auf.

Die App läuft seit einigen Tagen ohne Überwachungsprobleme, Speicherfehler oder Neustarts.

Vielen Dank für die Hilfe aller, es war ein ziemlich kniffliger Fehler, ihn aufzuspüren, da alles genau das tat, was es sollte, aber am Ende gelang es einer 3-Zeilen-Methode, alle Probleme zu beheben.

Können Sie die Produktionsbox mit aktiviertem JMX ausführen?

-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=<port>
...

Überwachung und Verwaltung mit JMX

Und dann mit JConsole, VisualVM anhängen ?

Ist es in Ordnung, einen Heap-Dump mit jmap durchzuführen ?

Wenn ja, können Sie den Heap-Dump mit JProfiler (bereits vorhanden), jhat , VisualVM, Eclipse MAT auf Lecks analysieren . Vergleichen Sie auch Heap-Dumps, die beim Auffinden von Lecks / Mustern hilfreich sein können.

Und wie du schon erwähnt hast, Jakarta-Commons. Es gibt ein Problem bei der Verwendung der Jakarta-Commons-Protokollierung im Zusammenhang mit dem Festhalten am Klassenladeprogramm. Für eine gute Lektüre über diesen Scheck

Ein Tag im Leben eines Memory-Leak-Jägers ( release(Classloader))

Es scheint, als ob ein anderer Speicher als der Heap undicht ist. Sie erwähnen, dass der Heap stabil bleibt. Ein klassischer Kandidat ist Permgen (permanente Generation), das aus zwei Dingen besteht: geladenen Klassenobjekten und internierten Zeichenfolgen. Da Sie mit VisualVM verbunden berichten, dass sie sollten Sie in der Lage sein , die Menge der geladenen Klassen scheinen, wenn es eine Erhöhung der weiterhin ist geladenen Klassen (wichtig, auch VisualVM zeigt die Gesamtmenge der Klassen je geladen, es ist in Ordnung , wenn diese nach oben geht aber Die Anzahl der geladenen Klassen sollte sich nach einer bestimmten Zeit stabilisieren.

Wenn sich herausstellt, dass es sich um ein Permgenleck handelt, wird das Debuggen schwieriger, da die Werkzeuge für die Permgenanalyse im Vergleich zum Heap eher fehlen. Am besten starten Sie ein kleines Skript auf dem Server, das wiederholt (jede Stunde?) Aufruft:

jmap -permstat <pid> > somefile<timestamp>.txt

jmap mit diesem Parameter generiert eine Übersicht über geladene Klassen zusammen mit einer Schätzung ihrer Größe in Bytes. Dieser Bericht kann Ihnen dabei helfen, festzustellen, ob bestimmte Klassen nicht entladen werden. (Hinweis: Ich meine die Prozess-ID und sollte ein generierter Zeitstempel sein, um die Dateien zu unterscheiden.)

Sobald Sie bestimmte Klassen als geladen und nicht entladen identifiziert haben, können Sie mental herausfinden, wo diese generiert werden könnten. Andernfalls können Sie jhat verwenden, um mit jmap -dump generierte Dumps zu analysieren. Ich werde das für ein zukünftiges Update aufbewahren, falls Sie die Informationen benötigen.

Ich würde nach direkt zugewiesenem ByteBuffer suchen.

Aus dem Javadoc.

Ein direkter Bytepuffer kann durch Aufrufen der Factory-Methode allocateDirect dieser Klasse erstellt werden. Die durch dieses Verfahren zurückgegebenen Puffer haben typischerweise etwas höhere Zuordnungs- und Freigabekosten als nicht direkte Puffer. Der Inhalt von Direktpuffern befindet sich möglicherweise außerhalb des normalen Heapspeichers, sodass ihre Auswirkungen auf den Speicherbedarf einer Anwendung möglicherweise nicht offensichtlich sind. Es wird daher empfohlen, direkte Puffer hauptsächlich für große, langlebige Puffer zuzuweisen, die den nativen E / A-Operationen des zugrunde liegenden Systems unterliegen. Im Allgemeinen ist es am besten, direkte Puffer nur dann zuzuweisen, wenn sie einen messbaren Gewinn an Programmleistung bringen.

Möglicherweise verwendet der Tomcat-Code diese Funktion für E / A. Konfigurieren Sie Tomcat für die Verwendung eines anderen Connectors.

Andernfalls könnte ein Thread vorhanden sein, der System.gc () regelmäßig ausführt. "-XX: + ExplicitGCInvokesConcurrent" könnte eine interessante Option sein.

Irgendwelche JAXB? Ich finde, dass JAXB ein Dauerwellen-Stuffer ist.

Außerdem finde ich, dass visualgc , das jetzt mit JDK 6 geliefert wird , eine großartige Möglichkeit ist, um zu sehen, was im Speicher vor sich geht. Es zeigt die Eden-, Generations- und Perm-Räume sowie das vorübergehende Verhalten des GC auf wundervolle Weise. Sie benötigen lediglich die PID des Prozesses. Vielleicht hilft das, während Sie an JProfile arbeiten.

Und was ist mit den Spring Tracing / Logging-Aspekten? Vielleicht können Sie einen einfachen Aspekt schreiben, ihn deklarativ anwenden und auf diese Weise den Profiler eines armen Mannes erstellen.

"Leider tritt das Problem auch sporadisch auf, es scheint unvorhersehbar zu sein, es kann tagelang oder sogar eine Woche lang ohne Probleme laufen oder es kann 40 Mal am Tag ausfallen, und das einzige, was ich konsequent zu fangen scheint ist, dass die Speicherbereinigung funktioniert. "

Klingt so, als wäre dies an einen Anwendungsfall gebunden, der bis zu 40 Mal am Tag und dann tagelang nicht mehr ausgeführt wird. Ich hoffe, Sie verfolgen nicht nur die Symptome. Dies muss etwas sein, das Sie eingrenzen können, indem Sie die Aktionen der Akteure der Anwendung (Benutzer, Jobs, Dienste) verfolgen.

Wenn dies durch XML-Importe geschieht, sollten Sie die XML-Daten des 40-Absturz-Tages mit Daten vergleichen, die an einem Null-Absturz-Tag importiert werden. Vielleicht ist es ein logisches Problem, das Sie nicht nur in Ihrem Code finden.

Ich hatte das gleiche Problem mit ein paar Unterschieden.

Meine Technologie ist die folgende:

Grale 2.2.4

tomcat7

Quarz-Plugin 1.0

Ich verwende zwei Datenquellen für meine Anwendung. Das ist eine Besonderheit, die die Fehlerursachen bestimmt.

Eine andere zu berücksichtigende Sache ist, dass Quarz-Plugin, Ruhezustand Sitzung in Quarz-Threads injizieren, wie @liam sagt, und Quarz-Threads noch am Leben, bis ich die Anwendung beendet habe.

Mein Problem war ein Fehler in Grails ORM, kombiniert mit der Art und Weise, wie das Plugin die Sitzung behandelt, und meinen beiden Datenquellen.

Das Quarz-Plugin hatte einen Listener, der Ruhezustandsitzungen initiierte und zerstörte

public class SessionBinderJobListener extends JobListenerSupport {

    public static final String NAME = "sessionBinderListener";

    private PersistenceContextInterceptor persistenceInterceptor;

    public String getName() {
        return NAME;
    }

    public PersistenceContextInterceptor getPersistenceInterceptor() {
        return persistenceInterceptor;
    }

    public void setPersistenceInterceptor(PersistenceContextInterceptor persistenceInterceptor) {
        this.persistenceInterceptor = persistenceInterceptor;
    }

    public void jobToBeExecuted(JobExecutionContext context) {
        if (persistenceInterceptor != null) {
            persistenceInterceptor.init();
        }
    }

    public void jobWasExecuted(JobExecutionContext context, JobExecutionException exception) {
        if (persistenceInterceptor != null) {
            persistenceInterceptor.flush();
            persistenceInterceptor.destroy();
        }
    }
}

In meinem Fall persistenceInterceptorInstanzen AggregatePersistenceContextInterceptor, und es hatte eine Liste von HibernatePersistenceContextInterceptor. Eine für jede Datenquelle.

Jede Operation AggregatePersistenceContextInterceptorwird ohne Änderung oder Behandlung an HibernatePersistence übergeben.

Wenn wir Anrufe init()auf HibernatePersistenceContextInterceptorihm die statische Variable erhöht unten

private static ThreadLocal<Integer> nestingCount = new ThreadLocal<Integer>();

Ich kenne den Zweck dieser statischen Zählung nicht. Ich weiß nur, dass er aufgrund der AggregatePersistenceImplementierung zweimal erhöht wurde, einmal pro Datenquelle .

Bis hierher erkläre ich nur das Szenario.

Das Problem kommt jetzt ...

Wenn mein Quarzjob beendet ist, ruft das Plugin den Listener auf, um Ruhezustandsitzungen zu leeren und zu zerstören, wie Sie im Quellcode von sehen können SessionBinderJobListener.

Die Spülung erfolgt perfekt, die Zerstörung jedoch nicht, da HibernatePersistencevor dem Schließen des Ruhezustands eine Überprüfung durchgeführt wird. Es wird geprüft nestingCount, ob der Wert größer als 1 ist. Wenn die Antwort "Ja" lautet, wird die Sitzung nicht geschlossen.

Vereinfachen, was Hibernate getan hat:

if(--nestingCount.getValue() > 0)
    do nothing;
else
    close the session;

Das ist die Basis meines Speicherverlusts. Quarz-Threads sind mit allen in der Sitzung verwendeten Objekten noch aktiv, da Grails ORM die Sitzung aufgrund eines Fehlers, der durch zwei Datenquellen verursacht wurde, nicht schließt.

Um dies zu lösen, passe ich den Listener an, um Clear vor Destroy aufzurufen und Destroy zweimal aufzurufen (eines für jede Datenquelle). Sicherstellen, dass meine Sitzung klar und zerstört war, und wenn die Zerstörung fehlschlägt, war er zumindest klar.