本システムでは、mod_jkを用いてApache-Tomcatの連携を行っている。mod_jkは一度作成したコネクションを使い回す。そのため、単純に考えればApache起動数と同じだけのObjectNameしか生成されないはずだ。
しかし現実には、ObjectNameは増え続けている。解析に落ち度があったのか、それとも、何かを見落としているのか。
そこで、各種設定ファイルを持参のうえ、Apache・modjk・Tomcatの有識者と打ち合わせを行った。すると、mod_jkのrecycle_timeout(現在はconnection_pool_timeout)オプションが原因で、コネクション切断/再接続が行われるという情報を得た。
recycle_timeoutは、mod_jkがコネクションを再利用する際、古いコネクション(recycle_timeout秒だけ利用されていない)ならばそれを破棄し、新規にコネクションを生成するというオプションだ。
具体的に、負荷が高いときと低いときについて考えてみよう。
負荷が高いときは、recycle_timeoutよりも短い間隔でリクエストを処理するため、コネクションが再利用されやすくなる。
逆に、負荷が低いとき、recycle_timeoutよりも長い間隔でリクエストを処理するようになるため、そのたびに既存のコネクションを破棄し、新規のコネクションを生成するようになる。
ここで、すべての説明がついた。当初の再現試験では、システムを高負荷状態にすることで、再現性を高めようとしていた。しかし、それでは逆に再現しづらくなっていたのだ。
逆に、hprofを利用した際は、hprofのオーバヘッドが原因で、非常に低い負荷しか掛けられなかった。そのため、再現していたのだ。最後の最後で、幸運に救われる形になった。
今回のメモリリークの事象をまとめてみよう。
本番環境では、非常に負荷の低い時間帯(閑散時間帯)が存在する。この閑散時間帯では、リクエストが到着するたびにmod_jkはTomcatとのコネクションを張り直していた。そして、Tomcatはmod_jkからのコネクションを受け付けると、そのコネクションをJMXの管理下に置いた。その際、JMXはオブジェクトを一意に識別するための識別子ObjectNameをキャッシュとして保持していたため、そのキャッシュの値がいつまでもメモリ内に存在し続けることとなり、それがメモリリークという事象の形で表に出たのだ……。
本トラブルの対処法は、いくつか考えられるであろう。実際には、3つほど検討を行った。
2と3は、ASF Bugzillaで調査を行っていたときに出てきた対処案だ。これらを比較検討した結果、コネクション再接続契機で、ObjectName以外にもリークしている可能性を考慮し、recycle_timeoutのオプションを無効化することを選択した。その際には、信頼性に影響を与えないよう、ほかのオプションも再度検討し直した。
そして、本対処策をもって、無事に事象の再発を防ぐことができた。
今回のトラブルハックの内容は、低負荷という想定外の発生契機、JMXとTomcatの複合バグという、比較的面倒なメモリリークであった。その解決の糸口が、本番環境でも利用に耐えるPrintClassHistogramオプションだ。このPrintClassHistogramオプションの使いどころと利用時の注意点をまとめて、本稿の締めとしたい。
上記のようなメリットがあるため、新規開発システムならば、開発当初から常にPrintClassHistogramを導入しておくことをお勧めする。
また、すでにサービスを行っているシステムに導入する際は、以下のことに注意されたい。
クラス統計情報を出力する際、必ずFull GCが一度発生する。そのため、一度のFull GCの時間が長いシステムでは、実行契機に注意されたい。逆に、意図的にFull GCを起こすための手段としても利用できる。
編集部注:Full GCについて詳しく知りたい読者は、連載第2回をご参照ください。
茂呂 範(もろ すすむ)
株式会社NTTデータ 基盤システム事業本部所属。入社時よりOSSを用いたWebシステムの開発支援にかかわる。最近では、トラブルシューティングとその際のノウハウの収集・展開に日々従事している。
山下 真一(やました しんいち)
株式会社NTTデータ 基盤システム事業本部所属。入社よりOSSを中心に構築されたWebシステムのトラブルシューティング、技術支援に携わる。最近は、社内で展開するOSSスタックの検証に明け暮れている。
Copyright © ITmedia, Inc. All Rights Reserved.