INDEX
hprofとは?
hprof を利用するには、J2SE 1.4.2 までは「-Xrunhprof」という起動オプションを指定しJavaアプリケーションを実行する。(注:Java 1.5 は非推奨に、Java 6 からは廃止された)
使い方はヘルプ・オプションで表示できる。hprof, jvmpi については、JVMPIリファレンスも参照。
- Java 仮想マシン・プロファイラインタフェース (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