2017.11.22
HProf
概要
HProfはHeapとCPU Profiling Agentの略でJDKレベルで提供されている形式のプロファイラです。 HProfは次のような特徴を持ちます。
・JDK 1.4まではJVMPIは、JDK 1.5からJVMTIインタフェースを介して実装します。 ・CPU Profiling、Heap Profiling、Monitor Monitoringなどの基本的な機能を提供します。 ・JDK標準はないが、ほとんどのすべてのJVM Vendorが実装を提供します。つまり、事実上の標準です。 ・HProfを介して収集されたデータは、Heap Analyzerのようなツールと連動して、より詳細な分析を行うことができます。
たとえばHProfが、JVMPIやJVMTIインターフェースとして提供している簡単なAgentが、Profilingに欠かせない基本的な機能として提供されるため、市販のProfilerを導入する前に、必ず利用みることをお勧めします。
使い方
Syntax
HProfの基本的なSyntaxは、以下の通りです。
java -Xrunhprof:heap=sites,cpu=samples,file=prof2.txt [Main Class] (>= JDK 1.4)
java -agentlib:hprof=heap=sites,cpu=samples,file=prof2.txt [Main Class] (>= JDK 1.5)
helpコマンドを使用すると、詳細なSyntaxを得ることができます。
Prompt>java -Xrunhprof:help
HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)
hprof usage: java -agentlib:hprof=[help]|[=, ...]
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= write data to file java.hprof[.txt]
net=: send data over a socket off
depth= stack trace depth 4
interval= sample interval in ms 10
cutoff= 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 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]|[=, ...]
will behave exactly the same as:
java -agentlib:hprof=[help]|[=, ...]
Warnings
--------
- This is demonstration code for the JVMTI 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.
出力ファイル（java.hprof.tx）
HProfの実行結果は、ファイル名を指定しない限りjava.hprof.txtという名前で保存されます。このファイル名は、file=オプションで変更することができます。
java -Xrunhprof:file=prof2.txt [Main Class]
java.hprof.txtファイルは指定されたオプションに応じてThread Stack Trace情報、Monitor情報、Heap情報などを提供します。
Signal
HProfによる出力結果は、基本的にJVMが終了（Exit）された時点でDumpファイルに格納されます。もし終了時点ではなく、特定の時間帯にProfiling結果を保存しようとする場合には、Signalを利用すればよいです。doe（dump on exit）オプションを使用すると、Dumpファイルに記録された時点を変更することができます。
Prompt> java -Xrunhprof:heap=sites,doe=n [Main Class]
- Windows Prompt> Ctrl + Break またはSendSignal利用 - Unix / Linux Prompt> Ctrl +\または Prompt> kill-3[PID]
上記の方法を利用すると、次のようにProfiling結果を複数回に渡って記録することができます。
SITES BEGIN (ordered by live bytes) Thu Oct 18 17:48:12 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 52.69% 52.69% 4401216 91725 4401216 91725 300228 char[]
2 26.35% 79.04% 2201400 91725 2201400 91725 300229 java.lang.String
3 6.47% 85.51% 540560 6757 5738320 71729 300233 char[]
4 5.64% 91.15% 470720 2 1412176 42 300230 java.lang.Object[]
5 3.88% 95.03% 324384 6758 4402896 91727 300226 char[]
6 1.94% 96.97% 162192 6758 2201448 91727 300227 java.lang.String
7 1.29% 98.27% 108144 6759 1467648 91728 300225 java.lang.StringBuilder
8 0.21% 98.48% 17760 3 17760 3 300074 byte[]
SITES END
SITES BEGIN (ordered by live bytes) Thu Oct 18 17:48:13 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 55.39% 55.39% 5643120 117598 5643120 117598 300228 char[]
2 27.70% 83.09% 2822352 117598 2822352 117598 300229 java.lang.String
3 8.09% 91.17% 823760 3 1765216 43 300230 java.lang.Object[]
4 3.53% 94.70% 359360 4492 7808080 97601 300233 char[]
5 2.12% 96.82% 215808 4496 5644800 117600 300226 char[]
6 1.06% 97.88% 107808 4492 2822376 117599 300227 java.lang.String
7 0.71% 98.58% 71888 4493 1881600 117600 300225 java.lang.StringBuilder
8 0.17% 98.76% 17760 3 17760 3 300074 byte[]
SITES END
SITES BEGIN (ordered by live bytes) Thu Oct 18 17:48:15 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 55.68% 55.68% 6827520 142273 6827520 142273 300228 char[]
2 27.85% 83.53% 3414552 142273 3414552 142273 300229 java.lang.String
3 9.60% 93.13% 1176800 4 2118256 44 300230 java.lang.Object[]
4 2.71% 95.84% 332240 4153 9782160 122277 300233 char[]
5 1.63% 97.47% 199536 4157 6829200 142275 300226 char[]
6 0.81% 98.28% 99600 4150 3414576 142274 300227 java.lang.String
7 0.54% 98.82% 66464 4154 2276416 142276 300225 java.lang.StringBuilder
8 0.14% 98.97% 17760 3 17760 3 300074 byte[]
SITES END
Heap Profilng
Heap Allocation Profiling
heap= sitesオプションを使用すると、Objectの数と大きさの情報を統計的に照会することができます。下に簡単な例を示します。
prompt> java -Xrunhprof:heap=sites [Main Class]
...
TRACE 300228:
java.lang.String.(String.java:208)
java.lang.StringBuilder.toString(StringBuilder.java:431)
alloc1.run(gc_dump.java:35)
...
SITES BEGIN (ordered by live bytes) Mon Sep 17 13:19:05 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 54.56% 54.56% 21856800 455383 21856800 455383 300228 char[]
2 27.28% 81.84% 10929192 455383 10929192 455383 300229 java.lang.String
3 5.95% 87.79% 2382976 2 7148992 50 300230 java.lang.Object[]
4 5.64% 93.43% 2261040 28263 34830800 435385 300233 char[]
5 3.39% 96.82% 1356576 28262 21858432 455384 300226 char[]
6 1.69% 98.51% 678336 28264 10929192 455383 300227 java.lang.String
7 1.13% 99.64% 452240 28265 7286144 455384 300225 java.lang.StringBuilder
8 0.04% 99.68% 17760 3 17760 3 300074 byte[]
SITES END
上記の結果を解釈するとchar[]オブジェクトに約20M（21856800）が使用され、455,383個のインスタンスが生成されているのが和kります。liveオブジェクトは、現在Live状態のオブジェクトを、alloc’edオブジェクトは、Application行った後、割り当てられたすべてのオブジェクトを意味します。このオブジェクトに割り当てを実行するStack trace番号は300228です。300228に対応するStack Traceはalloc1.run – > StringBuilder.toString – > new Stringにつながる呼び出し構造を持っていることを確認することができます。
Heap Dump
heap= dumpオプションを使用すると、現在のHeapが入っているすべてのLive Objectに関する情報を出力します。下に簡単な例を示します。
prompt> java -Xrunhprof:heap=sites [Main Class] ... HEAP DUMP BEGIN (198308 objects, 8127720 bytes) Mon Oct 15 17:03:21 2007 ... OBJ 50000130 (sz=24, trace=300004, class=java.lang.String@50000090) ARR 50000131 (sz=32, trace=300005, nelems=0, elem type=char[]) OBJ 50000133 (sz=24, trace=300229, class=java.lang.String@50000090) OBJ 50000134 (sz=24, trace=300229, class=java.lang.String@50000090) ARR 50000136 (sz=48, trace=300228, nelems=0, elem type=char[]) ARR 50000137 (sz=48, trace=300228, nelems=0, elem type=char[]) ARR 50000138 (sz=48, trace=300228, nelems=0, elem type=char[]) OBJ 5000013a (sz=24, trace=300229, class=java.lang.String@50000090) OBJ 5000013d (sz=24, trace=300229, class=java.lang.String@50000090) ...
上記の結果を解釈するとOBJ50000130は、サイズが24 byteであり、オブジェクトを生成したStack traceは300004回であり、オブジェクトのクラスjava.lang.Stringが存在します。Heap DumpはすべてのLiveのオブジェクトに対して、このような情報を出力します。
Heap Dumpを実行する一連の過程は、オーバーヘッドが大きいため、Heap分析が必要な場合にのみ選択的に実行する必要があります。
2.4.2.1 Heap DumpとHAT
Heap DumpはObject Allocationのための最も詳細な情報を提供します。その情報の量が非常に多いので、効果的に分析するためには、視覚的なツールが必要となります。Sunが提供するHeap Analysis Tool（HAT）が最も代表的なHeap Dump解析ツールです。HATはBinary FormatのHeap Dumpファイルを視覚的に分析する機能を提供します。以下にHATを使用する簡単な例を示します。
- Heap Dumpファイルを生成します。（Binary Format） Prompt> java-Xrunhprof：heap= dump、format= b、file= heapbinary.dmp[Main Class]
- HATを実行します。 Prompt> java-Xmx1024m-jar hat.jar heapbinary.dmp Started HTTP server on port7000 Reading from heapbinary1.dmp... Dump file created Thu Oct1814:11:28 KST2007 Snapshot read、resolving... Resolving380425 objects... Chasing references、expect760 dots......................................... Eliminating duplicate references...............................................。 Snapshot resolved Server is ready
HATはWeb Serverを内蔵しており、Web Browserを介して情報を照会する方法を使用します。以下にその例を示します。
CPU Profiling
CPU Profilingを使用すると、メソッド単位でCPU使用率を確認することができる。メソッドの効率を分析するための目的のために主に使用される。CPU Profilingは、次の3つのモード（Mode）を提供する。
・samples：特定のInterval単位でSamplingした結果を提供します。 Intervalのデフォルト値は10（ms）であり、intervalオプションで調整可能です。 Sampling方式のためのデータの精度は落ちますが、JVMに与える負荷が少ないという利点があります。 ・times：Sampling方式ではなく全数検査方法を使用する。したがってメソッドごとに非常に正確な CPU使用率を確認することができます。しかし、JVMに大きな負荷を与えます。 ・old：初期バージョンのHProfで使っていたフォーマットを使用して結果を出力します。 timesオプションのような方式を使用しますが、出力する方式が異なっています。
以下に3つのモードを使用する方法と出力例を示します。同じApplicationについてsamplesモードとtimesモードが非常に異なるProfiling結果を示すことを確認することができます。Profiling結果を解釈する際にこのような状況をよく理解している必要があります。
Samples
Prompt> java -Xrunhprof:cpu=samples,file=cpu_sample.txt [Main Class]
CPU SAMPLES BEGIN (total = 66) Thu Oct 18 15:07:16 2007 rank self accum count trace method 1 15.15% 15.15% 10 300042 java.lang.AbstractStringBuilder.append 2 15.15% 30.30% 10 300043 java.lang.StringBuilder.toString 3 13.64% 43.94% 9 300045 java.lang.AbstractStringBuilder.append 4 13.64% 57.58% 9 300047 java.lang.AbstractStringBuilder.expandCapacity 5 6.06% 63.64% 4 300040 alloc1.run 6 6.06% 69.70% 4 300044 java.lang.AbstractStringBuilder. 7 6.06% 75.76% 4 300041 java.lang.StringBuilder.toString 8 3.03% 78.79% 2 300037 alloc1.run 9 3.03% 81.82% 2 300050 java.lang.AbstractStringBuilder.stringSizeOfInt 10 3.03% 84.85% 2 300051 alloc1.run 11 3.03% 87.88% 2 300046 java.lang.Integer.getChars 12 3.03% 90.91% 2 300039 java.lang.String. 13 1.52% 92.42% 1 300049 alloc1.run 14 1.52% 93.94% 1 300038 alloc1.run 15 1.52% 95.45% 1 300053 java.util.ArrayList.ensureCapacity 16 1.52% 96.97% 1 300048 java.lang.Integer.getChars 17 1.52% 98.48% 1 300052 java.util.ArrayList.add 18 1.52% 100.00% 1 300025 java.lang.String.charAt CPU SAMPLES END
Times
Prompt> java -Xrunhprof:cpu=times,file=cpu_times.txt [Main Class]
CPU TIME (ms) BEGIN (total = 3062) Thu Oct 18 15:07:42 2007 rank self accum count trace method 1 32.66% 32.66% 1 301247 gc_dump.main 2 10.22% 42.88% 2 301162 alloc1.run 3 7.61% 50.49% 4795 301128 java.lang.AbstractStringBuilder.append 4 7.02% 57.51% 4795 301124 java.lang.AbstractStringBuilder.append 5 6.60% 64.11% 4795 301125 java.lang.StringBuilder.append 6 5.16% 69.27% 4795 301121 java.lang.StringBuilder. 7 5.16% 74.43% 4795 301131 java.lang.StringBuilder.toString 8 5.09% 79.52% 4795 301134 java.util.ArrayList.add 9 4.11% 83.64% 4795 301129 java.lang.StringBuilder.append 10 3.10% 86.74% 4795 301122 java.lang.String.length 11 3.10% 89.84% 4795 301133 java.util.ArrayList.ensureCapacity 12 2.55% 92.39% 4795 301123 java.lang.String.getChars 13 2.02% 94.42% 4795 301127 java.lang.Integer.getChars 14 1.57% 95.98% 4795 301126 java.lang.AbstractStringBuilder.stringSizeOfInt 15 1.50% 97.49% 4795 301120 java.lang.AbstractStringBuilder. 16 0.52% 98.01% 4 300471 java.util.jar.JarFile.hasClassPathAttribute 17 0.52% 98.53% 1 300892 java.util.HashMap.get 18 0.49% 99.02% 1 300537 sun.net.www.ParseUtil.decode 19 0.49% 99.51% 4795 301132 java.lang.String. 20 0.49% 100.00% 4 300393 java.util.jar.JarFile.getEntry
Times
Prompt> java -Xrunhprof:cpu=old,file=cpu_old.txt [Main Class]
count callee caller time
5883 java.lang.String.length()I java.lang.AbstractStringBuilder.append
(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder; 47
5879 java.lang.String.getChars(II[CI)V java.lang.AbstractStringBuilder.append
(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder; 30
5860 java.lang.AbstractStringBuilder.append(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder;
java.lang.StringBuilder.append(Ljava/lang/String;)Ljava/lang/StringBuilder; 267
5853 java.lang.AbstractStringBuilder.(I)V java.lang.StringBuilder.()V 76
5853 java.lang.String.([CII)V java.lang.StringBuilder.toString()Ljava/lang/String; 47
5834 java.util.ArrayList.ensureCapacity(I)V java.util.ArrayList.add(Ljava/lang/Object;)Z 46
5831 java.lang.AbstractStringBuilder.append(I)Ljava/lang/AbstractStringBuilder;
java.lang.StringBuilder.append(I)Ljava/lang/StringBuilder; 188
5831 java.lang.AbstractStringBuilder.stringSizeOfInt(I)I
java.lang.AbstractStringBuilder.append(I)Ljava/lang/AbstractStringBuilder; 48
5831 java.lang.Integer.getChars(II[C)V
java.lang.AbstractStringBuilder.append(I)Ljava/lang/AbstractStringBuilder; 62
5828 java.lang.StringBuilder.()V alloc1.run()V 218
5828 java.lang.StringBuilder.toString()Ljava/lang/String; alloc1.run()V 252
5828 java.lang.String.(Ljava/lang/String;)V alloc1.run()V 62
5828 java.util.ArrayList.add(Ljava/lang/Object;)Z alloc1.run()V 185
5828 java.lang.StringBuilder.append(I)Ljava/lang/StringBuilder; alloc1.run()V 345
...
Times
CPU Profiling結果を解釈する際に一つ注意すべき点は、CPU Orietend OperationとNon-CPU Oriented Operationによる影響を正確に分析する事です。以下に説明します。
・Operation Aは、CPUの作業で約0.1sを消費し、合計100回実行されます。 ・Operation Bは、I/ O操作で約10秒を消費し、合計1回実行されます。
つまり、Operation AとBは同じように10秒の時間を消費します。ユーザーの観点では、両方のOperationが同じ性能を持っているように見えます。しかし、上記の二つのOperationのProfilingを実行すると、呼び出し回数が多くCPUを大量に使用するOperation Aが呼び出し回数が小さく、CPU使用率が少ないOperation Bに比べてはるかに多くのことをすることがProfiling結果に表示されます。
上記の例を見れば分かるように、Operationの性質に応じてProfiling結果に反映される程度が異なり、これを誤って解釈すると、ユーザーの観点からのパフォーマンスの問題を把握するのに失敗する可能性があります。Profilingを実行し、その結果を解釈する際に、このような点に注意しなければなりません。
関連情報
1.jps 2.jstack 3.jmap 4.Heap Analysis Tool(HAT) 5.Heap Analyzer(HA) 6.VisualGC 7.JConsole
外部参照
1.JDK Tools
2.JDK 1.6 Troubleshooting guide
