ヒープダンプを出力する
それでは今からヒープの内容をダンプしてみましょう。何かの内容をディスクに出力することをダンプする、もしくはダンプを取ると言います。よってヒープの内容をディスクに出力したものが「ヒープダンプ」です。
ヒープダンプはツールを使って任意のタイミングでJVMから出力させることもできますし、特定の出来事に対応してJVMに自動的に出力させることもできます。ツールでの出力については本連載の後の回で解説します。ここでは特定の出来事に対応して出力する方法を用います。
OutOfMemoryError発生時にヒープダンプを出力するオプション
その特定の出来事について解説します。OutOfMemoryErrorおよびHeapDumpOnOutOfMemoryErrorオプションについてすでにご存じの方はプログラムが出てくるところまで文章を読み飛ばしていただいてかまいません。
ガベージコレクタが回収をしても新たにオブジェクトに対してヒープ領域を割り当てられないとき、JVMはjava.lang.OutOfMemoryErrorというエラーを発生させます。このOutOfMemoryErrorの発生時にヒープダンプを出力させる機能があります。機能を有効にするには、オプションHeapDumpOnOutOfMemoryErrorを有効にしてアプリケーションを実行します。皆さんが携わっているアプリケーションの実行オプションも見てみてください。このオプションがついていることが多いです。
OutOfMemoryErrorが発生したときは、メモリを消費しているものが何かを知ることが大切です。OutOfMemoryErrorにもさまざまな発生原因がありますが、ヒープを使い切ってしまった場合なら、ヒープダンプの内容を見ることで解決に向けた一歩を踏み出せます。なお、デフォルトではアプリケーションを実行したディレクトリにヒープダンプを出力します。出力ディレクトリはHeapDumpPathオプションで変更可能です。
HeapDumpOnOutOfMemoryErrorオプションを使う場合、OutOfMemoryErrorを発生させなければヒープダンプを出力しないので、OutOfMemoryErrorを発生させる以下のプログラムを用意しました。
import java.util.*;
class OomeSample {
public static void main(String... args) {
List<String> cache = new ArrayList<>();
String sql = "INSERT INTO table_a VALUES (?, ?, ?, ?, ?)";
while (true) {
cache.add(sql);
sql = sql + ", (?, ?, ?, ?, ?)";
}
}
}
深い意味があるプログラムでありませんが、複数行をINSERTするSQL文をリストに保持し続けます。ループごとにSQL文にINSERTする行を1行追加します。
| ループ回数 | SQL文 |
|---|---|
| 1回目 | INSERT INTO table_a VALUES (?, ?, ?, ?, ?) |
| 2回目 | INSERT INTO table_a VALUES (?, ?, ?, ?, ?), (?, ?, ?, ?, ?) |
| N回目 | INSERT INTO table_a VALUES (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), ... , (?, ?, ?, ?, ?) |
このプログラムをOomeSample.javaというファイル名で保存します。それでは実行しましょう。-XX:+HeapDumpOnOutOfMemoryErrorでHeapDumpOnOutOfMemoryErrorオプションを有効にし、-Xmx128mでヒープの最大サイズを128MBに設定します。ヒープダンプの出力は以前からある機能なので、Javaのバージョンは現在ダウンロード可能なものであればどれでも大丈夫です。本記事では執筆時の最新バージョンであるJava 16（Eclipse TemurinのJDK 16.0.2+7）を使用しました。以下のコマンドで実行します。
$ java -XX:+HeapDumpOnOutOfMemoryError -Xmx128m OomeSample.java
上記ではJava 11で入った「単一ファイルプログラム実行」機能を使っています。11より以前のバージョンであれば、以下のように従来どおりコンパイルして実行します。
$ javac OomeSample.java $ java -XX:+HeapDumpOnOutOfMemoryError -Xmx128m OomeSample
どちらも実行すると以下のメッセージが出ます。
java.lang.OutOfMemoryError: Java heap space Dumping heap to java_pid67127.hprof ... Heap dump file created [134485547 bytes in 0.048 secs] Exception in thread "main" java.lang.OutOfMemoryError: Java heap space （以下省略）
java.lang.OutOfMemoryError: Java heap spaceとあり、ヒープにおいてOutOfMemoryErrorが発生したことがわかります。Dumping heap to java_pid67127.hprofとあることから、ヒープの内容がjava_pid67127.hprofというファイルに出力されました。
このファイルがヒープダンプです。このファイル名のpidの後にある数字はプロセスIDです。そのため、このプログラムを実行した環境によって数字は変わります。今回ファイルサイズは128MBですが、本番環境ではヒープサイズが大きいためヒープダンプのファイルサイズも非常に大きくなります。
ヒープダンプを解析する
次にヒープダンプの内容を見てみましょう。ヒープダンプはテキストファイルではなくバイナリファイルです。エディタなどでファイルを開いても内容を確認できません。ヒープダンプを解析できるツールは複数ありますが、本記事ではEclipse Memory Analyzer（通称、MAT）を使います。
MATはIDEでなじみがある方も多いEclipse Rich Client Platformベースのツールです。スタンドアロン版もありますし、すでにEclipse IDEを使っている場合はプラグインとしてMATをインストールできます。
スタンドアロン版MATを前提に解説します。MATのダウンロードページに進み、プラットフォームに合わせたものをダウンロードします。解凍した後OSがWindowsであればMemoryAnalyzer.exeを実行してMATを起動します。MATの画面上部のメニューからFile > Open Heap Dump...を選択し、java_pid67127.hprofなどのヒープダンプファイルを開きます。
ファイルの読み込み後、Getting Started Wizardというウィンドウが表示されます。今回はFinishを押して閉じましょう。「Leak Suspects」の画面が表示されますが、リークの容疑者ということで、ここでヒントを得られるケースもあります。今回はこの画面を無視し、画面上部にある「Overview」タブを押します。Overviewは以下のような画面です。
このOverview画面を起点にさまざまな画面を開き、情報を得られます。「Histogram」のリンクを押しましょう。Histogramは以下のような画面です。
Histogramではクラスごとのヒープ消費量がわかります。表の列「Shallow Heap」はそのクラスのインスタンスのみを合計したサイズ、列「Retained Heap」はそのクラスのインスタンスが保持している何らかのインスタンス（が保持している何らかのインスタンスの……とツリーをたどり続けて）合計したサイズです。そのため「Retained Heap」が重要です。
最初は「>= 128...」という大まかな数字になっているので、この表上で右クリックして「Calculate Precise Retained Size」を実行することで正確なサイズを出せます。今回の例は単純なので、実行しても数値は変わりません。なお、サイズの単位はバイトです。
表ではbyte配列、Stringクラスという順で上位に並んでいます。このbyte配列を何のオブジェクトが使っているのかがわかれば大きなヒントです。「byte[]」の行を選択して右クリックし、List Objects > with incoming referencesを選択します。すると以下の画面に変わります。
byte配列のインスタンスがリスト表示され、その中身があのINSERT文であることが見て取れます。実際に表の1行を開いてみると、このbyte配列インスタンスを保持しているのがStringインスタンスだとわかります。プログラムと照らし合わせると大量のINSERT文を保持していることがOutOfMemoryErrorの原因だと突き止められます。
以下のイメージ図のように、ヒープの大部分をこれらのオブジェクトが占めており、かつまだそのメモリ領域を回収できない状態のためヒープが枯渇し、OutOfMemoryErrorが発生しました。
今回はあらかじめ答えを知っている状態でヒープダンプを見ているので、簡単な内容だったと思われるかも知れません。実はこのプログラムは筆者が実際にトラブルシュートした内容を極めて単純にしたものです。
あるアプリケーションでヒープが枯渇し、動作が非常に重くなっており、OutOfMemoryErrorには至らないものの運用でカバーする状況でした。また、環境の制約によりヒープサイズは小さく、サイズ変更もできませんでした。
そこでこの記事と同様にヒープダンプを取得し調査しました。解析の結果PreparedStatementのプールオブジェクトがヒープを多く消費しており、今回のようにINSERTする行数が異なるINSERT文のStringオブジェクトが多数あったのです。
データベースのコネクションプーリングをするライブラリの機能で、PreparedStatementを無制限にキャッシュしており、かつアプリケーションの機能として異なる行数をINSERTするSQL文を多数発行したためでした。
PreparedStatementのキャッシュはオフにすることも数の上限を設定することもできます。このケースでもそういった設定をすると正常に動作することが確認できました。障害はヒープダンプだけで解決するものではありませんが、障害発生直後のヒープダンプは取得しておくことが望ましいです。
まとめ
第1回ではJVMの概要とヒープダンプの出力、解析について解説しました。本連載はJVMの内部を文章で解説するものではなく、その情報を取得するさまざまなツールの利用を通じてJVMについての知識を深めることを目的としています。
連載を継続するためには、ここまで読んでくださった皆さんのポジティブなお声がぜひとも必要です。この画面にあるツイートやシェア、ブックマークボタンからフィードバックをいただけるとうれしいです。
第2回はJVMのログ、Unified LoggingとJDKに含まれているツールを使ってJVMの情報を取得、設定変更するという内容です。次回もお楽しみに！
