連載
» 2007年12月27日 00時00分 公開

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

[茂呂範,株式会社NTTデータ]

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

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

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

おさらい:PrintClassHistogramオプションとは?

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

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

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

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

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

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

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

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

 「あ!!」

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

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

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

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

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

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

編集部注RMIについて詳しく知りたい読者は、「Webアプリケーション実現の本質を知ろう」の「分散オブジェクト RMI & CORBA」をご参照ください。

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

図6 RMI利用のGCグラフ 図6 RMI利用のGCグラフ

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

4つのGCグラフ

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

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

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

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

Copyright © ITmedia, Inc. All Rights Reserved.

RSSについて

アイティメディアIDについて

メールマガジン登録

@ITのメールマガジンは、 もちろん、すべて無料です。ぜひメールマガジンをご購読ください。