目次 前 次
2.8 HPROF
HPROFは、すべてのJDKリリースに付属しているヒープおよびCPUプロファイリング用のツールです。 これは、Java Virtual Machine Tool Interface (JVM TI)を使用してJava仮想マシン(JVM)とインタフェースを取る、動的リンク・ライブラリ(DLL)です。 このツールは、プロファイル情報をファイルまたはソケットにASCII形式またはバイナリ形式で書き込みます。 この情報はさらに、プロファイラ・フロント・エンド・ツールを使用して処理できます。
HPROFツールでは、CPU使用率、ヒープ割当ての統計、およびモニター競合プロファイルを表示できます。 さらに、完全なヒープ・ダンプや、JVM内のすべてのモニターとスレッドの状態を報告できます。 問題の診断に関して、HPROFはパフォーマンス、ロック競合、メモリー・リークなどの問題を分析する際に役立ちます。
JDKにはHPROFライブラリだけでなく、HPROFのソースもJVM TIのデモ・コードとして含まれています。 このコードは$JAVA_HOME/demo/jvmti/hprofディレクトリにあります。
次の項では、HPROFツールによるトラブルシューティング手法について説明します。
2.8.1 HPROFツールによるトラブルシューティング
例2-6に示すように、HPROFツールを起動します。
例2-6 HPROFツールの起動方法
$ java -agentlib:hprof ToBeProfiledClass
$ java -agentlib:hprof=heap=sites ToBeProfiledClass
HPROFは要求されたプロファイルの種類に応じて、関連するイベントを送信するようにJVMに指示します。 その後、ツールはイベント・データをプロファイル情報に処理します。 たとえば、次のコマンドはヒープ割当てプロファイルを取得します。
例2-7に示すように、HPROFエージェントにhelpオプションを指定すると、オプションの完全な一覧が出力されます。
例2-7 HPROFエージェントのヘルプ
$ java -agentlib:hprof=help
HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)
hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]
Option Name and Value Description Default
--------------------- ----------- -------
heap=dump|sites|all heap profiling all
cpu=samples|times|old CPU usage off
monitor=y|n monitor contention n
format=a|b text(txt) or binary output a
file=<file> write data to file java.hprof[{.txt}]
net=<host>:<port> send data over a socket off
depth=<size> stack trace depth 4
interval=<ms> sample interval in ms 10
cutoff=<value> output cutoff point 0.0001
lineno=y|n line number in traces? y
thread=y|n thread in traces? n
doe=y|n dump on exit? y
msa=y|n Oracle Solaris micro state accounting n
force=y|n force output to <file> y
verbose=y|n print messages about dumps y
Obsolete Options
----------------
gc_okay=y|n
<>
Examples
--------
- Get sample cpu information every 20 millisec, with a stack depth of 3:
java -agentlib:hprof=cpu=samples,interval=20,depth=3 classname
- Get heap usage information based on the allocation sites:
java -agentlib:hprof=heap=sites classname
Notes
-----
- The option format=b cannot be used with monitor=y.
- The option format=b cannot be used with cpu=old|times.
- Use of the -Xrunhprof interface can still be used, e.g.
java -Xrunhprof:[help]|[<option>=<value>, ...]
will behave exactly the same as:
java -agentlib:hprof=[help]|[<option>=<value>, ...]
Warnings
--------
- This is demonstration code for the JVMTI interface and use of BCI,
it is not an official product or formal part of the JDK.
- The -Xrunhprof interface will be removed in a future release.
- The option format=b is considered experimental, this format may change
in a future release.
ヒープ・プロファイル情報(サイトとダンプ)はデフォルトで、現在の作業ディレクトリ内のjava.hprof.txtに(ASCIIで)書き出されます。
出力は通常、JVM終了時に生成されますが、それを無効にするには、doe (終了時にダンプ)オプションをnに設定します(doe=n)。 さらに、[Ctrl]+[\] (OracleおよびLinuxオペレーティング・システムの場合)または[Ctrl]+[Break] (Windowsの場合)を押すと、プロファイルが生成されます。 Oracle SolarisおよびLinuxオペレーティング・システムでは、プロセスがQUITシグナルを受信したとき(kill -QUIT pid)にもプロファイルが生成されます。 [Ctrl]+[\]または[Ctrl]+[Break]を複数回押すと、1つのファイルに複数のプロファイルが生成されます。
ほとんどの場合、出力にはトレース、スレッド、およびオブジェクトのIDが含まれています。 それぞれのタイプのIDは通常、ほかのIDとは異なる番号から始まります。 たとえば、トレースは300000から始まることがあります。
2.8.2 ヒープ割当てプロファイルheap=sites
例2-8は、一連の入力ファイルでのJavaコンパイラ(javac)の実行により生成されたヒープ割当てプロファイルです。 ここでは、プロファイラ出力の一部のみを示します。
例2-8 ヒープ割当てプロファイル
$ javac -J-agentlib:hprof=heap=sites Hello.java
SITES BEGIN (ordered by live bytes) Wed Oct 4 13:13:42 2006
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 44.13% 44.13% 1117360 13967 1117360 13967 301926 java.util.zip.ZipEntry
2 8.83% 52.95% 223472 13967 223472 13967 301927 com.sun.tools.javac.util.List
3 5.18% 58.13% 131088 1 131088 1 300996 byte[]
4 5.18% 63.31% 131088 1 131088 1 300995 com.sun.tools.javac.util.Name[]
ヒープ・プロファイル内の重要な情報は、プログラムのさまざまな部分で行われる割当ての量です。 前述のSITESレコードは、合計領域の44.13%がjava.util.zip.ZipEntryオブジェクトに割り当てられたことを示しています。
割当てサイトをソース・コードに関連付けるには、ヒープ割当ての原因となった動的スタック・トレースを記録するのが早道です。 例2-9は、プロファイラ出力の別の部分を示しています。 前述の出力では4つの割当てサイトによって参照されていたスタック・トレースを示しています。
例2-9 スタック・トレースのプロファイラ出力
TRACE 301926:
java.util.zip.ZipEntry.<init>(ZipEntry.java:101)
java.util.zip.ZipFile+3.nextElement(ZipFile.java:417)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1374)
com.sun.tools.javac.jvm.ClassReader.list(ClassReader.java:1631)
TRACE 301927:
com.sun.tools.javac.util.List.<init>(List.java:42)
com.sun.tools.javac.util.List.<init>(List.java:50)
com.sun.tools.javac.util.ListBuffer.append(ListBuffer.java:94)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1374)
TRACE 300996:
com.sun.tools.javac.util.Name$Table.<init>(Name.java:379)
com.sun.tools.javac.util.Name$Table.<init>(Name.java:481)
com.sun.tools.javac.util.Name$Table.make(Name.java:332)
com.sun.tools.javac.util.Name$Table.instance(Name.java:349)
TRACE 300995:
com.sun.tools.javac.util.Name$Table.<init>(Name.java:378)
com.sun.tools.javac.util.Name$Table.<init>(Name.java:481)
com.sun.tools.javac.util.Name$Table.make(Name.java:332)
com.sun.tools.javac.util.Name$Table.instance(Name.java:349)
スタック・トレースの各フレームには、クラス名、メソッド名、ソース・ファイル名、および行番号が含まれています。 ユーザーは、HPROFエージェントによって収集されるフレームの最大数を設定できます。 デフォルトの上限は4です。 スタック・トレースには、ヒープ割り当てを行なったメソッドだけでなく、最終的にメモリー割当てが発生する呼出しを行なったメソッドも表示されます。
2.8.3 ヒープ・ダンプ・プロファイルheap=dump
ヒープ・ダンプはheap=dumpオプションを使用して取得できます。 ヒープ・ダンプの形式は、formatオプションの設定に応じてASCII、バイナリのいずれかです。 jhatなどのツールではバイナリ形式を使用するので、format=bオプションが必要です。 詳細は、「jhatユーティリティ」を参照してください。 バイナリ形式が指定された場合、プリミティブ型のインスタンス・フィールドとプリミティブ配列の内容がダンプに含まれます。
例2-10は、javacコンパイラの実行から、ヒープ内の現在のライブ・オブジェクトの完全なダンプをASCIIテキスト形式で生成するコマンドを示しています。
例2-10 ASCIIテキストでのダンプ
$ javac -J-agentlib:hprof=heap=dump Hello.java
HEAP DUMP BEGIN (39793 objects, 2628264 bytes) Wed Oct 4 13:54:03 2006
ROOT 50000114 (kind=<thread>, id=200002, trace=300000)
ROOT 50000006 (kind=<JNI global ref>, id=8, trace=300000)
ROOT 50008c6f (kind=<Java stack>, thread=200000, frame=5)
:
CLS 50000006 (name=java.lang.annotation.Annotation, trace=300000)
loader 90000001
OBJ 50000114 (sz=96, trace=300001, class=java.lang.Thread@50000106)
name 50000116
group 50008c6c
contextClassLoader 50008c53
inheritedAccessControlContext 50008c79
blockerLock 50000115
OBJ 50008c6c (sz=48, trace=300000, class=java.lang.ThreadGroup@50000068)
name 50008c7d
threads 50008c7c
groups 50008c7b
ARR 50008c6f (sz=16, trace=300000, nelems=1,
elem type=java.lang.String[]@5000008e)
[0] 500007a5
CLS 5000008e (name=java.lang.String[], trace=300000)
super 50000012
loader 90000001
:
HEAP DUMP END
出力は大きなファイルになります。 これは、ガベージ・コレクタによって決定されたルート・セットと、そのルート・セットから到達可能なヒープ内の各Javaオブジェクトごとのエントリから構成されます。 次は、サンプル・ヒープ・ダンプから選択されたいくつかのレコードです。
各レコードは、ルート、オブジェクト・インスタンス、クラス、または配列を表すROOT、OBJ、CLS、またはARRです。 16進数は、HPROFによって割り当てられた識別子です。 これらの数値は、あるオブジェクトから別のオブジェクトへの参照を示すために使用されます。 前述の例で、java.lang.Threadのインスタンス50000114には、そのスレッド・グループ(50008c6c)と他のオブジェクトへの参照があります。
一般に出力のサイズは非常に大きいので、ツールを使ってヒープ・ダンプの出力をビジュアル化または処理する必要があります。 そのようなツールの1つがjhatです。 jhatユーティリティを参照してください。
2.8.4 CPU使用率サンプリング・プロファイルcpu=samples
HPROFツールは、スレッドのサンプリングによってCPU使用率の情報を収集できます。 例2-11は、javacコンパイラの実行によりCPU使用率サンプリング・プロファイルを生成する方法を示しています。
例2-11 CPU使用率サンプリング・プロファイル
$ javac -J-agentlib:hprof=cpu=samples Hello.java
CPU SAMPLES BEGIN (total = 462) Wed Oct 4 13:33:07 2006
rank self accum count trace method
1 49.57% 49.57% 229 300187 java.util.zip.ZipFile.getNextEntry
2 6.93% 56.49% 32 300190 java.util.zip.ZipEntry.initFields
3 4.76% 61.26% 22 300122 java.lang.ClassLoader.defineClass2
4 2.81% 64.07% 13 300188 java.util.zip.ZipFile.freeEntry
5 1.95% 66.02% 9 300129 java.util.Vector.addElement
6 1.73% 67.75% 8 300124 java.util.zip.ZipFile.getEntry
7 1.52% 69.26% 7 300125 java.lang.ClassLoader.findBootstrapClass
8 0.87% 70.13% 4 300172 com.sun.tools.javac.main.JavaCompiler.<init>
9 0.65% 70.78% 3 300030 java.util.zip.ZipFile.open
10 0.65% 71.43% 3 300175 com.sun.tools.javac.main.JavaCompiler.<init>
...
CPU SAMPLES END
HPROFエージェントは、実行中のすべてのスレッドのスタックを定期的にサンプリングし、もっとも頻繁にアクティブになるスタック・トレースを記録します。 上のcountフィールドは、特定のスタック・トレースがアクティブであることが見つかった回数を示しています。 これらのスタック・トレースは、アプリケーション内のCPU使用率のホット・スポットに相当します。
2.8.5 CPU使用時間プロファイルcpu=times
HPROFツールは、CPU使用率の情報を収集するために、あらゆるメソッドの入口と出口にコードを挿入し、それによって正確なメソッド呼出し回数と各メソッド内で費やされた時間を追跡します。 このプロセスではバイトコード・インデックス(BCI)が使用されるため、実行速度はcpu=samplesオプションよりもかなり低下します。 例2-12は、javacコンパイラの実行から収集されたCPU使用時間プロファイル出力の一部を示しています。
例2-12 CPU使用時間プロファイル
$ javac -J-agentlib:hprof=cpu=times Hello.java
CPU TIME (ms) BEGIN (total = 2082665289) Wed oct 4 13:43:42 2006
rank self accum count trace method
1 3.70% 3.70% 1 311243 com.sun.tools.javac.Main.compile
2 3.64% 7.34% 1 311242 com.sun.tools.javac.main.Main.compile
3 3.64% 10.97% 1 311241 com.sun.tools.javac.main.Main.compile
4 3.11% 14.08% 1 311173 com.sun.tools.javac.main.JavaCompiler.compile
5 2.54% 16.62% 8 306183 com.sun.tools.javac.jvm.ClassReader.listAll
6 2.53% 19.15% 36 306182 com.sun.tools.javac.jvm.ClassReader.list
7 2.03% 21.18% 1 307195 com.sun.tools.javac.comp.Enter.main
8 2.03% 23.21% 1 307194 com.sun.tools.javac.comp.Enter.complete
9 1.68% 24.90% 1 306392 com.sun.tools.javac.comp.Enter.classEnter
10 1.68% 26.58% 1 306388 com.sun.tools.javac.comp.Enter.classEnter
...
CPU TIME (ms) END
この出力で、countはこのメソッドに入った本当の回数を表し、パーセンテージはこのメソッドで費やされたスレッドCPU時間の尺度を表します。