肥え続けるTomcatと胃を痛めるトラブルハッカー：現場から学ぶWebアプリ開発のトラブルハック（8）（3/3 ページ）

本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい。（編集部）

[茂呂範, 山下真一，株式会社NTTデータ]

mod_jkのオプション1つでメモリリークが発生していた現実

　本システムでは、mod_jkを用いてApache-Tomcatの連携を行っている。mod_jkは一度作成したコネクションを使い回す。そのため、単純に考えればApache起動数と同じだけのObjectNameしか生成されないはずだ。

図13　Apache・modjk・Tomcatの接続イメージ

　しかし現実には、ObjectNameは増え続けている。解析に落ち度があったのか、それとも、何かを見落としているのか。

■原因解明のために有識者に聞き込み

　そこで、各種設定ファイルを持参のうえ、Apache・modjk・Tomcatの有識者と打ち合わせを行った。すると、mod_jkのrecycle_timeout（現在はconnection_pool_timeout）オプションが原因で、コネクション切断／再接続が行われるという情報を得た。

　recycle_timeoutは、mod_jkがコネクションを再利用する際、古いコネクション（recycle_timeout秒だけ利用されていない）ならばそれを破棄し、新規にコネクションを生成するというオプションだ。

図14　recycle_timeoutの説明

　具体的に、負荷が高いときと低いときについて考えてみよう。

図15　負荷が高いときのシーケンス図

　負荷が高いときは、recycle_timeoutよりも短い間隔でリクエストを処理するため、コネクションが再利用されやすくなる。

図16　負荷が低いときのシーケンス図

　逆に、負荷が低いとき、recycle_timeoutよりも長い間隔でリクエストを処理するようになるため、そのたびに既存のコネクションを破棄し、新規のコネクションを生成するようになる。

■最後は運

　ここで、すべての説明がついた。当初の再現試験では、システムを高負荷状態にすることで、再現性を高めようとしていた。しかし、それでは逆に再現しづらくなっていたのだ。

　逆に、hprofを利用した際は、hprofのオーバヘッドが原因で、非常に低い負荷しか掛けられなかった。そのため、再現していたのだ。最後の最後で、幸運に救われる形になった。

　今回のメモリリークの事象をまとめてみよう。

図17　まとめの図

　本番環境では、非常に負荷の低い時間帯（閑散時間帯）が存在する。この閑散時間帯では、リクエストが到着するたびにmod_jkはTomcatとのコネクションを張り直していた。そして、Tomcatはmod_jkからのコネクションを受け付けると、そのコネクションをJMXの管理下に置いた。その際、JMXはオブジェクトを一意に識別するための識別子ObjectNameをキャッシュとして保持していたため、そのキャッシュの値がいつまでもメモリ内に存在し続けることとなり、それがメモリリークという事象の形で表に出たのだ……。

■メモリリークの3つの対処法

　本トラブルの対処法は、いくつか考えられるであろう。実際には、3つほど検討を行った。

1. mod_jkのrecycle_timeoutオプションを無効化する
   もしくは、非常に長い時間に設定する
2. Tomcat内のjmx.jarを最新版と差し替える、もしくは修正する
3. コネクションをJMX管理下に置かないオプションを設定する

　2と3は、ASF Bugzillaで調査を行っていたときに出てきた対処案だ。これらを比較検討した結果、コネクション再接続契機で、ObjectName以外にもリークしている可能性を考慮し、recycle_timeoutのオプションを無効化することを選択した。その際には、信頼性に影響を与えないよう、ほかのオプションも再度検討し直した。

　そして、本対処策をもって、無事に事象の再発を防ぐことができた。

図18　対処後のGCログ（1）（画像をクリックすると拡大します）

図19　対処後のGCログ（2）（画像をクリックすると拡大します）

PrintClassHistogramオプションの使いどころと注意点

　今回のトラブルハックの内容は、低負荷という想定外の発生契機、JMXとTomcatの複合バグという、比較的面倒なメモリリークであった。その解決の糸口が、本番環境でも利用に耐えるPrintClassHistogramオプションだ。このPrintClassHistogramオプションの使いどころと利用時の注意点をまとめて、本稿の締めとしたい。

• オーバヘッドが小さい
  ほかの（ヒープ）プロファイラと比較して、オーバヘッドが小さいため、高負荷での検証時や、本番環境での利用にも耐え得る
• Sun JDK 1.4.2以降なら利用可能
  Sun JDK 1.4.2以降なら、本オプションを利用可能だ。いざトラブルハックという場面で、バージョンに合わせたプロファイラの選定などを行う必要がなくなる（ただし、JDK 1.5のうちいくつかのバージョンでは、JVMのバグによりCMSと併用しなければ、ヒープ統計情報が出力されない）
• 一次切り分けに最適
  ヒープ統計情報に焦点を当てているため、より詳細な解析のためにほかのツールが必要になることもある。しかし、新規にツールを導入する必要がなく、オプションの設定だけで手軽に利用できることから、一次切り分けに最適であろう

　上記のようなメリットがあるため、新規開発システムならば、開発当初から常にPrintClassHistogramを導入しておくことをお勧めする。

　また、すでにサービスを行っているシステムに導入する際は、以下のことに注意されたい。

• クラス統計情報出力時にFull GCが発生する

　クラス統計情報を出力する際、必ずFull GCが一度発生する。そのため、一度のFull GCの時間が長いシステムでは、実行契機に注意されたい。逆に、意図的にFull GCを起こすための手段としても利用できる。

編集部注：Full GCについて詳しく知りたい読者は、連載第2回をご参照ください。

プロフィール

茂呂　範（もろ　すすむ）

株式会社NTTデータ　基盤システム事業本部所属。入社時よりOSSを用いたWebシステムの開発支援にかかわる。最近では、トラブルシューティングとその際のノウハウの収集・展開に日々従事している。

山下　真一（やました　しんいち）

株式会社NTTデータ　基盤システム事業本部所属。入社よりOSSを中心に構築されたWebシステムのトラブルシューティング、技術支援に携わる。最近は、社内で展開するOSSスタックの検証に明け暮れている。

「次回」へ

「現場から学ぶWebアプリ開発のトラブルハック」バックナンバー

• 数百キロのコードでブルー - ドクターTomcat緊急救命
• DB操作の“壁”を壊すJPAが起こした「赤壁の戦い」
• アプリ開発でも、よ〜く考えよう。キャッシュは大事だよ
• スレッドダンプの森で覚えた死のロックへの違和感
• ThreadとHashMapに潜む無限回廊は実に面白い？
• JavaのGC頻度に惑わされた年末年始の苦いメモリ
• 肥え続けるTomcatと胃を痛めるトラブルハッカー
• 【トラブル大捜査線】失われたコネクションを追え！
• 【真夏の夜のミステリー】Tomcatを殺したのは誰だ？
• OutOfMemoryエラー発生!? GCがあるのに、なぜ？
• DBアクセスのトラブルは終盤で発覚しがち……
• 【実録ドキュメント】そのログ本当に必要ですか？
• “Stop the World”を防ぐコンカレントGCとは？
• Webアプリの問題点を「見える化」する7つ道具