– その1: 自宅サーバがハング
– その2: フリーズの原因はガベージコレクション
– その3: 侍でヒープ使用量を確認
– その4: リーク箇所を確認する色々な方法
– その5: Memory Analyzer でヒープダンプを解析(最終回)
延々と連載してきたメモリリークトラブルシューティング記もいよいよ最終回です。
今回のメモリリーク現象はリークの再現方法がわからないため、運用環境から詳細なデータが取得できるheapdumpを取得した、というのが前回までのあらすじです。
次は、ヒープダンプの解析。
ヒープダンプは JDK に付属の jmap コマンドで取得します。
jmap -heap:format=x [pid] または jmap -heap:format=b [pid] といった形で実行するとヒープダンプを xml 形式、またはバイナリ形式で記録できます。
通常生のヒープダンプを人間の目で読むことはないので xml 形式は使いません。バイナリ形式で取得します。
バイナリ形式のヒープダンプはEclipse Memory Analyzerというツールで解析できます。
Eclipse Memory Analyzer は SAP が開発した Eclipse RPC ベースのマルチプラットフォームアプリケーションです。
非常に良くできています。
Memory Analyzer を起動したところ
Memory Analyzer を起動したらヒープダンプの読み込みは簡単。
[File > Open Heap Dump…] でファイルダイアログを開き、ヒープダンプを選択するだけです。
ヒープダンプを読み込んだところ
メモリリーク問題の調査は大きく分けて２段階あります。
1. ヒープ中を占める割合の高いオブジェクトを見つけること
これはヒープダンプ一つ開けば解析できます。
2. アプリケーションを動作させていく過程で単調増加し続けるオブジェクトを見つけること
具体的にはヒープダンプを２回(以上)取得して差分を取ることで解析できます。
"1." で大きなオブジェクト、または大量に存在するオブジェクトを見るだけでピンと来ればしめたもの。その原因を取り除いてやりましょう。
しかし、そういったオブジェクトは予定通りドカっと確保したキャッシュであることも多いです。増加し続けているわけではなく、単にあるべくしてあるだけの場合は調べてもしかたがありません。
本当にリークしているオブジェクトを確認するためには "2." で単調増加し続けているオブジェクトを確認しないといけません。
1. ヒープ中を占める割合の高いオブジェクトの確認
ではやってみます。ヒープダンプを Memory Analyzer で開いたら表示されるオーバービュー画面で "Leak Suspects" というリンクをクリックします。
するとやたらと大きいオブジェクトを「なんとなく怪しい」と判断してピックアップしてくれます。
「なんとなく」ですので、かならずしもリークしているオブジェクトが検出されるとは限らないことに注意してください。
Leak Suspects を開いたところ
今回は org.apache.jasper.runtime.BodyContentImpl クラスのインスタンスが 108 つで、合計419MB(ヒープ中72.26%)も占めているとのレポートが出ました。
明らかに怪しいです。
org.apache というパッケージから Apache プロジェクトのコンポーネントであることがわかります。また jasper という名前は Apache の jsp 実装です。
インスタンスの数としては 108 つと多すぎるわけではありませんが、一つ一つのサイズが尋常ではありません。一体このインスタンスには何が記録されているのでしょう？
今度は dominator treeビューよりオブジェクトの中身を確認してみます。
dominator treeを開くには、ツールバーの箱３つが繋がれたアイコンをクリックします。
dominator treeを開くためのアイコン
dominator tree を開くと大きなオブジェクト順にソートされたインスタンスの一覧が見られます。
また、それぞれのインスタンスツリーを展開することで、保有しているフィールドやまたその中身を確認することができます。
dominator tree 表示
今回は dominator tree より、BodyContentImpl には非常にサイズの大きな char 配列が格納されていることがわかりました。
Inspector ペインで簡単に配列の中身をプレビューできますが、ほんの部分部分しか見られないのでもっとざっくりと見たいときは中身をファイルに保存することができます。
オブジェクトの中身をファイルに保存
保存した char 配列の中身を確認
中身を view コマンドで確認すると、html が記録されていることを確認できました。
さらによく見てみると・・・・あまり大きな声で口に出せないような英単語が<div class=”trackbackheader”>..</div>というタグに囲まれて大量にならんでいました。
これはトラックバックスパムですね。
<img border=”0″ src=”/jira/images/icons/document_exchange.gif” width=16 height=16 align=absmiddle> という要素が見られるので Jira が絡んでいるようです。
Jira は自分のオープンソースプロジェクトのバグトラッキングに使っている Web アプリケーションです。
を使うと何か JBoss Web(JBoss 内蔵の Tomcat ベースのコンテナ)でリークするのでしょうか？
BodyContentImpl 以外にも増加しているオブジェクトがないか、ヒープダンプの差分も確認してみることにしました。
2. 単調増加し続けるオブジェクトの確認
ヒープダンプの差分をとるには、ヒープダンプを２つ開き、ヒストグラムビュー(棒グラフのアイコン)を開いた状態で左右に矢印が伸びるアイコンをクリックします。
ヒープダンプの比較
すると Select baseline というダイアログが現れるので差分を取りたいもう一方のヒープダンプを選択します。
Select baselineで差分を取る対象のヒープダンプを選択
差分がとれたら、"Objects" – つまりインスタンス数でソートしてみます。
すると興味深いオブジェクトが浮かび上がってきました。
com.atlassian.trackback.Trackback というオブジェクトが20,211個も増えていることがわかります。
差分取得で浮かび上がってきたオブジェクト – com.atlassian.trackback.Trackback
atlassian は Jira を開発している会社です。どうもトラックバックスパムを大量に受けてトラックバックを表現するオブジェクトが増えまくっているようですね。
"com.atlassian.trackback.Trackback" で検索してみましたが、リークにまつわる情報はみつかりませんでした。
今度は
"jira tomcat leak"で検索。ビンゴ！
・05.03.04 Tomcat 6.0 – JIRA オンラインマニュアル (3.12.2版 – 最新) – Atlassian Confluence
Tomcatは、大きなJSPのページをリクエストするとメモリリークしてしまいます。
これを避けるために、bin/setenv.shを編集して（もしなければ作成して）、次のように設定してください。
export CATALINA_OPTS="$CATALINA_OPTS -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true"
ちゃんとドキュメントに書いてある設定をしていなかったのが原因でした。
LIMIT_BUFFER オプションについては以下のページで導入の経緯が詳しく説明されています。
・Bug 37793 – org.apache.jasper.runtime.BodyContentImpl doesn't reset the 'cb' character array, causes memory leak
Jira の issue ではこれ。
・[#JRA-10145] Set tomcat flag to not re-use buffers, as they result in OutOfMemoryErrors – Atlassian JIRA
どうも、Tomcat は書き込みバッファを再利用する仕組みがあるらしく、非常に大きなコンテンツを出力するとバッファでヒープがあふれてしまうようです。
この書き込みバッファを無尽蔵に増やさないためのオプションが LIMIT_BUFFER ですね。
つまり、今回のメモリリーク問題の発生ステップはこう想像できます。
1. トラックバックスパムを大量に受けて、特定のページのサイズが膨らむ
2. 検索エンジンのクローラかなにかが膨らんだページを閲覧する
3. 書き込みバッファが膨れる
ウチのサーバは Tomcat ではなく JBoss で運用していますが、Webコンテナである JBoss Web は Tomcat 由来なのでこのオプションがちゃんと効きました。
トラックバックオブジェクトが大量にあるのはよろしい状態なのかどうかわかりませんが、そもそもトラックバック機能は現在の所必要ないので、管理画面から無効に設定してしまいました。
トラックバック機能を OFF に設定
LIMIT_BUFFER オプションの設定とトラックバックの OFF 設定を実施してから1週間以上経ちますが、現在の所ヒープ使用量は一定しており安定稼働しています。
５回に渡るエントリで長々とトラブルシューティングの様子を説明してみました。
メモリリークのトラブルシューティングというと、じっくりソースコードを眺めたり、プロファイラを使ってがんばって現象を再現させたりという調査方法が有名ですね。
しかし、ヒープダンプや Memory Analyzer を使う方法はご存じない方も多いのではないでしょうか。
メモリリークトラブルは長期間稼働して初めて現れることも多い厄介な問題です。
トラブルが発生してからあわてることのないよう、あらかじめヒープダンプを使った解析の練習をしておくと良いかもしれません。