Java用にとにかくすぐ使えるプロファイラが欲しかったのでかなり久しぶりに hprof を使うことにしました。
本当はJava VisualVMが操作しやすくて良いのですが、諸般の事情で今回は hprof です。
久しぶりすぎて操作をすっかり忘れていたので操作方法をメモ。
† プロファイルの取得
実行時に引数として下記ように-agentlib:hprof=で始まるオプションつけてやればよい。Eclipseの場合はVM引数に入力する必要がある。
-agentlib:hprof=cpu=times,heap=all,file=hoge.txt
実際には下記のような感じになります。
java -agentlib:hprof=cpu=times,heap=all,file=hoge.txt Foo
今回はテキストファイルをで結果が欲しかったので、なにも細工していませんが、通常はファイルをバイナリ形式で取得して、jhat - Java ヒープ解析ツールを使うのがよいです。
† 例えば下記のようなプログラムのプロファイルを取る
ちょっと頭の悪いArrayListのようなもの。
Foo.java
public class Foo {
private static int[] list = new int[0];
public static void main(String[] args) {
for (int i = 1; i < 1000; i++) {
add(i);
}
}
public static void add(int n){
int[] newlist = new int[list.length+1];
for (int i = 0; i < list.length ; i++) {
newlist[i] = list[i];
}
newlist[list.length] = n;
list = newlist;
}
}
† メモリの使用量
ファイルの末尾近くにSITES BEGINという部分があり、これがメモリの使用量
SITES BEGIN (ordered by live bytes) Sun Jun 05 21:44:24 2011
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 81.09% 81.09% 2011984 999 2011984 999 301415 int[]
2 6.78% 87.86% 168104 1458 168104 1458 300000 char[]
3 1.44% 89.30% 35704 1474 35704 1474 300000 java.lang.String
4 1.02% 90.32% 25344 11 25344 11 300000 byte[]
5 0.97% 91.30% 24128 744 24128 744 300000 java.util.TreeMap$Entry
6 0.50% 91.79% 12344 303 12344 303 300000 java.lang.Object[]
このプログラムはint[]を毎回作るので、このようにメモリが無駄使いされているのがよくわかる。
ちなみにトレースには301415のような番号がついているので、前半のヒープの情報から301415を探すと詳細がわかる。
TRACE 301415:
Foo.add(Foo.java:11)
Foo.main(Foo.java:6)
† CPUの使用量
同じく、ファイルの末尾近くにCPU TIME (ms) BEGINいう部分があり、これがCPUの使用量になっている。
この場合は
CPU TIME (ms) BEGIN (total = 203) Sun Jun 05 21:44:24 2011
rank self accum count trace method
1 14.78% 14.78% 5 300343 java.lang.String$CaseInsensitiveComparator.compare
2 7.88% 22.66% 1 300750 sun.misc.URLClassPath.getResource
3 7.88% 30.54% 3 301295 java.io.ObjectStreamField.<init>
4 7.88% 38.42% 1 300445 java.util.jar.JarFile.<clinit>
5 7.88% 46.31% 3 300413 java.io.Win32FileSystem.normalize
6 7.88% 54.19% 9 300360 java.util.HashMap.hash
7 7.88% 62.07% 2 300903 java.lang.Character.toUpperCase
8 7.88% 69.95% 999 301416 Foo.add
9 7.88% 77.83% 3 300023 java.lang.Thread.<init>
10 7.39% 85.22% 1 301101 sun.net.www.URLConnection.<init>
11 7.39% 92.61% 3 300511 sun.nio.cs.ext.DoubleByteEncoder.encodeLoop
12 7.39% 100.00% 3 300017 java.lang.Thread.checkAccess
CPU TIME (ms) END
こちらもトレース番号を追えば詳細が分かります。
例えば、呼出回数が多いFoo.addの詳細は下記のような感じ。
TRACE 301416:
Foo.add(Foo.java:Unknown line)
Foo.main(Foo.java:Unknown line)
† 参考
・「Java SE 6完全攻略」第5回 プロファイラ hprofとよき相棒 jhat - Java技術最前線：ITpro
・HPROF: A Heap/CPU Profiling Tool in J2SE 5.0
java 
