こんにちは、ミドルウェア開発チームの青木(@a_o_k_i_n_g)です。将来の夢は川口浩探検隊に入ることです。
先日、弊社のアプリケーションサーバーで大量にメモリを消費するという現象に遭遇しました。アクセス頻度の低いサーバーがメモリを大量消費するという謎深いものでした。
発生当初の状況はこんな感じです。
- アプリケーションサーバーでは Jetty が稼働
- 現象が発生した JVM は 5GB 程度のメモリを消費しており、明らかに通常ではない量のメモリを消費している
- 複数台のサーバーで発生していたが、全てで発生したわけではない。
また、発生したサーバーはいずれもアクセス頻度が少ないサーバーだった。
ヒープ、パーマネント、スタック
ひとまず、JVM でトラブルが発生した時は何はともあれヒープダンプとスレッドダンプを見るに限ります。各種情報の取得をインフラ部隊へ依頼し、得られたヒープを解析すると、ある事実が判明しました。
ヒープの使用容量は 200MB にも達していなかったのです。これが原因では無いことは明白でした。
パーマネントも 250MB 程度で正常です。スレッドダンプも、スレッド数は 30 程度で、 JVM の持つスレッドと Jetty のスレッドプールに格納されているスレッドのみでした。異常はありません。
ではいったいどこでメモリを消費しているのでしょうか？
ここで改めておさらいしておくと、JVM が使うメモリは下記4つに大別できます。
- ヒープ
- パーマネント
- スタック
- C ヒープ
スタックは 1 スレッドにつきたかだか 1MB しか使用しない(64bit環境の場合)ので、スタックが原因でもありません。
ヒープでもパーマネントでもスタックでも無いので、消去法で C ヒープに何か潜んでいることがわかりました。
C ヒープに何か潜んでいるとわかった時点で、再度ヒープを調べました。ヒープに存在している領域が少なくとも、そのオブジェクトが C ヒープに大きなメモリを確保している可能性があるからです。 Java では java.nio.ByteBuffer.allocateDirect などでヒープ外にメモリを確保できるので、どこかに ByteBuffer を参照しているオブジェクトがあるのかもしれません。
Memory Analyzer と Eclipse OQLを使い、200MB のヒープを調べつくしました。 その中で ZipFileIndex というクラスがヒープ内に複数存在していることがわかり、このオブジェクト群が犯人ではないかと疑いました。ZIP 関連の処理は C ヒープを使うということが知られており、ZipFileIndex というファイルは如何にも怪しく見えたからです。
結論から言えば、これらは jar ファイルを保持していたのみでシロでした。
その他ヒープをどれだけ解析しても、犯人はどこにもいませんでした。
C ヒープの世界へ
jstat や jmap の力が及ばない領域、C ヒープ。この領域をどうやって調べれば良いでしょうか？ 我々は、メモリダンプを取得してメモリ内に存在する文字列から犯人を推定する、という方針で進めることにしました。
メモリダンプには gcore を使います。gcore は任意のプロセスのメモリ内容を出力してくれるツールです。 メモリダンプをいただき、早速バイナリエディタで中身を・・・というわけにはいきません。 今回の場合はメモリダンプが 7GB 程度もあり、hexdump -C したところで先頭の僅かな部分しか見れません。
そこで登場するのが strings コマンドです。 strings コマンドはバイナリ内に存在する文字列を抽出してくれるツールです。
$ strings -a memory.gcore > strings.txt
以上のようにして memory.gcore 内に存在する文字列を抽出します。 次に、得られた文字列をソートし、出現回数順に並べてみます。
こうなりました。
$ sort strings.txt | uniq -c | sort -nr | less
168269 com/mysql/jdbc/configs/maxPerformance.properties
158788 connectionAttributes=none
158634 # setup
155904 alwaysSendSetIsolation=false
155101 # query
155071 7i,\
155070 ('Rggm
155068 Ud=k
155068 e<|8
155030 dJxzd'
155029 v^e>
155029 D1*;
154939 enableQueryTimeouts=false
154854 # Bypass connection attribute handling during connection
153117 # Can cause high-GC pressure if timeouts are used on every
152992 elideSetAutoCommits=true
152787 # and transaction isolation
152780 useLocalSessionState=true
151611 # Connection methods to set current database, autocommit
146208 cacheCallableStmts=true
146167 cachePrepStmts=true
146062 cacheServerConfiguration=true
145959 # Reduces amount of calls to database to set
145849 # session state. "Safe" as long as application uses
145699 # restarting the application using this configuration bundle.
145661 # would be "dangerous" to run-of-the-mill J2EE applications
145661 # and the server configuration, this bundle isn't appropriate
145549 # for use with servers that get config'd dynamically without
145516 # still staying JDBC-compliant and not doing anything that
145502 # Note that because we're caching things like callable statements
108967 es performance, while
37258 # A configuration that maximizes performance, while
27736 Code
...
まず先頭が com/mysql/jdbc/configs/maxPerformance.properties です。これは MySQL のパフォーマンスを最大限に引き出すために指定していた、JDBC のプロパティ useConfigs=maxPerformance によって読み込まれるプロパティファイルです。cybozu.com ではパフォーマンスのため、useConfigs=maxPerformance を指定しています。
参考: Properties Files for the useConfigs Option
その後、意味不明な文字列も出てきてはいますが(おそらくこれは普通のバイナリデータがたまたま文字列化できてるに過ぎないものでしょう)、それ以外の意味のある文字列、これらはまさに maxPerformance.properties の中身です！
この時点で、JDBC が犯人ではないかという疑いが濃厚になりました。
ただし確定とは言えません。これは単に文字列を出力しただけであって、本当は文字列データが現れてないところに巨大なバイナリデータがあるかもしれないからです。
コネクションリークではありません。トラブル発生時の時点で lsof で JVM がオープンしているファイルやネットワークの情報を見たのですが、コネクションリークは発生していませんでした。
上記のソート結果からわかることがもうひとつあります。 maxPerformance.properties の中身を読んで保持しているなら、どの行も行数が同じになるはずです。 ですが実際には行数はバラバラです。このことから、おそらく maxPerformance.properties の中身は読まれたものの、破棄されて別のメモリに上書きされて消えているのでは、との推測が立ちました。 つまり現在も参照されているような活きたメモリではなく死んだメモリであると言えそうです。
一方、依然として下記の謎は我々を苦しめました。
- 複数台のサーバーで発生していたが、全てで発生したわけではない。
また、発生したサーバーはいずれもアクセス頻度が少ないサーバーだった。
何がトリガーで本現象が発生するのか、なぜ同じ環境でもっとヘビーに使われているサーバーで発生しないのか、 その条件を見極めるため再現実験を行うことにしました。
多数の再現実験
cybozu.com では、サーバーに対して毎秒、DB が生きているかどうかの監視 API を叩いています。 この監視は、ロードバランサの内側からと外側から叩かれており、内側からだけ監視、外側からだけ監視、 両方から監視のパターンに分けて再現実験することにしました。また、JDBC のダウングレード版も試しました。
得られた結果のほとんどからは JDBC ドライバが犯人であるという仮説を支持するものになりました。 また、監視系統を半分にすればメモリ使用量の増加が抑えられることがわかり、どうやらコネクション数に関係しそうなことがわかってきました。
この実験中、useConfigs=maxPerformance を使用しない場合、再現しない(メモリ使用量が抑えられる)こともわかりました。
犯人に近づいてきています。
JDBC のプロパティ
メモリ消費量増大という現象を抑えるための一番簡単な対策は useConfigs=maxPerformance プロパティを外すことですが、それは cybozu.com のパフォーマンス劣化につながるのでその議論はほとんど話題にもあがりません。 調査隊全員が今のパフォーマンスを維持したままの問題解決を目指していました。
さて、問題の useConfigs=maxPerformance は、複数のプロパティの集合体です。 使われているプロパティは下記の通り。
cachePrepStmts=true cacheCallableStmts=true cacheServerConfiguration=true useLocalSessionState=true elideSetAutoCommits=true alwaysSendSetIsolation=false enableQueryTimeouts=false
これらのうちのどれかがメモリリークを引き起こしてるのでしょう。各プロパティを個別に指定して再現実験を行い、現象が発生した環境のプロパティが犯人であると突き止めようとしたのです。 しかし、これらのプロパティを個別に試しても、メモリ消費量が増大する環境はありませんでした。
ということは複数プロパティの組み合わせで発生するのかもしれません。 二分法で試そうか、という話をしている時、ふと気になったことがあったのです。
そもそも、すべて同じパラメーターにしたら再現するだろうか？
useConfigs=maxPerformance を指定せず、個別のプロパティすべてを maxPerformance を指定した時と 同等のプロパティを指定して再現するか確かめることにしました。 結果は、再現せずメモリ消費量は抑えられたままでした。
犯人は useConfigs=maxPerformance を処理している付近に違いないとほぼ断定できました。 ここからは JDBC のソースコードの出番です。
JDBC ソースコード
useConfigs で指定したプロパティを読んでいる箇所は com.mysql.jdbc.NonRegisteringDriver の parseURL 付近です。 このあたりをくまなく読むと、怪しげな箇所がありました。
try { InputStream configAsStream = super.getClass().getResourceAsStream( "configs/" + configName + ".properties"); if (configAsStream == null) { throw SQLError.createSQLException("Can't find configuration template named '" + configName + "'", "01S00", null); } configProps.load(configAsStream); } catch (IOException ioEx) {
InputStream configAsStream に注目してください。これは maxPerformance.properties などを読むストリームですが、閉じていません。
おそらくこのクローズ漏れが犯人でしょう。ただ、気になることがありました。ここはコネクションを取得するたびに通るコードで、アクセスが無い環境ではあまり通らず、ヘビーに使われている環境ほどよく通るコードです。ではなぜヘビーに使われている環境では再現しないのでしょう？
とはいえここ以外に犯人がいるとも思えません。そこでこのほんの数行のコードの挙動をより深く追ってみます。 その結果、getClass().getResourceAsStream が返す InputStream は、BufferedInputStream にくるまれた FileInputStream が返されていることがわかり、FileInputStream は finalize メソッドで close 処理をしていました。
"finalize を使ってはいけない" というプラクティスはもはや常識のものと思われましたが、ここには残っていました。
でもようやくわかりました。犯人はこのクローズ漏れに間違いありません。
犯人確保、です。
解明
先ほどのコードの実装上、finalize が呼ばれない限り close 処理が行われません。finalize が呼ばれる場合というのはすなわち GC が発生する場合です。GC が発生しない場合ずっとメモリ上に蓄積したままになります。
これで、ヘビーにアクセスされている環境では発生せず、ほとんどアクセスが無いサーバーで発生する理由がわかりました。ヘビーにアクセスされている環境では GC が発生するので定期的にリソースが close されてメモリも綺麗になりますが、アクセスが少ないサーバーでは GC が発生しないため、メモリ上にどんどん蓄積していくという現象だったのです。C ヒープの消費量が増大しても GC は発生しないのです。
次に、ヒープが正常だった理由にも納得です。FileInputStream はファイルの中身をヒープに確保するようなことはせず、native コードで読み出します。なのでヒープ上に現れないのですね。
useConfigs を使わなければ発生しないというのも当然です。ここは useConfigs で指定されたプロパティを読む部分なのですから。
メモリ上の死んだ部分という推測も合ってました。FileInputStream が読むときにいったん載るものの、読みだしてしまえばもう使われませんからね。
念の為、検算もしました。現象が再現する環境に対して外部から GC を定期的に発生させる状況を作れば、メモリ使用量は増えないはずです。ちなみに JDK7 からは jcmd によって外部から GC を発生させることができるようになりました。
参考: How do you Force Garbage Collection from the Shell?
これを使って環境を作りメモリ使用量を見たところ、無事メモリ使用量は抑えられたままでした。期待する検算結果そのものです。
かくして、我々を悩ませたメモリ大量消費の謎は、JDBC 内のクローズ漏れが原因ということで一見落着しました。
後処理として、MySQL にバグレポートを出し、直るまでのワークアラウンドとして useConfigs=maxPerformance を指定せず内部プロパティを展開して指定するよう改修しました。
まとめ
現象の解明まで紆余曲折ありました。JDBC が犯人ではない説、ロードバランサが犯人説、JVM が量子力学的振る舞いをしている説、幽霊説、etc・・・。なによりアクセス頻度が低いサーバーで現象が発生するという謎に悩まされましたが、結局はバグとしてはありがちなクローズ漏れでした。幽霊の正体見たり枯れ尾花、です。
我々は、アプリケーションサーバーをお客さんへの影響無しに再起動する機構を持っています。そのため、やろうと思えば「現象が発生したら再起動してメモリを綺麗にする」方式でも対応できました。でもそんなことはしたくありません。そんなことをすればインフラ部隊に工数が発生してしまいますし、なにより美しくありません。面白くもありません。今回の現象解明には少々時間がかかってしまいましたが、それでもこれで良かったと思っています。根本治療出来たのですから。
そしてもうひとつ、声を大にして言いたいことがあります。
finalize に 頼 っ て は い け な い
それでは、良い JVM ライフを！
