Diagnostizieren Sie häufige Laufzeitprobleme mit hprof

Speicherlecks und Deadlocks und CPU-Probleme, oh mein Gott! Entwickler von Java-Anwendungen sind häufig mit diesen Laufzeitproblemen konfrontiert. Sie können in einer komplexen Anwendung mit mehreren Threads, die Hunderttausende von Codezeilen durchlaufen, besonders entmutigend sein - eine Anwendung, die Sie nicht versenden können, weil sie im Speicher wächst, inaktiv wird oder mehr CPU-Zyklen verschlingt, als sie sollte.

Es ist kein Geheimnis, dass Java-Profiling-Tools einen langen Weg zurückgelegt haben, um ihre Gegenstücke in einer anderen Sprache einzuholen. Es gibt jetzt viele leistungsstarke Tools, mit denen wir die Schuldigen hinter diesen häufigen Problemen aufspüren können. Aber wie entwickeln Sie Vertrauen in Ihre Fähigkeit, diese Tools effektiv einzusetzen? Schließlich verwenden Sie die Tools, um komplexes Verhalten zu diagnostizieren, das Sie nicht verstehen. Um Ihre Notlage zu verschärfen, sind die von den Tools bereitgestellten Daten relativ komplex und die Informationen, die Sie suchen oder suchen, sind nicht immer klar.

Als ich in meiner früheren Inkarnation als Experimentalphysiker mit ähnlichen Problemen konfrontiert war, erstellte ich Kontrollexperimente mit vorhersehbaren Ergebnissen. Dies hat mir geholfen, Vertrauen in das Messsystem zu gewinnen, das ich in Experimenten verwendet habe, die weniger vorhersehbare Ergebnisse lieferten. In ähnlicher Weise verwendet dieser Artikel das hprof-Profiling-Tool, um drei einfache Steuerungsanwendungen zu untersuchen, die die drei oben aufgeführten allgemeinen Problemverhalten aufweisen. Obwohl hprof nicht so benutzerfreundlich ist wie einige kommerzielle Tools auf dem Markt, ist es im Java 2 JDK enthalten und kann, wie ich zeigen werde, diese Verhaltensweisen effektiv diagnostizieren.

Laufen Sie mit hprof

Das Ausführen Ihres Programms mit hprof ist einfach. Rufen Sie einfach die Java-Laufzeit mit der folgenden Befehlszeilenoption auf, wie in der Dokumentation zum JDK-Tool für den Java Application Launcher beschrieben:

java -Xrunhprof [: help] [: =, ...] MyMainClass 

Eine Liste der Unteroptionen ist mit der [:help]angezeigten Option verfügbar . Ich habe die Beispiele in diesem Artikel über den Blackdown-Port des JDK 1.3-RC1 für Linux mit dem folgenden Startbefehl generiert:

java -classic -Xrunhprof: heap = sites, cpu = samples, tiefe = 10, monitor = y, thread = y, doe = y MemoryLeak 

In der folgenden Liste wird die Funktion jeder im vorherigen Befehl verwendeten Unteroption erläutert:

  • heap=sites: Weist hprof an, Stapelspuren zu generieren, die angeben, wo Speicher zugewiesen wurde
  • cpu=samples: Weist hprof an, statistische Stichproben zu verwenden, um festzustellen, wo die CPU ihre Zeit verbringt
  • depth=10: Weist hprof an, Stapelspuren mit einer Tiefe von höchstens 10 Ebenen anzuzeigen
  • monitor=y: Weist hprof an, Informationen zu Konfliktmonitoren zu generieren, mit denen die Arbeit mehrerer Threads synchronisiert wird
  • thread=y: Weist hprof an, Threads in Stapelspuren zu identifizieren
  • doe=y: Weist hprof an, beim Beenden einen Speicherauszug mit Profildaten zu erstellen

Wenn Sie JDK 1.3 verwenden, müssen Sie den Standard-HotSpot-Compiler mit dieser -classicOption deaktivieren . HotSpot verfügt über einen eigenen Profiler, der über eine -XprofOption aufgerufen wird und ein anderes Ausgabeformat verwendet als das hier beschriebene.

Wenn Sie Ihr Programm mit hprof ausführen, bleibt eine Datei java.hprof.txtin Ihrem Arbeitsverzeichnis. Diese Datei enthält die Profilinformationen, die während der Ausführung Ihres Programms gesammelt wurden. Sie können auch jederzeit während der Ausführung Ihres Programms einen Speicherauszug erstellen, indem Sie unter Unix in Ihrem Java-Konsolenfenster Strg- \ oder unter Windows Strg-Pause drücken.

Anatomie einer hprof-Ausgabedatei

Eine hprof-Ausgabedatei enthält Abschnitte, in denen verschiedene Merkmale des profilierten Java-Programms beschrieben werden. Es beginnt mit einem Header, der sein Format beschreibt. Änderungen am Header können ohne vorherige Ankündigung vorgenommen werden.

In den Abschnitten Thread und Trace der Ausgabedatei können Sie herausfinden, welche Threads bei der Ausführung Ihres Programms aktiv waren und was sie getan haben. Der Abschnitt Thread enthält eine Liste aller Threads, die während der Programmlaufzeit gestartet und beendet wurden. Der Abschnitt Trace enthält eine Liste nummerierter Stack-Traces für einige Threads. Diese Stack-Trace-Nummern werden in anderen Dateibereichen referenziert.

In den Abschnitten Heap Dump und Sites können Sie die Speichernutzung analysieren. Abhängig von der heapUnteroption, die Sie beim Starten der virtuellen Maschine (VM) auswählen, können Sie einen Speicherauszug aller Live-Objekte im Java-Heap ( heap=dump) und / oder eine sortierte Liste von Zuordnungssites abrufen, die die am stärksten zugewiesenen Objekte ( heap=sites) identifiziert .

Die Abschnitte CPU-Beispiele und CPU-Zeit helfen Ihnen, die CPU-Auslastung zu verstehen. Der Abschnitt, den Sie erhalten, hängt von Ihrer cpuUnteroption ( cpu=samplesoder cpu=time) ab. CPU Samples bietet ein statistisches Ausführungsprofil. Die CPU-Zeit enthält Messungen, wie oft eine bestimmte Methode aufgerufen wurde und wie lange die Ausführung jeder Methode gedauert hat.

In den Abschnitten Monitor Time und Monitor Dump erfahren Sie, wie sich die Synchronisierung auf die Leistung Ihres Programms auswirkt. Die Überwachungszeit zeigt an, wie lange Ihre Threads um gesperrte Ressourcen konkurrieren. Monitor Dump ist eine Momentaufnahme der derzeit verwendeten Monitore. Wie Sie sehen werden, ist Monitor Dump nützlich, um Deadlocks zu finden.

Diagnose eines Speicherverlusts

In Java definiere ich einen Speicherverlust als (normalerweise) unbeabsichtigten Fehler bei der Dereferenzierung verworfener Objekte, sodass der Garbage Collector den von ihnen verwendeten Speicher nicht zurückfordern kann. Das MemoryLeakProgramm in Listing 1 ist einfach:

Listing 1. MemoryLeak-Programm

01 import java.util.Vector; 02 03 öffentliche Klasse MemoryLeak {04 05 öffentliche statische Leere main (String [] args) {06 07 int MAX_CONSUMERS = 10000; 08 int SLEEP_BETWEEN_ALLOCS = 5; 09 10 ConsumerContainer objectHolder = neuer ConsumerContainer (); 11 12 while (objectHolder.size () <MAX_CONSUMERS) {13 System.out.println ("Objekt zuordnen" + 14 Integer.toString (objectHolder.size ()) 15); 16 objectHolder.add (neuer MemoryConsumer ()); 17 try {18 Thread.currentThread (). Sleep (SLEEP_BETWEEN_ALLOCS); 19} catch (InterruptedException ie) {20 // Nichts tun. 21} 22} // while. 23} // main. 24 25} // Ende von MemoryLeak. 26 27 / ** Benannte Containerklasse für Objektreferenzen. * / 28-Klasse ConsumerContainer erweitert Vector {} 29 30 / ** Klasse, die eine feste Menge an Speicher belegt. * / 31 Klasse MemoryConsumer {32 public static final int MEMORY_BLOCK = 1024;33 öffentliches Byte [] memoryHoldingArray; 34 35 MemoryConsumer () {36 memoryHoldingArray = neues Byte [MEMORY_BLOCK]; 37} 38} // MemoryConsumer beenden.

Wenn das Programm ausgeführt wird, erstellt es ein ConsumerContainerObjekt und erstellt und fügt MemoryConsumerdiesem ConsumerContainerObjekt Objekte mit einer Größe von mindestens 1 KB hinzu . Wenn Sie die Objekte zugänglich halten, sind sie für die Speicherbereinigung nicht verfügbar, wodurch ein Speicherverlust simuliert wird.

Schauen wir uns ausgewählte Teile der Profildatei an. Die ersten Zeilen des Sites-Abschnitts zeigen deutlich, was passiert:

SITES BEGIN (geordnet nach Live-Bytes) Mo Sep 3 19:16:29 2001 Prozent Live-zugewiesene Stapelklasse Rang Selbstakkumulationsbytes Objs Bytes Objs Trace-Name 1 97,31% 97,31% 10280000 10000 10280000 10000 1995 [B 2 0,39% 97,69% 40964 1 81880 10 1996 [L; 3 0,38% 98,07% 40000 10000 40000 10000 1994 MemoryConsumer 4 0,16% 98,23% 16388 1 16388 1 1295 [C 5 0,16% 98,38% 16388 1 16388 1 1304 [C ...

Es gibt 10.000 Objekte vom Typ byte[]( [Bin VM-Sprache) sowie 10.000 MemoryConsumerObjekte. Die Byte-Arrays belegen 10.280.000 Bytes, sodass anscheinend ein Overhead direkt über den Rohbytes besteht, die jedes Array verbraucht. Da die Anzahl der zugewiesenen Objekte der Anzahl der lebenden Objekte entspricht, können wir daraus schließen, dass keines dieser Objekte durch Müll gesammelt werden kann. Dies entspricht unseren Erwartungen.

Ein weiterer interessanter Punkt: Der von den MemoryConsumerObjekten als belegt gemeldete Speicher enthält nicht den von den Byte-Arrays belegten Speicher. Dies zeigt, dass unser Profiling-Tool keine hierarchischen Containment-Beziehungen verfügbar macht, sondern Statistiken nach Klassen. Dies ist wichtig zu verstehen, wenn Sie hprof verwenden, um einen Speicherverlust zu lokalisieren.

Woher kamen diese undichten Byte-Arrays? Beachten Sie, dass die MemoryConsumerObjekte und die Byte-Arrays auf Traces 1994und 1995im folgenden Trace-Abschnitt verweisen . Und siehe da, diese Traces sagen uns, dass die MemoryConsumerObjekte in der Methode der MemoryLeakKlasse erstellt wurden main()und dass die Byte-Arrays im Konstruktor erstellt wurden ( ()Methode in VM-speak). Wir haben unseren Speicherverlust, Zeilennummern und alles gefunden:

TRACE 1994: (thread = 1) MemoryLeak.main (MemoryLeak.java:16) TRACE 1995: (thread = 1) MemoryConsumer. (MemoryLeak.java:36) MemoryLeak.main (MemoryLeak.java:16) 

Diagnostizieren Sie ein CPU-Schwein

In Listing 2 hat eine BusyWorkKlasse für jeden Thread einen Aufruf einer Methode, die regelt, wie viel der Thread arbeitet, indem er seine Ruhezeit zwischen den CPU-intensiven Berechnungen variiert:

Listing 2. CPUHog program

01 /** Main class for control test. */ 02 public class CPUHog { 03 public static void main(String[] args) { 04 05 Thread slouch, workingStiff, workaholic; 06 slouch = new Slouch(); 07 workingStiff = new WorkingStiff(); 08 workaholic = new Workaholic(); 09 10 slouch.start(); 11 workingStiff.start(); 12 workaholic.start(); 13 } 14 } 15 16 /** Low CPU utilization thread. */ 17 class Slouch extends Thread { 18 public Slouch() { 19 super("Slouch"); 20 } 21 public void run() { 22 BusyWork.slouch(); 23 } 24 } 25 26 /** Medium CPU utilization thread. */ 27 class WorkingStiff extends Thread { 28 public WorkingStiff() { 29 super("WorkingStiff"); 30 } 31 public void run() { 32 BusyWork.workNormally(); 33 } 34 } 35 36 /** High CPU utilization thread. */ 37 class Workaholic extends Thread { 38 public Workaholic() { 39 super("Workaholic"); 40 } 41 public void run() { 42 BusyWork.workTillYouDrop(); 43 } 44 } 45 46 /** Class with static methods to consume varying amounts 47 * of CPU time. */ 48 class BusyWork { 49 50 public static int callCount = 0; 51 52 public static void slouch() { 53 int SLEEP_INTERVAL = 1000; 54 computeAndSleepLoop(SLEEP_INTERVAL); 55 } 56 57 public static void workNormally() { 58 int SLEEP_INTERVAL = 100; 59 computeAndSleepLoop(SLEEP_INTERVAL); 60 } 61 62 public static void workTillYouDrop() { 63 int SLEEP_INTERVAL = 10; 64 computeAndSleepLoop(SLEEP_INTERVAL); 65 } 66 67 private static void computeAndSleepLoop(int sleepInterval) { 68 int MAX_CALLS = 10000; 69 while (callCount < MAX_CALLS) { 70 computeAndSleep(sleepInterval); 71 } 72 } 73 74 private static void computeAndSleep(int sleepInterval) { 75 int COMPUTATIONS = 1000; 76 double result; 77 78 // Compute. 79 callCount++; 80 for (int i = 0; i < COMPUTATIONS; i++) { 81 result = Math.atan(callCount * Math.random()); 82 } 83 84 // Sleep. 85 try { 86 Thread.currentThread().sleep(sleepInterval); 87 } catch (InterruptedException ie) { 88 // Do nothing. 89 } 90 91 } // End computeAndSleep. 92 } // End BusyWork. 

There are three threads -- Workaholic, WorkingStiff, and Slouch -- whose work ethics vary by orders of magnitude, judging by the work they choose to do. Examine the profile's CPU Samples section shown below. The three highest ranked traces show that the CPU spent most of its time calculating random numbers and arc tangents, as we would expect:

CPU SAMPLES BEGIN (total = 935) Tue Sep 4 20:44:49 2001 rank self accum count trace method 1 39.04% 39.04% 365 2040 java/util/Random.next 2 26.84% 65.88% 251 2042 java/util/Random.nextDouble 3 10.91% 76.79% 102 2041 java/lang/StrictMath.atan 4 8.13% 84.92% 76 2046 BusyWork.computeAndSleep 5 4.28% 89.20% 40 2050 java/lang/Math.atan 6 3.21% 92.41% 30 2045 java/lang/Math.random 7 2.25% 94.65% 21 2051 java/lang/Math.random 8 1.82% 96.47% 17 2044 java/util/Random.next 9 1.50% 97.97% 14 2043 java/util/Random.nextDouble 10 0.43% 98.40% 4 2047 BusyWork.computeAndSleep 11 0.21% 98.61% 2 2048 java/lang/StrictMath.atan 12 0.11% 98.72% 1 1578 java/io/BufferedReader.readLine 13 0.11% 98.82% 1 2054 java/lang/Thread.sleep 14 0.11% 98.93% 1 1956 java/security/PermissionCollection.setReadOnly 15 0.11% 99.04% 1 2055 java/lang/Thread.sleep 16 0.11% 99.14% 1 1593 java/lang/String.valueOf 17 0.11% 99.25% 1 2052 java/lang/Math.random 18 0.11% 99.36% 1 2049 java/util/Random.nextDouble 19 0.11% 99.47% 1 2031 BusyWork.computeAndSleep 20 0.11% 99.57% 1 1530 sun/io/CharToByteISO8859_1.convert ... 

Beachten Sie, dass Anrufe an die BusyWork.computeAndSleep()Methode übernehmen 8,13 Prozent, 0,43 Prozent und 0,11 Prozent für die Workaholic, WorkingStiffund SlouchFäden, respectively. Wir können feststellen, um welche Threads es sich handelt, indem wir die Traces untersuchen, auf die in der Trace-Spalte des CPU-Beispielabschnitts oben (Rang 4, 10 und 19) im folgenden Trace-Abschnitt verwiesen wird: