48.3 Einsatz eines Profilers
48.3.1 Grundlagen
Die bisher vorgestellten Tips 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.
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:
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 |
Listing 48.9: Ein Beispielprogramm zum Testen des Profilers
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.
48.3.2 Eine Beispielsitzung mit dem Profiler
Erzeugen der Profiling-Informationen
Zunächst muß 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 48.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,
daß 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, daß dort nennenswert Rechenzeit
verbraucht wird.
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
Das CPU-Profile
Das Programm erzeugt nun die Ausgabedatei java.hprof.txt
mit den Profiling-Informationen. Sie besteht aus drei Teilen:
- Im oberen Teil werden allgemeine Informationen zur Struktur der
Datei und den darin verwendeten Einträgen gegeben
- Im mittleren Teil befinden sich die Stacktraces
- Im unteren Teil werden die Sampling-Ergebnisse ausgegeben
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.StringBuffer.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.StringBuffer.toString
5 1.22% 91.06% 3 17 java.lang.StringBuffer.append
6 0.81% 91.87% 2 19 java.lang.StringBuffer.append
7 0.81% 92.68% 2 24 sun.io.CharToByteSingleByte.convert
8 0.81% 93.50% 2 12 java.lang.StringBuffer.<init>
9 0.41% 93.90% 1 20 java.lang.StringBuffer.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 StringBuffer
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, daß 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.StringBuffer.expandCapacity(StringBuffer.java:202)
java.lang.StringBuffer.append(StringBuffer.java:401)
ProfTest1A.dots(ProfTest1A.java:11)
ProfTest1A.main(ProfTest1A.java:18)
Er besagt, daß der Sample in Zeile 202 der Methode expandCapacity
der Klasse StringBuffer
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 StringBuffer
übersetzt.
Als erste Erkenntnis stellen wir also fest, daß offensichtlich
der +=-Operator zur String-Verkettung
interne StringBuffer-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, daß 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.StringBuffer.append(StringBuffer.java:402)
ProfTest1A.dots(ProfTest1A.java:11)
ProfTest1A.main(ProfTest1A.java:18)
TRACE 13:
java.lang.System.arraycopy(System.java:Native method)
java.lang.StringBuffer.expandCapacity(StringBuffer.java:203)
java.lang.StringBuffer.append(StringBuffer.java:401)
ProfTest1A.dots(ProfTest1A.java:11)
ProfTest1A.main(ProfTest1A.java:18)
Beide Arten von Samples gehen letztlich auf Zeile 11 unseres Programmes
zurück und zeigen Rechenzeitverbräuche, die durch die vom
+=-Operator ausgelöste Verarbeitung temporärer Strings und
StringBuffer 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, muß getChars
bei jedem Aufruf eine Kopie des Zeichenarrays erstellen), andererseits
wird arraycopy
in expandCapacity
benötigt, um das bei einer Verlängerung des StringBuffers
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 StringBuffer-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.
Das Heap-Profile
Einen noch deutlicheren Eindruck vermittelt ein Heap-Profile. Wir
erstellen es, indem wir das Programm mit der Option heap=samples
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,
daß 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.StringBuffer.expandCapacity(StringBuffer.java:202)
java.lang.StringBuffer.append(StringBuffer.java:401)
ProfTest1A.dots(ProfTest1A.java:11)
ProfTest1A.main(ProfTest1A.java:18)
Wieder liegt der Verursacher in Zeile 11 unseres Programmes, und wir
sehen, daß 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.
Die optimierte Version des Programms
Da wir auf die Interna der Klassen String
und StringBuffer
keinen Einfluß 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 48.2.1 bekannt
und besteht darin, direkt mit StringBuffer-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 StringBuffer sb = new StringBuffer(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 |
Listing 48.10: Das verbesserte Programm nach der Profiler-Sitzung
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.StringBuffer.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.
48.3.3 Ausblick
Egal, ob mit dem eingebauten Profiler das Laufzeitverhalten oder der
Speicherverbrauch der Anwendung untersucht werden soll, die prinzipielle
Vorgehensweise ist stets gleich:
- Zunächst wird das Programm mit der Option -Xrunhprof
gestartet und eine Datei mit Profiling-Informationen erstellt.
- Die größten Rechenzeit- und Speicherverbraucher werden
ermittelt, und über ihre Stacktraces wird bestimmt, woher sie
aufgerufen werden und in welcher Weise sie zum Programmergebnis beitragen.
- Stehen genügend Erkenntnisse zur Verfügung, kann das
Programm verbessert werden und ein erneuter Profilerlauf durchgeführt
werden.
- Sind die Ergebnisse zufriedenstellend, kann der Profiler deaktiviert
werden, andernfalls beginnt das Spiel von vorne.
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.klg.com),
der auch für Teile der Software zu diesem Buch verwendet wurde,
OptimizeIt (http://www.optimizeit.com)
oder JInsight (http://www.alphaWorks.ibm.com).
Zu ihren Fähigkeiten zählen beispielsweise:
- Die graphische Darstellung der Aufrufhierarchie mit Laufzeitinformationen
zu Methoden und Aufrufen.
- Das Ermitteln von Profiling-Informationen bis auf die Ebene einzelner
Quelltextzeilen hinab.
- Das Erstellen dynamischer Profile, um die Veränderung wichtiger
Parameter bereits während des laufenden Programms beobachten
zu können.
- Die Rückverfolgung von alloziertem Speicher sowohl zu den
Programmstellen, die den Speicher belegt haben, als auch zu den Variablen,
in denen die zugehörigen Objekte gehalten werden.
- Das Vergleichen von Profiling-Läufen, um die Auswirkungen
von Optimierungsversuchen studieren zu können.
- Die Ausgabe von Reports und HTML-Dateien zu Vergleichs- und Dokumentationszwecken.
