BLOGTIMES
2011/06/05

hprof を使ってみた

  java 
このエントリーをはてなブックマークに追加

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


    トラックバックについて
    Trackback URL:
    お気軽にどうぞ。トラックバック前にポリシーをお読みください。[policy]
    このエントリへのTrackbackにはこのURLが必要です→https://blog.cles.jp/item/4251
    Trackbacks
    このエントリにトラックバックはありません
    Comments
    愛のあるツッコミをお気軽にどうぞ。[policy]
    古いエントリについてはコメント制御しているため、即時に反映されないことがあります。
    コメントはありません
    Comments Form

    コメントは承認後の表示となります。
    OpenIDでログインすると、即時に公開されます。

    OpenID を使ってログインすることができます。

    Identity URL: Yahoo! JAPAN IDでログイン