From 33613a85afc4b1481367fbe92a17ee59c240250b Mon Sep 17 00:00:00 2001
From: Sven Eisenhauer
+Die bisher vorgestellten Tipps und Tricks sind sicherlich eine Hilfe,
+um bereits während der Entwicklung eines Programms grundsätzliche
+Performance-Probleme zu vermeiden. Läuft das fertige Programm
+dann trotzdem nicht mit der gewünschten Geschwindigkeit (was
+in der Praxis häufig vorkommt), helfen pauschale Hinweise leider
+nicht weiter. Statt dessen gilt es herauszufinden, welche Teile des
+Programms für dessen schlechte Performance verantwortlich sind.
+Bei größeren Programmen, die aus vielen tausend Zeilen
+Quellcode bestehen, ist das eine komplizierte Aufgabe, die nur mit
+Hilfe eines guten Profilers bewältigt
+werden kann. Der Profiler ist ein Werkzeug, mit dessen Hilfe im laufenden
+Programm Performanceparameter, wie beispielsweise die verbrauchte
+CPU-Zeit, die Anzahl der allozierten Objekte oder die Anzahl der Aufrufe
+bestimmter Methoden, überwacht und gemessen werden können.
+Durch manuelle Inspektion der erzeugten Logdateien oder mit Hilfe
+eines Auswertungsprogramms kann dann festgestellt werden, welche Teile
+des Programms die größte Last erzeugen und daher verbesserungsbedürftig
+sind.
+
+
+Das Standard-JDK enthält bereits seit der Version 1.0 einen eingebauten
+Profiler, der Informationen über Laufzeit und Aufrufhäufigkeit
+von Methoden geben kann. Im JDK 1.2 wurde er erweitert und kann seither
+den Speicherverbrauch messen und Profiling-Informationen threadweise
+ausgeben. Mit dem JDK 1.3 wurde er erneut verbessert und mit einem
+offenen Profiler-API versehen (JVMPI,
+Java Virtual Machine Profiler Interface).
+Mit dessen Hilfe ist es möglich, eigene Profiling-Werkzeuge zu
+schreiben. Fester Bestandteil des JDK ist eine Beispielimplementierung
+hprof,
+die für einfache Profiling-Aufgaben verwendet werden kann.
+Im Vergleich zu spezialisierten Produkten sind die Fähigkeiten
+des eingebauten Profilers etwas rudimentär. Insbesondere die
+vom Profiler erzeugte Ausgabedatei erfordert einigen Nachbearbeitungsaufwand.
+Zudem gibt es keine grafischen Auswertungen wie bei kommerziellen
+Profilern. Dennoch ist der JDK-Profiler ein brauchbares und hilfreiches
+Instrument, mit dem Performanceprobleme und Speicherengpässe
+analysiert werden können. Wir wollen uns in diesem Abschnitt
+mit den Grundlagen seiner Bedienung vertraut machen.
+
+
+Als Beispiel für die Anwendung des Profiler wollen wir ein Programm
+verwenden, dessen simple Aufgabe darin besteht, einen String
+mit 10000 Punkten zu erzeugen und auf dem Bildschirm auszugeben. Statt
+die Ratschläge aus dem vorigen Abschnitt zu beherzigen, verwendet
+das Programm den Operator +=,
+um den String
+zeichenweise in einer Schleife zusammenzusetzen. Auf langsameren Rechnern
+kann es durchaus einige Sekunden dauern, bis der String erzeugt und
+vollständig auf dem Bildschirm ausgegeben wurde:
+
+
+
+
+
+
+ Titel
+ Inhalt
+ Suchen
+ Index
+ DOC
+ Handbuch der Java-Programmierung, 5. Auflage
+
+ <<
+ <
+ >
+ >>
+ API
+ Kapitel 50 - Performance-Tuning
+
+
+
+
+
+50.3 Einsatz eines Profilers
+
+
+
+
+
+
+
+50.3.1 Grundlagen
+
+
+
+
+
+
+
+
+![]()
+
+![]()
+
+
+
+![]()
+
+
+
+
+
+ JDK1.1-6.0
+
+
+
+
+Listing 50.9: Ein Beispielprogramm zum Testen des Profilers
+
+
+
+
+
+001 /* ProfTest1A.java */
+002
+003 import java.util.*;
+004
+005 public class ProfTest1A
+006 {
+007 public static String dots(int len)
+008 {
+009 String ret = "";
+010 for (int i = 0; i < len; ++i) {
+011 ret += ".";
+012 }
+013 return ret;
+014 }
+015
+016 public static void main(String[] args)
+017 {
+018 String s = dots(10000);
+019 System.out.println(s);
+020 }
+021 }
+
+
+ProfTest1A.java
+
+Nachfolgend wollen wir uns eine Beispielsitzung mit dem Profiler ansehen. +Ähnlich wie bei einem Debugger besteht die typische Vorgehensweise +darin, schrittweise Informationen über Rechenzeit- und Speicherverbrauch +zu gewinnen und das Programm mit diesen Informationen nach und nach +zu optimieren. Für gewöhnlich gibt es dabei kein Patentrezept, +das direkt zum Erfolg führt. Statt dessen ähnelt der Umgang +mit dem Profiler einer Detektivarbeit, bei der die einzelnen Teile +der Lösung nach und nach gefunden werden. + + + + +
+Zunächst muss das Programm wie gewöhnlich übersetzt
+werden:
+
+
+javac ProfTest1A.java
+
+
+
+
+Um das Programm unter Kontrolle des Profilers zu starten, ist die +Option -Xrunhprof +zu verwenden und nach einem Doppelpunkt mit den erforderlichen Parametrisierungen +zu versehen. Die Parameter werden als kommaseparierte Liste von Argumenten +der Form »Name=Wert« angegeben. Die wichtigsten Parameter +von hprof +sind: + +
+
| Name | +Mögliche Werte |
| cpu | +samples, times, old |
| heap | +dump, sites, all |
| file | +Name der Ausgabedatei |
| depth | +Maximale Tiefe der Stacktraces |
+Tabelle 50.2: Parameter von hprof
+ ++Mit der Option cpu wird der +CPU-Profiler aktiviert. Er kennt die Modi »samples«, »times« +und »old«. Im Modus »samples« werden die Profiling-Informationen +dadurch gewonnen, dass das laufende Programm mit Hilfe eines separaten +Threads regelmäßig unterbrochen wird. Bei jeder Unterbrechung +wird ein Stacktrace gezogen, der dem Profiler Auskunft darüber +gibt, welche Methode gerade ausgeführt wird, in welcher Quelltextzeile +das Programm steht und wie die Kette ihrer Aufrufer aussieht. Jeder +derartige Schnappschuß wird als Sample bezeichnet. + +
+Die unterschiedlichen Stacktraces werden mit einem Aufrufzähler +versehen, der immer dann um 1 erhöht wird, wenn bei einer Unterbrechung +ein entsprechender Stacktrace gefunden wird. Aus dem Endwert der Zähler +kann dann abgeleitet werden, wo das Programm die meiste Rechenzeit +verbraucht hat. Denn je höher der Zähler war, desto öfter +wurde das Programm an der zugehörigen Programmstelle »angetroffen« +und desto wahrscheinlicher ist es, dass dort nennenswert Rechenzeit +verbraucht wird. +
+
![]() |
+![]() |
+
+
+ +Natürlich ist diese Vorgehensweise nicht sehr präzise, und +es sind Fälle denkbar, bei denen sie ganz versagt. Aber sie ist +einfach zu implementieren und beeinträchtigt die Laufzeit des +Programms nur unwesentlich. In der Praxis sollten die Ergebnisse mit +der nötigen Vorsicht betrachtet werden. Sie dürfen nicht +als absolute Meßwerte angesehen werden, sondern sind vorwiegend +dazu geeignet, Tendenzen zu erkennen und Programmteile mit besonders +hoher Rechenzeit ausfindig zu machen. |
+
+
|
+![]() |
+
+Der zweite Modus »times« arbeitet etwas anders. Statt lediglich +die Anzahl der Stacktraces zu zählen, misst er tatsächlich +die innerhalb der einzelnen Methoden verbrauchte Rechenzeit. Allerdings +wird dadurch auch die Laufzeit des Programms stärker erhöht +als im Modus »samples«. In der Praxis kann eine gemischte +Vorgehensweise sinnvoll sein, bei der zunächst per »samples« +die größten Performancefresser eliminiert werden und dann +per »times« das Feintuning vorgenommen wird. Die Option +»old« erstellt die Ausgabedatei in einem Format, wie sie +von den Profilern der Prä-1.2-Versionen verwendet wurde. Wir +wollen hier nicht weiter darauf eingehen. + +
+Bei der Verwendung des CPU-Profilers sind weiterhin die Optionen file +und depth von Bedeutung. Mit +file kann der Name der Ausgabedatei +angegeben werden, er ist standardmäßig java.hprof.txt. +Mit depth wird festgelegt, mit +welcher maximalen Tiefe die Stacktraces aufgezeichnet werden (standardmäßig +4). Ist die Aufrufkette einer Methode länger als der angegebene +Wert, wird der Stacktrace abgeschnitten, und bei der Analyse ist nicht +mehr bis ins letzte Detail erkennbar, von welcher Stelle aus der Aufruf +erfolgte. Wird depth auf 1 gesetzt, +sind nur noch die Aufrufstellen sichtbar, die Aufrufer selbst bleiben +unsichtbar. + +
+Wir wollen einen ersten Lauf mit dem CPU-Profiler im Modus »samples«
+und mit einer maximalen Stacktiefe von 10 machen und rufen das Programm
+daher wie folgt auf:
+
+
+java -Xint -Xrunhprof:cpu=samples,depth=10 ProfTest1A
+
+
+
+
![]() |
+
+
+ +Die Option -Xint +geben wir an, um das Programm im Interpreter-Modus laufen zu lassen +und mögliche Verfälschungen durch den Hotspot-Compiler zu +vermeiden. |
+
+
|
+![]() |
+
+Das Programm erzeugt nun die Ausgabedatei java.hprof.txt +mit den Profiling-Informationen. Sie besteht aus drei Teilen: +
+Die Analyse beginnt im unteren Teil. Er sieht bei unserer Beispielsitzung
+so aus (die Samples ab Position 11 wurden aus Gründen der Übersichtlichkeit
+entfernt):
+
+
+CPU SAMPLES BEGIN (total = 246) Sun Jun 18 17:56:28 2000
+rank self accum count trace method
+ 1 53.66% 53.66% 132 9 java.lang.StringBuilder.expandCapacity
+ 2 17.48% 71.14% 43 13 java.lang.System.arraycopy
+ 3 17.07% 88.21% 42 11 java.lang.System.arraycopy
+ 4 1.63% 89.84% 4 10 java.lang.StringBuilder.toString
+ 5 1.22% 91.06% 3 17 java.lang.StringBuilder.append
+ 6 0.81% 91.87% 2 19 java.lang.StringBuilder.append
+ 7 0.81% 92.68% 2 24 sun.io.CharToByteSingleByte.convert
+ 8 0.81% 93.50% 2 12 java.lang.StringBuilder.<init>
+ 9 0.41% 93.90% 1 20 java.lang.StringBuilder.append
+ 10 0.41% 94.31% 1 14 java.lang.String.getChars
+ ...
+CPU SAMPLES END
+
+
+
+
+Die Ausgabe ist nach Aufrufhäufigkeit geordnet. Von den insgesamt +246 Samples, die während des Programmlaufs gezogen wurden, waren +132 in der Methode expandCapacity +der Klasse StringBuilder +und 43 und noch einmal 42 in der Methode arraycopy +der Klasse System. +Damit fielen insgesamt 88.21 Prozent aller Samples in diese Methoden. + +
+Da beide Methoden nicht selbstgeschrieben sind und sich damit unseren
+Optimierungsversuchen entziehen, kann eine Performance-Verbesserung
+lediglich dadurch erreicht werden, dass die Anzahl ihrer Aufrufe vermindert
+wird. Um die Aufrufer herauszufinden, müssen wir uns die in der
+fünften Spalten angegebenen Stacktraces ansehen. Der Stacktrace
+zu expandCapacity
+hat die Nummer 9 und sieht so aus:
+
+
+TRACE 9:
+ java.lang.StringBuilder.expandCapacity(StringBuilder.java:202)
+ java.lang.StringBuilder.append(StringBuilder.java:401)
+ ProfTest1A.dots(ProfTest1A.java:11)
+ ProfTest1A.main(ProfTest1A.java:18)
+
+
+
+
+Er besagt, dass der Sample in Zeile 202 der Methode expandCapacity +der Klasse StringBuilder +erzeugt wurde. Diese wurde von append +aufgerufen, das von unserer eigenen Methode dots +in Zeile 11 aufgerufen wurde. In Zeile 11 steht zwar kein Aufruf von +append, +dort befindet sich aber der +=-Operator zur Verkettung der Strings. +Dieser wird vom Compiler in entsprechende Methoden- und Konstruktorenaufrufe +der Klassen String +und StringBuilder +übersetzt. + +
+Als erste Erkenntnis stellen wir also fest, dass offensichtlich der ++=-Operator zur String-Verkettung +interne StringBuilder-Objekte +erzeugt, die einen erheblichen Teil der CPU-Zeit benötigen, um +während des Anfügens von Zeichen vergrößert zu +werden. + +
+Die Stacktraces 11 und 13 der nächsten beiden Kandidaten verstärken
+den Eindruck, dass der +=-Operator in unserem Programm CPU-intensiven
+Code erzeugt:
+
+
+TRACE 11:
+ java.lang.System.arraycopy(System.java:Native method)
+ java.lang.String.getChars(String.java:553)
+ java.lang.StringBuilder.append(StringBuilder.java:402)
+ ProfTest1A.dots(ProfTest1A.java:11)
+ ProfTest1A.main(ProfTest1A.java:18)
+TRACE 13:
+ java.lang.System.arraycopy(System.java:Native method)
+ java.lang.StringBuilder.expandCapacity(StringBuilder.java:203)
+ java.lang.StringBuilder.append(StringBuilder.java:401)
+ ProfTest1A.dots(ProfTest1A.java:11)
+ ProfTest1A.main(ProfTest1A.java:18)
+
+
+
+
+Beide Arten von Samples gehen letztlich auf Zeile 11 unseres Programms +zurück und zeigen Rechenzeitverbräuche, die durch die vom ++=-Operator ausgelöste Verarbeitung temporärer Strings und +StringBuilder verursacht werden. Obwohl die Samples in beiden Fällen +in arraycopy +gezogen wurden, gibt es zwei unterschiedliche Stacktraces, weil die +Aufruferkette in beiden Fällen unterschiedlich ist. Einerseits +wird arraycopy +aus getChars +aufgerufen (da Strings immutable sind, muss getChars +bei jedem Aufruf eine Kopie des Zeichenarrays erstellen), andererseits +wird arraycopy +in expandCapacity +benötigt, um das bei einer Verlängerung des StringBuilders +erforderliche Umkopieren der Zeichen zu erledigen. + +
+Unsere erste Vermutung hat sich also bestätigt: Der harmlos aussehende +Aufruf des +=-Operators in Zeile 11 unseres Programms erzeugt temporäre +String- +und StringBuilder-Objekte, +in der ein Großteil der Rechenzeit durch das Anhängen und +Kopieren von Zeichen und das Erhöhen der Kapazität verbraucht +wird. + + + + +
+Einen noch deutlicheren Eindruck vermittelt ein Heap-Profile. Wir
+erstellen es, indem wir das Programm mit der Option heap=sites
+erneut unter Profiler-Kontrolle laufen lassen:
+
+
+java -Xint -Xrunhprof:heap=sites,depth=10 ProfTest1A
+
+
+
+
+Die Ausgabe besteht wie beim CPU-Profiling aus drei Teilen. Die ersten
+beiden entsprechen dem CPU-Profiler, der dritte enthält Informationen
+zur dynamischen Heap-Belegung:
+
+
+SITES BEGIN (ordered by live bytes) Sun Jun 18 18:37:28 2000
+ percent live alloc'ed stack class
+ rank self accum bytes objs bytes objs trace name
+ 1 48.27% 48.27% 189974 25 75074238 19950 471 [C
+ 2 38.00% 86.27% 149524 157 149524 157 1 [I
+ 3 4.91% 91.17% 19304 741 19364 747 1 [C
+ 4 2.44% 93.61% 9588 153 9588 153 1 [B
+ 5 2.29% 95.90% 9010 1550 9022 1552 1 <Unknown>
+ 6 1.13% 97.03% 4460 199 4460 199 1 [S
+ 7 1.06% 98.09% 4164 253 4220 260 1 [L<Unknown>;
+ 8 0.06% 98.15% 238 3 238 3 403 [B
+ 9 0.04% 98.20% 172 1 172 1 396 [B
+ 10 0.04% 98.24% 170 10 170 10 390 [C
+ ...
+SITES END
+
+
+
+
+Auch hier geben die erste Spalte die Rangordnung und die nächsten +beiden die einzelnen und kumulierten Prozentanteile am Gesamtverbrauch +an. die Spalten 4 und 5 geben einen Überblick über die aktiven +Objekte, die nächsten beiden über die insgesamt allozierten +Objekte (jeweils mit der Gesamtzahl allozierter Bytes und der Anzahl +der Objekte). Die letzte Spalte stellt den Datentyp des Objekts dar. +[C +steht beispielsweise für ein Zeichen-Array, [I +für ein Integer-Array. + +
+Am auffälligsten ist die oberste Zeile und die darin ersichtliche
+Diskrepanz zwischen aktiven und allozierten Objekten. Dort steht,
+dass unser Programm 19950 Zeichen-Arrays mit insgesamt 75 MByte Speicher
+alloziert hat, davon aber nur noch 25 Objekte mit kaum 200 kByte Speicher
+aktiv sind. Hier wurden also in erheblichen Umfang kurzlebige Objekte
+erzeugt und anschließend wieder fallengelassen. Stacktrace 471
+sieht so aus:
+
+
+TRACE 471:
+ java.lang.StringBuilder.expandCapacity(StringBuilder.java:202)
+ java.lang.StringBuilder.append(StringBuilder.java:401)
+ ProfTest1A.dots(ProfTest1A.java:11)
+ ProfTest1A.main(ProfTest1A.java:18)
+
+
+
+
+Wieder liegt der Verursacher in Zeile 11 unseres Programms, und wir +sehen, dass der +=-Operator nicht nur viel Rechenzeit verbraucht, +sondern zudem eine große Anzahl temporärer Objekte erzeugt +und damit das Laufzeitsystem und den Garbage Collector belastet. + + + + +
+Da wir auf die Interna der Klassen String +und StringBuilder +keinen Einfluss haben, kann die Optimierung nur darin bestehen, die +Verwendung des +=-Operators einzuschränken oder eine besser geeignete +Alternative zu wählen. Diese ist natürlich schon aus Abschnitt 50.2.1 +bekannt und besteht darin, direkt mit StringBuilder-Objekten +zu arbeiten. Die verbesserte Version unseres Programms sieht dann +so aus: + + +
+
+
+
+001 /* ProfTest1B.java */
+002
+003 import java.util.*;
+004
+005 public class ProfTest1B
+006 {
+007 public static String dots(int len)
+008 {
+009 StringBuilder sb = new StringBuilder(len + 10);
+010 for (int i = 0; i < len; ++i) {
+011 sb.append('.');
+012 }
+013 return sb.toString();
+014 }
+015
+016 public static void main(String[] args)
+017 {
+018 String s = dots(10000);
+019 System.out.println(s);
+020 }
+021 }
+
+ |
++ProfTest1B.java | +
+Wird nun ein CPU-Profiling durchgeführt, ergibt sich ein gänzlich
+anderes Bild:
+
+
+CPU SAMPLES BEGIN (total = 15) Sun Jun 18 19:03:56 2000
+rank self accum count trace method
+ 1 26.67% 26.67% 4 9 sun.io.CharToByteSingleByte.convert
+ 2 6.67% 33.33% 1 2 java.io.InputStreamReader.<init>
+ 3 6.67% 40.00% 1 12 sun.io.CharToByteSingleByte.getNative
+ 4 6.67% 46.67% 1 11 sun.io.CharToByteSingleByte.convert
+ 5 6.67% 53.33% 1 13 java.io.FileOutputStream.writeBytes
+ 6 6.67% 60.00% 1 4 sun.security.provider.PolicyFile.getPermissions
+ 7 6.67% 66.67% 1 5 sun.net.www.protocol.file.FileURLConnection.getPermission
+ 8 6.67% 73.33% 1 10 java.io.FileOutputStream.writeBytes
+ 9 6.67% 80.00% 1 1 sun.misc.URLClassPath$FileLoader.getResource
+ 10 6.67% 86.67% 1 6 java.net.URLClassLoader.getPermissions
+ 11 6.67% 93.33% 1 3 java.security.Security.loadProviders
+ 12 6.67% 100.00% 1 8 java.lang.StringBuilder.append
+CPU SAMPLES END
+
+
+
+
+Statt 246 gab es nur noch 15 Samples (die Laufzeit des Programms hat +sich also auf ein Sechzehntel reduziert), und nur noch ein einziger +von ihnen wurde durch den Aufruf der Methode dots +verursacht. Alle anderen sind auf den Aufruf von println +in Zeile 019 zurückzuführen. +Der Heap-Profiler liefert ein ähnliches Bild: der gesamte Speicherverbrauch +des Programms liegt nun in der Größenordnung von 150 kByte, +und es gibt keine nennenswerten temporären Objektallokationen +mehr. +
+
![]() |
+![]() |
+
+
+ +In früheren JDKs wurde der Profiler nicht mit der Option -Xrunhprof, +sondern mit -Xprof +bzw. mit -prof +aufgerufen. Zudem durfte nicht der normale Interpreter verwendet werden, +sondern mit java_g +mußte dessen Debug-Version aufgerufen werden. Auch das Deaktivieren +des Just-In-Time-Compilers hat sich im Laufe der Versionen geändert. +Während es seit dem JDK 1.3 mit dem Schalter -Xint +erledigt wird, mußte zuvor die Umgebungsvariable JAVA_COMPILER +auf den Wert NONE gesetzt werden. +Soll der Profiler bei einem Applet verwendet werden, kann die Aufrufoption +mit dem Schalter -J +an den Appletviewer übergeben werden. |
+
+
|
+![]() |
+
+Egal, ob mit dem eingebauten Profiler das Laufzeitverhalten oder der +Speicherverbrauch der Anwendung untersucht werden soll, die prinzipielle +Vorgehensweise ist stets gleich: +
+Ist der Anteil von lokalem Code am Rechenzeitverbrauch hoch, kann +versucht werden, diesen zu verringern. Typische Ansatzpunkte dafür +sind das Vermindern der Anzahl von Schleifendurchläufen (durch +bessere Algorithmen), die Verwendung von Ganz- statt Fließkommazahlen, +das Herausziehen von schleifeninvariantem Code, das Vermeiden der +Doppelauswertung von gemeinsamen Teilausdrücken, das Wiederverwenden +bekannter Teilergebnisse, die Verwendung alternativer Datenstrukturen, +das Eliminieren von unbenutztem Code oder das Reduzieren der Stärke +von Ausdrücken, indem sie durch algebraisch gleichwertige, aber +schnellere Ausdrücke ersetzt werden. Wird ein großer Anteil +der Rechenzeit dagegen in Aufrufen von Untermethoden verbraucht, kann +versucht werden, deren Aufrufhäufigkeit zu vermindern, sie durch +performantere Aufrufe zu ersetzen, oder - im Falle eigener Methoden +- ihre Ablaufgeschwindigkeit zu erhöhen. + +
+Der zielgerichtete Einsatz dieser Techniken erfordert gute Werkzeuge, +namentlich einen guten Profiler. Bei kleineren Problemen mag es ausreichend +sein, die Ablaufgeschwindigkeit mit Ausgabeanweisungen und System.currentTimeMillis +zu ermitteln, und auch der JDK-Profiler kann mit Erfolg eingesetzt +werden. Daneben gibt es einige kommerzielle und experimentelle Produkte +mit wesentlich erweiterten Fähigkeiten. Beispiele für solche +Profiler sind JProbe (http://www.quest.com/jprobe/), +der auch für Teile der Software zu diesem Buch verwendet wurde +oder JInsight (http://www.alphaWorks.ibm.com). +Zu ihren Fähigkeiten zählen beispielsweise: +
| Titel + | Inhalt + | Suchen + | Index + | DOC + | Handbuch der Java-Programmierung, 5. Auflage, Addison +Wesley, Version 5.0.1 + |
| << + | < + | > + | >> + | API + | © 1998, 2007 Guido Krüger & Thomas +Stark, http://www.javabuch.de + |