JavaのOutOfMemoryErrorを追いかけてみた

だいたいのことは、ネットに書いてある

Java自体、すでに歴史ある技術ですし、今回のOutOfMemoryErrorも、その解析方法も確立されているようで、ネットでかなりの情報が手に入り、10年くらい前、Java1.4の案件でちょっとコード書いた程度にしかJavaと接点のない私でも理解できました。

インターネットすばらしい。

一方、本職アプリケーションエンジニアで今回の案件もJavaのコードをバリバリ書いてる人たちがたくさん集まっているはずなのに、なんでその情報に一番最初にたどり着くのが自分なんだろう、みたいなモヤモヤもあったりして。

事の発端

DB屋、プラスアルファでDB以外のインフラも対応、という感じのポジションなので、アプリケーションエンジニアが書いたコードのことはよくわからない立場だったのですが、DBに接続して来るJavaのプログラムがOutOfMemoryErrorに悩まされていたので、一緒に格闘してました。

アプリケーションエンジニアに開発したソースコードを確認してもらっても、オブジェクト参照の解放漏れはないようだけど、環境によって、ほぼ毎回発生する環境と、一回もエラーにならない環境がある、とのこと。

エラーになるケースでは、CPU利用率が跳ね上がる、ということで、以下の仮説、確認ポイントを設けて、調査することに。

多分GCがCPU利用率を引き上げてる原因だよね。
GC発生してるのにOutOfMemoryErrorが出るってことは、意図せず解放できていないやつがいるよね。
エラー発生時にログに出力されているStackTraceでは、どこでエラーが発生したかはわかるけど、それって犯人じゃなくて被害者の可能性もあるよね。
具体的にはメモリ（JavaHeap）に何が乗っているかわからないと、特定難しいよね。

DB観点で言うと、クライアントサイドの話なのでDBサーバーサイドの設定は基本的に関係なし、あるとすれば投入データの差異か、クライアントパラメータの設定か、クライアントライブラリのバグでメモリリーク？か、という感じで、どれも可能性が薄いなあと思いつつ、いい機会なのでJavaの事もお勉強です。

Javaといえば、GC（garbage collection：ガベージコレクション）

Javaといえば、確保したメモリの解放をVMにおまかせして、使わなくなったメモリ領域はGCによって回収、再利用するというのが、Javaが出てきた当初から？の仕様です。
文字通り「ゴミ拾い」。

RDBMS脳でいうと、「バッファプール」と似たような考え方でOK。

特にMySQLで例えるなら、新しいデータはバッファプールのYoung領域に一旦置いて、Young領域があふれるタイミングでまだ使っているものはOld領域へ、そうじゃないものはプールから破棄（開放）、を繰り返すイメージですね。

ただし、GCはあくまで「使わなくなった領域」を回収するわけで、「もう使わないよ」っていうことを忘れていると、GCで回収できる領域が減って、いずれOutOfMemoryError（VMが確保した領域では処理できない）が発生してしまいます。

このあたりのイメージは、
Java技術最前線 - 「メモリーを意識してみよう」第2回 GCの仕組みを理解する：ITpro
とか
HP-UX Developer Edge - Javaのかなめ、「ガベージ・コレクション」をやさしく学ぶ・前編 | HPE 日本
とかの図解がわかりやすいので、軽く読んで頭に入れておくと良いですね。

解析に使うのは「GC Log＋GC Viewer」「jstat」「HeapDump＋Eclipse Memory Analyzer （MAT）」

GC Log

「GC Log」はJavaVMにおいて、ガベージコレクションが発動されたタイミングでログに出力されるものです。
テキストファイルに出力されるので、その量を見るだけでも発生頻度が分かりますが、GC Viewerというツールに読み込ませると、時系列での変化をグラフィカルに表示されるのでわかりやすいです。
解析したいJavaアプリケーションの起動オプションとして指定してあげるだけで出力するようになりますが、「GC Log出力先に、そのユーザでの書き込み権限が必要」という条件に注意。

使い方は
最強のJVMチューニング・ツール: GCログを可視化するGCViewerとリモート接続でプロファイリング可能なVisualVM
とか
JavaVMのGCログ出力とGCViewerについて - TASK NOTES
あたりを参照してください。

jstat

「jstat」は、JavaVMのHeapの状況を確認できるツールで、OSレベルでいうvmstatコマンドのようなものです。

解析したいJavaアプリケーションのプロセスID（psコマンドやjpsコマンドで確認）を指定します。

また、オプションに実行間隔をミリ秒単位で指定できます。
GC logがGC発生時のみ記録されるのに対し、GC未発生の状況も収集できますので、時系列でのヒープ内部の状況変化をより正確に把握できます。

ファイルにロギングさせたものをExcelに貼り付けてグラフ化してあげると見やすいですね。

HeapDump

「Heap Dump」は、JavaVMのヒープの状態をそのままDumpしたものです。
jmapコマンドやkill -3で出力することができるのですが、特にHeapの解析が必要となるOutOfMemoryErrorに関しては、「このエラーが発生したらHeapDumpを出力する」という指定を、Javaの起動オプションとして設定することができます。

GC Logと同様に、出力先の書き込み権限に注意するひつようがあるのと、ヒープの内容をまるごと出力するのでHeapサイズ指定（Xms、Xmx指定）が大きい場合に注意が必要です。

ダンプファイルはそのままでは読めませんので、ツールを使うことになります。

Eclipse Memory Analyzer（通称「MAT」）

JavaのHeap Dumpを読み取り、解析できるツールで、Eclipseのプラグインおよびツール単体での使用が可能です。

ツール自体もJavaで動きます。大きなダンプファイルを解析する場合には、ツール自身のXms、Xmxを大きめに指定する必要がありますが、そもそもOSが32bit版Windowsだったりすると大きなダンプファイルを読めなかったりします。
*1

OutOfMemoryError発生時のHeap Dumpを読み込むことで、Heap Dumpに残っている＝GCでも回収できなかったJavaのオブジェクトがクラスレベルで特定できます。

その専有量のランキング、表面上必要な量と、つかみっぱなしになっている量の差、掴んでいるオブジェクトに格納されている具体的な値、そのオブジェクトを参照しているオブジェクトのスタックトレースが確認できます。

メモリリークの「疑い」があるオブジェクトの候補を抽出する機能なども存在します。

HeapDumpとEclipse Memory Analyzer諸々のお話は、このSlideshare
OutOfMemoryError の対応方法/Heap 分析ツール(MAT)の使い方
が非常によくまとまっています。

なお、なぜMA「T」なのか、わかりません。

VisualVM

GC Viewerの参照先で紹介した
最強のJVMチューニング・ツール: GCログを可視化するGCViewerとリモート接続でプロファイリング可能なVisualVM
に記載がありますが、実行中のJVMをグラフィカルにモニタリングできるツールのようです。

今回はこのツール自体を知らなかったこともあり、使いませんでしたが、OutOfMemoryErrorでHeapDumpを発生させる前から「どのクラス/オブジェクトがヒープ領域を食っているか」が見えるようですので、もっと早くに原因を掴めたかもしれません。

解析結果

今回のケースでは、JavaVMを監視してアプリケーションパフォーマンスの情報を収集、管理する「APM：Application Performance Management」のエージェントプログラムが、SQL文を格納しているオブジェクトへの参照を掴んでいて、GCの発生時に解放ができず、OutOfMemoryErrorを引き起こしていました。

APMエージェント的には「管理サーバーに情報を送って解放」という流れだったのかと思いますが、流量が多すぎたのか、転送・解放が追いつかなかったようです。「メモリリークだった」という確証には至っていません。

アプリケーションエンジニアにとっても自分たちでコードを書いた部分ではなかったので、特定するのにかなり手間取りましたが、HeapDumpをEclipse Memory Analyzerで解析した所、見かけないクラスがSQLを格納したオブジェクトを掴んでいて「誰だコイツは！？」ってなった次第です。