🔍

jcmd で取得した Heap Dump, Thread Dump を各種ツールで分析する

2024/04/08に公開

Java

はじめに

JVM 言語で動くアプリケーションがハングアップしたり、動作が遅くなったり、不安定な状態になった際、やるべきことってなんだろう。

（という書き出しは、エスカレーションとか...自分が書きたい内容と逸れる気がしたものの）
今回は、問題が起こった時の調査手段のひとつとして、実行中の Java プロセスから各種 dump を取得して分析する方法を整理します。

この話は、本番環境で上記のような問題が発生して急ぎ対応が必要な状況下で動けるようにするためのものです。その際、各種 dump の取得方法や関連する知識は準備しておいたほうが無難だと考えています。

また、ここにある内容は、色んな選択肢の中から自分好みのものを選択しているので、あくまで自分向けの内容であると捉えていただけるとありがたいです。各々が使いやすい、手に馴染んだツールを活用するのが一番いいと思います。

環境

チップ: Apple M1 Pro
macOS: Sonoma 14.3

$ java --version
openjdk 11.0.19 2023-04-18 LTS
OpenJDK Runtime Environment Corretto-11.0.19.7.1 (build 11.0.19+7-LTS)
OpenJDK 64-Bit Server VM Corretto-11.0.19.7.1 (build 11.0.19+7-LTS, mixed mode)

必要な知識

まずは必要な知識を頭に入れます。

Heap Dump

Heap Dump は、特定の時点での Java ヒープメモリの内容をキャプチャしたもの。
この dump には、実行時に使用されているすべてのオブジェクトの現在の状態が含まれる。
非効率なメモリ消費や、Java の OutOfMemoryError の分析に活用できる。

想定以上にメモリを食ってたり、GC が頻発している状況で取得するといい。大雑把にオブジェクト特定できるだけでも調査が早く進むことがあるが、Heap Dump は出力に時間がかかるし、JVM の動作も一時的に停止するため、本番環境で取得する場合はロードバランサから一旦外す等の考慮をしたほうがいいかもしれない。

※ヒープメモリは、Java プロセス内に存在する Java オブジェクトを格納するための領域。

Thread Dump

Thread Dump は、特定の時点で実行されている Java アプリケーションのすべてのスレッドの状態をキャプチャしたもの。この dump には、各スレッドの名前や状態、スタックトレースなどが含まれる。
Thread Dumpは、デッドロック（複数のスレッドが互いにリソース解放を待つ）やパフォーマンスのボトルネックを特定するのに活用できる。それ以外にも、スレッドを活用した複雑なアプリケーションの動作分析にも有用（かもしれない）。

Thread dump の取得にかかる負荷は Heap dump に比べてかなり低い。スレッドの使い方で起こる問題の切り分けでは、スレッドの状態の変化を見る必要があるので、たぶん連続して何回か取得したほうがいい。

※スレッドは、プロセスにおけるプロセッサ利用の最小単位。

Core Dump

Core Dump は、プログラムが予期せず終了した時のプロセスのメモリをキャプチャしたもの。クラッシュダンプとも呼ばれる。この dump には、プロセスの実行状態、CPUのレジスタの内容、プログラムカウンタ、スタックメモリ、ヒープメモリなどが含まれる。OS が提供する機能であり OS レベルの dump。gcore <pid> で取得できる。

JVM の文脈では、JVM 自体がクラッシュした時に Core Dump が生成される。jcmd で Heap Dump や Thread Dump が取得できないケースで Core Dump を経由しての取得を試みる際に利用する。

今回使うツール

JVM 言語のツールやユーティリティは数が多く、それぞれのツールに歴史もあるため機能が被ってるものも中には存在していると認識しています。Oracle の資料では jstack、jinfo、jmap のかわりに最新の jcmd を使ってねと書かれているので、jcmd を使います。

各種 Dump の取得

jcmd

jcmd は、JVM にさまざまなコマンドを送信できる。Heap Dump や Thread Dump の取得以外にも、実行中の Java プロセスの一覧を出したり、system properties や起動時のコマンドライン引数などを取得できる。JDK がインストールされていれば jcmd は使える。

各種 Dump の分析

InteliJ IDEA

InteliJ IDEA で各種 dump を分析することができる。

Heap Dump: メモリスナップショットを分析する
Thread Dump: スタックトレースまたはスレッドダンプを解析

他のツールに比べて、めちゃ早く Heap Dump の分析結果を見ていけるが機能は少なめ。
個人的には、一番印象いい。

VisualVM

VisualVM は、コマンドライン JDK ツールと軽量のプロファイリング機能を統合したツール。

jcmd でやりたいことや、remote java process に接続しての分析、heapdump の分析などを GUI でできる。remote 接続したときに感動がある（かもしれない）。

Eclipse Memory Analyzer Tool (MAT)

Eclipse Memory Analyzer Tool (MAT) は、メモリリークを見つけてメモリ消費を削減したい時に役立つツール。

でかい Heap Dump を分析したい（というか Heap Dump は基本でかい）場合、MAT の Heap が足りずに失敗するため、MemoryAnalyzer.ini を編集して、割り当てるヒープサイズを大きくしておくといいかもしれない^[1]。

読み込みが終わるまで時間かかるのだけつらい。MAT はメモリが潤沢なマシンで動かすのがいいと思う。個人的には、どうしてもわからない場合や、可能な限り詳細な情報が欲しい場合に MAT を使うくらいの順番で見ている...。

ハンズオン

実際に使ってみたほうがスキルは身につくので、意図的にトラブルを発生させるコードを実行します。

Heap Dump を取得して分析する

メモリリークを再現するデモ用のコード

Heap Dump の取得

# Java プロセスの一覧を出力
$ jcmd -l | grep org.example
19771 org.example.MemoryLeakDemo

# Heap Dump を出力（jcmd <pid> GC.heap_dump <filename>）
$ jcmd 19771 GC.heap_dump heapdump_$(date +"%Y%m%d-%H%M%S").hprof
19771:
Dumping heap to heapdump_20240407-155011.hprof ...
Heap dump file created [11711142766 bytes in 18.975 secs]

Heap Dump の分析

InteliJ IDEA の memory snapshots 分析機能

.hprof ファイルを開くと、クラス別の Shallow Heap と Reatined Heap などが確認できる。

Shallow: オブジェクトによって直接使用されているメモリのサイズ。
Retained: オブジェクトがガベージコレクションの対象になった場合に解放されるメモリのサイズ。

VisualVM

.hprof ファイルを開くと、Heap Dump のサマリなどが確認できる。

Eclipse Memory Analyzer Tool (MAT)

.hprof ファイルを開くと、Histogram や Doninator Tree などが確認できる。

Thread Dump を取得して分析する

特定の処理が目立って CPU リソースを消費するデモ用のコード

Thread Dump の取得

# Java プロセスの一覧を出力
$ jcmd -l | grep org.example
39303 org.example.CpuLoadDemo

# Thread Dump を出力（jcmd <pid> Thread.print > <filename>）
$ jcmd 39303 Thread.print > threaddump_$(date +"%Y%m%d-%H%M%S").tdump

# 確認
$ ls -lh | grep tdump
-rw-r--r--@ 1 rea9r  staff    14K  4  7 21:51 threaddump_20240407-215122.tdump

Thread Dump の分析をする前に知っておくべきこと

取得した Thread Dump を題材にして、読み方を簡単に説明します。

Thread Dump の構造について

まず、Thread Dump の先頭には pid、取得日時、JVM に関する情報が書かれています。

39303:
2024-04-07 21:51:22
Full thread dump OpenJDK 64-Bit Server VM (11.0.19+7-LTS mixed mode):

次のセクションでは、取得した時点の JVM で動いているスレッドのリストが載っています。

Threads class SMR info:
_java_thread_list=0x0000600000eb4080, length=30, elements={
0x0000000142167800, 0x000000014216c800, 0x0000000141880800, 0x0000000142168800,
0x0000000142169000, 0x000000014216d800, 0x000000014216e000, 0x000000014187f000,
0x000000014280c800, 0x0000000141944000, 0x0000000141945000, 0x000000014281b000,
0x000000014300f800, 0x0000000143014000, 0x0000000143015000, 0x0000000143015800,
0x000000012f00f800, 0x000000014196a800, 0x000000012f012800, 0x000000012f013800,
0x000000012f014800, 0x000000012f015800, 0x000000012f016000, 0x000000014380f000,
0x00000001439aa800, 0x000000014600a800, 0x000000014600b800, 0x000000014600c000,
0x0000000140809800, 0x0000000146808800
}

ここからは、スレッドの数も読み取ることができます。同ファイル内で tid を検索すると、該当のスレッド情報を確認することができます。

各スレッドのセクションには以下のような情報が記載されています。

"HeavyTaskThread" #18 prio=5 os_prio=31 cpu=22494.33ms elapsed=25.35s tid=0x0000000143015000 nid=0x6b03 runnable  [0x0000000172d46000]
   java.lang.Thread.State: RUNNABLE
	at org.example.CpuLoadDemo.heavyTask(CpuLoadDemo.java:26)
	at org.example.CpuLoadDemo.lambda$main$0(CpuLoadDemo.java:11)
	at org.example.CpuLoadDemo$$Lambda$1/0x0000000800065840.run(Unknown Source)
	at java.lang.Thread.run(java.base@11.0.19/Thread.java:829)

Name: この例では "HeavyTaskThread" の部分。アプリケーションで明示的に指定しない場合、JVM によって自動的に設定される。
ID: この例では #12 の部分。
Priority(prio): JVM 内でのスレッドの優先度。
OS Priority(os_prio): OSレベルでのスレッドの優先度。OS により振る舞いが異なる。
CPU: スレッドが CPU リソースを消費した時間の総量。値が大きいほど、スレッドが多くの CPU リソースを使用していることを意味する。
elapsed: スレッドが開始されてから経過した時間。
Thread ID(tid): JVM によってスレッドに割り振られたユニークなID。
Native ID(nid): OS によってスレッドに割り振られたユニークなID。
Status: この例では runnable の部分。スレッドの状態を示す。
Stack Trace: スレッドにマップされた最後の Stack Trace。

Thread Dump の状態について

Thread.State を読むと、各ステータスがどんな状態なのかが説明されている。

NEW: まだ開始されていない
RUNNABLE: 実行中
BLOCKED: ブロックされている状態（実行資格がないモニターロックを待機していて、他のスレッドによってロックされているコードにアクセスしようとしている）
WAITING: ほかのスレッドが特定のアクションを実行するのを無期限に待機
TIMED_WAITING: ほかのスレッドが特定のアクションを実行するのを指定された時間だけ待機
TERMINATED: 終了

Thread Dump の分析

Thread Dump の分析は、ツールを活用したとしても泥臭くみていくことになります。

InteliJ IDEA

Code > Analyze Stack Trace or Thread Dump... で起動した画面に Thread Dump をコピペすると見れる。

Stack Trace より、デモコードのロジックが確認できる２種類の内容を比較する。

HeavyTaskThread

"HeavyTaskThread" #12 prio=5 os_prio=31 cpu=22212.62ms elapsed=25.35s tid=0x000000014280c800 nid=0x5e03 runnable  [0x00000001720fe000]
   java.lang.Thread.State: RUNNABLE
	at org.example.CpuLoadDemo.heavyTask(CpuLoadDemo.java:26)
	at org.example.CpuLoadDemo.lambda$main$0(CpuLoadDemo.java:11)
	at org.example.CpuLoadDemo$$Lambda$1/0x0000000800065840.run(Unknown Source)
	at java.lang.Thread.run(java.base@11.0.19/Thread.java:829)

LightTaskThread

"LightTaskThread" #13 prio=5 os_prio=31 cpu=1.59ms elapsed=25.35s tid=0x0000000141944000 nid=0x6103 waiting on condition  [0x000000017230a000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(java.base@11.0.19/Native Method)
	at org.example.CpuLoadDemo.lightTask(CpuLoadDemo.java:34)
	at org.example.CpuLoadDemo.lambda$main$1(CpuLoadDemo.java:17)
	at org.example.CpuLoadDemo$$Lambda$2/0x0000000800066c40.run(Unknown Source)
	at java.lang.Thread.run(java.base@11.0.19/Thread.java:829)

HeavyTaskThread は CPU リソースの消費が激しめになっている。計算処理が動き続ける実装になっているため、この結果は期待通り。
LightTaskThread は TIMED_WAITING の状態になっており、CPU リソースの消費に関与していない。Thread.sleep を呼び出すだけの実装になっているため、この結果は期待通り。

VisualVM

Thread Dump の内容を保存したファイルを開くと、多少見やすく色分けしてくれる。

おわりに

Java 関連のツールはたくさん存在していますが、私個人としてはまだまだ知らないこともあり、ツールも使い切れてない感が否めないです。ただ、そうは言っても、何かできるようになるためには知識を蓄積して実際に手を動かす必要があるので、今後もまだ自分の理解が薄い部分に対する勉強は続けていきたいと思っています。

個人的には、JProfiler が気になってるんですが、お金がかかるのがなあ...。
より良いツールやアプローチなどがあれば、教えてもらえると嬉しいです。

参考資料

脚注

MemoryAnalyzer/FAQ: Out of Memory Error while Running the Memory Analyzer ↩︎

はじめに

環境

必要な知識

Heap Dump

Thread Dump

Core Dump

今回使うツール

各種 Dump の取得

jcmd

各種 Dump の分析

InteliJ IDEA

VisualVM

Eclipse Memory Analyzer Tool (MAT)

ハンズオン

Heap Dump を取得して分析する

メモリリークを再現するデモ用のコード

Heap Dump の取得

Heap Dump の分析

InteliJ IDEA の memory snapshots 分析機能

VisualVM

Eclipse Memory Analyzer Tool (MAT)

Thread Dump を取得して分析する

特定の処理が目立って CPU リソースを消費するデモ用のコード

Thread Dump の取得

Thread Dump の分析をする前に知っておくべきこと

Thread Dump の構造について

Thread Dump の状態について

Thread Dump の分析

InteliJ IDEA

VisualVM

おわりに

参考資料

Discussion