jstack でスレッドダンプを取る

jstack というツールがある。このツールは、現在実行中の Java プロセスのスレッドの状態を取得出来るツールだ。

思ったように性能が出ない時やデッドロックっぽい現象が発生した際はこのツールを使ってスレッドの状態を取得、つまりスレッドダンプを得て、そこから解決の糸口を探す。

今回のサンプルコードは下記コード。
少し長いが、Thread1 と Thread2 クラスはほぼ同一だ。違うのは、リソースをロックする順序。Thread1 クラスは resource1, resource2 の順にロックするが、Thread2 クラスは resource2, resource1 の順にロックする。つまり、これら２つのクラスを同時に実行するとデッドロックを起こす。

public class DeadLockTest {
    public static Object resource1 = new Object();
    public static Object resource2 = new Object();

    public static void main(String[] args) {
        // Thread1, Thread2 クラスを(ほぼ)同時に実行
        new Thread(new Thread1()).start();
        new Thread(new Thread2()).start();
    }
}

// resource1, resource2 の順にロックする
class Thread1 implements Runnable {
    @Override
    public void run() {
        synchronized (DeadLockTest.resource1) {
            System.out.println("thread1 - locked resource1");
            synchronized (DeadLockTest.resource2) {
                System.out.println("thread1 - locked resource2");
            }
        }
    }
}

// resource2, resource1 の順にロックする
class Thread2 implements Runnable {
    @Override
    public void run() {
        synchronized (DeadLockTest.resource2) {
            System.out.println("thread2 - locked resource2");
            synchronized (DeadLockTest.resource1) {
                System.out.println("thread2 - locked resource1");
            }
        }
    }
}

さて上記 DeadLockTest クラスを実行すると、たやすくデッドロックが発生する。コンソールには下記のような出力がされた後、ずっとリソースの解放を待っている状態に陥る。(タイミングによっては発生しない場合もある)

thread1 - locked resource1
thread2 - locked resource2
(ここでロック解放待ち状態)

さて、無事デッドロックを再現したところでこいつのスレッドダンプを取得してみよう。jstack には引数に対象の Java プロセスのプロセス ID を渡す。なのでまずは jps コマンドで対象の Java プロセスのプロセス ID を調べよう。

$ jps
12359 Jps
11367 org.eclipse.equinox.launcher_1.2.0.v20110502.jar
12316 DeadLockTest

この結果は環境によって異なるが、このテスト以外に Java プロセスを立ち上げていない場合は上記のような結果になるだろう。さて、これで DeadLockTest の PID は 12316 だと判明した。

では jstack でスレッドダンプを取得する。これだけのプログラムでも結果はそれなりに長いので中略する。

$ jstack 12316
2012-06-29 09:17:50
Full thread dump OpenJDK 64-Bit Server VM (20.0-b12 mixed mode):

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

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

...(中略)...

Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007f11940036c8 (object 0x00000007ac7596f8, a java.lang.Object),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007f1194005e28 (object 0x00000007ac759708, a java.lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
	at Thread2.run(DeadLockTest.java:32)
	- waiting to lock <0x00000007ac7596f8> (a java.lang.Object)
	- locked <0x00000007ac759708> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:679)
"Thread-0":
	at Thread1.run(DeadLockTest.java:19)
	- waiting to lock <0x00000007ac759708> (a java.lang.Object)
	- locked <0x00000007ac7596f8> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:679)

Found 1 deadlock.

結果下部に見ると、このプロセスがデッドロックを起こしていることが明らかだ。親切にもデッドロックを検出して出力してくれている。

ここでは、仮にこの "Found one Java-level deadlock" という情報が無いものとして、どのようにスレッドダンプを読むか、その読み方について記述することにする。
スレッドダンプは、基本的に下記のようなフォーマットの繰り返しで出力される。

スレッド名 prio=優先度 tid=スレッドID nid=管理ID 状態 スタックアドレス
   java.lang.Thread.State: 状態
      スタックトレース1
      スタックトレース2
      ...

出力したスレッドダンプを見るとガベージコレクト用のスレッドなど多数存在するが、注目すべきは Thread-1, Thread-2 のログだ。

"Thread-1" prio=10 tid=0x00007f11cc18c000 nid=0x303b waiting for monitor entry [0x00007f11bbbfa000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread2.run(DeadLockTest.java:32)

        - waiting to lock <0x00000007ac7596f8> (a java.lang.Object)

        - locked <0x00000007ac759708> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)
"Thread-0" prio=10 tid=0x00007f11cc17a000 nid=0x303a waiting for monitor entry [0x00007f11bbcfb000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread1.run(DeadLockTest.java:19)

        - waiting to lock <0x00000007ac759708> (a java.lang.Object)

        - locked <0x00000007ac7596f8> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)

注目すべきは、- locked という行と - waiting to lock という行。 の値はロックオブジェクトのアドレスを表す。ここで、"Thread-1" スレッドの - waiting to lock <0x00000007ac7596f8> に注目する。"Thread-1" はこの行で <0x00000007ac7596f8> オブジェクトをロックしようとしているが、獲得できずに待ち状態になっている。さて、このアドレス <0x00000007ac7596f8> を見てみると、"Thread-0" でロックしていることがわかる。

"Thread-1" prio=10 tid=0x00007f11cc18c000 nid=0x303b waiting for monitor entry [0x00007f11bbbfa000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread2.run(DeadLockTest.java:32)

        - waiting to lock <0x00000007ac7596f8> (a java.lang.Object)

        - locked <0x00000007ac759708> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)

"Thread-0" prio=10 tid=0x00007f11cc17a000 nid=0x303a waiting for monitor entry [0x00007f11bbcfb000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Thread1.run(DeadLockTest.java:19)
- waiting to lock <0x00000007ac759708> (a java.lang.Object)
- locked <0x00000007ac7596f8> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:679)

次に、"Thread-0" の waiting to lock に注目する。 Thread-0 では <0x00000007ac759708> というアドレスのオブジェクトのロックを獲得しようとしているが獲得できずに待ち状態になっている。先程と同様にこのアドレスに注目すると、"Thread-1" でロックしていることがわかる。

"Thread-1" prio=10 tid=0x00007f11cc18c000 nid=0x303b waiting for monitor entry [0x00007f11bbbfa000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread2.run(DeadLockTest.java:32)

        - waiting to lock <0x00000007ac7596f8> (a java.lang.Object)

        - locked <0x00000007ac759708> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)
"Thread-0" prio=10 tid=0x00007f11cc17a000 nid=0x303a waiting for monitor entry [0x00007f11bbcfb000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread1.run(DeadLockTest.java:19)

        - waiting to lock <0x00000007ac759708> (a java.lang.Object)

        - locked <0x00000007ac7596f8> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)

つまりお互いのロック解放を待っている状態で、デッドロックになっていることがわかった。

この waiting to lock と locked が発生しているのは DeadLockTest の 32 行目と 19 行目であることが読み取れる。

"Thread-1" prio=10 tid=0x00007f11cc18c000 nid=0x303b waiting for monitor entry [0x00007f11bbbfa000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread2.run(DeadLockTest.java:32)

        - waiting to lock <0x00000007ac7596f8> (a java.lang.Object)

        - locked <0x00000007ac759708> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)
"Thread-0" prio=10 tid=0x00007f11cc17a000 nid=0x303a waiting for monitor entry [0x00007f11bbcfb000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at Thread1.run(DeadLockTest.java:19)

        - waiting to lock <0x00000007ac759708> (a java.lang.Object)

        - locked <0x00000007ac7596f8> (a java.lang.Object)

        at java.lang.Thread.run(Thread.java:679)

では改めて DeadLockTest のソースを読む。下記の太字の行が 19 行目と 32 行目、ではなく、なぜか一行ずれて19行目と32行目はSystem.out.printlnの行だった(なぜずれているのだろう？)。ただここまで限定できればロックしてる箇所は明らかなので、18行目と31行目の synchronized の行を太字にしてある。

...

// resource1, resource2 の順にロックする

class Thread1 implements Runnable {

    @Override

    public void run() {

        synchronized (DeadLockTest.resource1) {

            System.out.println("thread1 - locked resource1");

            synchronized (DeadLockTest.resource2) {

                System.out.println("thread1 - locked resource2");

            }

        }

    }

}
// resource2, resource1 の順にロックする

class Thread2 implements Runnable {

    @Override

    public void run() {

        synchronized (DeadLockTest.resource2) {

            System.out.println("thread2 - locked resource2");

            synchronized (DeadLockTest.resource1) {

                System.out.println("thread2 - locked resource1");

            }

        }

    }

}

これはデッドロック用に作ったコードなのでどこがデッドロックを起こしているかは自明だが、実際はもう少し複雑だ。重要なのは、jstack で取得出来るスレッドダンプでここまで簡単に、そしてスピーディに原因と思われる箇所を特定出来る点だ。また、デッドロックはあまり起こるものではないのでスレッドダンプを取得してもデッドロックの探索にはあまり使えないが、性能問題を調べる場合にはスレッドダンプは非常に活躍する。ロックを獲得するのに多量のスレッドが待っているような場合は一目瞭然だ。そのような場合、Thread.State が WAITING になっているので Thread.State で grep すれば即座に明らかになるだろう。

Thread.State が取りうる状態は下記の通り。

スレッドの状態です。スレッドの状態は、次のどれかです。

• NEW
  
  起動していないスレッドの状態
• 
  RUNNABLE
  
  Java 仮想マシンで実行されているスレッドの状態
• BLOCKED
  
  ブロックされ、モニターロックを待機しているスレッドの状態
• WAITING
  
  ほかのスレッドが特定のアクションを実行するのを無期限に待機しているスレッドの状態
• TIMED_WAITING
  
  指定された待機時間、ほかのスレッドがアクションを実行するのを待機しているスレッドの状態
• TERMINATED
  
  終了したスレッドの状態

http://java.sun.com/javase/ja/6/docs/ja/api/java/lang/Thread.State.html

まとめると、スレッドダンプを取って読めるようになることは性能問題の解決に非常に役立つツール・能力となる。
１つ上のプログラマになるため、習得しておくべし。

増補改訂版 Java言語で学ぶデザインパターン入門 マルチスレッド編