OutOfMemoryError発生！ その解決への近道とは：現場にキく、Webシステムの問題解決ノウハウ（5）

　前回記事「調査の難しい「OutOfMemoryError」事例、5選」では、「OutOfMemoryError」に対する切り分け方法の基本と、「OutOfMemoryError」発生につながる危険なケースを具体例を挙げて解説した。

　今回は、その「OutOfMemoryError」の対応・調査方法を系統立てて解説する。

システムの回復が必要な場合を確認

図　システムの再起動の手順

　OutOfMemoryErrorによるメモリ障害が発生すると、標準出力にOutOfMemoryErrorのメッセージが表示される。そして、JavaVMは空き領域が枯渇している中でGCを実行することになり、場合によってはGCが繰り返され、スローダウンに陥ることがある。そのため、システムの再起動が必要な場合もある。

　基本的なことだが、システム再起動を自動で行わずに手動で行う場合、クライアントからのリクエストが入ってこないようにWebサーバの停止後に、Java EEサーバを起動させるのが望ましい。

　また再起動後には、業務アプリケーションや利用しているリソースアダプタが正しく開始したかを確認しておきたい。

障害調査時に採取すべき7つの資料

　OutOfMemoryErrorの障害調査を行う場合、資料として以下の7つの情報は取得しておきたい。

　これらの情報を基に、OutOfMemoryErrorの障害発生原因を探ることとなる。

障害調査〜メモリ領域を切り分ける〜

　まずは、GCログやOutOfMemoryErrorのエラー情報から、「Javaのどのヒープ領域（Javaヒープ、Permanentヒープ、Cヒープ）でOutOfMemoryErrorになっているか」「どれだけのメモリを確保しようとして失敗したか」を確認する。

　前回記事で、OutOfMemoryのエラー情報からどの領域でメモリ不足が発生しているかを見分けるポイントについては紹介した。例えば、以下のような場合には（*1）からJavaヒープでメモリが不足していることが分かる。

java.lang.OutOfMemoryError: Java heap space              <=======【*1】
        at java.nio.CharBuffer.wrap(CharBuffer.java:350)
        at java.nio.CharBuffer.wrap(CharBuffer.java:373)
        at java.lang.StringCoding$StringDecoder.decode(StringCoding.java:138)
        at java.lang.StringCoding.decode(StringCoding.java:173)
        at java.lang.String.<init>(String.java:444)
        at com.sun.tools.javac.zip.ZipFileIndex$ZipDirectory.readEntry(ZipFileIndex.java:805)
        at com.sun.tools.javac.zip.ZipFileIndex$ZipDirectory.buildIndex(ZipFileIndex.java:720)
        at com.sun.tools.javac.zip.ZipFileIndex$ZipDirectory.access$000(ZipFileIndex.java:652)
        at com.sun.tools.javac.zip.ZipFileIndex.checkIndex(ZipFileIndex.java:261)
 ……

　また、JavaVMのオプションに「-verbose:gc」「-XX:+PrintGCDetails」オプションを指定すると、GCログにGC発生前後での各領域の使用メモリサイズが出力される。

　サーバにCosminexusを利用している場合は、拡張verbosegc情報を出力するオプション（-XX:+HitachiVerboseGCオプション）が用意されているという。このオプションを指定すると、JavaVMのログ情報にGC実行前後の各領域の使用メモリサイズに加えて、GCの発生した要因が出力される。

　例えば以下のように、GC前後の領域サイズや発生原因、GC処理にかかったCPU時間などが出力されるという。

……
 
[VGC]<Mon Apr 18 20:36:29 2005>[Full GC 57051K->25121K(129792K), 0.5531230 secs][DefNew::Eden: 40943K->0K(41088K)][DefNew::Survivor: 1280K->0K(1280K)][Tenured: 14827K->25121K(87424K)][Perm: 20479K->20479K(20480K)][cause:PermAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs]
 
……

　上記では、「Permanentヒープが枯渇したので、Full GCが発生している」ことが読み取れる。

　このように、エラー情報やGCログの情報からどのメモリ領域が枯渇したかを判別する。

障害調査〜3つの各メモリ領域での調査の手順〜

　OutOfMemoryErrorが発生した場合、各ヒープ領域での調査の流れは、以下の通りとなる。

表　各ヒープ領域での調査の流れ   Javaヒープ Permanentヒープ Cヒープ 調査に必要な資料 GCログ Webサーバのログ Java EEサーバのログ リダイレクタのログ スレッドダンプ プロファイラ情報 GCログ Java EEサーバのログ プロファイラ情報 GCログ OSの統計情報 Java EEサーバのログ スレッドダンプ メモリダンプ 調査方法 調査方法

　以降、3つの場合に分けて、詳細に説明する。

【1】Javaヒープのメモリ不足の場合

　Javaヒープでメモリ不足が発生した場合、まずはGCログの情報からメモリの増加傾向を調査する。短時間でメモリを大量に確保してメモリ不足になっているのか、それともFull GCでのメモリ解放量が少なくなっていき、最終的にメモリ不足になったのかを確認するのだ。

　短時間で急激にメモリ使用量が上昇している場合には、大量にメモリを確保している処理が存在しているかを調査する。これは、メモリが急激に使われた時間帯を確認して、実行されていた処理内容に問題がないかを確認するということだ。

　例えば、GCログが以下のようになっていたとしよう。

……
 
[VGC]<Mon Nov 19 13:11:48.429 2007>[GC 166611K->42819K(660864K)、 0.0310920 secs]
[VGC]<Mon Nov 19 13:30:15.745 2007>[GC 163011K->46586K(660864K)、 0.0399470 secs]
[VGC]<Mon Nov 19 13:40:36.063 2007>[GC 166778K->45196K(660864K)、 0.0358040 secs]
[VGC]<Mon Nov 19 14:06:52.233 2007>[GC 165388K->66988K(660864K)、 0.1960800 secs]
[VGC]<Mon Nov 19 14:06:55.956 2007>[GC 187180K->158487K(660864K)、 1.2088840 secs]
[VGC]<Mon Nov 19 14:06:57.777 2007>[GC 278679K->213350K(660864K)、 0.9072150 secs]
[VGC]<Mon Nov 19 14:06:59.216 2007>[GC 333542K->267532K(660864K)、 0.7970100 secs]
[VGC]<Mon Nov 19 14:07:00.553 2007>[GC 387724K->321909K(660864K)、 0.8215320 secs]
[VGC]<Mon Nov 19 14:07:01.968 2007>[GC 442101K->377525K(660864K)、 0.8518270 secs]
[VGC]<Mon Nov 19 14:07:03.337 2007>[Full GC 497717K->441259K(660864K)、 3.9811080 secs]
[VGC]<Mon Nov 19 14:07:07.904 2007>[Full GC 561451K->496918K(660864K)、 4.0300470 secs]
[VGC]<Mon Nov 19 14:07:14.219 2007>[Full GC 660863K->569864K(660864K)、 4.7080780 secs]
[VGC]<Mon Nov 19 14:07:20.931 2007>[Full GC 660863K->590180K(660864K)、 5.3994630 secs]

　このログからは、14:06:52からGC後のメモリ使用量が右肩上がりになっていることが読み取れる。つまり、「上記時刻のリクエストにより動作した業務プログラムに問題があるかもしれない」と判断できる。

　次に、上記時間帯に動作した業務プログラムは、下記から確認できる。

　直感的に分かりやすいのは、Webサーバのアクセスログだ。メモリが増加し始めた時間帯のアクセスURLを基に、リダイレクタやJava EEサーバのログとつき合わせて、その時間帯に実行された業務アプリケーションを特定し、処理に問題がなかったかを確認する。

　短時間での急なメモリ使用量の増加とは反対に、Full GCでのメモリ解放量が少なくなり、Old領域に徐々にメモリがたまっていって最終的にメモリ不足になっている場合は、メモリリークの可能性が高い。この場合は、さらなる調査が必要となる。プロファイラなどを利用して、増加している業務クラスを特定するといいだろう。

【2】Permanentヒープのメモリ不足の場合

　Permanentヒープは、クラスなどのメタ情報を格納する領域だ。この領域でのメモリ不足の場合、「単純にヒープサイズの見積もりの誤りだけなのか」「メモリリークしているのか」を確認する。アプリケーションの停止（アンデプロイ）をしても、十分にメモリが解放できていない場合は、メモリリークしている可能性が高い。

　そこで、アプリケーションの停止や入れ替えを行い、GCログのメモリ増加傾向を確認する。また、アプリケーションの開始や停止がエラーが発生していないかも確認しておく。

　GCログの調査の結果、見積もりミスではなくメモリリークと思われる場合、Javaヒープの場合と同様にプロファイラでの調査となる。

　なおJavaヒープとは異なり、Permanentヒープのオブジェクト解放のタイミングはFullGCのタイミングであることには注意が必要だ。

【3】Cヒープのメモリ不足の場合

　Cヒープ不足の場合、まずはスレッド生成数が多くてメモリ不足になっていないかを確認する。スレッドダンプなどからスレッド数を確認するのだ。業務アプリケーションでスレッドを生成していない場合でも、Java EEサーバの定義によってスレッド数が増加している場合もあるので、注意が必要だ。OSの統計情報も併せて確認し、想定以上のスレッドが生成されていないかをチェックする。

　Java EEサーバの設定値やOSのカーネルパラメータなどの妥当性も検証が必要だ。不正な場合には、設定を変更し、現象が解決されるかを確認する。前回の記事で紹介したCヒープの不足につながる可能性のあるケースも参考にしてほしい。

　設定ミスではなく、メモリリークの可能性がある場合は、JNI（Java Native Interface）を仕様している個所の確認やメモリダンプを開発元に送付しての調査依頼などが必要となる。

＠IT：連載：サーバーサイドJava初心者のためのWebシステム入門　第7回 via kwout

初期調査の方法を体系立てることが解決への近道

　このようにOutOfMemoryError発生時は、ヒープ領域とメモリ使用量の変化からメモリリークかを見極めながら調査するのがいいそうだ。

　OutOfMemoryErrorなど、JavaVMのメモリに関する障害が発生すると、知識や技術資料の不足などによって、調査が長期化する場合が多い。初期調査の方法を体系立てて理解しておくだけで、解決への近道になるはずなので参考にしてほしい。