JavaのGC頻度に惑わされた年末年始の苦いメモリ：現場から学ぶWebアプリ開発のトラブルハック（9）（2/3 ページ）

【第3話】伝家の宝刀にご登場願おう

　さて、これまでの経緯を簡単にまとめてみよう。

• 1週間前の機能追加により、新しくJava常駐プロセスがAPサーバ内に追加された
• 機能追加前までは、問題はまったくなかった
• 機能追加後からは、メモリ使用量が時間とともに増加していることが分かった
• GCログより、新規の追加したJava常駐プロセス内でメモリリークが発生していた

図3　トラブルのイメージ

■おさらい：PrintClassHistogramオプションとは？

　ここまで事象が特定されていれば、伝家の宝刀PrintClassHistogramオプションにご登場願おう。ここで簡単におさらいすると、PrintClassHistogramは、Javaヒープ内に存在するインスタンスの個数と総サイズを、クラスごとの統計情報として出力するオプションだ。

　クラスごとに、この統計情報を時系列に追うことで、どのクラスがメモリリークしている原因かを容易に特定できる。その上オーバヘッドも少なく、環境への変更も最低限で済むため、サービス中の商用環境でも利用できる使い勝手のよいJavaVMのデバッグオプションだ。詳しくは、前回を参照いただきたい。

　PrintClassHistogramオプションを紹介すると、現場からは安堵（あんど）の声が漏れた。そして、早速PrintClassHitogramオプションを利用して、試験環境にて再現試験を行うことになった。

　そして、年越し3日間の連続稼働の後、驚くべき事実を目の当たりにすることになる。

【第4話】「再現していません!!」

　年明けのある朝、現場に到着すると、プロジェクトメンバがGCグラフを手に駆け付けてきた。

図4　メモリリーク再現試験：失敗

　再現試験のGCグラフは、何の問題もないGCグラフだった。再現失敗か、何か見落としがあったのか。

　「あ!!」

　そのとき、プロジェクトメンバの1人が大きな声で叫んだ。指さしていたのは、同じくGCグラフだったが、そのグラフでは商用環境に近い動作をしていたのだ!!

図5　メモリリーク再現試験：近い動作6日分

　確認を行うと、このGCグラフは、メモリリーク検証用のPrintClassHistogramオプションを意図的に設定しなかったJava常駐プロセスだという。

　きな臭いにおいが漂い始めている。

■Javaプログラムでは一切利用されていなかったRMI

　さらにこのとき、この再現試験の裏で行っていたJavaプログラムのソースコードレビューを担当していた同僚が、面白い事実に気が付いた。それは、既存プログラムはすべて、何らかの形でRMI（Remote Method Invocation）を利用していたが、新規に追加したJavaプログラムでは一切RMIを利用していなかったのだ。

　すぐさま、RMIを利用しているJava常駐プロセスのGCグラフを確認すると、以下のようなものだった。なお、背景が黒くなっているが、誤植でも何でもない。RMIを利用すると、1分に1回Full GCが発生するため、黒い線が重なってこのように見えてしまうのだ。

図6　RMI利用のGCグラフ

　これまでの3つのGCグラフを見比べると、メモリリークを引き起こしているGCグラフだけ、明らかな違いが見て取れるだろう。

■4つのGCグラフ

　これまで登場してきた4つのGCグラフを並べてみたので、ぜひとも比較していただきたい。

図7　4つのGCグラフ（画像をクリックすると拡大します）

　おそらく、グラフの見え方により2種類のグラフに分類されるだろう。この、見え方の違いがメモリリークを引き起こしていた原因につながるのだ。

　読者の中には、もう犯人が分かった人もいるかもしれない。