連載

2007年11月27日

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

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

[茂呂範, 山下真一，株式会社NTTデータ] PC用表示関連情報

LINE

Hatena

前のページへ | 次のページへ

PrintClassHistogramオプションで、迷宮入りを防げ!!

　残された道はただ1つ。いまもメモリリークが発生している本番環境で、何としても発生状況の情報を取得することだ。プロファイラを用いることが確実だが、性能劣化が確実に予想されるため、本番環境に導入することは考えられない。

編集部注：プロファイラについて詳しく知りたい読者は、連載第1回の「その6：プロファイラ」をご参照ください。

　どうすれば、と考えあぐねていたところ、一緒に解析に当たっていた同僚より「PrintClassHistogramオプションが使えるのではないか」との情報を得た。試験環境でサービスへの影響がないことを確認した後、プロジェクトメンバが見守る中、最後の望みを賭けてPrintClassHistogramを本番環境へ適用した。

■PrintClassHistogramオプションとは？

　このオプションを知らない方のために、PrintClassHistogramオプションについて説明しよう。PrintClassHistogramオプションは、ヒープ内のクラス統計情報を出力するためのオプションだ。出力時点での各クラスのインスタンスの個数および全インスタンスの合計サイズを、GCログとともに出力する。

　PrintClassHitogramの特徴は、プロファイラと比較して性能への影響が非常に小さく、Java起動オプションの修正だけで利用でき、適用可能なバージョンがJava 1.4.2以上と幅広いという点だ（詳細は後述）。利用方法は至って簡単で、Java起動時に以下のオプションを追加するだけだ。

リスト1　オプションを付けて実行するコマンド

java -verbose:gc -XX:+PrintClassHistogram TestMain

　GCログを出力していないと、本オプションは機能しないことに注意してほしい。このオプションを付加してJavaを起動後、そのプロセスに対して一定間隔ごとにSIGQUITシグナルを送信する。

リスト2　crontabで実行するコマンド

kill -3 <java pid>

　UNIX系ならば、crontabで上記コマンドを実行するよう設定すれば、定期的にクラス統計情報をGCログに出力するようになる。

■最後の望みを実行！

　上記javaコマンドを実行すると、以下のフォーマットで、クラス統計情報がGCログに出力される。

リスト3　PrintClassHitogramの出力例

num #instances #bytes class name
--------------------------------------
1: 244594 35380344 [C
2: 982063 23569512 java.lang.String
3: 15788 17285632 [B
4: 59009 9135936 <methodKlass>
5: 292468 7019232 java.util.Hashtable$Entry
6: 96069 5493752 [Ljava.util.Hashtable$Entry;
 
 
……（略）……
 
 
3509: 1 8 sun.reflect.GeneratedMethodAccessor1681
3510: 1 8 sun.reflect.GeneratedMethodAccessor1256
Total 2483297 137466336

　「#instances」はインスタンス数、「#bytes」は全インスタンスの合計サイズ、「class name」はクラス名を表している。上記例では、計24万4594個、3538万0344bytesのchar型の配列が存在していることが分かる。なお、インスタンス数が0であるクラスは、このリスト内には表れないという点に注意してほしい。

　1つのクラス統計情報だけでは、メモリリーク解析には不十分だ。複数のクラス統計情報を取得し、クラスごとに集計することで、どのクラスのインスタンスがリークしているかを調べることで、より確実にメモリリークを解析できるようになる。

■判断のためのサンプル

　では、簡単なサンプルを示そう。

図5　リークしていないクラスのヒープ使用量

　オブジェクト数やサイズが一定値を保ち続けている。このような場合、メモリリークは発生していないと判断できる。

図6　明らかにリークしているクラスのヒープ使用量

　オブジェクト数もしくはサイズが右肩上がりで上昇を続けている。このような場合、メモリリークが発生していると判断せざるを得ない。

図7　リークしているかどうか判断が微妙なクラスのヒープ使用量

　オブジェクト数およびサイズがある一定値まで上昇を続けるも、その後はその値で飽和している。このような場合、メモリリークか否かを判断することは難しいが、メモリを圧迫するようなプログラム（例えば、LRU（Least Recently Used）キャッシュやWeakReferenceの利用など）が動作している可能性がある。全ヒープサイズに対して、該当クラスの総サイズが目立って大きい場合、プログラムの修正対象となるであろう。

図8　乱高下し過ぎて判断できないクラスのヒープ使用量

　Stringクラスなどのよく利用されるクラスである場合、図8のようなグラフになりやすい。このような場合、下がり切っているいくつかの個所を直線で結び（フットプリント）、そのフットプリントが右肩上がりか否かで、リークか否かの判断をするとよい。

ObjectNameの上昇！まさかのメモリリーク

　仕込み完了日から、クラス統計情報付きのGCログを受け取り解析を進めていくと、ある特定のクラスで明確なメモリリークが発生していることが確認できた。

図9　javax.management.ObjectNameクラスのヒープ使用量の時系列グラフ

図10　java.util.HashMapクラスのヒープ使用量の時系列グラフ

図11　java.util.HashMap.Entryクラスのヒープ使用量の時系列グラフ

図12　java.util.HashMap.Entry[]クラスのヒープ使用量の時系列グラフ

　ObjectNameの正式名称は、javax.management.ObjectNameである。ObjectNameはMBeanのオブジェクト名を表し、オブジェクトをJMX（Java Management Extensions）管理下に置く際に作成される。業務担当者に確認すると、開発したプログラム内で、ObjectNameどころかJMXを利用している個所はどこにもないという。

編集部注：JMXについて詳しく知りたい読者は、連載第1回の「その7：JMXクライアント」をご参照ください。

■トラブルハッカーとしての勘がささやく

　また、java.util.HashMap関連のクラスの挙動が興味深い。HashMapの個数とObjectNameの個数とでは相関があるようには見えない。しかし、HashMap.Entryの個数とObjectNameの個数とでは、非常に強い相関が見られる。さらに、HashMap.Entry[]のサイズが、階段を駆け上るように突然上昇している。そのうえ、昇幅はそれまでのサイズと同等程度だ。

　この動きからいえることは、putはされるもののremoveされないような、ObjectNameがキーもしくは値となるHashMapが1つ存在することだ。ObjectNameにはキャッシュがあるに違いない。トラブルハッカーとしての勘がささやいた。

■無限に増加する可能性

　早速、JMXのソースコードを追いかけていくと、メモリリークしているとおぼしき該当個所を確認できた。先ほどの想定どおり、staticのHashMapをキャッシュとして利用していたのだ。そして、残念ながらこのキャッシュは、無限に増加する可能性を秘めていた。

リスト4　javax.management.ObjectNameのソースコード

public class ObjectName implements Serializable{
 
……（略）……
 
    private static HashMap m_cache = new HashMap();
 
……（略）……
 
    private void parse(String objectName) 
    throws MalformedObjectNameException{
 
……（略）……
 
        m_cache.put(objectName, this);
 
……（略）……
 
    }
 
……（略）……
 
}

■発生契機を探し出せ！ HPROFでの解析

　リークしているインスタンスは分かった。だが、何を契機にリークしているか、すなわちどうすれば再現するか、ということは分かっていない。そこで、リークしているObjectNameクラスに的を絞って、試験環境にてさらなる調査を行うことにした。

　利用するツールは、HPROFだ。HPROFは、そのオーバヘッドの大きさから本番環境では利用できない（HPROFについて詳しく知りたい読者は、「HPROF プロファイラエージェント」をご参照ください）。しかし、すでにいままでの調査でObjectNameがリークしていると突き止めているため、顕著にメモリがリークするまで再現試験を行う必要はない。再現試験にて、ObjectNameを生成しているスタックトレースのうち、少しでも上昇が見られるスタックトレースさえ見付け出せれば、任務は完了となる。

■ついに該当個所を発見！

　では、HPROFを用いた試験結果を見てみよう。下記のスタックトレースにて、ObjectNameが生成されていることが分かった。

リスト5　取得したスタックトレース（1）（拡大したものはこちら）

TRACE 54218:
org.apache.jk.common.ChannelSocket.registerRequest(ChannelSocket.java:431)
org.apache.jk.common.HandlerRequest.decodeRequest(HandlerRequest.java:443)
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:352)
org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:743)
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:675)
org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:866)
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
java.lang.Thread.run(Thread.java:534)

リスト6　取得したスタックトレース（2）

4509  0.00% 97.06%      512   16     512   16 54218 javax.management.ObjectName
22676  0.00% 99.33%       48    1      48    1 54218 [C
43364  0.00% 99.88%       24    1      24    1 54218 java.lang.String
132178  0.00% 100.00%        0    0     384   16 54218 java.lang.StringBuffer

　ここはなんと、Apache（mod_jk）からの接続を受け付けたときに実行される個所なのだ。これが正しければ、Tomcatがmod_jkから接続を受け付けると、コネクションが生成される。そのコネクションをJMXで管理する際にObjectNameが生成される。生成されたものは、キャッシュとしてHashMapに格納され、メモリリークを引き起こしているというのだ。

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