HPROF: ヒープ/CPUプロファイリング・ツール
Java 2 Platform Standard Edition (J2SE)では、ヒープとCPUのプロファイリング用にHPROFと呼ばれる簡単なコマンド行プロファイリング・ツールが常に提供されます。HPROFは、実際にはJVMのネイティブ・エージェント・ライブラリであり、JVMの起動時にコマンド行オプションで動的にロードされ、JVMプロセスの一部になります。ユーザーは、起動時にHPROFのオプションを指定することで、HPROFに対してヒープ、CPU、またはその両方のさまざまなプロファイリング機能を要求できます。生成されるデータは、テキスト形式またはバイナリ形式にでき、メモリー使用量や効率の低いコードが関与するパフォーマンス上の問題を見つけて切り分けるために使用できます。HPROFによって生成されるバイナリ形式ファイルは、jhatなどのツールでヒープ内の割当て済みオブジェクトを参照するために使用できます。
J2SE Version 5.0では、HPROFは新しいJava Virtual Machine Tool Interface (JVM TI)上に実装されています。
HPROFの起動
HPROFでは、CPU使用率、ヒープ割当ての統計データ、およびコンテンション・モニター・プロファイルを表示できます。さらに、完全なヒープ・ダンプや、Java仮想マシン内のすべてのモニターとスレッドの状態を報告することもできます。HPROFは次のようにして呼び出すことができます。
java -agentlib:hprof[=options] ToBeProfiledClass
または
java -Xrunhprof[:options] ToBeProfiledClass
HPROFは、要求するプロファイリングの種類に応じて、該当するJVM TIイベントを送信するように仮想マシンに指示し、そのイベント・データを処理してプロファイリング情報を生成します。たとえば、次のコマンドはヒープ割当てプロファイルを取得します。
java -agentlib:hprof=heap=sites ToBeProfiledClass
HPROFに渡すことができるオプションの完全なリストを次に示します。
java -agentlib:hprof=help
HPROF: Heap and CPU Profiling Agent (JVM TI 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 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 JVM TI interface and use of BCI,
it is not an official product or formal part of the J2SE.
- 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.
ヒープ・プロファイリング情報(sitesおよびdump)は、デフォルトではjava.hprof.txtに書き込まれます(ASCII)。ほとんどの場合、出力にはトレース、スレッド、およびオブジェクトのIDが含まれています。それぞれのIDは、通常、ほかのIDとは異なる番号から始まります。たとえば、トレースは300000から始まります。
通常、デフォルト(force=y)では出力ファイル内の既存の情報が上書きされるため、複数のVMが実行されている環境でHPROFを有効にした場合は、必要に応じてforce=nを使用し、出力ファイル名の末尾に文字が追加されるようにしてください。
intervalオプションは、cpu=samplesにのみ適用され、スレッドのサンプリングがスレッド・スタックのサンプル間でスリープする時間を制御します。
msaオプションは、Solarisにのみ適用され、Solarisマイクロ・ステート・アカウンティングが使用されるようにします。
interval、msa、およびforceオプションは、J2SE 1.5で新たに導入されたHPROFのオプションです。
使用例
アプリケーションを作成することもできますが、ここではJ2SEの既存のJavaアプリケーションであるjavacを取り上げます。javacでは、-Jを使ってJavaオプションを渡す必要があります。Javaを直接実行している場合は、接頭辞 -Jを使用しません。
環境変数JAVA_TOOL_OPTIONSを使ってJ2SE 5.0のJavaオプションを渡す方法もありますが、どのような環境変数も、対象となるVM以外に影響を与えないように注意する必要があります。
ヒープ割当てプロファイル(heap=sites)
一連の入力ファイルに対してJavaコンパイラ(javac)を実行することで生成されたヒープ割当てプロファイルを次に示します。ここでは、プロファイラの出力ファイル(java.hprof.txt)の一部のみを示します。
Command used: javac -J-agentlib:hprof=heap=sites Hello.java
SITES BEGIN (ordered by live bytes) Fri Oct 22 11:52:24 2004
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 44.73% 44.73% 1161280 14516 1161280 14516 302032 java.util.zip.ZipEntry
2 8.95% 53.67% 232256 14516 232256 14516 302033 com.sun.tools.javac.util.List
3 5.06% 58.74% 131504 2 131504 2 301029 com.sun.tools.javac.util.Name[]
4 5.05% 63.79% 131088 1 131088 1 301030 byte[]
5 5.05% 68.84% 131072 1 131072 1 301710 byte[]
ヒープ・プロファイルに含まれる重要な情報は、プログラムのさまざまな部分で行われる割当ての量です。上記のSITESレコードを見ると、全領域の44.73%が特定のサイト(深さが固定されている固有のスタック・トレース)でjava.util.zip.ZipEntryオブジェクトに割り当てられています。ライブ・データの量が割当て量の合計と一致しているため、HPROFがヒープを反復する直前にガベージ・コレクションが行われた可能性があります。通常、ライブ・データの量は特定のサイトで行われた割当ての合計以下になります。
割当てサイトをソース・コードに関連付けるには、ヒープ割当ての原因となった動的スタック・トレースを記録するのが早道です。上記の出力に含まれる割当てサイトの上位2つによって参照されたスタック・トレースを示すjava.hprof.txtファイルの別の部分を次に示します。
TRACE 302032:
java.util.zip.ZipEntry.<init>(ZipEntry.java:101)
java.util.zip.ZipFile$3.nextElement(ZipFile.java:435)
java.util.zip.ZipFile$3.nextElement(ZipFile.java:413)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)
TRACE 302033:
com.sun.tools.javac.util.List.<init>(List.java:43)
com.sun.tools.javac.util.List.<init>(List.java:51)
com.sun.tools.javac.util.ListBuffer.append(ListBuffer.java:98)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)
スタック・トレースの各フレームには、クラス名、メソッド名、ソース・ファイル名、および行番号が含まれています。ユーザーは、HPROFエージェントによって収集されるフレームの最大数(depthオプション)を設定できます。depthのデフォルトは4です。スタック・トレースには、ヒープ割り当てを行なったメソッドだけでなく、最終的にメモリー割当てが発生する呼出しを行なったメソッドも表示されます。
上記のスタック・トレースは、実行中のすべてのスレッドで共有されるため、異なるスレッドのスタック・トレースを分離する必要がある場合は、threadオプションを使用する必要があります。これにより、使用される領域と出力ファイル内のスタック・トレースの数が増加します。
スタックの深さが十分でない場合は、depthオプションを使用してスタックの深さを増やすことができます。現在のところ、再帰は特別に扱われないため、非常に深い再帰スタック上で呼出し側の情報を取得するのは困難です。depthが大きいほど、スタック・トレースを保存するためにより多くの領域が必要になります。
では、上の情報から何がわかるでしょうか。javacでは、ZipEntryクラスやListクラスのインスタンスが数多く存在するのは当然のことなので、javacがこれらのクラスに大きく依存しているという以外に言えることはほとんどありません。通常、同じ場所で割り当てられたオブジェクトが過剰と思われるほど大量に蓄積されている場合は、注意する必要があります。
高度にマルチスレッド化されているアプリケーションでは、同一の実行で上記の情報が再現されるとは考えないでください。
このオプションは、オブジェクト割り当てとガベージ・コレクションに対するデータ収集(スタック・トレース)のため、アプリケーションのパフォーマンスに影響を与えることがあります。
ヒープ・ダンプ(heap=dump)
次のようにして、ヒープ内の現在のライブ・オブジェクトの完全なダンプを取得できます。
Command used: javac -J-agentlib:hprof=heap=dump Hello.java
この出力ファイルは非常に大きくなりますが、任意のエディタで表示および検索できます。ただし、この種の詳細情報を表示するには、HATを使用するのがより適切です。上記のheap=sitesオプションのすべての情報が含まれ、さらにあらゆる割当て済みオブジェクトの詳細情報と、すべてのオブジェクトへの参照が追加されます。
このオプションは、あらゆる割当て済みオブジェクトの詳細情報を格納するため、大量のメモリーを使用します。また、オブジェクト割り当てとガベージ・コレクションに対するデータ収集(スタック・トレース)のため、アプリケーションのパフォーマンスにも影響を与えることがあります。
CPU使用率サンプリング・プロファイル(cpu=samples)
h2>
HPROFは、スレッドのサンプリングによってCPU使用率の情報を収集できます。次は、javacコンパイラの実行から収集された出力の一部です。
Command used: javac -J-agentlib:hprof=cpu=samples Hello.java CPU SAMPLES BEGIN (total = 126) Fri Oct 22 12:12:14 2004 rank self accum count trace method 1 53.17% 53.17% 67 300027 java.util.zip.ZipFile.getEntry 2 17.46% 70.63% 22 300135 java.util.zip.ZipFile.getNextEntry 3 5.56% 76.19% 7 300111 java.lang.ClassLoader.defineClass2 4 3.97% 80.16% 5 300140 java.io.UnixFileSystem.list 5 2.38% 82.54% 3 300149 java.lang.Shutdown.halt0 6 1.59% 84.13% 2 300136 java.util.zip.ZipEntry.initFields 7 1.59% 85.71% 2 300138 java.lang.String.substring 8 1.59% 87.30% 2 300026 java.util.zip.ZipFile.open 9 0.79% 88.10% 1 300118 com.sun.tools.javac.code.Type$ErrorType.<init> 10 0.79% 88.89% 1 300134 java.util.zip.ZipFile.ensureOpen
HPROFエージェントは、実行中のすべてのスレッドのスタックを定期的にサンプリングし、もっとも頻繁にアクティブになるスタック・トレースを記録します。上記のcountフィールドは、特定のスタック・トレースがアクティブになった回数(メソッドが呼び出された回数ではない)を示します。これらのスタック・トレースは、アプリケーション内のCPU使用率のホット・スポットに相当します。このオプションでは、ロードされるクラスおよびすべてのオプションのBCIや変更は必要なく、プロファイリングされるアプリケーションへの影響を最小限に抑えることができます。
intervalオプションを使用すると、サンプリング時間(スレッドのサンプリングがサンプル間でスリープする時間)を調整できます。
では、上の情報から何がわかるでしょうか。まず、サンプルが126個しかなく、統計的にきわめて不十分なサンプルです。より大きなJavaソース・ファイル(できれば、まとまった数のJavaソース)をコンパイルすると、より適切な情報が得られる可能性があります。次に、当然のことながらjavacがZipFileクラスに大きく依存していることがわかるという点で、このデータはheap=sitesのデータとほぼ一致します。ZipFileのパフォーマンスを向上させることで、javacのパフォーマンスも向上する可能性があります。該当するスタック・トレースを次に示します。
TRACE 300027: java.util.zip.ZipFile.getEntry(ZipFile.java:Unknown line) java.util.zip.ZipFile.getEntry(ZipFile.java:253) java.util.jar.JarFile.getEntry(JarFile.java:197) java.util.jar.JarFile.getJarEntry(JarFile.java:180) TRACE 300135: java.util.zip.ZipFile.getNextEntry(ZipFile.java:Unknown line) java.util.zip.ZipFile.access$700(ZipFile.java:35) java.util.zip.ZipFile$3.nextElement(ZipFile.java:419) java.util.zip.ZipFile$3.nextElement(ZipFile.java:413)
高度にマルチスレッド化されているアプリケーションでは、特にサンプル数が少ない場合、同一の実行で上記の情報が再現されるとは考えないでください。
CPU使用時間プロファイル(cpu=times)
HPROFは、CPU使用率の情報を収集するために、あらゆるメソッドの入口と出口にコードを挿入し、正確なメソッド呼出し回数と各メソッド内で費やされた時間を追跡します。このために、バイト・コード・インジェクション(BCI)が使用され、実行速度はcpu=samplesよりかなり低下します。次は、javacコンパイラの実行から収集された出力の一部です。
Command used: javac -J-agentlib:hprof=cpu=times Hello.java CPU TIME (ms) BEGIN (total = 103099259) Fri Oct 22 12:21:23 2004 rank self accum count trace method 1 5.28% 5.28% 1 308128 com.sun.tools.javac.Main.compile 2 5.16% 10.43% 1 308127 com.sun.tools.javac.main.Main.compile 3 5.15% 15.58% 1 308126 com.sun.tools.javac.main.Main.compile 4 4.07% 19.66% 1 308060 com.sun.tools.javac.main.JavaCompiler.compile 5 3.90% 23.56% 1 306652 com.sun.tools.javac.comp.Enter.main 6 3.90% 27.46% 1 306651 com.sun.tools.javac.comp.Enter.complete 7 3.74% 31.21% 4 305626 com.sun.tools.javac.jvm.ClassReader.listAll 8 3.74% 34.95% 18 305625 com.sun.tools.javac.jvm.ClassReader.list 9 3.24% 38.18% 1 305831 com.sun.tools.javac.comp.Enter.classEnter 10 3.24% 41.42% 1 305827 com.sun.tools.javac.comp.Enter.classEnter 11 3.24% 44.65% 1 305826 com.sun.tools.javac.tree.Tree$TopLevel.accept 12 3.24% 47.89% 1 305825 com.sun.tools.javac.comp.Enter.visitTopLevel 13 3.23% 51.12% 1 305725 com.sun.tools.javac.code.Symbol.complete 14 3.23% 54.34% 1 305724 com.sun.tools.javac.jvm.ClassReader.complete 15 3.23% 57.57% 1 305722 com.sun.tools.javac.jvm.ClassReader.fillIn 16 1.91% 59.47% 16 305611 com.sun.tools.javac.jvm.ClassReader.openArchive 17 1.30% 60.78% 330 300051 java.lang.ClassLoader.loadClass 18 1.28% 62.06% 330 300050 java.lang.ClassLoader.loadClass 19 1.22% 63.28% 512 300695 java.net.URLClassLoader.findClass 20 1.21% 64.48% 512 300693 java.net.URLClassLoader$1.run 21 1.09% 65.57% 14516 305575 java.util.zip.ZipFile$3.nextElement 22 0.98% 66.55% 14516 305574 java.util.zip.ZipFile$3.nextElement 23 0.96% 67.52% 1 304560 com.sun.tools.javac.main.JavaCompiler.instance 24 0.96% 68.48% 1 304559 com.sun.tools.javac.main.JavaCompiler.<init> 25 0.71% 69.19% 256 302078 java.net.URLClassLoader.access$100
ここで、countはこのメソッドに入った本当の回数を表し、パーセンテージはこれらのメソッドで費やされたスレッド時間の尺度を表します。
通常、行番号はトレースに含まれませんが、linenoオプションを使って追加できます。
上記のデータを見ると、ZipFile$3クラスの一部のメソッドの呼出し回数が14,000回を超えているにもかかわらず、それらのメソッドが大量のCPU時間を使用しているようには見えません。やはり、これはサンプルが十分でないことの表れであるため、時間をかけて上記の情報を解析することはしません。
HPROFとHATの併用
HAT (ヒープ解析ツール)は、HPROFのバイナリ形式を使用してWebページを作成し、ヒープ内のすべてのオブジェクトを参照したり、オブジェクト間のすべての参照を表示したりできるブラウザ・ベースのツールです。
HPROFの簡単な歴史
J2SEの以前のバージョン(1.2から1.4まで)には、試験的なJVMPI上に構築されたHPROFエージェントが含まれていました。JVMPIは古い1.2のClassic VMでは確実に動作しましたが、1.3および1.4リリースの新しいHotSpot VMや各種のガベージ・コレクタでは不安定で維持することは困難でした。J2SE 5.0では、JVMDIとJVMPIが新しいJVM TIに置き換えられました。5.0リリースでは、JVMPIが引き続き使用可能であり、1.4.2で導入された古いJVMPIベースのHPROFエージェントも5.0で実際に使用できますが、非推奨です。J2SE 5.0の新しいHPROFは、(一部の例外を除いて)古いHPROFに置き換わるフル機能のツールですが、ソースに関しては完全な書換えに近いものでした。古いオプションはすべて使用可能であり、出力形式も基本的に同じです。したがって、古いHPROFの出力に慣れている場合や、任意のHPROF形式を読み取るツールがある場合は、相違点はあまりなく、従来のJVMPIベースのHPROFで発生していた問題が減ることも期待できます。HPROFのソースは、完全なJDKダウンロードのdemo/jvmti/hprofインストール・ディレクトリから入手できます。
HPROFの動作
HPROFは、動的にリンクされるネイティブ・ライブラリです。JVM TIを使用し、ファイル記述子またはソケットにASCII形式またはバイナリ形式でプロファイリング情報を書き出します。この情報は、さらにプロファイラのフロントエンド・ツールで処理したり、ファイルにダンプしたりできます。この情報は、JVM TIの呼出し、JVM TIからのイベント・コールバック、およびVMにロードされたすべてのクラス・ファイル・イメージに対するバイト・コード挿入(BCI)を利用して生成されます。JVM TIにはJVMTI_EVENT_CLASS_FILE_LOAD_HOOKと呼ばれるイベントがあり、これによってHPROFは実際にVMにロードされる前にクラス・ファイル・イメージにアクセスし、そのクラス・ファイル・イメージを変更する機会を得ます。怖いですか。そのとおり、BCIを甘く見てはいけません。HPROFの場合、BCIの操作はバイト・コードの動作を計測するだけであり、変更しません。HPROFがBCIを実行するには、JVM TIを使用することが非常に重要でした。これは、java.lang.Objectのような初期のクラスを含むすべてのクラスに対してBCIを実行する必要があったためです。もちろん、VMがこの挿入されたコードを実行できる段階(通常はJVMTI_EVENT_VM_INITイベント)に達するまでは、計測コードを動作不能にする必要があります。
HPROFが実行するBCIの量は、指定されるオプションに依存します。cpu=timesでは、すべてのメソッドの入口と出口に挿入が行われます。heapオプションでは、java.lang.objectの<init>メソッドと、任意のメソッドに含まれる「newarray」操作コードに対してBCIが実行されます。このBCIの操作は、実際には共有ライブラリjava_crw_demoによって行われます。このライブラリは、一連のオプションとクラス・ファイル・イメージを受け入れ、新しいクラス・ファイル・イメージを返します。java_crw_demoライブラリは、J2SE 5.0のdemo/jvmtiディレクトリに含まれるソースの一部です。
現在のところ、HPROFはstatic Javaメソッドへの呼出しを挿入し、それらのメソッドがHPROFエージェント・ライブラリ自体に含まれるネイティブ・メソッドを呼び出します。これは、プロファイリング時に導入される余分なJavaコードを制限するために、初期の設計段階で選択された方法です。したがって、要求されたJVM TIイベントと作成されたBCIイベントの組み合わせが、HPROFの動作の基本になっています。
cpu=samplesオプションでは、HPROFはBCIを使用せず、別個のスレッドを生成します。このスレッドは、一定のマイクロ秒数だけスリープしてから起動し、JVM TIを使用して実行中のすべてのスレッド・スタックをサンプリングします。
cpu=timesオプションでは、すべてのスレッドの実行中のスタックを追跡し、すべてのメソッドの正確なCPU使用時間を保持しようとします。このオプションでは、あらゆるメソッドの入口と出口が追跡されるため、VMにもっとも大きな負荷がかかる可能性があります。メソッドの呼出しが多いアプリケーションは、ほかのアプリケーションより大きな影響を受けます。
heap=sitesおよびheap=dumpオプションは、オブジェクトの割り当てを追跡する必要があるオプションです。これらのオプションは、(hprof=sitesよりは少ないが)大量にメモリーを使用する可能性があり、多くのオブジェクトを割り当てるアプリケーションや、オブジェクトの割り当てと解放を繰り返すアプリケーションは、これらのオプションによって大きな影響を受けます。オブジェクトが割り当てられるたびに、どこでオブジェクトが割り当てられたかを知るためにスタックをサンプリングし、そのスタック情報を保存する必要があります。HPROFには、C (malloc())ヒープに割り当てられた一連の表があり、そこにすべての情報が記録されます。現在のところ、HPROFはJavaオブジェクトを割り当てません。
サマリー
これまでの説明でわかるように、HPROFエージェントはさまざまなプロファイルを生成するために使用できます。しかし、上記のjavacを使った例が示すように、データを有意義なものにするには、十分な数のサンプリングを行う必要があります。
度胸のあるC/JNIプログラマなら、HPROFのソースを入手して(J2SE SDKのdemo/jvmti/hprofディレクトリから入手できます)、それをカスタマイズしたり、独自の特別なプロファイリング・ツールを作成したりすることも可能です。