Herumlungernde Objekte bringen Webunternehmen Geld ein

Von Jeroen Borgers Kürzlich wurde ich von einem Unternehmen angerufen, das Probleme mit seiner Website hatte. Und da sie ihr ganzes Geld online verdienen, war es offensichtlich, dass sie das Problem unbedingt gelöst haben wollten. An dem Tag, an dem ich kam, war die Website in den letzten 24 Stunden etwa 5 Mal ausgefallen. Das hatte zur Folge, dass sie weniger Besucher hatten, was wiederum weniger Einnahmen bedeutete. Die Protokolldateien zeigten lange Antwortzeiten und OutOfMemoryErrors. Die Fragen lauteten: Warum tritt dieses Verhalten auf? und Wie können wir es beheben? Meine kurze Antwort lautete: wegen zu vieler herumlungernder Objekte. Das lässt sich beheben, indem man sie nicht in der HTTP-Sitzung festhält. Ich werde es Ihnen erklären. Fehlerbehebungsauftrag Wie so oft bei dieser Art von Fehlerbehebungsaufträgen haben Sie das Problem fast schon gelöst, wenn Sie erst einmal herausgefunden haben, was genau falsch ist. Die Schwierigkeit liegt in der detektivischen Arbeit, um die Ursache zu finden. Oder anders ausgedrückt, die Nadel im Heuhaufen zu finden. VisualVM Das Tool, das sie bereits verwendet haben und das für mich eigentlich neu war, war VisualVM.

Abbildung 1. VisualVM Über das Fenster Ähnlich wie die jconsole von jdk können Sie einen Blick in die JVM werfen. Es verfügt über eine Plugin-Architektur, bei der z.B. Teile von jconsole in visualVm integriert werden, um Heap- und Thread-Nutzung, geladene Klassen und MBeans anzuzeigen. Für einen geringeren Overhead als jconsole verfügt es jedoch über weniger Details in Bereichen wie Heap. Außerdem verfügt es über ein Profiler-Plugin, den Netbeans-Profiler. Damit können Sie lokale Anwendungen mit einem CPU- oder Speicherprofil versehen. Und seit der aktuellen Version 1.6.0_07 ist dieses großartige Tool auch im JDK enthalten. Falls Sie es im JDK nicht finden können: Es wurde in jvisualvm umbenannt.

Abbildung 2. VisualVM Monitor Beispiel VisualVM half uns, da wir in den generierten Stack-Dumps sehen konnten, dass Threads oft auf eine log4j-Sperre warteten. Der Grund dafür war, dass die Protokollstufe auf DEBUG eingestellt war. Die Einstellung auf INFO verbesserte die Leistung etwas. In diesem Fall lieferte mir visualVM jedoch nicht die entscheidenden Fakten. Der Grund dafür war ein doppelter. Der erste war der von mir erwähnte Mangel an Details und der zweite war die Art des Tools, da man Zeuge der Problemsituation sein muss, um sie analysieren zu können. Finden der entscheidenden Informationen Das Toolset, das mir die erste Hälfte der entscheidenden Informationen lieferte, war das Flag -Xloggc:gc.log in Kombination mit HPJmeter. Dies gibt die Möglichkeit, nach den Fakten zu analysieren. In dieser Nacht war der Datenverkehr eher gering und die Website fiel nicht aus, aber sie war während einiger Stunden sehr langsam. Am nächsten Tag zeigte die Protokolldatei den Zeitpunkt, an dem die Leistung schlecht wurde: 15045.703: [GC 1786342K->1481712K(1856512K), 0.1639990 secs] 15053.886: [GC 1790320K->1489985K(1858880K), 0.1722250 secs] 15065.930: [GC 1800257K->1493876K(1859968K), 0.1601460 secs] 15066.090: [Full GC 1493876K->1467212K(1859968K), 3.5031310 secs] 15071.966: [Full GC 1708415K->1471029K(1859968K), 3.5039160 secs] 15078.215: [Full GC 1708277K->1476287K(1859968K), 3.5326720 secs] 15087.847: [Full GC 1708386K->1408698K(1859968K), 4.5038550 secs] Wir sehen hier den Übergang von hauptsächlich GC's (Young Space) zu hauptsächlich Full GC's, also von kurzen Pausen zu langen Pausen. Eigentlich alle 6 Sekunden oder so, und eine Sammlung dauert 3,5 s. Es wird also eine Menge Zeit in GC verbracht. Wie Sie sehen können, wird jedoch noch etwas Speicher zurückgewonnen. Mit HPJMeter konnte ich dies in schönen Grafiken sehen, um Schlussfolgerungen zu ziehen:

Abbildung 3. HPJmeter zeigt den prozentualen Anteil der für GC aufgewendeten Zeit an. So wurde mir klar, dass die Website so langsam war, weil bis zu 95% der CPU-Zyklen für die Garbage Collection aufgewendet wurden und nur 5% für die Anwendung selbst übrig blieben. Ich brauche mehr Details Was aber der Grund für diesen übermäßigen gc war, war mir noch nicht klar. Ich brauchte mehr Details über die Speichernutzung. Also schalteten wir das Flag -XX:+PrintGCDetails ein, das uns die zweite Hälfte der entscheidenden Informationen lieferte. Leider konnte HPJMeter mit dem erzeugten Protokollformat nicht umgehen, aber wir erhielten Zeilen am Anfang der Probleme wie: 21270.421: [GC [PSYoungGen: 436938K->112249K(481664K)] 1808785K->1489945K(1879808K), 0.1790760 secs] 21277.559: [GC [PSYoungGen: 443385K->111206K(486528K)] 1821081K->1497781K(1884672K), 0.1815330 secs] 21284.659: [GC [PSYoungGen: 442406K->107401K(489536K)] 1828981K->1504035K(1887680K), 0.1780120 secs] 21284.837: [Full GC [PSYoungGen: 107401K->79553K(489536K)] [PSOldGen: 1396634K->1398143K(1398144K)] 1504035K->1477697K(1887680K) [PSPermGen: 79038K->79038K(262144K)], 3.5320210 secs] 21292.969: [Full GC [PSYoungGen: 331200K->83102K(489536K)] [PSOldGen: 1398143K->1398143K(1398144K)] 1729343K->1481246K(1887680K) [PSPermGen: 79047K->79047K(262144K)], 3.5302490 secs] 21302.663: [Full GC [PSYoungGen: 331200K->85665K(489536K)] [PSOldGen: 1398143K->1398143K(1398144K)] 1729343K->1483809K(1887680K) [PSPermGen: 79055K->79055K(262144K)], 3.4508870 secs] 21311.177: [Full GC [PSYoungGen: 330681K->21303K(489536K)] [PSOldGen: 1398143K->1398144K(1398144K)] 1728825K->1419447K(1887680K) [PSPermGen: 79065K->79027K(262144K)], 4.4884740 secs] Auch hier sehen wir den Fall-over. Schauen Sie sich den alten Speicherplatz an: Die erste vollständige GC verschiebt Objekte aus dem jungen in den alten Speicher, so dass dieser fast voll ist. In den vollständigen GC-Zeilen ist nur noch 1K oder weniger ungenutzter Speicherplatz zu sehen. Die Verwirrung entsteht durch die Nutzung des jungen Speicherplatzes, wo der meiste Müll noch gesammelt werden kann. Dadurch ist der gesamte Heap nicht voll, während der alte Speicherplatz an seine Grenzen stößt. Einige Dinge bleiben also im alten Speicherplatz stecken. Das Bemerkenswerte ist, dass sich die Situation nach etwa einer Stunde erholt und ein OOME nicht auftritt. Heap-Analysen mit Netbeans So, jetzt ist es an der Zeit, weitere Heap-Analysen durchzuführen. Netbeans verfügt über einen großartigen integrierten Profiler mit einem nützlichen Heap-Analysator. Wir haben festgestellt, dass der meiste Speicher von Kategorieobjekten verwendet wurde, die nicht als solche vorgesehen waren. Mit dem Heap Walker konnten wir feststellen, dass die meisten Verweise darauf von Tomcat-Sitzungsobjekten gehalten wurden. Jede HTTP-Sitzung hatte also ihre eigene Kopie dieser Kategorien und sie blieben eine halbe Stunde lang hängen: der Standard-Timeout für HTTP-Sitzungen. Der Begriff für diese Art von Objekten lautet: loitering objects. Die schnelle und die wirkliche Lösung An diesem Punkt konnten wir eine schnelle Lösung finden: die Zeitüberschreitung für HTTP-Sitzungen von 30 auf 5 Minuten verringern. Das verringerte den größten Druck auf uns Fixer und verschaffte uns etwas Luft zum Atmen. Dann erstellten wir einige Tests und konnten das Verhalten in einer Testumgebung reproduzieren. Ein Blick auf jconsole zeigte auch deutlich den zunehmenden Verbrauch von altem Speicherplatz.

Abbildung 4. JConsole zeigt die Speichernutzung für die einzelnen Speicherpools an. Im Quellcode konnten wir leicht die Stelle finden, an der alle Kategorieobjekte aus der Datenbank geladen, einmal in einen Cache gelegt und nebenbei auch eine Kopie in jede Benutzer-HTTP-Sitzung gelegt wurden. Eigentlich ohne Grund. Und bei 1700 Benutzersitzungen beanspruchte dies den größten Teil des Speichers. Es war also ein Kinderspiel, dieses Problem im Code zu lösen. Und nach der Bereitstellung und dem Zurücksetzen des Sitzungs-Timeouts auf die Standardeinstellung von 30 Minuten waren die Probleme gelöst. Ich liebe es, wenn ein Plan aufgeht. Erfahren Sie mehr Wenn Sie mehr über dieses Thema erfahren und praktische Erfahrungen sammeln möchten, kommen Sie zu meinem Kurs "Beschleunigung von Java-Anwendungen" im April oder November 2009.