スレッド名にデバッグ情報を埋め込むと激しく捗る件

こんにちは、アプリケーション基盤チームの青木(@a_o_k_i_n_g)です。

今回、Java のちょっとしたデバッグテクニックを紹介したいと思います。Java で運用中何かトラブルが発生した場合、スレッドダンプを取得することはしばしばあると思いますが、スレッドダンプだけだとちょっと情報が足りないことがあります。今回はスレッドダンプから得られる情報を増やして、素早く障害対応したりデバッグに役立てる方法を紹介します。

まずはじめに: スレッドダンプの取り方

基本ですが、改めてスレッドダンプの取得の仕方を紹介しておきます。スレッドダンプを取得する対象のプロセス ID を仮に 12345 として、下記のように jstack コマンドを実行すればスレッドダンプが取得できます(※Linux上で操作する想定)。

$ jstack 12345

対象のプロセス ID は ps aux | grep java や、jps -l コマンドで調べましょう。

一つ注意点があります。jstack を実行するユーザーは Java プロセス実行ユーザーと同じユーザーでなければなりません。仮にログインユーザーが aoking で、対象プロセスの実行ユーザーが cybozu なら下記のようにしましょう。

$ sudo -u cybozu jstack 12345

さて jstack を発行するとこんなスレッドダンプが取得できます(一部抜粋)。

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f31fc09c000 nid=0x57d4 in Object.wait() [0x00007f31ccd17000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000005cab10ff8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000005cab10ff8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"main" #1 prio=5 os_prio=0 tid=0x00007f31fc01a000 nid=0x57c4 runnable [0x00007f3204b90000]
   java.lang.Thread.State: RUNNABLE
    at java.util.regex.Pattern.<init>(Pattern.java:1351)
    at java.util.regex.Pattern.compile(Pattern.java:1028)
    at com.cybozu.common.Sample.main(Sample.java:8)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)

これはスレッドごとにスレッド名や優先度、スレッド ID、スタックトレース等を出力したものです。例えば例では main スレッドと Finalizer スレッドがあり、main スレッドでは java.util.regex.Pattern クラスのインスタンス初期化をしている最中だということがわかります。

スレッド名に情報を埋め込もう

さて前述の例のスレッド名は main と Finalizer だったので一目瞭然でしたが、一般的なスレッド名は pool-472-thread-6392 や qtp278934944-22 などで、実質意味を成さないものがよくあります。ここに任意の名前を埋め込んで、デバッグ効率を高めましょう。

早速例を見てみます。

long customerId = ...
String requestId = ...

Thread current = Thread.currentThread();
String originalName = current.getName();

String name = String.format("blob-add-%d-%s", customerId, requestId);
current.setName(name); // スレッド名をセット
try {
    addFile(...);
} finally {
    current.setName(originalName); // スレッド名を元に戻す
}

こちらは cybozu.com 内で利用しているファイルサーバーの実装を元にした例です。このファイルサーバーに対してファイル追加を行うリクエストが来た時を想定しています。ここでは、ファイル追加処理であるという目印(blob-add の部分)と、顧客 ID、それからリクエスト ID というものをスレッド名に載せています。リクエスト ID とは cybozu.com へのアクセスごとに割り当てられる ID のことで、このリクエスト ID があればどのサーバーに何時にアクセスしたのかということがわかるようになっています。

この処理を入れておくと、スレッドダンプを出した際のスレッド名が blob-add-52153-1bd6bb9a88cc4ad のようになり、スレッドダンプを眺める時に「ファイル追加処理が怪しい。顧客 ID 52153 のユーザーに影響が出ていそうだ、リクエスト ID を元に他のログを見よう」ということができるようになります。

これはあくまで例であり、アプリケーションによって必要な情報は大きく異なります。過去の障害調査の経緯などを参考にしてスレッド名に埋め込む情報を決めると良いでしょう。

処理が終わったらスレッド名を元の名前に戻しておくと良いです。理由はふたつほどあります。ひとつ目は、スレッドは処理が終わったらスレッドプール内で寝ているので、その寝ている時のスレッドと処理中のスレッドを見分けるため、という理由が一つ。もうひとつは、スレッドが再利用された時、スレッド名を適切な名前に設定していなかったらリクエストとスレッドの情報に乖離が生じることになってしまう、という理由です。

スレッドプールの名前を任意の名前にしよう

前章では Web アプリケーションをイメージしており、リクエストごとにスレッド名を指定する作りでした。しかしアプリケーションの種類によっては、スレッド個々についてではなくスレッドプール単位で情報が分かれば良い、というケースもあります。

Java でスレッドプールといえば ExecutorService が便利なので良く使われますが、こちらはデフォルトだと pool-7-thread-5 のような味気ないスレッド名が使われます。ExecutorService を使う場合でもスレッド名を自由に設定することができるので、今回の例では新規にスレッドが生成される度にスレッドに番号を埋め込む方法を紹介します。

通常、ExecutorService の生成は Executors.newCachedThreadPool() あたりが良く使われます。このメソッドには java.util.concurrent.ThreadFactory を渡すことができ、ThreadFactory ではスレッド生成時の処理を書けるので、そこで任意の名前を設定することができます。

コード例です。

public class CybozuExecutors {
    public static ExecutorService newCachedThreadPool(String poolName) {
        // ここのスレッド名の %d にスレッド番号が自動的に割り当てられる
        ThreadFactory factory = new CybozuThreadFactory(poolName + "-thread-%d");
        return Executors.newCachedThreadPool(factory);
    }

    private static class CybozuThreadFactory implements ThreadFactory {
        private final AtomicInteger counter = new AtomicInteger();
        private final String threadNameFormat;

        private CybozuThreadFactory(String threadNameFormat) {
            this.threadNameFormat = threadNameFormat;
        }

        @Override
        public Thread newThread(Runnable r) {
            // ここでスレッド名をフォーマットする
            String name = String.format(threadNameFormat, counter.incrementAndGet());
            return new Thread(null, r, name);
        }
    }
}

使う側ではこのようにして呼び出して ExecutorService を生成します。

ExecutorService executor = CybozuExecutors.newCachedThreadPool("mail-processor-" + customerId);

するとこの executor を使ったタスクのスレッド名は mail-processor-52153-thread-3 や mail-processor-52153-thread-27 のようなスレッド名になり、顧客 ID 52153 のメール関連の処理を担当するスレッドということがスレッドダンプから一目瞭然になります。

注意点。CybozuThreadFactory はあくまでサンプル用に書いたコードです。実際に使う場合は Guava の ThreadFactoryBuilder 等を使うと安全でシンプルに ThreadFactory を生成できるのでおすすめです。

最後に

スレッド名にデバッグ情報を埋め込むのは大変便利ですが、当たり前すぎるのかあまり紹介されないテクニックなので今回紹介させていただきました。適切な情報をスレッド名に指定しておくと原因や影響範囲が特定しやすくなり、結果的にユーザーへのサービス品質が高めることができると思います。

特にマルチスレッドなプログラムはデバッグに大変時間がかかることが多いです。スレッド名の改善だけで解決できるようになるわけではありませんが、解決困難な現象に立ち向かう時のひとつの手がかりとしては有用なので、ぜひ参考にしてみてください。

それでは、良いデバッグライフを！