HPROF: ヒープ/CPU プロファイリングツール
Java 2 Platform Standard Edition (J2SE) では、ヒープと CPU のプロファイリング用に HPROF と呼ばれる簡単なコマンド行プロファイリングツールが常に提供されます。HPROF は、実際には JVM のネイティブエージェントライブラリであり、JVM の起動時にコマンド行オプションで動的にロードされ、JVM プロセスの一部になります。ユーザーは、起動時に HPROF のオプションを指定することで、HPROF に対してヒープ、CPU、またはその両方のさまざまなプロファイリング機能を要求できます。生成されるデータは、テキスト形式またはバイナリ形式にでき、メモリー使用量や効率の低いコードが関与するパフォーマンス上の問題を見つけて切り分けるために使用できます。HPROF によって生成されるバイナリ形式ファイルは、HAT などのツールでヒープ内の割り当て済みオブジェクトを参照するために使用できます。
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 ディレクトリから入手できます)、それをカスタマイズしたり、独自の特別なプロファイリングツールを作成したりすることも可能です。