Erläuterungen zur HPROF-Ausgabedatei
Im ersten Abschnitt der Datei stehen allgemeine Kopfzeileninformationen wie eine Erklärung der Optionen, das Copyright und Haftungsausschlüsse. Es folgt eine Zusammenfassung der einzelnen Threads.
Sie können die Ausgabe sehen, nachdem Sie HPROF mit einem einfachen Programm (wie im Folgenden
gezeigt) verwendet haben. Das folgende Testprogramm erstellt zwei Threads und führt sie für eine
kurze Zeit aus. Der Ausgabe können Sie entnehmen, dass die beiden Threads mit den Namen
apples und oranges nach dem systemgenerierten Thread
main erstellt wurden. Beide Threads werden vor dem Thread main
beendet. Für jeden Thread werden die Adresse, die ID, der Name und der Threadgruppenname angezeigt. Sie können sehen, in welcher Reihenfolge Threads gestartet und beendet werden.
THREAD START (obj=11199050, id = 1, name="Signal dispatcher", group="system")
THREAD START (obj=111a2120, id = 2, name="Reference Handler", group="system")
THREAD START (obj=111ad910, id = 3, name="Finalizer", group="system")
THREAD START (obj=8b87a0, id = 4, name="main", group="main")
THREAD END (id = 4)
THREAD START (obj=11262d18, id = 5, name="Thread-0", group="main")
THREAD START (obj=112e9250, id = 6, name="apples", group="main")
THREAD START (obj=112e9998, id = 7, name="oranges", group="main")
THREAD END (id = 6)
THREAD END (id = 7)
THREAD END (id = 5)Der Traceausgabeabschnitt enthält normale Stack-Trace-Informationen. Die Tiefe jedes Trace kann festgelegt werden und jeder Trace hat eine eindeutige ID:
TRACE 5:
java/util/Locale.toLowerCase(Locale.java:1188)
java/util/Locale.convertOldISOCodes(Locale.java:1226)
java/util/Locale.<init>(Locale.java:273)
java/util/Locale.<clinit>(Locale.java:200)Ein Trace enthält eine Anzahl Frames und jeder Frame enthält den Klassennamen, Methodennamen, Dateinamen und die Zeilennummer. Im vorhergehenden Beispiel können Sie sehen, dass
Zeilennummer 1188 der Datei Locale.java (die sich in der Methode
toLowerCase befindet) von der Funktion convertOldISOCodes()
in derselben Klasse aufgerufen wurde. Diese Traces sind bei der Verfolgung des Ausführungspfads
Ihres Programms hilfreich. Wenn Sie die Option 'monitor' angeben, wird ein Monitorspeicherauszug
erstellt, der dem folgenden Beispiel ähnlich ist:
MONITOR DUMP BEGIN
THREAD 8, trace 1, status: R
THREAD 4, trace 5, status: CW
THREAD 2, trace 6, status: CW
THREAD 1, trace 1, status: R
MONITOR java/lang/ref/Reference$Lock(811bd50) unowned
waiting to be notified: thread 2
MONITOR java/lang/ref/ReferenceQueue$Lock(8134710) unowned
waiting to be notified: thread 4
RAW MONITOR "_hprof_dump_lock"(0x806d7d0)
owner: thread 8, entry count: 1
RAW MONITOR "Monitor Cache lock"(0x8058c50)
owner: thread 8, entry count: 1
RAW MONITOR "Monitor Registry lock"(0x8058d10)
owner: thread 8, entry count: 1
RAW MONITOR "Thread queue lock"(0x8058bc8)
owner: thread 8, entry count: 1
MONITOR DUMP END
MONITOR TIME BEGIN (total = 0 ms) Thu Aug 29 16:41:59 2002
MONITOR TIME END- R — Runnable (Der Thread kann ausgeführt werden, wenn er die Möglichkeit dazu erhält)
- S — Suspended (Der Thread wurde von einem anderen Thread ausgesetzt)
- CW — Condition Wait (Der Thread befindet sich im Wartestatus)
- MW — Monitor Wait (Der Monitor befindet sich im Wartestatus)
Der nächste Abschnitt ist der Heapspeicherauszug. Er enthält eine Liste der verschiedenen Speicherbereiche und zeigt an, wie sie zugeordnet sind:
CLS 1123edb0 (name=java/lang/StringBuffer, trace=1318)
super 111504e8
constant[25] 8abd48
constant[32] 1123edb0
constant[33] 111504e8
constant[34] 8aad38
constant[115] 1118cdc8
CLS 111ecff8 (name=java/util/Locale, trace=1130)
super 111504e8
constant[2] 1117a5b0
constant[17] 1124d600
constant[24] 111fc338
constant[26] 8abd48
constant[30] 111fc2d0
constant[34] 111fc3a0
constant[59] 111ecff8
constant[74] 111504e8
constant[102] 1124d668
...
CLS 111504e8 (name=java/lang/Object, trace=1)
constant[18] 111504e8CLS informiert Sie darüber, dass Speicher für eine Klasse zugeordnet wird. Die danach folgende Hexadezimalzahl ist die Adresse, an der der Speicher zugeordnet wird.
Als Nächstes folgen der Klassenname und eine Tracereferenz. Verwenden Sie diese Informationen
als Querverweis auf die Traceausgabe und schauen Sie dort nach, wann die Klasse aufgerufen wird. Anhand des Verweises können Sie in dem betreffenden Trace die Zeilennummer der Anweisung ermitteln,
die zur Erstellung dieses Objekts geführt hat. Die Adressen der Konstanten in dieser Klasse werden
ebenso angezeigt wie, im vorherigen Beispiel, die Adresse der Klassendefinition für die
Superklasse. Beide Klassen sind untergeordnete Objekte derselben Superklasse (mit der Adresse
11504e8). Im weiteren Verlauf der Ausgabe finden Sie die Definition und den Namen
dieser Klasse. Es handelt sich um die Klasse 'Object' (eine Klasse, von der jede Klasse etwas
erbt). Die JVM lädt die gesamte Superklassenhierarchie, bevor sie eine Unterklasse verwenden
kann. Deshalb sind immer für alle Superklassen Klassendefinitionen vorhanden. Es gibt auch Einträge
für Objekte (OBJ) und Arrays (ARR):
OBJ 111a9e78 (sz=60, trace=1, class=java/lang/Thread@8b0c38)
name 111afbf8
group 111af978
contextClassLoader 1128fa50
inheritedAccessControlContext 111aa2f0
threadLocals 111bea08
inheritableThreadLocals 111bea08
ARR 8bb978 (sz=4, trace=2, nelems=0, elem type=java/io/ObjectStreamField@8bac80)Wenn Sie die Option heap auf sites oder all setzen, erhalten Sie eine Liste der einzelnen Speicherbereiche, die Ihrem Code zugeordnet sind. Der Parameter all kombiniert dump und sites. Die Liste ist so sortiert, dass die Sites mit den größten Speicherzuordnungen am Anfang stehen:
SITES BEGIN (ordered by live bytes) Tue Feb 06 10:54:46 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 20.36% 20.36% 190060 16 190060 16 300000 byte[]
2 14.92% 35.28% 139260 1059 139260 1059 300000 char[]
3 5.27% 40.56% 49192 15 49192 15 300055 byte[]
4 5.26% 45.82% 49112 14 49112 14 300066 byte[]
5 4.32% 50.14% 40308 1226 40308 1226 300000 java.lang.String
6 1.62% 51.75% 15092 438 15092 438 300000 java.util.HashMap$Entry
7 0.79% 52.55% 7392 14 7392 14 300065 byte[]
8 0.47% 53.01% 4360 16 4360 16 300016 char[]
9 0.47% 53.48% 4352 34 4352 34 300032 char[]
10 0.43% 53.90% 3968 32 3968 32 300028 char[]
11 0.40% 54.30% 3716 8 3716 8 300000 java.util.HashMap$Entry[]
12 0.40% 54.70% 3708 11 3708 11 300000 int[]
13 0.31% 55.01% 2860 16 2860 16 300000 java.lang.Object[]
14 0.28% 55.29% 2644 65 2644 65 300000 java.util.Hashtable$Entry
15 0.28% 55.57% 2640 15 2640 15 300069 char[]
16 0.27% 55.84% 2476 17 2476 17 300000 java.util.Hashtable$Entry[]
17 0.25% 56.08% 2312 16 2312 16 300013 char[]
18 0.25% 56.33% 2312 16 2312 16 300015 char[]
19 0.24% 56.57% 2224 10 2224 10 300000 java.lang.ClassIn diesem Beispiel sind 5,27 % des insgesamt zugeordneten Speichers dem Trace 300055 zugeordnet. Aus dem Prozentsatz ergibt sich eine Größe von 49192 Byte.
Die Option cpu liefert Profilerstellungsinformationen über den Prozessor. Wenn cpu auf 'samples' gesetzt wird, enthält die Ausgabe die Ergebnisse regelmäßiger Stichproben, die während der Ausführung des Codes erhoben werden. Für jede Stichprobe wird der verarbeitete Codepfad aufgezeichnet und ein Bericht wie der folgende erstellt:
CPU SAMPLES BEGIN (total = 714) Fri Aug 30 15:37:16 2002
rank self accum count trace method
1 76.28% 76.28% 501 77 MyThread2.bigMethod
2 6.92% 83.20% 47 75 MyThread2.smallMethod
...
CPU SAMPLES ENDSie können sehen, dass die Methode bigMethod() 76,28 % der Ausführungszeit des Prozessors beansprucht hat und bei 714 Stichproben 501 Mal ausgeführt wurde. Anhand der Trace-ID können Sie die genaue Route ermitteln, die zum Aufruf dieser Methode geführt hat.