あえて実装し、解析することでバグを理解する (1) デッドロック(Java)

概要

メモリリークやデッドロックなどの問題を解析する方法はインターネットにたくさん公開されています。しかし、解析の対象となる問題自体は、いつ、どのようなものが目の前に現れるか分からないので、実際に問題に直面するまでに、体系的に解析の方法を習得し、実践しておくのはなかなか難しいことではないかと思います。

そこで、実践形式で学習ができるように、問題を意図的に再現可能なバグだらけのWebアプリケーションを開発し、Qiitaにもそれに関する情報を公開してみました。このWebアプリケーションは、コマンド1つでビルドや起動ができるとても手軽なものなので、実験や教育の目的でも活用できると思います。

このWebアプリケーションを使って、これからいろいろな問題(バグ)とそれを解析する方法を少しずつ紹介していきたいと思います。

ということで、第1回目に紹介するバグは、Javaのスレッドのデッドロックです。

デッドロックを再現する

まずは、デッドロックを実際に再現してみましょう。Webアプリケーションをダウンロードして、起動します。

$ java -jar easybuggy.jar

または

$ git clone https://github.com/k-tamura/easybuggy
$ cd easybuggy
$ mvn clean install exec:exec

その他にROOT.warをTomcatなどのサーブレットコンテナにデプロイしても起動できます。以下のメッセージが表示されたら、Webアプリケーションの起動は完了しています。

5 27, 2017 3:29:58 午後 org.apache.coyote.AbstractProtocol start
情報: Starting ProtocolHandler ["http-bio-8080"]

※補足： バージョンが1.2.x以前の場合、Windowsではeasybuggy.jarが正常に動作しない可能性があります。その場合は、pathにJDKのbinまでのパスをセットしてから、JDKに含まれるJREのjavaで起動してみて下さい。 ¹

> set path=%path%;C:\Program Files\Java\jdk1.8.0_121\bin
> "C:\Program Files\Java\jdk1.8.0_121\jre\bin\java" -jar easybuggy.jar

起動したら次のURLにアクセスします。

正常に起動していると、以下のような画面が表示されます。

この中にある「デッドロック (Java)」と書かれたリンクをクリックして下さい。すると、「このページを数回ロードすると、デッドロックが発生します。」とだけ記載された画面が表示されます。まずは、F5キーを1回だけ押して画面をロードしてみて下さい。5秒ほどすると応答が返り、「デッドロックは発生しませんでした。」というメッセージが表示されます。デッドロックは単一のリクエストだけを処理しているような状況では発生しません。次にF5キーを2回連続で押して下さい。今度は、どれだけ待っても応答が返らないはずです。このときWebアプリケーションではデッドロックが発生しています。

解析する

応答が返らないということは、次の可能性が考えられます。

・処理が停止している (デッドロックなどが原因)
・処理が終わらなくなってしまっている (無限ループなどが原因)
・想定を大きく超えるほど処理に時間がかかっている (性能に対する考慮不足のロジックなどが原因)

応答が返らない場合に最初にすべきことは、スレッドダンプを取得するということです。

まずはjpsコマンドでWebアプリケーションのプロセスIDを特定します。

＄ jps
85489 org.eclipse.equinox.launcher_1.3.100.v20150511-1540.jar
45733 Launcher
69970 easybuggy.jar
89901 Jps

このWebアプリケーションのプロセス名は、javaコマンドで起動している場合が「easybuggy.jar」、mvnコマンドで起動している場合が「EmbeddedJettyServer」になります。上の場合は、69970がプロセスIDになります。

特定したプロセスIDを指定して、jstackコマンドを実行すると、スレッドダンプが出力されます。

$ jstack 69970
2017-02-26 18:58:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode):

"Attach Listener" #71 daemon prio=9 os_prio=0 tid=0x00007f4804001800 nid=0x1120f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"derby.rawStoreDaemon" #70 daemon prio=5 os_prio=0 tid=0x00007f4798deb800 nid=0x111b2 in Object.wait() [0x00007f47e0473000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at org.apache.derby.impl.services.daemon.BasicDaemon.rest(Unknown Source)
	- locked <0x00000000f7aa3a80> (a org.apache.derby.impl.services.daemon.BasicDaemon)
	at org.apache.derby.impl.services.daemon.BasicDaemon.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:745)

　　・・・(略)・・・

Found one Java-level deadlock:
=============================
"http-listener(8)":
  waiting to lock monitor 0x00007f4830363368 (object 0x00000000f0165dc8, a java.lang.Object),
  which is held by "http-listener(9)"
"http-listener(9)":
  waiting to lock monitor 0x00007f4830364b78 (object 0x00000000f0165db8, a java.lang.Object),
  which is held by "http-listener(8)"

Java stack information for the threads listed above:
===================================================
"http-listener(8)":
	at org.t246osslab.easybuggy.troubles.DeadlockServlet.lock12(DeadlockServlet.java:61)
	- waiting to lock <0x00000000f0165dc8> (a java.lang.Object)
	- 
	- locked <0x00000000f0165db8> (a java.lang.Object)
	at org.t246osslab.easybuggy.troubles.DeadlockServlet.doGet(DeadlockServlet.java:43)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

　　・・・(略)・・・

"http-listener(9)":
	at org.t246osslab.easybuggy.troubles.DeadlockServlet.lock21(DeadlockServlet.java:70)
	- waiting to lock <0x00000000f0165db8> (a java.lang.Object)
	- locked <0x00000000f0165dc8> (a java.lang.Object)
	at org.t246osslab.easybuggy.troubles.DeadlockServlet.doGet(DeadlockServlet.java:46)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

　　・・・(略)・・・

Found 1 deadlock.

「Found one Java-level deadlock:」とあるようにデッドロックが発生していることが分かります。デッドロックは、スレッドダンプにより簡単に検出でき、原因となるスレッドがどれであるかも特定可能です。上の場合は、「http-listener(8)」と「http-listener(9)」という2つのスレッド間でデッドロックが発生していることを示しています。前者はDeadlockServlet.javaの61行目で、後者はDeadlockServlet.javaの70行目でロック獲得待ち(waiting to lock)していることが分かります。

デッドロックとは？

そもそもデッドロックとはどのような事象でしょうか？デッドロックとは、複数のプロセス(本ケースではスレッド)が互いに相手の占有(ロック)しているリソース(本ケースではオブジェクト)の解放を待ってしまい、処理が停止してしまうことを言います。

例えば、以下のようにスレッド1がオブジェクト1を、スレッド2がオブジェクト2をロックした後で、両者のロックが解除されないまま、今度は逆にスレッド1がオブジェクト2を、スレッド2がオブジェクト1をロックしようとすると、どちらのスレッドもお互いの完了待ち状態となり、処理が停止してしまいます。この状態がデッドロックです。

どのような実装になっているのか

ソースコードはどのような実装になっていたのでしょうか？先ほどスレッドダンプに出力されていたDeadlockServlet.javaを見てみましょう。重要なのは以下の部分です。

    private final Object lock1 = new Object();
    private final Object lock2 = new Object();
    private boolean switchFlag = true;

    protected void doGet(HttpServletRequest req, HttpServletResponse res) throws ServletException, IOException {

　　・・・(略)・・・

                switchFlag = !switchFlag;
                if (switchFlag) {
                    lock12();
                } else {
                    lock21();
                }

　　・・・(略)・・・

    }

    private void lock12() {
        synchronized (lock1) {
            sleep();
            synchronized (lock2) {
                sleep();
            }
        }
    }

    private void lock21() {
        synchronized (lock2) {
            sleep();
            synchronized (lock1) {
                sleep();
            }
        }
    }

このサーブレットでは、switchFlagというフラグでリクエストを2つのメソッドlock12()とlock21()に交互に振り分けています。lock12()ではオブジェクト「lock1」をロック→5秒スリープ→オブジェクト「lock2」をロックという順で処理をしています。lock21()ではその逆順で処理を実行しています。

したがって、今回のケースは以下のようになります。

クライアントからのリクエストを受け付けるために生成されていた2つのHTTPリスナースレッド(http-listener(8)とhttp-listener(9))が、それぞれのロックしているオブジェクト(lock1、lock2)の開放を待つことで、デッドロックとなっているのです。

スレッドダンプ以外の検出方法

デッドロックを検出する方法は他にもあります。

VisualVM

OracleのJDKに付属しているVisualVMを使っても、デッドロックを検出できます。VisualVMは、デッドロックを自動的に検出して赤字で警告を表示します。

Java Mission Control

同じくOracleのJDKに付属しているJava Mission Controlを使う場合は、「デッドロック検出」のチェックボックスにチェックを入れておくことで検出ができます。

JConsole

OpenJDKにはVisualVMやJava Mission Controlはありませんが、JConsoleがあります。「デッドロックの検出」ボタンをクリックすることで、こちらも検出が可能です。

JVMはデッドロックを検出し、一方のスレッドを終了できるか

一般的なRDBMSでは、デッドロックを検出すると、一方のトランザクションをロールバックして、もう一方をコミットすることができます。JVMも同様のことができるのでしょうか。答えは「いいえ」です。そういったJVMオプションはありません。デッドロックから、Webアプリケーションを復元する唯一の方法は、再起動をするということです。
一般的にデッドロックはすぐに表面化することは稀れなので、気がつくと大量のスレッドが待ち状態になっているようなことが起こりえます。したがって、オブジェクトをロックする処理を実装する場合、プログラマーは処理順序に不整合が発生しないように注意する必要があります。

プログラムでデッドロックを検出する

プログラムでデッドロックを検出することはできます。以下のようにjava.lang.management.ThreadMXBean.findDeadlockedThreads()を使用して、デッドロックとなったスレッドの情報が取得できます。

        ThreadMXBean bean = ManagementFactory.getThreadMXBean();
        long[] threadIds = bean.findDeadlockedThreads();
        if (threadIds != null) {
            ThreadInfo[] infos = bean.getThreadInfo(threadIds);
            for (ThreadInfo info : infos) {
                log.error(info.toString());
            }
        }

今回のまとめ

• デッドロックは、複数のプロセス(スレッド)が互いに相手のロックしているリソースの解放を待ってしまい、処理が停止してしまうことを言う
• デッドロックが発生すると、そのプロセス(スレッド)が停止してしまうため、Webアプリケーションの場合、レスポンスが永久に返らなくなる
• デッドロックは、jstackやJConsoleなどのJDK付属のツールで検出できる
• デッドロックから回復するJVMオプションは無い
• デッドロックから回復するには、JVMを再起動するしかない
• デッドロックを回避するのはプログラマーの責任である
• デッドロックはプログラム(ThreadMXBean.findDeadlockedThreads())からも検出できる

---

参考：
COMP 3400 Lecture 7: Deadlock (オターバイン大学の講義資料？)
http://faculty.otterbein.edu/PSanderson/COMP3400/notes/lecture07.html

---

1. おそらくPayara Microのバグに起因していると思いますが、原因を特定できていません。時間がある時に調べます。 ↩