スレッドダンプを取得して Javaプロセスのトラブル調査に役立てよう

Javaで長時間が処理が終わらない、異常にメモリを消費しているなど、IT エンジニアであれば、こうしたアプリケーションのトラブルに出会ったことがある人は少なくないでしょう。

この記事では、アプリケーションのトラブル調査に役立つ、Java のスレッドダンプの取り方と、取得したダンプの見方について解説していきます。

スレッドダンプとは？

スレッドダンプとは、指定した Java プロセスの、ある時点においての全スレッドの情報を出力したファイルです。

スレッドダンプには、すべてのスレッドのスタックトレースの情報が出力され、さらにデットロックなどが発生していれば、その情報も出力されます。

マルチスレッドで動作する Web アプリケーションでは、同時に複数のスレッドが動作しています。スレッドダンプを出力することで、それらのスタックトレースの状況を確認し、アプリケーションのボトルネックとなっている原因などを調査します。

テスト用プログラム

今回は次のサンプルコードを実行して、複数のスレッド情報を、スレッドダンプに出力してみましょう。

import java.util.concurrent.*;

public class Main {

  public static void main(String[] args) throws InterruptedException {
    //スレッドプールの作成
    ExecutorService pool = Executors.newFixedThreadPool(5);

    //５つのスレッド作成
    for (int cnt = 0; cnt < 5; cnt++) {
      pool.submit(() -> {
        for (int i = 0; i < 1800; i++) {
          try {
            Thread.sleep(100);
          } catch (InterruptedException e) {
          }
        }
      });
    }

    try {
      //すべてのスレッドが終了するまで、ここで待機する
      pool.shutdown();
      pool.awaitTermination(Long.MAX_VALUE, TimeUnit.NANOSECONDS);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
  }
}

スレッドダンプを取得してみよう

スレッドダンプは jstack コマンドを用いて取得します。

Java のプロセスIDを特定する

jstack コマンドは、動作中の JavaプロセスIDを指定してスレッドダンプを出力するため、まずはダンプを出力するプロセスのIDを特定する必要があります。

上で書いたサンプルコードを実行した状態で、jps コマンドで実行中の Java プロセスを確認します。

$ jps

81824 Jps
79596 org.eclipse.equinox.launcher_1.6.200.v20210416-2027.jar
81822 Main

複数の Java プロセスが実行中だと、上のように複数行の結果が出力されます。サンプルコードのプロセス名は「Main」で出力されるため、プロセスID＝81822 をメモしておきます。

特定したプロセスIDでスレッドダンプを出力する

jps コマンドでプロセスが特定できたら、jstack コマンドにプロセスIDを指定してスレッドダンプを出力しましょう。

$ jstack <プロセスID>

jstack コマンドを実行すると、次のような結果が出力されます。

ダンプの中身を確認してみよう

初めてスレッドダンプを見ると、大量の文字が出力され、とまどうかもしれませんが、出力されたファイルを上から順を追って見ていきましょう。

スレッド ダンプの先頭

スレッド ダンプの先頭には、ヘッダー情報としてダンプを出力した日時や、使用されている JRockit JVM のバージョン番号が出力されます。

2021-09-12 16:14:36
Full thread dump OpenJDK 64-Bit Server VM (16.0.1+9 mixed mode, sharing):

スレッドのリスト

次に出力されるのが、実行中のスレッドIDのリストが出力されます。

Threads class SMR info:
_java_thread_list=0x00007fae1ff0dbb0, length=17, elements={
0x00007fae20008200, 0x00007fae2101d000, 0x00007fae2101f800, 0x00007fae2009a800,
0x00007fae2009ae00, ...
}

ポテパンダの一言メモ

スレッドIDのリストには、メインスレッドおよび、メインスレッドから起動したスレッドと、JVM がバックグラウンドで実行するガベージコレクションコレクションなどのデーモンスレッドのIDも出力されます。

スタックトレース情報

スレッドリストの次は、メインスレッドのスタックトレースが出力されます。

続けて、メインスレッド以外のスレッド情報と、JVM のバックグラウンドスレッドのスタックトレースの情報が出力されます。

デットロックの情報

プロセスでデットログが発生していると、スレッドダンプにはデットログックを引き起こしているスレッドIDの情報が出力されます。

デットロックは、普通のプログラムテストでは中々気付くことが難しく、本番環境で発生してしまうことがあります。このようなトラブル時にスレッドダンプを出力することで、デットロックの発生をすぐさま検知することができ、素早く問題への対処が行えます。

Found one Java-level deadlock:
=============================
"pool-1-thread-1":
  waiting to lock monitor 0x00007f853a71c9e0 (object 0x0000000787f1b740, a java.lang.Object),
  which is held by "pool-1-thread-2"

"pool-1-thread-2":
  waiting to lock monitor 0x00007f853a43d470 (object 0x0000000787f1b730, a java.lang.Object),
  which is held by "pool-1-thread-1"

Java stack information for the threads listed above:
===================================================

スレッドダンプを取得する時のポイント

アプリケーショントラブル時に、原因究明に役立つスレッドダンプを取得する時のポイントは次のとおりです。

数秒おきに複数回取る

スレッドダンプは数秒間隔で複数回取るようにしましょう。１回だけだと、偶然ネットワークアクセスが発生してスレッドが一時停止し、それがアプリケーションのボトルネックとして勘違いしてしまうことがあるため、何度か取得し、出力されたスタックトレースなどの情報から、共通している情報を抽出し、ボトルネックの調査に役立てます。

jstack プロセスID >  threaddump.$(date +%F-%H%m%S)

ヒープダンプも出来れば合わせて取りたい

Java にはスレッドダンプに似たものとして、現在のメモリ情報を出力ヒープダンプがあります。ヒープダンプとスレッドダンプを組み合わせて取得することで、より情報が揃っている状態で調査を進められるため、できれば合わせて取得しておきたいところです。

しかし、ヒープダンプはメモリ情報をダンプに出力する際にアプリケーションが一時的に停止するため、取得する時は注意が必要です。（スレッドダンプは取得時にアプリケーションを停止せず、それほぞ思い処理でもないため、積極的に取ることをお勧めします）

【関連記事】
▶【Java】wait・notifyを使ってスレッド間の待ち合わせを実装する