Titel   Inhalt   Suchen   Index   API  Go To Java 2, Zweite Auflage, Handbuch der Java-Programmierung
 <<    <     >    >>  Kapitel 48 - Performance-Tuning

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.

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.

 JDK1.1-1.3 

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.

Natürlich ist diese Vorgehensweise nicht sehr präzise, und es sind Fälle denkbar, bei den 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.

 Warnung 

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.

 Hinweis 

Das CPU-Profile

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.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.

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 im 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.

 JDK1.1-1.3 

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:

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:


 Titel   Inhalt   Suchen   Index   API  Go To Java 2, Zweite Auflage, Addison Wesley, Version 2.0
 <<    <     >    >>  © 2000 Guido Krüger, http://www.gkrueger.com