HProf

EXEM Knowledge Base

(Hprof에서 넘어옴)
Jump to: navigation, 찾기

목차

[편집] 개요

HProfHeap And CPU Profiling Agent의 약자로 JDK 레벨에서 제공되는 간단한 형태의 Profiler이다. HProf는 다음과 같은 특징을 지닌다.

  • JDK 1.4까지는 JVMPI, JDK 1.5부터는 JVMTI 인터페이스를 통해 구현된다.
  • CPU Profiling, Heap Profiling, Monitor Monitoring 등의 기본적이고 필수적인 기능을 제공한다.
  • JDK 표준은 아니지만, 대부분의 모든 JVM Vendor들이 구현체를 제공한다. 즉, 사실상의 표준이다.
  • HProf를 통해 수집된 데이터는 Heap Analyzer와 같은 툴과 연동해서 더욱 상세한 분석을 수행할 수 있다.

비록 HProfJVMPIJVMTI 인터페이스에 대한 Demonstration 차원에서 제공되는 간단한 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>=<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 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=<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.<init>(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 개의 인스턴스가 생성되어있다. 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)
...

위의 결과를 해석하면 OBJ 50000130는 크기가 24 byte이며, 오브젝트를 생성한 Stack trace는 300004번이며, 오브젝트의 클래스 java.lang.String이다. Heap Dump는 모든 Live 오브젝트들에 대해 이런 정보들을 출력한다.

Heap Dump를 수행하는 일련의 과정은 오버헤드가 크기 때문에, Heap 분석이 필요한 경우에만 선별적으로 수행해야 한다.

[편집] 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 port 7000
Reading from heapbinary1.dmp...
Dump file created Thu Oct 18 14:11:28 KST 2007
Snapshot read, resolving...
Resolving 380425 objects...
Chasing references, expect 760 dots.........................................
Eliminating duplicate references................................................
Snapshot resolved.
Server is ready.

HAT은 Web Server를 내장하고 있으며 Web Browser를 통해서 정보를 조회하는 방식을 사용한다. 아래에 그 예가 있다.

그림:HAT.jpg

[편집] CPU Profiling

CPU Profiling을 사용하면 메소드 단위로 CPU 점유율을 확인할 수 있다. 메소드의 효율성을 분석하기 위한 목적으로 주로 사용된다. CPU Profiling은 다음 세 가지 모드(Mode)를 제공한다.

  • samples: 특정 Interval 단위로 Sampling한 결과를 제공한다. Interval의 기본 값은 10(ms)이며, interval 옵션으로 조정 가능하다. Sampling 방식이기 때문에 데이터의 정확도는 떨어지지만, JVM에 주는 부하가 적다는 장점이 있다.
  • times: Sampling 방식이 아닌 전수 검사 방식을 사용한다. 따라서 메소드별로 매우 정확한 CPU 점유율을 확인할 수 있다. 하지만 JVM에 큰 부하를 준다.
  • old: 초기 버전의 HProf에서 사용하던 포맷을 사용해 결과를 출력한다. times 옵션과 같은 방식을 사용하지만 출력하는 방식이 다르다.

아래에 세 가지 모드를 사용하는 방법과 출력 예제가 있다. 동일한 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.<init>
   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.<init>
  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.<init>
   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.<init>
  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.<init>
  20  0.49% 100.00%       4 300393 java.util.jar.JarFile.getEntry

[편집] Old

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.<init>(I)V java.lang.StringBuilder.<init>()V 76
5853 java.lang.String.<init>([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.<init>()V alloc1.run()V 218
5828 java.lang.StringBuilder.toString()Ljava/lang/String; alloc1.run()V 252
5828 java.lang.String.<init>(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
...

[편집] CPU Profiling 해석시 주의점

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. HAT
  2. JDK Tools
  3. JDK 1.6 Troubleshooting guide