HPROF 出力ファイルの説明

ファイルの先頭のセクションには、オプションの説明、著作権、特記事項などの一般ヘッダー情報が記述されています。その後に、各スレッドの要約が続きます。

シンプルなプログラムで HPROF を使用した後に次のような出力を表示できます。このテスト・プログラムでは、2 つのスレッドを作成して短時間だけ実行しています。出力から、applesと呼ばれる2つのスレッドがあり、システム生成のmainスレッドの後に orangesが作成されたことがわかります。どちらのスレッドも、mainスレッドの前に終了します。各スレッドについて、そのアドレス、ID、名前、およびスレッド・グループ名が表示されています。スレッドが開始および終了した順序を確認できます。

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)

トレース出力セクションには、通常のスタック・トレース情報が記述されています。各トレースの深さを設定可能であり、各トレースには一意の 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)

トレースにはいくつかのフレームが含まれており、各フレームには、クラス名、メソッド名、ファイル名、および行番号が含まれています。上記の例では、Locale.java (toLowerCase メソッド内) の行番号 1188 が同じクラス内の convertOldISOCodes() 関数から呼び出されたことがわかります。これらのトレースは、お使いのプログラムの実行パスをたどるのに役立ちます。モニター・オプションを設定した場合は、次の例のようなモニター・ダンプが生成されます。

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) (スレッドは必要に応じて実行可能)
S - 中断状態 (Suspended) (スレッドは他のスレッドによって中断されています)
CW - 待機状態 (Condition Wait) (スレッドは待機中)
MW — 待機モニター (Monitor Wait) (モニターは待機中)

その次の部分では、一連のモニターがその所有者とともにリストされており、これらのモニターを待っているスレッドが存在するかどうかが示されています。

Heapdump はその次のセクションです。この情報では、各種のメモリー領域がリストされており、これらの領域の割り振り状況が示されています。

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]	111504e8

CLS は、メモリーがクラス用に割り振られていることを示しています。それに続く 16 進数はそのメモリーの割り振り先のアドレスです。

それに続いて、クラス名とトレース参照が示されています。この情報を使用して、トレース出力を相互参照して、そのクラスがいつ呼び出されたのかを確認できます。そのトレースを参照すると、このオブジェクトが作成される原因となった命令の行番号を取得できます。このクラス内の定数のアドレスも表示され、上記の例では、スーパークラスのクラス定義のアドレスが表示されています。どちらのクラスも、同じスーパークラスの子(アドレス11504e8を持つ)です。出力の後続部分を見ると、このクラスの定義と名前がわかります。これは Object クラスです (すべてのクラスの継承元となるクラス)。 JVM は、サブクラスを使用する前に、スーパークラス階層全体を読み込む必要があります。したがって、すべてのスーパークラスのクラス定義が常に存在しています。オブジェクト(OBJ)および配列(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)

heap オプションを sites または all に設定すると、お使いのコードによって割り振られた各ストレージ域のリストが得られます。パラメーター all は、 ダンプ と サイトを結合します。このリストでは、割り振ったメモリー量が多い順にサイトがリストされています。

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

この例では、トレース 300055 によって割り振られたメモリーは、割り振られた合計メモリーの 5.27% です。この比率は 49192 バイトに相当します。

cpu オプションを使用すると、プロセッサーに関するプロファイル情報が得られます。 cpu を samples に設定すると、出力にはコード実行時に取得した定期的サンプルの結果が含まれます。各サンプルでは、処理中のコード・パスが記録されて、以下のようなレポートが生成されます。

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 END

この出力内容から、bigMethod() はプロセッサー実行時間の 76.28% を消費していたこと、および 714 回のサンプルのうち 501 回で実行されていたことがわかります。トレース ID を使用すると、このメソッドの呼び出しにつながった正確なルートがわかります。