トップ 履歴 一覧 カテゴリ ソース 検索 ヘルプ RSS ログイン

Java/hprof(jvmpi)

INDEX

hprofとは?

hprof を利用するには、J2SE 1.4.2 までは「-Xrunhprof」という起動オプションを指定しJavaアプリケーションを実行する。(注:Java 1.5 は非推奨に、Java 6 からは廃止された)

使い方はヘルプ・オプションで表示できる。hprof, jvmpi については、JVMPIリファレンスも参照。

 起動とオプション

C:\Java\jdk1.4.2_17\bin>java -version
java version "1.4.2_17"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_17-b06)
Java HotSpot(TM) Client VM (build 1.4.2_17-b06, mixed mode)

C:\Java\jdk1.4.2_17\bin>java -Xrunhprof:help
Hprof usage: -Xrunhprof[: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             ascii or binary output     a
file=<file>            write data to file         java.hprof(.txt for ascii)
net=<host>:<port>      send data over a socket    write to file
depth=<size>           stack trace depth          4
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
gc_okay=y|n            GC okay during sampling    y

Example: java -Xrunhprof:cpu=samples,file=log.txt,depth=3 FooClass

Note: format=b cannot be used with cpu=old|times

C:\Java\jdk1.4.2_17\bin>
オプション名前と値 オプションの説明 デフォルト
heap=dump|sites|all ヒープのプロファイリング all
cpu=samples|times|old CPU 使用率のプロファイル off
monitor=y|n モニターの競合 n
format=a|b ASCII またはバイナリ形式 a
file=name データをファイルに書き出す java.hprof[.txt]
net=host:port データをソケット経由で送信 ファイルに書き出す
depth=size スタックトレースの深さ 4
cutoff=value 出力のカットオフポイント 0.0001
lineno=y|n トレースに行番号を出力するか y
thread=y|n トレースにスレッドを出力するか n
doe=y|n 終了時にダンプするか y
gc_okay=y|n GC okay during sampling y

デフォルトでは、ヒープのプロファイリング情報(サイトおよびダンプ)を JavaVM 終了時にテキスト形式で java.hprof.txt に出力されます。

サーバプログラムなど稼働し続けるプログラムを JavaVM 実行中に hprof でプロファイリングする場合は、doe=n オプションを指定して実行中に Ctrl-\ (Solaris) / Ctrl-Break (Win32) を押すことで結果が出力される。

ヒーププロファイリングのオプション値

引数 動作
sites 使用メモリの統計情報を出力
dump ヒープのダンプを出力
all sitesとdumpの両方を出力

CPU使用率プロファイルのオプション値

引数 動作
samples 定期的にサンプリングし、アクティブなスレッド(メソッド)をカウントする
times メソッドのIN/OUTを監視し、メソッドのコール回数をカウントする
old timesと同様。出力形式が、旧hprofフォーマットとなる

ヒーププロファイリング

 実行方法

使用したメモリ量を測定するには、heap オプションを指定して起動する。オプション値は、通常 sites で十分。

java -Xrunhprof:heap=sites,file=heap.txt hprof.HprofHeap

 結果

JAVA PROFILE 1.0.1, created Mon Dec 22 00:00:00 2008

Header for -Xhprof ASCII Output

Copyright 1998 Sun Microsystems, Inc. 901 San Antonio Road, Palo Alto,
California, 94303, U.S.A.  All Rights Reserved.

   :(中略)
--------

THREAD START (obj=bfed48, id = 1, name="Finalizer", group="system")
THREAD START (obj=bfe950, id = 2, name="Reference Handler", group="system")
THREAD START (obj=bb5bb0, id = 3, name="main", group="main")
THREAD START (obj=2dc9a50, id = 4, name="Signal Dispatcher", group="system")
THREAD END (id = 3)
THREAD START (obj=34743c8, id = 5, name="DestroyJavaVM", group="main")
THREAD END (id = 5)
TRACE 173:
	java.util.HashMap.addEntry(HashMap.java:739)
	java.util.HashMap.put(HashMap.java:392)
	java.io.ExpiringCache.put(ExpiringCache.java:69)
	java.io.Win32FileSystem.canonicalize(Win32FileSystem.java:355)
TRACE 1:
	<empty>
   :(中略)
TRACE 241:
	java.lang.Integer.toString(Integer.java:315)
	hprof.HprofHeap$ObjectHolder.<init>(HprofHeap.java:44)
	hprof.HprofHeap.execute(HprofHeap.java:20)
	hprof.HprofHeap.main(HprofHeap.java:14)
   :(中略)
SITES BEGIN (ordered by live bytes) Mon Dec 22 00:00:00 2008
          percent         live       alloc'ed  stack class
 rank   self  accum    bytes objs   bytes objs trace name
    1 30.98% 30.98%  1302528 54272 1302528 54272   241 java.lang.String
    2 24.94% 55.92%  1048576 65536 1048576 65536   227 java.lang.Integer
    3 20.66% 76.58%   868352 54272  868352 54272   242 [C
    4  6.63% 83.20%   278528 1024  278528 1024   225 java.lang.Integer
    5  6.63% 89.83%   278528 1024  278528 1024   226 java.lang.String
    6  3.35% 93.18%   140728  578  141784  600     1 [C
    7  1.95% 95.13%    81920 1024   81920 1024   224 [B
    8  1.13% 96.26%    47520  231   47584  234     1 [B
    9  0.58% 96.84%    24576 1024   24576 1024   223 hprof.HprofHeap$ObjectHolder
   10  0.42% 97.26%    17744  329   17744  329     1 java.lang.Object
   11  0.41% 97.68%    17328  310   17328  310     1 [S
   12  0.39% 98.06%    16256  254   16256  254     1 java.lang.Class
   13  0.34% 98.40%    14232  593   14784  616     1 java.lang.String
   14  0.29% 98.69%    12336  227  602440  238     1 [I
   :(中略)
SITES END

TRACE nnn: の部分が、オブジェクトをアロケートしたときのトレース出力で、トレース番号とインスタンスが展開された場所のスタックトレースが出力される。

SITES BEGIN から SITES END の部分が、使用メモリの統計情報で、メモリの使用量順に出力される。各カラム内容は以下の通り。
タイトル 意味
rank 消費メモリの順位
percent self 消費メモリのパーセンテージ
percent accum 消費メモリの累積パーセンテージ(上位rankのpercent selfとの和)
live bytes ライブオブジェクト(GCされていないオブジェクト)の消費バイト数
live objs ライブオブジェクトのオブジェクト数
alloc'ed bytes アロケートされたオブジェクト(GCされたオブジェクトを含む)の消費バイト数
alloc'ed objs アロケートされたオブジェクトのオブジェクト数
stack trace 対応するトレース番号
class name クラス名

クラス名の部分に記述されている [C[I といったクラス名は配列を表す。
クラス名 意味
[Lクラス名 オブジェクトの配列
[Z boolean型の配列
[B byte型の配列
[C char型の配列
[S short型の配列
[I int型の配列
[J long型の配列
[F float型の配列
[D double型の配列

上記の例でrank=1の部分では、全体の約30%を占める String オブジェクトが最もメモリを消費している。stack trace 欄を見ると、トレース番号が 241 のトレースが対応することがわかる。トレース番号 241 のトレースを見ると、プログラムの44行目での処理であることがわかる。

CPU使用率プロファイリング

 実行方法

各メソッドが使用したCPU時間を測定するには、cpu オプションを指定して起動する。オプション値は、samples か times を指定する。

java -Xrunhprof:cpu=times,file=cpu.txt hprof.HprofCpu

 結果

JAVA PROFILE 1.0.1, created Mon Dec 22 00:00:00 2008

Header for -Xhprof ASCII Output

Copyright 1998 Sun Microsystems, Inc. 901 San Antonio Road, Palo Alto,
California, 94303, U.S.A.  All Rights Reserved.

   :(中略)
--------

THREAD START (obj=2d73270, id = 2, name="Finalizer", group="system")
THREAD START (obj=2d73e60, id = 1, name="Reference Handler", group="system")
THREAD START (obj=2d73f18, id = 3, name="main", group="main")
THREAD START (obj=2d76548, id = 4, name="Signal Dispatcher", group="system")
THREAD END (id = 3)
THREAD START (obj=2d74a10, id = 5, name="DestroyJavaVM", group="main")
THREAD END (id = 5)
TRACE 1:
	<empty>
TRACE 3:
	hprof.HprofCpu.shortProcessingTime(HprofCpu.java:Unknown line)
	hprof.HprofCpu.execute(HprofCpu.java:Unknown line)
	hprof.HprofCpu.main(HprofCpu.java:Unknown line)
TRACE 4:
	java.lang.Package.getSystemPackage(Package.java:Unknown line)
	java.lang.ClassLoader.getPackage(ClassLoader.java:Unknown line)
	java.lang.ClassLoader.getPackage(ClassLoader.java:Unknown line)
	java.lang.ClassLoader.definePackage(ClassLoader.java:Unknown line)
TRACE 2:
	hprof.HprofCpu.longProcessingTime(HprofCpu.java:Unknown line)
	hprof.HprofCpu.execute(HprofCpu.java:Unknown line)
	hprof.HprofCpu.main(HprofCpu.java:Unknown line)
CPU TIME (ms) BEGIN (total = 4155) Mon Dec 22 00:00:00 2008
rank   self  accum   count trace method
   1 50.01% 50.01%    1024     3 hprof.HprofCpu.shortProcessingTime
   2 49.63% 99.64%       1     2 hprof.HprofCpu.longProcessingTime
   3  0.36% 100.00%       1     4 java.lang.Package.getSystemPackage
CPU TIME (ms) END

TRACE nnn: の部分が、オブジェクトをアロケートしたときのトレース出力で、トレース番号とインスタンスが展開された場所のスタックトレースが出力される。

CPU TIME (ms) BEGIN から CPU TIME (ms) END の部分が、CPU使用率の情報で、使用率順に出力される。各カラム内容は以下の通り。
タイトル 意味
rank CPU時間の順位
self CPU時間のパーセンテージ
accum CPU使用時間の累積パーセンテージ(上位rankのselfとの和)
count ヒットしたサンプリング数(samples指定)/メソッドのコール回数(times指定)
trace 対応するトレース番号
method メソッド名

CPU時間は、「そのメソッド自身が占有したCPU時間」を表していて、呼び出し元のメソッドの時間には影響しない。

上記の例でrank=1の部分では、全体の約50%を 1024回呼ばれている shortProcessingTime が消費している。trace 欄を見ると、トレース番号が 3 のトレースが対応することがわかる。トレース番号 3 のトレースを見ると、main, execute, shortProcessingTime と呼ばれているのがわかる。

モニターオブジェクト監視

 実行方法

モニターオブジェクトは、マルチスレッドで同期処理を行う際に利用するロックオブジェクトに当たるものです。

モニターオブジェクトの状態を取得するには、monitor オプションを指定して起動する。

java -Xrunhprof:monitor=y,file=monitor.txt hprof.HprofMonitor

 結果

JAVA PROFILE 1.0.1, created Mon Dec 22 00:00:00 2008

Header for -Xhprof ASCII Output

Copyright 1998 Sun Microsystems, Inc. 901 San Antonio Road, Palo Alto,
California, 94303, U.S.A.  All Rights Reserved.

   :(中略)
--------

THREAD START (obj=2d76620, id = 1, name="Finalizer", group="system")
THREAD START (obj=2d767c0, id = 2, name="Reference Handler", group="system")
THREAD START (obj=2d76900, id = 3, name="main", group="main")
THREAD START (obj=2d781b0, id = 4, name="Signal Dispatcher", group="system")
THREAD START (obj=2d99060, id = 5, name="Thread-0", group="main")
THREAD START (obj=2d99020, id = 6, name="Thread-1", group="main")
THREAD END (id = 3)
TRACE 1:
	<empty>
THREAD START (obj=2d76900, id = 7, name="main", group="main")
MONITOR DUMP BEGIN
    MONITOR hprof.HprofMonitor(2d99060)
	owner: thread 5, entry count: 1
	waiting to enter: thread 6
    MONITOR hprof.HprofMonitor(2d99020)
	owner: thread 6, entry count: 1
	waiting to enter: thread 5
    MONITOR java.lang.ref.ReferenceQueue$Lock(2d98f40) unowned
	waiting to be notified: thread 1
    MONITOR java.lang.ref.Reference$Lock(ba4400) unowned
	waiting to be notified: thread 2
    MONITOR java.lang.Class(2d97130)
	owner: thread 7, entry count: 0
MONITOR DUMP END
MONITOR TIME BEGIN (total = 0 ms) Mon Dec 22 00:00:00 2008
MONITOR TIME END

TRACE nnn: の部分が、オブジェクトをアロケートしたときのトレース出力で、トレース番号とインスタンスが展開された場所のスタックトレースが出力される。

MONITOR DUMP BEGIN から MONITOR DUMP END の部分が、終了時のモニターオブジェクトの状態です。

waiting to enter: thread n が記述されている箇所が、このモニターオブジェクトの解放を待っているスレッドを指します。

owner: thread n が記述されている箇所が、このモニターオブジェクトを持っているスレッドを指します。

最終更新時間:2008年12月23日 01時02分00秒 指摘や意見などあればSandBoxのBBSへ。

HprofCpu.java HprofHeap.java HprofMonitor.java