Java Profiler – Marke Eigenbau mit Elasticsearch, Logstash und Kibana (ELK Stack)

In meinen Beitrag “OutOfMemoryError: Java Heapdump Analyse – Was tun? Wenn die Produktion spinnt!” werden verschiedene Werkzeuge genannt, mit denen man eine Java-Anwendung überwachen kann. VisualVM und JConsole sind hervorragende  Werkzeuge, die einem Software Ingenieur Einblick in eine einzelne laufende Applikation geben.

VisualVM ermöglicht es zwar Snapshots von Anwendungsmetriken, wie Speicherverbrauch, CPU-Auslastung aufzunehmen, aber man muss diese Snapshots  händisch erstellen, tut man das nicht sind alle Daten weg, wenn man VisualVM beendet. Außerdem muss VisualVM  zur Aufzeichnung der Daten die ganzen Zeit parallel zur Anwendung laufen. Wenn VisualVM gerade nicht läuft, dann werden logischerweise auch keine Daten gesammelt. Meistens hat man in modernen Web-Architekturen auch nicht nur einen Anwendungsserver und gerade für die Überwachung und Aufzeichnung eines kompletten Clusters ist VisualVM nur bedingt geeignet, hier braucht man schnell kommerzielle Lösungen, wie AppDynamics oder NewRelic.

VisualVM

Abbildung 1: VisualVM – Laufzeitmetriken während eines Lasttests

Ein anderes Problem ist, dass man Laufzeitmetriken nur schwer mit Logdaten korrelieren kann, da es für unterschiedliche Probleme in den meisten Unternehmen auch unterschiedliche Lösungen gibt, z.B. NewRelic zum Aufzeichnen von Laufzeitmetriken einer Anwendung und Splunk für die Logdateianalyse. Man muss also ständig zwischen den unterschiedlichen Software-Lösungen  hin und her springen und ist selbst dafür verantwortlich seine Zeiteinstellungen in beiden Anwendungen zu synchronisieren, was bei komplexeren Zeitreihenanalysen lästig ist. Somit kann es schwer fallen das Zugriffsprotokoll mit dem Ansteigen des Speichers oder der CPU-Auslastung in Beziehung zu bringen. Gerade bei plötzlich auftretenden java.lang.OutOfMemoryError wäre es wünschenswert, wenn man Laufzeitmetriken mit den Aktivitäten auf der Webseite korrelieren könnte.

Daraus ergeben sich die folgenden funktionalen Anforderungen an eine Software Lösung zur Laufzeit-Überwachung einer Anwendung:

  • Laufzeitdaten einer Anwendung sollen kontinuierlich automatisch gesammelt werden,
  • Logdaten sollen ebenfalls automatisch kontinuierlich gesammelt werden,
  • Laufzeitdaten und Logdaten von mehren Server müssen korreliert werden können.

Im meinem letzten Beitrag „Splunk – Marke Eigenbau mit Elasticsearch, Logstash und Kibana (ELK Stack)“ wird der ELK Stack vorgestellt, um Logdaten sammeln und analysieren zu können. Mit Kibana werden die gesammelten Logdaten visualisiert und ausgewertet. Eine interessante Frage ist nun: Kann man den ELK Stack auch benutzen, um seine Java-Anwendung zu überwachen. Dann wären alle drei Anforderungen an Software-Lösung zur Laufzeit-Überwachung einer Anwendung auf einen Schlag erfüllt.

Die Frage, ob man den ELK Stack auch zum Überwachen von Java-Anwendungen benutzen kann, wird in diesem Beitrag beantwortet, in dem wir einen einfachen Java-Profiler bauen, der auf dem ELK Stack basiert. Ziel ist es den Speicherverbrauch eines Anwendungsserver-Cluster mit dem ELK Stack zu  überwachen und mit Logdaten korrelieren zu können. Betrachten wir also zunächst, welche Möglichkeiten in der Java-Laufzeitumgebung existieren, um das Laufzeitverhalten von Software zu messen.

Java Profiling

Profiler sind Werkzeuge, mit denen sich das Laufzeitverhalten von Software analysieren lässt. Es gibt unterschiedliche Problembereiche in der Softwareentwicklung, die durch ineffiziente Programmierung ausgelöst werden. Ein Profiler hilft einem Software Ingenieur durch Analyse und Vergleich von laufenden Programmen die verschiedensten Problembereiche aufzudecken. Daraus kann man Maßnahmen zur strukturellen und algorithmischen Verbesserung des Quellcodes ableiten. Beispielsweise kann das Ziel eines Profiling das Aufspüren von Performance-Bottenecks oder eines Memory-Leaks sein, die anschließend beseitigt werden müssen.

Die JVM ist der Teil der Java-Laufzeitumgebung, der für die Ausführung des Bytecodes verantwortlich ist. Während der Bytecode-Ausführung gibt es bestimmte Laufzeitmetriken, die gemessen werden können. Beispiele für Laufzeitmetriken sind der Speicherverbrauch, die Anzahl von laufenden Threads oder die CPU Auslastung.

Abbildung 2 zeigt die Java Memory Architektur der Oracle HotSpot Implementierung der JVM und die JVM-Parameter, mit denen man die Speicherverwaltung beeinflussen kann. Young und Old Generation bilden zusammen den Heap. Daneben steht die Permanent Generation, die man seit JDK8 auch Metaspace nennt. In allen genannten Bereichen kann der Speicher ausgehen, schließlich handelt es sich dabei um eine physikalisch begrenzte Größe. Geht der Speicher in Heap oder Metaspace aus, dann kommt es zum  sogenannten OutOfMemoryError.

Java Heap
Abbildung 2: Java Speicher Unterteilung

In der Java-Welt gibt es die folgenden beiden Spezifikationen, die sich u.a. damit beschäftigen die Java Memory Architektur zu überwachen können: JSR-174: Monitoring and Management Specification for the Java Virtual Machine und JSR-163: Java Platform Profiling Architecture. JSR-174 definiert Anforderungen an ein JVM Monitoring- und Managementsystem. Der JSR-163 definiert nicht nur Schnittstellen, die von JSR-174 benötigt werden, sondern stellt auch Referenz-Implementierungen und Test-Werkzeuge bereit, um Java-Anwendungen überwachen, fern steuern und messen zu können. Seit JDK5 sind die beiden JSRs in der Laufzeitumgebung integriert (Quelle). Beispiele für eine  Schnittstelle und Referenz-Implementierung zur Überwachung der Java Memory Architektur sind die Schnittstelle java.lang.management.MemoryPoolMXBean und die Klasse java.lang.management.MemoryUsage.

Die JVM besitzt eine automatische Speicherverwaltung und benutzt den Heap zum Allokieren von neuen Objekten, der wiederum aus mehreren Speicherbereichen besteht. Außerdem besitzt die JVM den sogenannten Non-Heap Memory in dem sich das sogenannte Method Area befindet, in dem sich die geladenen Klassen befinden. Daraus resultieren mehre Memory Pools. Ein Instanz der Management-Schnittstelle MemoryPoolMXBean repräsentiert also immer einen spezifischen Memory Pool, wie z.B Old Generation oder Eden Space. In Oracle HotSpot Implementierung findet man alle in Abbildung 2 dargestellten Memory Pools wieder. Auf alle Instanzen (sun.management.MemoryPoolImpl) der unterschiedlichen Memory Pools kann man mit der ManagementFactory.getMemoryPoolMXBeans() zugreifen.

Mit der Methode  getUsage() bekommt man die geschätzte Speichergröße des aktuellen Memory Pools. Für einen Memory Pool, der vom einem Garbage Collector bereinigt wird, gilt das die Speichergröße sowohl reachable als auch unreachable Objekte beinhaltet.

Die Klasse MemoryUsage beinhaltet die folgenden vier Werte:

WertBeschreibung
initrepräsentiert die initiale Speichermenge in bytes, die während des Startvorgangs der JVM allokiert wird. Dieser Wert kann auch undefined sein.
usedrepräsentiert den aktuellen Speicherverbrauch in bytes.
committedrepräsentiert den maximalen Speicherverbrauch, der von der JVM ohne Speicherumstrukturierung garantiert wird. Dieser Wert kann sich über die Laufzeit hinweg ändern.
maxrepräsentiert maximalen Speicherverbrauch, der von der JVM allokiert werden kann.

Ähnliche Management-Beans gibt es auch zum Abfragen von anderen Laufzeitmetriken, wie Anzahl an laufenden Threads oder geladenen Klassen. Laufzeitmetriken, die nicht in der java.lang.management API enthalten ist, kann man selbst implementieren. Dazu gibt es die java.lang.instrument API, damit ist es z.B. auch möglich die Laufzeit von Methoden zu messen, in dem man den Bytecode eine Klasse verändert. Dazu verwendet man einen sogenannten Java-Agenten. Diese API ist die Grundlage für viele kommerzielle Profiler und wird üblicherweise als JAR-Datei aufgeliefert. Das folgende Listig zeigt einen Java-Agenten und wie man den Bytecode einer Klasse mit Javassist umschreiben kann, um nach jeden Methoden-Aufruf die Ausführungzeit der Methode in der Konsole ausgegeben wird:

public class AppStashAgent {
    public static void premain(String agentArguments, Instrumentation instrumentation) {
         instrumentation.addTransformer(new ClassFileTransformer() {
            @Override
            public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException {
                byte[] result = new byte[0];

                try {
                    String dotClassName = className.replace('/', '.');

                    ClassPool cp = ClassPool.getDefault();
                    CtClass ctClazz = cp.get(dotClassName);

                    for (CtMethod method1 : ctClazz.getDeclaredMethods()) {
                        method1.addLocalVariable("elapsedTime", CtClass.longType);

                        method1.insertBefore("elapsedTime = System.nanoTime();");
                        method1.insertAfter(" { elapsedTime = System.nanoTime() - elapsedTime; "
                                + "System.out.println(\" Method elapsedTime = \" + elapsedTime);}");
                        result = ctClazz.toBytecode();

                    }

                } catch (Throwable e) {
                    e.printStackTrace();
                }
                return result;
            }
        });
    }
}

Die meisten Java-Profiler geben zwar einen detaillierten Einblick in eine Anwendung. Es kann aber vorkommen, dass man einen  Profiler nicht produktiv Betrieb benutzen kann. Das kann daran liegen, dass dieser Profiler entweder das Java Virtual Machine Profiling Interface (JVMPI) oder das Java Virtual Machine Tool Interface (JVMTI) zum Sammeln von Daten benutzt.  Die Verwendung der JVMPI oder JVMTI kann dazu führen, dass sich die Ausführungszeit der Anwendung verlangsamt.

In diesem Fall erzwingt das Vorhandensein eines Agenten, dass der gesamte Bytecode einer Klasse immer von der Festplatte geladen wird, da der Bytecode nach dem Laden der Klasse verändert wird. Um einen solchen Profiler trotzdem benutzen zu können, muss man aufwändig produktionsnahe Lastsenarien mit Lasttest-Werkzeugen wie JMeter oder Gatling simulieren.

Eine Alternative zum klassischen Profiling ist die manuelle Messung der Ausführungszeit im Quellcode, die in eine Logdatei geschrieben wird. Abhängig von der Größe des Entwicklungsteams und Anwendung kann das Schnell zum Wartungsalptraum werden, da man den Quellcode mit dem Messcode verschmutzt. Um den Quellcode nicht zu verschmutzen, existieren Frameworks wie JETM. JETM betrachten wir im Folgenden, um ein besseres Verständnis darüber zu bekommen, welche Möglichkeiten und Konzepte existieren, um eine Anwendung alternativ als mit einem Agenten zu messen.

Java Execution Time Measurement Library (JETM)

Mit Java Execution Time Measurement Library (JETM) kann ein Software Ingenieur die Ausführungsgeschwindigkeit seiner Anwendung bis auf Methoden-Ebene messen. In einer Spring-Anwendungen kann mit JETM die Ausführungsgeschwindigkeit sogar messen werden, ohne eine Zeile Quellcode anzufassen. JETM benutzt dann Spring AOP und generiert dynamische Proxies zum Messen der Spring-Beans. JETM ist sehr einfach zu benutzen, man muss nur die JETM-JARs auf dem ClassPath packen und die Konfiguration der Anwendung entsprechend anpassen. Das folgende Listing zeigt, was man in der web.xml einer Web-Anwendung konfigurieren muss, um mit JETM die einzelnen Requests einer Anwendung zu messen.

<servlet>
    <servlet-name>performanceMonitor</servlet-name>
    <servlet-class>etm.contrib.integration.spring.web.SpringHttpConsoleServlet</servlet-class>
    <load-on-startup>1</load-on-startup>
</servlet>
<servlet-mapping>
    <servlet-name>performanceMonitor</servlet-name>
    <url-pattern>/performance/*</url-pattern>
</servlet-mapping>

<filter>
    <filter-name>performance-monitor</filter-name>
    <filter-class>
      etm.contrib.integration.spring.web.SpringHttpRequestPerformanceFilter
    </filter-class>
</filter>

<filter-mapping>
    <filter-name>performance-monitor</filter-name>
    <url-pattern>*</url-pattern>
</filter-mapping>

Die sogenannte JETM Console macht die Ergebnisse der Messungen verfügbar. In Abbildung 3 ist ein Bildschirmfoto der JETM Konsole zu sehen. Die JETM Console kann man entweder über ein Servlet in eine bestehende Web-Anwenundung integrieren werden oder man benutzt einen Standalone HTTP Console Server. Damit kann JETM sowohl für Macrobenchmarks als auch für Microbenchmarks benutzt werden.JETM Console

Abbildung 3: JETM Console

Aus den Betrachtungen über die java.lang.management, java.lang.instrument API und JETM ergeben sich noch zwei nicht funktionale Anforderungen an eine Software-Lösung zur Laufzeit-Überwachung einer Java-Anwendung:

  • Laufzeitdaten müssen auch in Produktion gesammelt werden können,
  • Das Sammeln von Laufzeitmetriken sollte über Konfiguration gestartet werden.

Betrachten wir nun im Folgenden, wie wir aus den definierten funktionalen und nicht-funktionalen Anforderungen ein Minimum Viable Product einer Software-Lösung zur Laufzeit-Überwachung bauen können.

Profiler auf ELK Stack Basis

Wie bereits erwähnt, ergeben sich die folgenden funktionalen und nicht-funktionalen Anforderungen an eine Software-Lösung zur Laufzeit-Überwachung einer Anwendung:

  • Laufzeitdaten einer Anwendung sollen kontinuierlich automatisch gesammelt werden,
  • Logdaten sollen ebenfalls automatisch kontinuierlich gesammelt werden,
  • Laufzeitdaten und Logdaten von mehren Server müssen korreliert werden können,
  • Laufzeitdaten müssen auch in Produktion gesammelt werden können,
  • Das Sammeln von Laufzeitmetriken sollte über Konfiguration gestartet werden.

Der ELK Stack ermöglicht es Logdaten automatisch zu sammeln und besteht aus den folgenden Komponenten:

  • Elasticsearch – für die Suche und Datenanalyse,
  • Logstash – zum Zentralisieren, Anreichern und Parsen von Logdaten,
  • Kibana – für die Daten Visualisierung.
logstash-architecture
Abbildung 4: ELK Stack Architektur

Abbildung 4 zeigt einen möglichen architektonischen Aufbau eines ELK Clusters. Das Cluster besteht aus drei Rechnern. Auf zwei Rechner sind Tomcat-Anwendungserver installiert. Von den Tomcat-Anwendungserver werden kontinuierlich Logdaten schreiben. Auf diesen beiden Rechnern ist deshalb ausserdem Logstash installiert. Logstash wirkt in der Installation als ETL-Tool und extrahiert die Logdaten, transformiert sie ggf., sodass die Logdaten in Elasticsearch geschrieben und von Elasticsearch indexiert werden können. Auf einem dritten Rechner ist ein Apache Webserver installiert, der als Webverzeichnis für Kibana dient, dass die von Logstash gesammelten Logdaten der beiden Tomcat-Anwendungsserver visualisiert. Für die Visualisierung nutzt Kibana die Rest-API von Elasticsearch.

Log = Timestamp + Data

Die Logdaten einer Anwendung bestehen immer aus einem Zeitstempel und irgendwelchen Daten. Die Laufzeitmetriken unserer Anwendung haben einen ähnlichen Aufbau. Zu einem bestimmten Zeitpunkt wird von der Anwendung eine bestimmte Menge des Speichers konsumiert.

Man kann sich die JVM, wie eine echte Maschine vorstellen, die mit Sensoren bestückt ist, diese Sensoren können periodisch zur Überwachung abgefragt werden. Ein solcher Sensor ist z.B. eine MemoryPoolMXBean-Instanz. Wenn man diese Sensordaten in eine Form bringt, die noch über einen Zeitstempel verfügt und in eine Datei schreibt, können die Logdaten von Logstash verarbeitet und in Elasticsearch überführen werden. Das folgende Listing zeigt eine mögliche JSON Struktur für unseren Speichersensor:

{
    "name": "PS Old Gen", 
    "type": "Heap memory", 
    "@timestamp": "2014-05-28T23:43:19", 
    "@version": "1",
    "init": 266862592,
    "used": 2417592, 
    "committed": 266862592, 
    "max": 2863661056 
}

Damit ist der ELK Stack schonmal in der Lage unsere funktionalen Anforderungen an eine Software-Lösung zur Laufzeit-Überwachung einer Anwendung zu erfüllen.  Wir haben aber noch nicht-funktionale Anforderungen definiert, u.a sollen die Laufzeitmetriken auch produktiv gesammelt werden können und das Sammeln über Konfiguration gestartet werden. Um losgelöst von Rest der Anwendung Laufzeitmetriken sammeln, bietet sich ein Runnable an. Ein Runnable kann über den ScheduledThreadPoolExecutor immer im einem Hintergrund der Anwendung laufen und kontinuierlich Laufzeitmetriken sammeln. Denn ScheduledThreadPoolExecutor kann man mit Spring einfach konfigurieren, wie wir später sehen werden. Das folgende Listing zeigt, wie man die MemoryUsage Werte der unterschiedlichen MemoryPoolMXBean in der Konsole im JSON-Format weglassen kann:

public class MemoryLoggingTask implements Runnable {
    private static final Logger LOGGER = LoggerFactory.getLogger(MemoryLoggingTask.class);
    private static final ObjectMapper OBJECT_MAPPER = new ObjectMapper();

    @Override
    public void run() {
        for (MemoryPoolMXBean memoryPoolMXBean : ManagementFactory.getMemoryPoolMXBeans()) {
            try {
                String message = memoryUsageAsJsonString(memoryPoolMXBean);
                LOGGER.info(message);
            } catch (IOException e) {
                LOGGER.error("Object could not converted to JSON String:", e);
            }
        }
    }

    private String memoryUsageAsJsonString(MemoryPoolMXBean memoryPoolMXBean) throws IOException {
        return OBJECT_MAPPER.writeValueAsString(buildMemoryUsageInfo(memoryPoolMXBean));
    }

    private MemoryUsageInfo buildMemoryUsageInfo(MemoryPoolMXBean memoryPoolMXBean) {
        return MemoryUsageInfo.builder()
                .name(memoryPoolMXBean.getName())
                .type(memoryPoolMXBean.getType().toString())
                .usage(memoryPoolMXBean.getUsage())
                .build();
    }
}

Die Frage ist nun: Ist unser MemoryLoggingTask schnell genug für den produktiven Einsatz? Abbildung 5 zeigt einen Microbenchmark der run-Methode, der mit JETM aufgezeichnet wurden ist. Die Methode wurde 130 mal aufgerufen und die Ausführungszeit braucht im Mittel 1ms. Was man in der Abbildung nicht sieht, ist das der Maximalwert bei ersten Aufruf erfolgt ist. Bei jeden weiteren Methoden wird ungefähr 150ns für die Ausführung benötigt. Damit spricht nichts gegen den produktiven Einsatz des MemoryLoggingTask.

JETM Console MemoryLoggingTask
Abbildung 5: MemoryLoggingTask Laufzeitverhalten

Die letzte nicht-funktionale Anforderung ist, dass das Sammeln von Laufzeitmetriken über Konfiguration gestartet werden sollte. Wie schon erwähnt, ist es mit Spring sehr einfach unseren MemoryLoggingTask im Hintergrund laufen zulassen. Das folgende Listing zeigt, was man dazu machen muss.

<bean id="appStashMemoryLogging" class="io.github.appstash.task.MemoryLoggingTask" />

<task:scheduled-tasks scheduler="appStashScheduler">
    <task:scheduled ref="appStashMemoryLogging" method="run" fixed-delay="1000"/>
</task:scheduled-tasks>

<task:scheduler id="appStashScheduler" pool-size="10"/>

Zusammenfassung

Wie haben in diesen Beitrag gesehen, dass man sich mit einfachsten Mitteln einen Profiler selber schreiben kann. Da Laufzeitmetriken auch als Zeitstempel mit Daten gesehen werden können, kann man diese Daten in eine Datei schreiben und mit einem Loganalysewerkzeug visualisieren. Abbildung 6 zeigt die Kibana Visualisierung vom Heap-Speicher neben VisualVM. Deutlich zu erkennen ist die kontinuierliche Garage Collection des Heaps.  Natürlich kann man das gleiche Konzept auch mit anderen Loganalysewerkzeugen, wie z.B. Splunk nutzen, um ähnliche Visualisierungen herzustellen.

Cluster-Heap-Analyse
Abbildung 6: Cluster-Heap-Analyse mit Kibana im Vergleich zu VisualVM

Um den kompletten Cluster, der in Abbildung 4 dargestellt ist, zu starten, muss man nur VirtualBox und Vagrant installieren. Danach kann man nur die folgenden drei Befehle ausführen. Das in Abbildung 6 dargestellte Dashbord befindet sich unter /appstash/external/Heap Memory Dashboard.

bernd@mbp ~$ git clone https://github.com/zutherb/AppStash.git appstash
bernd@mbp ~$ git checkout elk-example
bernd@mbp ~$ cd appstash/vagrant
bernd@mbp ~$ vagrant up

Auf die inAbbildung 4 im dargestellten Komponenten des ELK Stacks kann man über die folgenden Port Forwardings zu greifen:

  • Kibana – http://localhost:8000/
  • Elasticsearch – http://localhost:9200/
  • Applikation 1 – http://localhost:8080/pizza/
  • Applikation 2 – http://localhost:8081/pizza/
Share Button

OutOfMemoryError: Java Heapdump Analyse – Was tun? Wenn die Produktion spinnt!

Die Ausnahme java.lang.OutOfMemoryError kann zum Alptraum eines Entwickler werden. Diese Ausnahme tritt oft ohne Vorwarnung, erst unter Volllast in der Produktion auf. OutOfMemoryErrors sind während der Entwicklung nur schwer zu entdecken. Denn häufig wird die Bedeutung von automatisierten Lasttest unterschätzt, die ein solches Szenario simulieren könnten. Kommt es in Produktion zum Super-GAU und die Applikation steigt mit einem OutOfMemoryError aus, dann geht für den Entwickler die forensische Arbeit los. Dabei gilt es herauszufinden, in welchen Situationen die Applikation zu viel Speicher benötigt und wie man vermeiden kann, dass die Applikation abstürzt. In diesem Beitrag geht es darum, wie man bei der Analyse eines solchen Fehlers vorgeht. Um diese Ausnahme besser zu verstehen, wird  zuerst die Java Memory Architektur vorgestellt.

Java Memory Architektur

Die Java Plattform verfügt über eine automatische Speicherverwaltung, die in der Java Virtual Machine Specification festgelegt ist. Zur Laufzeit wird zwischen verschiedenen Speicherbereichen unterschieden. Es gibt einen Speicherbereich, der für alle Threads sichtbar. Dieser Speicherbereich enthält unter anderen das sogenannte Method Area (PermGen) und den Heap.  Ein anderer Speicherbereich ist exklusiv nur für den ausgeführten Thread sichtbar.

Java Memory Architektur
Abbildung 1: Java Memory Architektur

Das Method Area wird beim Start der JVM initialisiert und darin befinden sich die geladenen Klassen. Der Heap verwaltet hingegen alle Objekte und Arrays, die zur Laufzeit erzeugt werden. Der Heap ist für alle Threads sichtbar.

Die JVM Spezifikation sieht weiterhin eine automatische Speicherverwaltung des Heaps in Form einer sogenannten Garbage Collection vor, die vom Garbage Collector durchgeführt wird. Bei der Garbage Collection handelt es sich, um eine explizite Deallokation von Objekten auf dem Heap, die automatisch abläuft. Eine Garbage Collection sollte normalerweise ohne das Zutun eines Entwicklers ablaufen.

Java Heap
Abbildung 2: Java Heap Struktur

Abbildung 2 zeigt den Aufbau der Oracle HotSpot Implementierung des Heaps und die JVM-Parameter, die man benutzen kann, um den Speicher an entsprechenden Stellen zu vergrößern. Der Heap ist in mehreren Generationen unterteilt: Der Young Generation und der Old Generation. Die Young Generation sorgt für eine Optimierung der Garbage Collection. Außerdem soll die Young Generation die Allokation neuer Objekte, sowie die Deallokation nicht mehr benötigter Objekte vereinfachen. Wenn Objekte ein gewisses Lebensalter überschritten, werden sie in die langsamere Old Generation kopiert. Neben diesen beiden Generationen gab es bis Java 8 noch die Permanent Generation. Im Zuge der Vereinigung der Codebasis der HotSpot und JRockit JVM wurde die Permanent Generation allerdings entfernt (Quelle).

Nachdem nun der Aufbau der Java Memory Architektur  geklärt ist, betrachten wir im Folgenden , wie man Java Memory Architektur überwachen kann.

Überwachung der Java Memory Architektur

Die Java Plattform bringt eine Reihe von Werkzeugen mit, um die Java Memory Architektur zu überwachen. Das einfachste Werkzeug ist das  Konsolen-Programm jmap. jmap gibt dem Benutzer textuelle Informationen über die verfügbaren JVM Speicherbereiche auf der Konsole aus, wie Young Generation und Old Generation. Das folgende Listing zeigt den Aufruf, den man in der Konsole ausführen muss, um sich Information über den Java-Heap mit jmap anzeigen zu lassen. Zunächst muss man mit dem Konsolenprogramm jps die Prozess-ID des Java Prozesses ermitteln, den man überwachen möchte. Dann kann man mit der herausgefundenen Prozess-ID und dem Parameter -heap das Programm jmap aufrufen und erhält Informationen über den verfügbaren Speicher:

bernd@mbp ~ $ jps
7409 Runner
25297 Jps
bernd@mbp ~ $ jmap -heap 7409
...
Heap Usage:
PS Young Generation
Eden Space:
   capacity = 60817408 (58.0MB)
   used     = 24817576 (23.667884826660156MB)
   free     = 35999832 (34.332115173339844MB)
   40.80669797700027% used
...
13008 interned Strings occupying 1759648 bytes.

Natürlich gibt es auch grafische Werzeuge, um die Java Memory Architektur zu überwachen. Im Folgenden werden die beiden Tools JConsole und VisualVM kurz vorgestellt.

JConsole ist eine Swing-Applikation, die seit Java Version 1.5 mit dem JDK mitgeliefert wird und  zur Überwachung von Java Prozessen via JMX auf lokalen oder entfernten Systemen dient. JMX steht für Java Management Extension und ist eine Weiterentwicklung eines Java Standards, der auch die Kommunikation zwischen unterschiedlichen Java Prozessen ermöglicht.

Last login: Wed Apr 30 19:51:45 on ttys000
bernd@mbp ~ $ jconsole

Nach dem Start von JConsole auf der Kommandozeile erscheinen  im einem Startscreen alle lokalen Java-Prozesse, diese können mit einem Doppelklick überwacht werden. Für das Monitoring entfernter JVM’s muss auf dem Zielsystem der entsprechende RMI-Zugriff aktiviert sein.

JConsole Startbildschirm
Abbildung 3: JConsole Startbildschirm
Abbildung 4: JConsole Überschicht
Abbildung 4: JConsole Überschicht
Abbildung 5: JConsole Speicherübersicht
Abbildung 5: JConsole Speicherübersicht
Last login: Thu May  1 10:08:40 on ttys003
bernd@mbp ~ $ jvisualvm

VisualVM ist ein weiteres grafisches Werkzeug mit einfachen Profiling-Möglichkeiten, dass auch über eine grafischen Oberfläche für das JDK-Tool jstack verfügt, mit dem Threaddumps erstellen werden können. VisualVM ist Bestandteil des JDK 6. Innerhalb der JDK heißt VisualVM allerdings Java VisualVM und kann mit dem Befehl jvisualvm in der Kommandozeile aufgerufen werden. Die aktuelle Version von VisualVM findet sich auf der Webseite und kann getrennt von der JVM installiert werden.

JVisualVM-Speicherübersicht
Abbildung 6: JVisualVM Speicherübersicht

Da wir nun wissen, wie wir die JVM überwachen können, sollten wir als Nächstes betrachten, welche Arten der Ausnahme java.lang.OutOfMemoryError auftreten können.

Arten von OutOfMemoryError

Ein Speicherüberlauf tritt immer dann auf, wenn der Garbage Collector keinen Speicher mehr deallokieren kann, um eine Speicheranfrage für das Instanzieren eines neuen Objekts zu erfüllen. Ein solcher Fehler führt zu einem java.lang.OutMemoryError, der sich in einer der folgenden textuelle Beschreibung äußert:

OutOfMemoryErrorBedeutung
Java heap spaceDer Garbage Collector kann keinen Speicher mehr freimachen, um eine Speicheranfrage für ein neues Objekt zu erfüllen.
Requested array size exceeds Es wird versucht ein Array auf dem Heap anzulegen, das größer ist als der Heap selber.
PermGen spaceEs steht nicht genug Speicher zur Verfügung, um Klassen Informationen im Method Area abzulegen oder der Code Cache vollläuft.
unable to create new native threadEs existieren zu viele Threads innerhalb der JVM. Es steht nicht mehr genug Speicher zur Verfügung , um einen neuen nativen Thread anzulegen.
request bytes for . Out of swap space? Der Heap muss erweitert werden, aber auf Betriebssystem Seite steht nicht mehr genügend Speicher zur Verfügung.
GC overhead limit exceededDer Garbage-Collector ist überdimensional oft und zu lange aktiv, so dass das eigentliche Programm nicht mehr vorankommt.

Nachdem nun die unterschiedlichen OutMemoryErrors kurz vorgestellt worden, wird im Folgenden genauer betrachtet, wie ein solcher Fehler entsteht und wie man ihn aufspüren kann.

Java Memory Leaks

Alle Objekte werden auf dem Heap erzeugt. Die Lebensdauer eines Objekts auf dem Heap ist abhängig davon, ob das Objekt von einem anderen Objekt referenziert wird. Der Garbage Collector prüft, wenn bestimmte Schwellwerte überschritten werden, ob ein Objekt noch referenziert ist. Sollte ein Objekt nicht mehr referenziert sein, wird das Objekt vom Garbage Collector als „Müll“ markiert und in einem späteren Schritt aufgeräumt und dessen Speicher freigegeben.

Sogenannte Garbage Collector Root (GC Root) Referenzen sind für das Überleben eines Objekts entscheidend. Ein GC Root ist ein Objekt, auf das es keine eingehenden Referenzen gibt. GC Roots sind verantwortlich dafür, dass referenzierte Objekte im Speicher gehalten werden. Wird weder direkt noch indirekt von einem GC Root referenziert, wird ein Objekt es als “unreachable” gekennzeichnet und zur Garbage Collection freigegeben. Man kann die folgenden Arten von Garbage Collection Roots unterscheiden:

  • Temporäre Variablen auf dem Stack eines Threads
  • Statische Felder von Klassen
  • Spezielle native Referenzen in JNI

GC Root lassen sich am besten anhand eines konkreten Code-Beispiels verdeutlichen:

public class MyPage extends org.apache.wicket.markup.html.WebPage {

  //Die Liste ist erreichbar,
  //wenn die Klasse geladen ist
  public static final List STATIC = new ArrayList();

  //Die Liste ist erreichbar,
  //solange eine Instanz der Seite existiert
  private final List instance = new ArrayList()

  //Die Liste ist erreichbar,
  //solange die Methode ausgeführt wird
  //auch wenn die Liste nicht benutzt wird
  private void myMethod(List parameter) {
    
    //solange die Methode ausgeführt wird
    //ist die List von Stack erreichbar
    List local = new ArrayList();
  }

}

GC Root Objekte sind für die folgenden OutOfMemoryError Problemen verantwortlich:

  • Objekte, die nie mehr im Anwendungscode genutzt werden, aber noch eine GC Root Referenz haben, verursachen Java Memory Leaks, da diese Objekte nicht vom Carbage Collector aufgeräumt werden können.
  • Durch die Verwendung von großen Objektbäume, die im Speicher gehalten werden (z.B. Caches), kann es dazu kommen, dass nicht genug Heap zu Verfügung steht. Dann muss der Speicher für die Applikation erhöht werden.
  • Zu viele temporäre Objekte, die dazu führen, dass temporär bei der Verarbeitung im Java-Code zu viel Speicher benötigt wird.

Java Memory Leaks entstehen immer dann, wenn ein Objekt noch eine GC Root Referenz hat, aber nicht mehr in der Anwendung benutzt wird. Solche Objekte werden „Loitering Objects“ genannt. Loitering Objects belegen für die komplette Ausführungsdauer den JVM Speicher. Durch solche „Objekt-Leichen“  wird der Anwendungsspeicher nicht mehr ausreichen und es kommt zu einem OutOfMemoryError. Häufig wird ein OutOfMemoryError von statischen Collections ausgelöst.  Dann werden Objekte der Collection hinzugefügt, aber nicht wieder gelöscht. Die hinzugefügten Objekte werden durch die statischen Collection-Einträge referenziert und können aufgrund der GC Root Referenz (statisch) nicht mehr freigegeben werden.

Abbildung 6 - Dominatoren
Abbildung 7 – Dominatoren

Im Zusammenhang mit Java Memory Leaks wird weiterhin oft von sogenannten Dominatoren und Dominatorbäumen gesprochen. Bei  Dominatoren handelt es sich, um ein Konzept aus der Graphentheorie.  Ein Dominator ist ein Knoten, durch den ein kompletter Teilgraph erreichbar ist. Auf das Speichermanagement umgesetzt, heißt das, dass  ein Objekt A ein Dominator eines anderen Objekts B ist, wenn es kein weiteres Objekt C gibt, das eine Referenz auf B hält. Wird also die Wurzelreferenz freigegeben, wird auch der ganze Dominatorbaum freigeben. Sehr große Dominatorenbäume sind also sehr gute potenzielle Kandidaten bei der Memory Leak Suche.

Die Memory Leak Suche beginnt mit dem Erstellen eines Heapdump. Im Folgenden werden zunächst Möglichkeiten vorgestellt, um einen Heapdump zu erstellen.

Java Heapdump

Ein Heapdump ist eine textuelle oder binäre Abbildung des Java Heaps. Aus den Informationen, die in einem Heapdump enthalten sind, lassen sich mit verschiedenen Werkzeugen die gesamten Objekte, die von einer Applikation erzeugt werden, rekonstruieren. Außerdem sind alle Referenzen zwischen den Objekten in einem Heapdump enthalten. Ein Heapdump kann im Fehlerfall durch die JVM  Option -XX:+HeapDumpOnOutOfMemoryError beim Auftreten eines OutOfMemoryErrors  automatisch erzeugen werden. Heapdumps enthalten meistens die folgenden Arten von Objekten:

  • lebendige Objekte, das sind Objekte, die über eine GC Root Referenz erreichbar sind
  • Alle nicht mehr referenzierten Objekte

Alternativ zur JVM Option kann ein Heapdump mit dem Konsolen-Werkzeug jmap erstellt werden, das wir bereits zur Überwachung der JVM kennengelernt haben. Das folgende Listing zeigt, wie man einen Heapdump über die Konsole erstellen kann.

bernd@mbp ~ $ jps
16497 AppMain
16520 Jps
bernd@mbp ~ $ jmap -dump:live,format=b,file=dump.hprof 16497
Dumping heap to /Users/berndzuther/dump.hprof ...
Heap dump file created

Natürlich gibt es auch ein grafische Werkzeug, wie z.B. VisualVM, mit dem man auch einen Heapdump erstellen kann.

VisualVM Heapdump
Abbildung 8: VisualVM Heapdump

Nachdem wir nun einen Heapdump erzeugen können, können wir beginnen den Heapdump zu analysieren. Dazu stehen uns die folgenden Tools zur Verfügung.

Heapdump Analyse

Das JDK 1.6 bringt ein kleines Tool mit Namen jhat (Java Heap Analysis Tool) zur Analyse von Heapdumps mit. jhat startet einen lokalen Webserver. Der Heapdump kann unter Verwendung der Defaulteinstellungen über die Adresse http://localhost:7000 analysiert werden. Das Tool stellt aber leider nur sehr rudimentäre Funktionen zur Auswertung des Heapdumps zur Verfügung und ist es nicht sehr gut zu bedienen.

bernd@mbp ~ $ jhat -J-mx2000m dump.hprof
Reading from dump.hprof...
Dump file created Fri May 02 18:37:18 CEST 2014
Snapshot read, resolving...
Resolving 2013119 objects...

Ein schönes Werkzeug für die Analyse von Heapdumps ist der  Memory Analyzer (MAT), der in der Lage ist sehr große Heapdumps zu verarbeiten. Ältere Tools haben oft das Problem, dass der Heapdump zur Analyse komplett in den Arbeitsspeicher geladen werden muss und man i.d.R. das 1,5-fache des Heaps zur Analyse benötigt. D.h. ein Heap von 2GB Größe benötigte 3 GB Heap zur Analyse. Der Memory Analyzer indiziert zunächst einen Heapdump, um hinterher in vertretbarer Zeit und mit verkraftbarem Speicherverbrauch eine Analyse auf dem Dump ermöglichen zu können.

Memory Analyzer
Abbildung 9: Memory Analyzer

Der Memory Analyzer analysiert die Referenzbeziehungen zwischen Objekten auf dem Heap und erzeugt daraus  Dominatorbäume. Außerdem sucht der Memory Analyzer die Dominatoren im Heap (diese werden im MAT Akkumulierungspunkte genannt) heraus. Die Dominatoren erhalten große Mengen Speicher am Leben und werden als „Suspect Report“ dargestellt, wie es in Abbildung 9 zu sehen ist.

Memory Analyzer OGL
Abbildung 10: Memory Analyzer OGL

Um Objekte in einem Heapdump abzufragen, gibt es die sogenannte Object Query Language (OQL). OQL führt bei Abfragen zu mehr Flexibilität und ermöglicht es Objekte nach bestimmten Kriterien zu filtern. Dazu benutzt OQL die JavaScript Expression Language.

Eine OQL Anfrage hat die folgende Struktur:

select 
         [ from [instanceof]  
         [ where  ] ]

--selektiert alle Strings, die mehr als 100 Zeichen haben
select s from java.lang.String s where s.count >= 100

--selektiert alle int arrays mit mehr als 256 Elementen
select a from int[] a where a.length >= 256

Im nächten Schritt führen wir eine Java Heap Analyse mit dem Memory Analyzer an einem konkreten Beispiel aus.

Online Shop – Beispiel Heapdump-Analyse

Die Firma comSysto hat im Rahmen des Meetup Boost your Java Enterprise Stack with MongoDB einen Onlineshop in seinen Github Repository veröffentlicht. Das folgende Youtube-Video zeigt, über welche Funktionalität dieser Onlineshop verfügt und gibt eine kleine Einführung in den Onlineshop.

[youtube http://www.youtube.com/watch?v=uJpFp9qR4Z4&rel=0&hd=1]

Im Folgenden verwenden wir einen Fork dieses Onlineshop, um eine Memory Leak Analyse durchzuführen. Diesen Fork kann man in meinem Github Repository auschecken.  Das folgende Listing zeigt, was dazu zu tun ist:

bernd@mbp ~ $ git clone https://github.com/zutherb/memory-leak-detection.git
Cloning into 'memory-leak-detection'...
remote: Counting objects: 1231, done.
remote: Compressing objects: 100% (632/632), done.
remote: Total 1231 (delta 211), reused 1231 (delta 211)
Receiving objects: 100% (1231/1231), 5.72 MiB | 1.56 MiB/s, done.
Resolving deltas: 100% (211/211), done.
Checking connectivity... done.
bernd@mbp ~ $ cd memory-leak-detection
bernd@mbp ~/memory-leak-detection (master)$ git branch -r
  origin/HEAD -> origin/master
  origin/master
  origin/memory-leak-fix

Manchen wir uns im nächsten Schritt mit dem Repository vertraut. Das Repository verfügt über zwei Branches. Der master-Branch ist mit einem Memory Leak präpariert und im memory-leak-fix-Branch befindet sich der Onlineshop in einer  Memory Leak freien Version.

Gitk - Memory Leak Detection Repository
Abbildung 11: Gitk – Memory Leak Detection Repository

Nachdem wir nun den Aufbau des Repository kennen, können wir uns mit dem Onlineshop selbst vertraut machen. Der Onlineshop basiert auf Java 8. Um den Onlineshop bauen und starten zu können, muss also auch Java 8 auf dem Rechner installiert sein und das entsprechende Java_Home als Umgebungsvariable eingestellt sein. Als Buildtool wird Gradle verwendet, das schon aus dem Artikel „Gradle: Erstellen von einem Java Application Bundle unter Mac OS X“ bekannt ist. Gradle ist ein auf Groovy und Java basierendes Build-Management-Automatisierungs-Tool, dass vergleichbar mit Apache Ant und Apache Maven ist. Gradle nutzt jedoch im Gegensatz zu Maven und Ant eine auf Groovy basierende domänenspezifische Sprache (DSL) zur Beschreibung der zu bauenden Projekte. Gradle muss nicht auf dem Rechner installiert sein, man kann den sogenannten Gradle-Wrapper benutzen, der sich im Wurzel-Verzeichnis des Projektes befindet. Um das Projekt zu bauen und die Anwendung zu starten. Hierzu nutzen wir den Task jettyRun im Projekt shop/ui. Nach einer Weile startet der Onlineshop auf der Url http://localhost:8080/pizza. Das folgende Listing zeigt, wie man unter MacOSX das JAVA_HOME für Java 8 setzen kann  (VORRAUSSETZUNG: Java 8 ist installiert) und den Onlineshop startet:

bernd@mbp ~/mld $ export JAVA_HOME="${/usr/libexec/java_home -v 1.8}"
bernd@mbp ~/mld (master)$ ./gradlew -p shop/ui/ jettyRun

Die Katalog-Seite des Onlineshop ist mit einem Memory Leak präpariert. Dieser äußert sind in einem OutOfMemoryError: Java Heap Space, wenn man die Katalog-Seite oft genug aufruft.  Um nicht ständig die Katalog-Seite http://localhost:8080/pizza/productcatalog/pizza per Hand aufrufen zu müssen, befindet sich im Verzeichnis external  die Datei loadtest.jmx. Diese Datei kann man mit dem Programm Apache JMeter ausführen. JMeter ist ein freies, in Java geschriebenes Werkzeug zum Ausführen von Lasttests in Client/Server-Anwendungen. JMeter ermöglicht es durch das  Zusammenstellen eines Testplanes zu spezifizieren, welche Teile der Anwendung durchlaufen werden sollen, um konkrete Ergebnisse über das Antwortzeitverhalten zu bekommen.

JMeter - Lasttest
Abbildung 12: JMeter – Lasttest

Öffnen wir  JMeter und führen die Datei loadtest.jmx gegen den laufenden Shop aus, in dem wir auf den grünen Play-Button unterhalb der Menü-Liste in JMeter klicken. Nach einiger Zeit kommt es zu einem OutOfMemoryError: Java heap space.

Error for /pizza/productcatalog/pizza
java.lang.OutOfMemoryError: Java heap space

Jetzt ist der Moment erreicht, in dem wir einen Heapdump erstellen sollen. Das folgende Listing zeigt, wie wir mittels jps die Prozess-ID des laufenden Onlineshops herausfinden können, um einen Heapdump erstellen zu können. Denn ersten jps Aufruf sollte man machen bevor, man mit Gradle den Onlineshop startet. In der Regel ist aber die höchste Prozess-ID des GradleDaemon auch die Prozess-ID des laufenden Onlineshops.

bernd@mbp ~/memory-leak-detection (master)$ jps
6097 
535 WrapperSimpleApp
4509 GradleDaemon
6404 Jps
bernd@mbp ~/memory-leak-detection (master)$ jps
6097 
535 WrapperSimpleApp
6451 GradleDaemon
4509 GradleDaemon
6481 Jps
6441 GradleWrapperMain
bernd@mbp ~/memory-leak-detection (master)$ jmap -dump:live,format=b,file=dump.hprof 6451
Dumping heap to /Users/berndzuther/memory-leak-detection/dump.hprof ...
Heap dump file created

Natürlich kann man den Onlineshop auf während des Lasttests mit VisualVM überwachen. Dann kann man dabei zu gucken, wie der Heap Speicher vollläuft, wie es in Abbildung 13 zusehen ist.

VisualVM - Lasttest
Abbildung 13: VisualVM – Lasttest

Wenn wir den Dump nun in den Memory Analyzer laden und einen Suspect Report erstellen, warnt uns der Memory Analyzer vor einem potentiellen Memory Leak in der Klasse ProductCatalogPage.

Memory Analyzer - Suspect Report
Abbildung 14: Memory Analyzer – Suspect Report

In unserem Beispiel wird eine ArrayList als Hauptverdächtiger präsentiert.  Durch das verdächtige Objekt wird circa die Hälfte, des Speichers verbraucht, der der Anwendung zur Verfügung steht. Als nächstes kann man sich eine detailliere Beschreibung ausgeben lassen, in dem man auf Details klickt. In dieser Ansicht sieht man, was die verdächtige ArrayList enthält und wer die ArrayList referenziert.  Auch diese Information ist im Memory Analyzer gut aufbereitet:

Memory Analyzer - Suspect Report Detail
Abbildung 15: Memory Analyzer – Accumulation Point

In der Accumulation Point Ansicht des Suspect Report sieht man, das die Klasse ProductCatalogPage eine Variable memoryLeak  enthält, die die verdächtige  ArrayList referenziert. Ein Blick in den Quellcode verrät uns, dass es sich dabei um eine statische Variable handelt, die bei jeden rendern des Produkt-Katalogs immer wieder alle Elemente im Katalog in sich und sich danach selbst kopiert. Wenn man die Liste entfernt, kann man den Lasttest ausführen, ohne das es zu einem OutOfMemoryError kommt. Damit haben wir das Memory Leak in der Applikation gefunden und beseitigt.

@MountPath("productcatalog/${type}")
@EnumProductTypeNavigationItem(enumClazz = ProductType.class, defaultEnum = "PIZZA", sortOrder = 2)
public class ProductCatalogPage extends AbstractBasePage {

    @SpringBean(name = "productService")
    private ProductService productService;

    private IModel productTypeModel;
    private IModel productListModel;
    private Component basketPanel;

    private static List memoryLeak = new ArrayList();
    ...
    private Component productView() {
        return new DataView("products", productDataProvider()) {

            @Override
            protected void populateItem(final Item item) {
                memoryLeak.add(item.getModelObject());
                memoryLeak.addAll(new ArrayList<>(memoryLeak));
                ...
            }
        };
    }
    ...
}

Auch in Dominatorbaum Ansicht, die in Abbildung 15 dargestellt wird, sieht man, dass es sich bei der ArrayList, um einen potenziellen Kandidaten für einen Memory-Leak handelt.

Memory Analyzer - Dominatorbaum
Abbildung 16: Memory Analyzer – Dominatorbaum

Zusammenfassung

In diesem Artikel haben wir die Suche nach Memory Leaks mit Hilfe eines Heapdumps betrachtet. Ein Heapdump kann z.B. mit dem Konsolen-Programm jmap oder über eine JVM Option im Fehlerfall erstellt werden.

Eine Heapdumps Analyse wird oft post mortem durchgeführt, nachdem die Anwendung bereits wegen einem OutOfMemoryError abgebrochen wurde. Für eine  Heapdump-Analyse, kann das frei verfügbare Werkzeug Memory Analyzer MAT verwendet werden, das einen potentielle Kandidaten für einen Memory Leak vorschlägt. Sehr große Dominatorenbäume sind auch sehr gute potenzielle Kandidaten bei der Memory-Leak-Suche.

—————————————————-

Ich danke Daniel Mitterdorfer für die vielen Anregungen und Ideen zu diesem Artikel. Daniel Mitterdorfer ist ein Software Engineer und Mitglied der Application Performance guild bei der comSysto GmbH.

Share Button