Javaのコマンドラインでのモニタリング／トラブルシューティングツール

Javaアプリでトラブルがあったりすると、アプリケーションのログなどを読んで解析をすると思いますが、パフォーマンスやGC周りでのトラブルについては、JDKに標準付属しているコマンドを使用すると原因究明の手がかりがつかめたりすることがあります。

自分も、ちょっと前にやっていたプロジェクトでは、かなり使うことになりました。どれも有名だとは思いますが、使い方をメモしておくという意味を込めて書いておきます。

まず、今回のサンプルとして、以下のような明らかに問題のあるプログラムを用意。
Monitor.java

import java.util.ArrayList;
import java.util.List;

public class Monitor {
    public static void main(String[] args) {
        int busyThreadNum = 3;
        int spareThreadNum = 10;

        for (int i = 0; i < busyThreadNum; i++) {
            new BusyThread(i).start();
        }

        for (int i = 0; i < spareThreadNum; i++) {
            new SpareThread(i).start();
        }
    }
}

class BusyThread extends Thread {
    public BusyThread(int num) {
        super("Busy-Thread-" + num);
    }

    @Override
    public void run() {
        int counter = 0;
        int limit = 100000;
        long sleepTime = 10L;
        List<String> list = new ArrayList<>();
        while (true) {
            counter++;
            list.add("counter-" + counter);

            if (counter > limit) {
                try {
                    Thread.sleep(sleepTime);
                } catch (InterruptedException e) { }
                counter = 0;
                list = new ArrayList<>();
            }
        }
    }
}

class SpareThread extends Thread {
    public SpareThread(int num) {
        super("Spare-Thread-" + num);
    }

    @Override
    public void run() {
        long sleepTime = 1000L;

        while (true) {
            try {
                Thread.sleep(sleepTime);
            } catch (InterruptedException e) { }
        }
    }
}

せっかくJava SE 7を使っているので、ダイアモンド演算子を使ってみました。

それでは、これを起動しておきます。

$ java Monitor

jps

コマンドを実行したマシンで起動している、JavaアプリケーションのPIDを取得することができます。まあ、psコマンドとかで代用しても、全く問題ないと思います。

$ jps
3835 Monitor
3861 Jps

jpsコマンド自身のPIDも出てくるので、これは除外しておきましょう。
ここで取得したPIDを、以降のコマンドで使用します。

jstat [option] [PID] [interval] [count]

JavaVMのヒープやGCの統計情報を取得するコマンドです。New（Suvivor／Eden）やOld、Permentの使用状況やGCの実行回数、実行時間などを確認することができます。
実行例。

$ jstat -gc 3835 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT   
16768.0 7424.0  0.0   7400.3 302144.0 216304.5  70912.0    35858.5   21248.0 2361.2    773   14.729   3      0.423   15.152
15616.0 16064.0  0.0   8645.5 304320.0 154566.3  70912.0    35858.5   21248.0 2361.2    777   14.788   3      0.423   15.212
13440.0 14144.0  0.0   7168.9 308544.0 193178.0  70912.0    35858.5   21248.0 2361.2    781   14.840   3      0.423   15.263
12928.0 13248.0  0.0   7200.9 310208.0 158366.9  70912.0    35858.5   21248.0 2361.2    785   14.870   3      0.423   15.294

オプションや出力項目はこちらを見ていただくとして…
http://java.sun.com/javase/ja/6/docs/ja/technotes/tools/share/jstat.html

「-t」オプションを付けるとJavaVMが起動してからの時間を出してくれるのですが、

$ jstat -gc -t 3835 1000
Timestamp        S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT   
          269.1 19584.0 19520.0 1997.8  0.0   298816.0   0.0     70912.0    49258.5   21248.0 2361.2    990   17.947   3      0.423   18.370
          270.2 18368.0 18240.0 2267.5  0.0   300096.0 77625.2   70912.0    49258.5   21248.0 2361.2    994   17.976   3      0.423   18.400
          271.2 16064.0 16448.0 6880.9  0.0   302464.0 166894.8  70912.0    49258.5   21248.0 2361.2    998   18.017   3      0.423   18.440

これだといつ取得したのか全然わからないので、自分はPerlのOne Linerとかで時間をくっつけるようにしてます。

$ jstat -gc 3835 1000 | perl -wn -e '$d = `date "+%Y/%m/%d %H:%M:%S"`; chomp $d; print "$d | $_"'
2012/06/23 20:30:24 |  S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT   
2012/06/23 20:30:24 | 18816.0 19328.0  0.0   4373.9 299264.0 114667.8  107072.0   85039.6   21248.0 2361.5   2637   43.167   5      0.668   43.835
2012/06/23 20:30:25 | 19584.0 9472.0  0.0   9436.4 297472.0 113238.5  107072.0   85039.6   21248.0 2361.5   2641   43.226   5      0.668   43.894
2012/06/23 20:30:26 | 18240.0 17856.0  0.0   11290.1 299712.0 212660.6  107072.0   85039.6   21248.0 2361.5   2645   43.274   5      0.668   43.942

jmap　[option] [PID]

ヒープダンプやヒープのヒストグラムを取得できるコマンドです。オプションを含めて、詳しい使い方はこちら。
http://java.sun.com/javase/ja/6/docs/ja/technotes/tools/share/jmap.html

ヒープダンプは、以下のようにして取得します。

$ jmap -dump:live,format=b,file=heap.dmp 3835
Dumping heap to /xxxxx/perf_mon/heap.dmp ...
Heap dump file created

「-dump:live」で現在生存しているオブジェクトのみを、format=bでバイナリ形式でダンプします。出力ファイルはfile=[ファイル名]で指定します。取得したダンプファイルはjhatとかで見ることができますが、ヒープサイズがギガバイトクラスになると、ちょっと取得が難しくなりますね…。

ヒープのヒストグラムは、以下のようにして取得します。

$ jmap -histo:live 3835

 num     #instances         #bytes  class name
----------------------------------------------
   1:         21822        1001016  [C
   2:          5232         716288  <methodKlass>
   3:         21801         697632  java.lang.String
   4:          5232         627456  <constMethodKlass>
   5:           347         394304  <constantPoolKlass>
   6:           313         250144  <constantPoolCacheKlass>
   7:           347         249968  <instanceKlassKlass>
   8:           313          97480  [Ljava.lang.Object;
   9:           419          79792  [B
  10:           407          49472  java.lang.Class
  11:           560          36568  [[I
  12:           515          32504  [S
  13:           348          27320  [I
  14:            43          24768  <objArrayKlassKlass>
  15:            28           7736  <methodDataKlass>
  16:             8           4608  <typeArrayKlassKlass>
  17:           110           3520  java.util.Hashtable$Entry
  18:            11           2288  <klassKlass>
  19:            61           1952  java.util.concurrent.ConcurrentHashMap$HashEntry
  20:            52           1904  [Ljava.lang.String;
  〜省略〜
 161:             1             16  sun.misc.Launcher$Factory
 162:             1             16  java.nio.charset.CoderResult$1
 163:             1             16  java.util.Collections$EmptyList
 164:             1             16  java.util.Hashtable$EntrySet
 165:             1             16  java.nio.charset.CoderResult$2
Total         58719        4334552

結果は、標準出力に吐き出されます。
「-histo」オプションでヒープヒストグラムを、liveを付けると現在生存中のオブジェクトのみを出力します。なお、liveを付けると副作用として強制的にFull GCがかかるため、外部からFull GCをかけるトリガーとしても有効です。ま、JMXが使えるのならその副作用自体はいらないかもしれませんが。

なお、注意点としてはjmapを実行すると、結果が取得できるまではJavaアプリ本体の動きが停止します。特に、ヒープダンプなんて取ろうものなら、ヒープのサイズに比例して停止時間が伸びるので、停止を許容できる時間内でダンプを取得できるかはかなり微妙です…。そもそも、ギガバイトクラスのヒープダンプを取得して、それを解析できるのか？って話もありますが。

あと、「-permstat」でパーマネント領域の統計情報を取得することもできます。

kill -3 [PID] または kill -QUIT [PID] ＊Windowsの場合はCtrl＋Break

OS標準コマンドですが、これでスレッドダンプを取得することができます。なんかアプリの応答がないような時とか、現在どの辺りを処理しているかを見たい時に重宝します。割と便利なコマンドです。
実行例。

2012-06-23 20:45:42
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.1-b03 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f5b24001000 nid=0x10d3 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f5b50008800 nid=0xefc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Spare-Thread-9" prio=10 tid=0x00007f5b50118800 nid=0xf13 waiting on condition [0x00007f5b47dfc000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at SpareThread.run(Monitor.java:56)

  〜省略〜

"Busy-Thread-2" prio=10 tid=0x00007f5b50106000 nid=0xf09 runnable [0x00007f5b4c8f7000]
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:32)

  〜省略〜

"Signal Dispatcher" daemon prio=10 tid=0x00007f5b500e3800 nid=0xf02 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f5b50096800 nid=0xf01 in Object.wait() [0x00007f5b544e0000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000c2217b90> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
	- locked <0x00000000c2217b90> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x00007f5b50094800 nid=0xf00 in Object.wait() [0x00007f5b545e1000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000c22178e0> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x00000000c22178e0> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x00007f5b5008d000 nid=0xeff runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f5b50016800 nid=0xefd runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f5b50018000 nid=0xefe runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f5b500f5800 nid=0xf06 waiting on condition 

JNI global references: 135

Heap
 PSYoungGen      total 321024K, used 173113K [0x00000000eb600000, 0x0000000100000000, 0x0000000100000000)
  eden space 304896K, 56% used [0x00000000eb600000,0x00000000f5ede700,0x00000000fdfc0000)
  from space 16128K, 1% used [0x00000000fdfc0000,0x00000000fdff0000,0x00000000fef80000)
  to   space 16640K, 0% used [0x00000000fefc0000,0x00000000fefc0000,0x0000000100000000)
 ParOldGen       total 160640K, used 100344K [0x00000000c2200000, 0x00000000cbee0000, 0x00000000eb600000)
  object space 160640K, 62% used [0x00000000c2200000,0x00000000c83fe158,0x00000000cbee0000)
 PSPermGen       total 21248K, used 2361K [0x00000000bd000000, 0x00000000be4c0000, 0x00000000c2200000)
  object space 21248K, 11% used [0x00000000bd000000,0x00000000bd24e5e8,0x00000000be4c0000)

GCスレッドを含めて、JavaVMに存在するすべてのスレッドのダンプが出力されます。また、結果は、killコマンドが適用されたJavaアプリケーションの標準出力に吐き出されます。よって、コンソールを失っているプログラムだと、結果が取得できない可能性があります。Tomcatの場合は、catalina.outに出力されます。

なお、killコマンドでスレッドダンプを取得した場合は、最後にヒープの統計情報が出力されます。

jstack [option] [PID]

kill -QUITと同じく、スレッドダンプを取得するコマンドです。場合によっては、kill -QUITよりも役に立つことがあります。
http://java.sun.com/javase/ja/6/docs/ja/technotes/tools/share/jstack.html

実行例。

$ jstack 3835
2012-06-23 20:50:44
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.1-b03 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f5b24001000 nid=0x10d3 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f5b50008800 nid=0xefc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

  〜省略〜

"VM Thread" prio=10 tid=0x00007f5b5008d000 nid=0xeff runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f5b50016800 nid=0xefd runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f5b50018000 nid=0xefe runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f5b500f5800 nid=0xf06 waiting on condition 

JNI global references: 135

kill -QUITで取得した場合との違いは、以下になります。

結果は、jstackコマンドを実行した側に出力される
ヒープの統計情報は出力されない
「-m」オプションで、ネイティブC/C++フレームの情報も取得可能

バッチプログラムなどで標準出力を捨ててしまっている場合などは、kill -QUITでは結果を見ることができないのでけっこう重宝します。

なお、kill -QUITもjstackも取得する時にはやっぱり対象のJavaアプリケーションが一瞬停止します。まあ、ホントに瞬間なのであまり問題はありませんが、「-m」でネイティブ領域を含めた場合はかなりの時間がかかるので、その場合だけ注意ですね。

【オマケ：CPUを消費しているスレッドをjstackの結果と紐付ける】

Linuxの場合の例です。やり方自体は、けっこう最近知りました。
まず、psコマンドでスレッド単位に出力した上で、CPUの使用率も取っておきます。

$ ps auxww -L
USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1     1  0.0    1  0.0  24448  2416 ?        Ss   19:21   0:03 /sbin/init
root         2     2  0.0    1  0.0      0     0 ?        S    19:21   0:00 [kthreadd]
root         3     3  0.0    1  0.0      0     0 ?        S    19:21   0:00 [ksoftirqd/0]
  〜省略〜
xxxxx     3835  3846  0.0   26 13.4 2263124 543200 pts/3  Sl+  20:18   0:02 java Monitor
xxxxx     3835  3847 32.6   26 13.4 2263124 543200 pts/3  Rl+  20:18  13:31 java Monitor
xxxxx     3835  3848 32.5   26 13.4 2263124 543200 pts/3  Rl+  20:18  13:31 java Monitor
xxxxx     3835  3849 32.5   26 13.4 2263124 543200 pts/3  Rl+  20:18  13:30 java Monitor
xxxxx     3835  3850  0.0   26 13.4 2263124 543200 pts/3  Sl+  20:18   0:00 java Monitor
xxxxx     3835  3851  0.0   26 13.4 2263124 543200 pts/3  Sl+  20:18   0:00 java Monitor
xxxxx     3835  3852  0.0   26 13.4 2263124 543200 pts/3  Sl+  20:18   0:00 java Monitor
  〜省略〜

この場合、スレッドのLWPのうち、3847、3848、3849が主にCPUを消費していることがわかります。この3つを16進数に変換します。16進数に変換する方法は何でもいいですが。

$ printf '%#x\n' 3847
0xf07
$ printf '%#x\n' 3848
0xf08
$ printf '%#x\n' 3849
0xf09

ここで、jstackやkill -QUITでスレッドダンプを取得してみます。

$ jstack 3835
2012-06-23 21:03:34
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.1-b03 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f5b24001000 nid=0x10d3 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f5b50008800 nid=0xefc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

  〜省略〜

"Spare-Thread-0" prio=10 tid=0x00007f5b50108800 nid=0xf0a waiting on condition [0x00007f5b4c7f6000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at SpareThread.run(Monitor.java:56)

"Busy-Thread-2" prio=10 tid=0x00007f5b50106000 nid=0xf09 sleeping[0x00007f5b4c8f7000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at BusyThread.run(Monitor.java:36)

"Busy-Thread-1" prio=10 tid=0x00007f5b50104000 nid=0xf08 runnable [0x00007f5b4c9f8000]
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

"Busy-Thread-0" prio=10 tid=0x00007f5b50102000 nid=0xf07 runnable [0x00007f5b4caf9000]
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

"Service Thread" daemon prio=10 tid=0x00007f5b500eb000 nid=0xf05 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

  〜省略〜

JNI global references: 135

ここで、「nid=」箇所に注目してみます。

"Busy-Thread-2" prio=10 tid=0x00007f5b50106000 nid=0xf09 sleeping[0x00007f5b4c8f7000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at BusyThread.run(Monitor.java:36)

"Busy-Thread-1" prio=10 tid=0x00007f5b50104000 nid=0xf08 runnable [0x00007f5b4c9f8000]
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

"Busy-Thread-0" prio=10 tid=0x00007f5b50102000 nid=0xf07 runnable [0x00007f5b4caf9000]
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

先ほど取得した、スレッドのLWPと一致することが確認できましたね。

スレッドのCPU使用率順にソートして表示するなら、こんな感じでいいかな。

$ ps auxww -L | sort -n -k 4

また、スレッドのIDとjstackの結果の紐付け方ですが、16進数に変換するのではなくてPerl One Linerとかで
「nid=」の部分を直接10進数に戻しても良いかなと。

$ jstack 3835 | perl -wp -e 's!(.+)nid=0x([a-z0-9]+)(.+)!print "$1nid=" . hex("$2") . "$3"!e'
2012-06-23 21:03:34
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.1-b03 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f5b24001000 nid=4307 waiting on condition [0x0000000000000000]1
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f5b50008800 nid=3836 waiting on condition [0x0000000000000000]1
   java.lang.Thread.State: RUNNABLE

  〜省略〜

"Spare-Thread-0" prio=10 tid=0x00007f5b50108800 nid=3850 waiting on condition [0x00007f5b4c7f6000]1
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at SpareThread.run(Monitor.java:56)

"Busy-Thread-2" prio=10 tid=0x00007f5b50106000 nid=3849 sleeping[0x00007f5b4c8f7000]1
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at BusyThread.run(Monitor.java:36)

"Busy-Thread-1" prio=10 tid=0x00007f5b50104000 nid=3848 runnable [0x00007f5b4c9f8000]1
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

"Busy-Thread-0" prio=10 tid=0x00007f5b50102000 nid=3847 runnable [0x00007f5b4caf9000]1
   java.lang.Thread.State: RUNNABLE
	at BusyThread.run(Monitor.java:34)

"Service Thread" daemon prio=10 tid=0x00007f5b500eb000 nid=3845 runnable [0x0000000000000000]1
   java.lang.Thread.State: RUNNABLE

  〜省略〜

JNI global references: 135

CLOVER🍀

That was when it all began.

Javaのコマンドラインでのモニタリング／トラブルシューティングツール

jps

jstat [option] [PID] [interval] [count]

jmap　[option] [PID]

kill -3 [PID] または kill -QUIT [PID] ＊Windowsの場合はCtrl＋Break

jstack [option] [PID]

【オマケ：CPUを消費しているスレッドをjstackの結果と紐付ける】

jps

jstat [option] [PID] [interval] [count]

jmap [option] [PID]

kill -3 [PID] または kill -QUIT [PID] ＊Windowsの場合はCtrl＋Break

jstack [option] [PID]

【オマケ：CPUを消費しているスレッドをjstackの結果と紐付ける】

jmap　[option] [PID]