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を介して情報を照会する方法を使用します。以下にその例を示します。

 

HAT

 

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