SMG

コラム: HPROFによるJavaプロファイリング

1: JDBC - PreparedStatementを使って高速化
2: HPROFによるJavaプロファイリング
3: Java Web Startのリモートデバッグ
4: ネイティブスレッドとJavaスレッドのマッピング
5: ネイティブスレッドとJavaスレッドのマッピング (Windows編)
6: Java障害対策と問題解決

HPROFによるJavaプロファイリング

本コラムの対象：
HPROFを今すぐ使いたい方。プロファイリングの基本を理解している方。

１．HPROFとは?

今回はプロファイリングの基本を理解している方を対象に、HPROFプロファイラエージェントの使い方を説明します。

HPROFとはJava 2 SDKに付属しているJVMPIプロファイラエージェントです。無料で使用でき、CPU／ヒーププロファイリングやモニターオブジェクトの状態監視など、プロファイラが備えるべき基本的な機能を提供しています。

これらの機能を利用することで、Javaプログラムのパフォーマンス分析、メモリ使用量の改善、デッドロック問題の解決に役立つ情報の収集を行うことができます。

今回の内容

◆　ヒーププロファイリング
◆　CPUプロファイリング
◆　モニターオブジェクトの状態監視
◆　オプション一覧

HPROF、JVMPIについては、JVMPIリファレンスもご覧ください。

２．プロファイリング結果の出力タイミング

HPROFは、デフォルトではプロファイリング結果をJavaVM終了時に出力します。

JavaVMの実行中に結果を出力したい場合には、doeオプションにnを設定します。
こうしておくとHPROFは、JavaVM終了時にはプロファイリング結果を出力しません。
Windows環境の場合は[Ctrl]+[Break]、Solaris環境の場合は[Ctrl]+[\]と押すことで、
JavaVM実行中に結果を出力することができます。Solaris環境ではコマンドラインから
"kill -3"と入力しても、同じ結果を得ることができます。（※１）

サーバプロセス、デーモンプロセスなどの稼働し続けるJavaプログラムをHPROFで
プロファイリングする場合には、この方法を用いると良いでしょう。

　ただしこの操作はJavaコンソール上で行う必要があります。
GUIプログラムの実行時などは注意してください。

　JavaVMは、VMのシャットダウン時にプロファイラエージェントに対して
JVMPI_EVENT_JVM_SHUT_DOWNイベントを通知します。
hprofは、JavaVMからのJVMPI_EVENT_JVM_SHUT_DOWNイベントを受信したタイミングで、
各ダンプイベント(JVMPI_EVENT_HEAP_DUMPやJVMPI_EVENT_MONITOR_DUMPなど)の
発行により、JavaVMの状態を取得し、出力します。

３．ヒーププロファイリング

３－１．ヒーププロファイリングの実行方法

　オブジェクトが使用したメモリ量を測定するには、「heap」オプションを使用します。

実行例：

java -Xrunhprof:heap=sites,file=sites.txt HprofSample1

　heapオプションの引数には、「sites」、「dump」、「all」が指定可能で、それぞれ以下のような動作をします。　通常は「sites」の指定で十分でしょう。

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

　また、プロファイリング結果の出力ファイル名は「file」オプションで指定することができます。

３－２．SITES出力の読み方

　以下に、プロファイリング対象となるjavaサンプルプログラムとそのプロファイリング結果を示します。
　プロファイル結果は適宜省略して記述します。また、文中、赤太文字で記述されている部分は説明のための補足であり、実際のファイルには出力されません。

→ サンプルプログラム

プロファイリング結果（sites指定）：

JAVA PROFILE 1.0.1, created Mon Jul 14 08:35:46 2003

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=a3fb78, id = 1, name="Finalizer", group="system")
THREAD START (obj=a3f780, id = 2, name="Reference Handler", group="system")
THREAD START (obj=9aa4b0, id = 3, name="main", group="main")
THREAD START (obj=abe4558, id = 4, name="Signal Dispatcher", group="system")
THREAD END (id = 3)
THREAD START (obj=abe30a8, id = 5, name="DestroyJavaVM", group="main")
THREAD END (id = 5)
TRACE 264:  ←トレース番号
  java.util.HashMap.addEntry(HashMap.java:719)  ←スタックトレース
  java.util.HashMap.put(HashMap.java:388)
  java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:158)
  java.security.SecureClassLoader.defineClass(SecureClassLoader.java:123)
TRACE 1:
  <empty>
TRACE 60:
  java.util.zip.ZipFile.getTotal(ZipFile.java:Native method)
  java.util.zip.ZipFile.<init>(ZipFile.java:114)
  java.util.jar.JarFile.<init>(JarFile.java:117)
  java.util.jar.JarFile.<init>(JarFile.java:55)
TRACE 8:
  java.net.URLClassLoader.findClass(URLClassLoader.java:186)
  java.lang.ClassLoader.loadClass(ClassLoader.java:299)
  java.lang.ClassLoader.loadClass(ClassLoader.java:292)
  sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:265)

　(略)

TRACE 276:
  ObjectHolder.<init>(HprofSample1.java:44)  ←生成箇所
  HprofSample1.execute(HprofSample1.java:23)
  HprofSample1.main(HprofSample1.java:11)

　(略)

SITES BEGIN (ordered by live bytes) Mon Jul 14 08:35:47 2003
          percent         live       alloc'ed  stack class
 rank   self  accum    bytes objs   bytes objs trace name
  (1)   (2)    (3)       (4)  (5)     (6)  (7)   (8) (9)
    1 38.50% 38.50%   786432 32768  786432 32768   276 java.lang.String  ← rank=1
    2 25.67% 64.17%   524288 32768  524288 32768   277 java.lang.Integer
    3  7.99% 72.16%   163136 1135  163560 1145     1 [C
    4  7.22% 79.38%   147456 1024  147456 1024   274 java.lang.String
    5  7.22% 86.60%   147456 1024  147456 1024   275 java.lang.Integer
    6  2.61% 89.20%    53248  257   53248  257     1 [B
    7  1.33% 90.53%    27136  342   27136  342     1 [S
    8  1.09% 91.63%    22344  931   22584  941     1 java.lang.String
    9  0.96% 92.59%    19608  370   19608  370     1 java.lang.Object
   10  0.81% 93.39%    16464  294   16464  294     1 java.lang.Class
   11  0.80% 94.19%    16384 1024   16384 1024   273 ObjectHolder
   12  0.75% 94.94%    15224  259  605432  271     1 [I
   13  0.56% 95.50%    11496  479   11496  479     1 java.util.HashMap$Entry
   14  0.33% 95.83%     6664    5    6664    5    74 [B
   15  0.30% 96.13%     6064   63    6064   63   141 [C
   16  0.25% 96.38%     5136    1   10272    7   278 java.lang.Object
   17  0.22% 96.60%     4536   63    4536   63   149 [C
   18  0.15% 96.75%     3024   13    3024   13     1 java.util.HashMap$Entry
   19  0.13% 96.88%     2640    5    2640    5    89 [B
   20  0.12% 97.00%     2520   63    2520   63   143 java.util.HashMap

　(略)

SITES END

　前半部分がオブジェクトをアロケートした場所を表すトレース出力部分です。実際にオブジェクトがメモリに展開された場所のスタックトレースとトレース番号を出力しています。

　後半部分がSITES出力です。メモリ使用量順にソートされています。各カラム内容は、次の表に示す通りです。

数字	タイトル	意味
(1)	rank	消費メモリの順位
(2)	percent self	消費メモリのパーセンテージ
(3)	percent accum	消費メモリの累積パーセンテージ(上位rankのpercent selfとの和)
(4)	live bytes	ライブオブジェクト(GCされていないオブジェクト)の消費バイト数
(5)	live objs	ライブオブジェクトのオブジェクト数
(6)	alloc'ed bytes	アロケートされたオブジェクト(GCされたオブジェクトを含む)の消費バイト数
(7)	alloc'ed objs	アロケートされたオブジェクトのオブジェクト数
(8)	stack trace	対応するトレース番号
(9)	class name	クラス名

　クラス名の部分に記述されている「[C」や「[I」といったクラス名は配列を表します。

クラス名	意味
[Lクラス名	オブジェクトの配列
[Z	boolean型の配列
[B	byte型の配列
[C	char型の配列
[S	short型の配列
[I	int型の配列
[J	long型の配列
[F	float型の配列
[D	double型の配列

　SITES出力から、最もメモリを消費しているオブジェクトを生成している部分を特定してみましょう。

オブジェクトの特定

トレース番号の特定

生成箇所の特定

４．CPUプロファイリング

４－１．CPUプロファイリングの実行方法

　Javaプログラム中の各メソッドが使用したCPU時間を測定するには、「cpu」オプションを使用します。

実行例：

java -Xrunhprof:cpu=times,file=cpu_times.txt HprofSample2

　cpuオプションの引数には「samples」、「times」、「old」が指定可能で、それぞれ以下のような動作をします。

引数	動作
samples	実行中の全てのスレッドを定期的にサンプリングし、各サンプリングタイミングにおいてアクティブになったスレッド（メソッド）をカウントする。
times	メソッドのIN/OUTを監視し、メソッドのコール回数をカウントする。
old	timesと同様。出力形式が、旧hprofフォーマットとなる。

　「samples」と「times」の結果はほぼ同じになります。ただしカウンタの値が異なります（samplesはサンプリング回数、timesはメソッドコール回数）。「old」を指定することはまずないでしょう。

４－２．SAMPLES、TIMES出力の読み方

　以下に、プロファイリング対象となるjavaサンプルプログラムとそのCPUプロファイリング結果を示します。

→ サンプルプログラム

プロファイリング結果（samples指定）：

JAVA PROFILE 1.0.1, created Mon Jul 14 08:35:49 2003

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=ab81ef8, id = 1, name="Finalizer", group="system")
THREAD START (obj=ab82040, id = 2, name="Reference Handler", group="system")
THREAD START (obj=ab82120, id = 3, name="main", group="main")
THREAD START (obj=ab85758, id = 4, name="HPROF CPU profiler", group="system")
THREAD START (obj=ab85860, id = 5, name="Signal Dispatcher", group="system")
THREAD END (id = 3)
THREAD START (obj=ab82168, id = 6, name="DestroyJavaVM", group="main")
THREAD END (id = 6)
TRACE 4:
	<empty>
TRACE 5:
	HprofSample2.shortMethod(HprofSample2.java:35)  ←最ヒット箇所
	HprofSample2.execute(HprofSample2.java:21)      ←shortMethod 呼び出し箇所
	HprofSample2.main(HprofSample2.java:9)

　(略)

CPU SAMPLES BEGIN (total = 20) Mon Jul 14 08:35:52 2003
 (1)   (2)    (3)      (4)   (5) (6)
rank   self  accum   count trace method
   1 50.00% 50.00%      10     5 HprofSample2.shortMethod  ← rank=1
   2 35.00% 85.00%       7     6 HprofSample2.longMethod
   3  5.00% 90.00%       1     1 sun.misc.URLClassPath$JarLoader.parseExtensionsDependencies
   4  5.00% 95.00%       1     3 java.security.SecureClassLoader.getPermissions
   5  5.00% 100.00%       1     2 java.util.jar.Attributes.read
CPU SAMPLES END

プロファイリング結果（times指定）：

JAVA PROFILE 1.0.1, created Mon Jul 14 08:35:54 2003

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=ab84818, id = 2, name="Finalizer", group="system")
THREAD START (obj=ab84930, id = 1, name="Reference Handler", group="system")
THREAD START (obj=ab849e8, id = 3, name="main", group="main")
THREAD START (obj=ab87750, id = 4, name="Signal Dispatcher", group="system")
THREAD END (id = 3)
THREAD START (obj=ab854e0, id = 5, name="DestroyJavaVM", group="main")
THREAD END (id = 5)
TRACE 1:
  <empty>
TRACE 3:
  HprofSample2.longMethod(HprofSample2.java:Unknown line)
  HprofSample2.execute(HprofSample2.java:Unknown line)
  HprofSample2.main(HprofSample2.java:Unknown line)

　(略)

CPU TIME (ms) BEGIN (total = 2652) Mon Jul 14 08:35:57 2003
 (1)   (2)    (3)      (4)   (5) (6)
rank   self  accum   count trace method
   1 49.81% 49.81%   65535     5 HprofSample2.shortMethod
   2 46.04% 95.85%       1     3 HprofSample2.longMethod
   3  2.26% 98.11%       1     2 HprofSample2.execute
   4  0.38% 98.49%      63     8 java.lang.String.<init>
   5  0.38% 98.87%       5     4 java.io.WinNTFileSystem.getLastModifiedTime
   6  0.38% 99.25%    1036     9 java.lang.Character.toLowerCase
   7  0.38% 99.62%      68     7 java.util.AbstractMap.<init>
   8  0.38% 100.00%       1     6 sun.net.www.URLConnection.<init>
CPU TIME (ms) END

注：
このプログラムをtimes指定で実行するとHPROFが"HPROF ERROR : stack underflow"というメッセージを出力してstack underflowを起こすため、トレース出力の行番号は"Unknown line"と出力されています。

　サンプリング回数の出力部分以外は、samples指定、times指定共に同じ内容を示しています。

　前半部分がトレース出力です。内容はヒーププロファイリングの項で説明したとおりです。

　後半部分が使用したCPU時間になります。この部分は、使用したCPU時間順にソートされています。 1行目のtotal=xxxがサンプリング回数です。各カラム内容は、次の表に示す通りです。

数字	タイトル	意味
(1)	rank	CPU時間の順位
(2)	self	CPU時間のパーセンテージ
(3)	accum	CPU使用時間の累積パーセンテージ(上位rankのselfとの和)
(4)	count	ヒットしたサンプリングタイミング数(samples指定)、またはメソッドのコール回数(times指定)
(5)	trace	対応するトレース番号
(6)	method	メソッド名

　ボトルネックとなるメソッドは、ヒーププロファイリングの場合と同様に、各統計情報に対応するトレース番号をたどることで発見することができます。

　ここで注意しなければならないのは、プロファイリング結果は「そのメソッド自体が占有したCPU時間」をあらわしていることです。

　例えばtimes指定の出力を見ると、HprofSample2.shortMethod()の実行が全体の約50%を占めていますが、shortMethod()の呼び出し元であるHprofSample2.execute()メソッドのCPU占有率は3%未満です。特定のメソッドから始まる処理全体がCPUを占有した割合を知るには、注目したいメソッドから始まる一連のメソッドについてCPU占有率を足していく必要があります。

　samples出力から最もＣＰＵを利用しているメソッドを特定してみましょう。

オブジェクトの特定

トレース番号の特定

呼び出し箇所の特定

５．モニターオブジェクトの状態監視

５－１．モニターオブジェクト状態監視の実行方法

　モニターオブジェクトとは、スレッドのブロックと回復を行うオブジェクトです。

　一般的に、マルチスレッドプログラムが同期処理を行う場合、特定のロック用オブジェクトを取り合うことで実現します。このロックオブジェクトにあたるものがモニターオブジェクトです。

　簡単に言うと、synchronizedキーワードによって同期指定されたコードを持つオブジェクトがモニターオブジェクトとなります。

　モニターオブジェクトの状態を出力するには、「monitor」オプションを使用します。

　ただしデッドロックした場合に、どちらのオブジェクトが先に相手を掴んだのかまでは分かりません。

実行例：

java -Xrunhprof:monitor=y,file=monitor.txt HprofSample3

５－２．モニター競合出力の読み方

　以下に、プロファイリング対象となるjavaサンプルプログラムとそのモニター競合出力を示します。サンプルプログラムは、デッドロックを発生させた上でSystem.exit()により強制的に終了するようになっています(普通はこんなことしません。あくまでサンプルです)。

→ サンプルプログラム

プロファイリング結果(monitor指定)：

JAVA PROFILE 1.0.1, created Mon Jul 14 08:35:59 2003

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=ab85eb8, id = 1, name="Finalizer", group="system")
THREAD START (obj=ab86060, id = 2, name="Reference Handler", group="system")
THREAD START (obj=ab861a0, id = 3, name="main", group="main")
THREAD START (obj=ab88cb8, id = 4, name="Signal Dispatcher", group="system")
THREAD START (obj=abf8e08, id = 5, name="Thread-1", group="main")
THREAD START (obj=abf8de0, id = 6, name="Thread-2", group="main")
THREAD START (obj=abf9e48, id = 7, name="Thread-0", group="main")
THREAD END (id = 7)
THREAD END (id = 3)
TRACE 1:
	<empty>
TRACE 2:
	HprofSample3.main(HprofSample3.java:9)
THREAD START (obj=ab861a0, id = 9, name="main", group="main")
MONITOR DUMP BEGIN
    MONITOR SyncClass(abff2a8)
	owner: thread 5, entry count: 1
	waiting to enter: thread 6  ←thread 6 が待っている
    MONITOR java.lang.ref.ReferenceQueue$Lock(9a9ff0) unowned
	waiting to be notified: thread 1
    MONITOR SyncClass(abff2c8)
	owner: thread 6, entry count: 1
	waiting to enter: thread 5  ←thread 5 が待っている
    MONITOR java.lang.ref.Reference$Lock(9a9f30) unowned
	waiting to be notified: thread 2
    MONITOR java.lang.Class(a500d8)
	owner: thread 9, entry count: 0
MONITOR DUMP END
MONITOR TIME BEGIN (total = 0 ms) Mon Jul 14 08:36:01 2003
MONITOR TIME END

　前半のトレース出力部分はこれまでと同様です。

　後半部分がJavaVMシャットダウン時のモニターオブジェクトの状態です。この出力結果から、デッドロックが発生していないか、分析してみましょう。

解放待ちスレッドの特定

「waiting to enter: thread XX」

モニターオブジェクト所有スレッドの特定

「owner: thread XX」

デッドロックの有無を確認

互いのスレッドの解放を待っている

　これは典型的なデッドロックの状態を表しています。

６．オプション一覧

　HPROFでは、これまでに説明したfile、heap、cpu、monitorを含め、以下のオプションが指定可能です。

オプション	機能	デフォルト値
heap=dump\|sites\|all	ヒープのプロファイリングを行う。	all
cpu=samples\|times\|old	CPU 時間のプロファイリングを行う。	off
monitor=y\|n	モニターの競合のプロファイリングを行う。	n
format=a\|b	出力形式。aはASCII形式、bはバイナリ形式。	a
file=name	データを出力するファイル名を指定する。	java.hprof (ASCII の場合は .txt)
net=host:port	指定した場合、プロファイリングデータをソケット経由で送信する。	ファイル出力
depth=size	出力スタックトレースの深さ。	4
cutoff=value	出力のカットオフポイント。例えば0.2と指定した場合、ヒープ占有率またはCPU占有率が20%未満のデータは出力されない。	0.0001
lineno=y\|n	トレースに行番号を出力するか。	y
thread=y\|n	トレースにスレッド番号を出力するか。	n
doe=y\|n	終了時にダンプするかを指定する。	y

７．まとめ

　今回のコラムでは、HPROFプロファイラエージェントの使い方として、ヒープおよび使用したCPU時間の統計情報、モニター競合の調べ方を説明しました。他の商用プロファイリングツールと比較すると機能的に見劣りはしますが、導入や使用にあたっての手間が少なく、かつ無料で利用することができるという利点があります。

　また、フリーで提供されている、HPROF出力結果解析ツールなどと併用することで威力を発揮します。

　ENdoSnipeを利用することでHPROFとは異なる側面からJavaの内部動作をみることができます。
　詳細な情報はこちらをクリック。

【参考文献】

※１	『プロフェッショナルJava　下　JDBC、XML、分散オブジェクト、セキュリティ、チューニング編』　Brett Spell著　株式会社インプレス発行　2001年

注意：本文書の内容に誤りがあり、またこの文書によって不利益を被っても、
エスエムジー株式会社は一切関知いたしません。

現象別Index

コラム

Find Bugsバグ詳細

RSSで更新情報を取得する

RSSとは、ホームページの更新情報を配信する為のフォーマットです。
RSSを利用すると、登録したページの情報が更新された場合に、更新情報を自動的に受け取る事ができます。

弊社小森が執筆致しました

Javaプログラミング言語習得において、新人プログラマーの最初の障害は「オブジェクト指向の壁」です。
本書は、Javaのソフトウェア開発を中心に事業を発展させてきたSMG社の新人教育セミナーを加筆・書籍化したもので、大卒の新人に対して、ゼロからJava言語を教えてきた実績をフィードバックしています。

メールマガジン配信中

Javaトラブルシューティングのメルマガをはじめました！是非ご購読ください