Trouble 23: Java VMに関する問題
＜Q23-1＞VM HotSpotエラーメッセージのErrorIDの読み方が分かりません。
VMが以下のHotSpotエラーを出しました。
# HotSpot Virtual Machine Error : 11
# Error ID : 4F530E43505002E6
# Please report this error at
# http://java.sun.com/cgi-bin/bugreport.cgi
このError IDってどういう意味なのでしょうか？
同じIDを出力することもあれば、異なる場合もあります。
| ＜発生環境＞ |
| OS |
Any |
| JDK |
JDK1.4 |
| Vender |
Sun |
- ＜A23-1＞
- Error IDはエラーが発生したJavaVMソース(※)のファイル名（のアスキーコード）＋エラー発生行番号となっています。
※ JavaVMのソースコードは、Sunから無料でダウンロードすることができます。
具体的には、エラーが発生したファイル名（例えばruntime.cpp）の各キャラクタの文字コードから 0x20（空白文字のアスキーコード）を引いた値に、エラー発生行数の16進表現（2バイト）を連結した値となります。
例えば Error IDが4F530E43505002E6のときは、以下のように解釈できます。
Error ID = 4F530E43505002E6
↓
ファイル名部分=4F530E435050 ＋ 行番号部分=02E6
a) ファイル名部分の各値(2桁)に、0x20を加算する。
4F 53 0E 43 50 50
→6F 73 2E 63 70 70
b) アスキーキャラクタ変換する。
6F 73 2E 63 70 70
→ o s . c p p
c) 末尾4桁を 10進変換する。
02E6
→742
というわけで、os.cppの 742行目でエラーが発生したことがわかります。
＜Q23-2＞-verbose:gcで出力される情報がたりません。
ガベージコレクションがパフォーマンス上のボトルネックになっています。
解析のため起動オプションに「-verbose:gc」を指定しましたが、GCがかかった時刻もGCの場所も出力されないため、解析が難航しています。
なにか良い手はありませんか？
| ＜発生環境＞ |
| OS |
Any |
| JDK |
JDK1.4 |
| Vender |
Sun |
- ＜A23-2＞
- 「-XX:+PrintGCTimeStamps」と「-XX:+PrintGCDetails」を指定することで、それぞれGCのタイムスタンプとGCの詳細情報が得られます。
(例1) -verbose:gcのみ
[GC 2198K->150K(3520K), 0.0200894 secs]
意味：
・GCにより、トータルヒープ使用サイズが2198KBから150KBになった
・GCによる停止時間は0.0200894秒
(例2) -XX:+PrintGCTimeStamps、-XX:+PrintGCDetailsを指定
4.12082: [GC 4.12096: [DefNew: 2048K->0K(2112K), 0.0003650 secs] 2198K->150K(3520K), 0.0004982 secs]
意味：
・アプリケーションを起動してから 4.12082秒経過
・New世代のガベージコレクションで New世代の使用サイズが2048KBから0KBになった
・マイナーコレクション(New世代のみを対象としたGC)による停止時間は0.0003650秒
・トータルヒープ使用サイズは2198KBから150KBになった
・全ガベージコレクションによる停止時間は0.0004982秒
またその他の主要なGC関連オプションとして、以下のようなものがあります。
| オプション |
得られる情報 |
| -Xloggc:filename |
GC情報をファイル出力 |
| -XX:+PrintTenuringDistribution |
オブジェクトの年齢情報 |
| -XX:+TraceGen0Time |
New世代の累積GC回数、総時間、平均時間 |
| -XX:+TraceGen1Time |
Old世代の累積GC回数、総時間、平均時間 |
| -XX:+PrintHeapAtGC |
GC前後のヒープ情報 |
ひととおり出力情報を参照しておくと、後々役立つでしょう。
＜Q23-3＞tomcatの起動シェルでは起動オプションを指定していないのに、環境ごとに最大ヒープサイズが変わります。
環境A:
マシン : Sun Fire V490
メモリ : 8GB
CPU : ×4
⇒serverモード,最大ヒープサイズ=1024M
環境B:
マシン : Sun Fire V210
メモリ : 4GB
CPU : ×1
⇒clientモード,最大ヒープサイズ=64M
環境C:
マシン : Sun Fire V250
メモリ : 2GB
CPU : ×2
⇒serverモード,最大ヒープサイズ=512M
| ＜発生環境＞ |
| OS |
Any |
| JDK |
5.0 |
| Vender |
Sun |
＜Q23-4＞ヒープ領域のメモリを殆ど使用していないのにFull GCに非常に時間がかかってしまいます。
ヒープ領域のメモリは殆ど使用していないにも関わらず、
Full GCの完了に非常に時間がかかる場合があります。
またファイル処理・DB処理をしていないにも関わらず、
Full GC時にディスクへのアクセスが発生します。
※JDK1.5.0で動作確認を行いました。
| ＜発生環境＞ |
| OS |
Windows XP |
| JDK |
any |
- ＜A23-4＞
- これはヒープ領域を大量に確保しているJavaプロセスが長時間実行される場合に
発生する問題です。
Javaでは、プロセスの起動時にJavaプロセスが利用するヒープ領域の確保を行います。
そのため、ヒープ領域を大量に確保するJavaプロセスでは、
ヒープ領域のうち実際に使っているメモリは少なくても、
ヒープ領域は大量に確保されている状態になります。
OSの設定によっては、一定時間利用されていないヒープ領域の一部がディスクに書き出され、
実メモリ上から無くなる場合があります。
一方、JavaのFull GCではJavaのヒープ領域の全スキャンを行います。
その結果、ヒープ領域の一部がディスクに書き出された状態でFull GCが発生すると、
ディスクに書き出されたヒープをスキャンするために、
ディスクから実メモリへの読み込みが発生します。
一般にディスクアクセスには非常に時間がかかるため、
通常短時間で終わるJavaのFull GCが、非常に長い時間のかかる処理に変わってしまいます。
この問題はヒープ領域のサイズが大きいほど顕著に現れます。
このためヒープ領域のサイズを必要最低限のサイズに設定することで、
問題発生時の影響を抑えることができます。
Javaプロセスのヒープ領域のサイズは-Xms, -Xmxオプションで指定できます。
この記事の詳細な情報をJTSメールマガジンにて配信しています。
情報を取得したい方は、メールマガジンのバックナンバーを参照して下さい。
＜Q23-5＞メモリを大量確保しないアプリケーションでOutOfMemoryErrorが発生します。
複数のWebアプリケーションをtomcat上で動かしています。
メモリを大量確保していないアプリケーションばかりなのですが、
長時間運用しているとOutOfMemoryErrorが発生してしまい、
tomcatが異常終了してしまいます。
表示されるエラーメッセージは以下の通りです。
Exception in thread "xxxx" java.lang.OutOfMemoryError: PermGen space
at java.lang.ClassLoader.defineClass1(Native Method)
at java.lang.ClassLoader.defineClass(Unknown Source)
- ＜A23-5＞
-
この現象はJava VMのPermanent領域が大量に必要になる場合に発生します。
Java VMが管理するメモリ領域にはヒープと非ヒープの２種類があります。
-
ヒープ
newなどを使って生成されるオブジェクトが利用する領域です。
-
非ヒープ
ヒープ以外に、Javaの実行で必要になる領域です。各スレッドごとの
スタック領域やJavaのクラス情報の格納領域などがあります。
Permanent領域は、非ヒープの一部であり、
主にJavaのクラス情報を保存するために使われます。
単純なプログラムでは、起動時に必要なクラス情報を読み込むため、
Permanent領域に新たに情報が追加されることはありません。
しかし、tomcatなどのような、起動した後に外部のjarファイルを読み込んで
実行する仕組みをもったプログラムの場合には、起動した後にも
Permanent領域への情報追加が行われる場合があります。
この情報追加が大量に行われるプログラムの場合には、
デフォルトで決められたPermanent領域が枯渇してしまいます。
Permanent領域が枯渇すると、ヒープが枯渇した場合と同じように、
OutOfMemoryErrorが発生して、プログラムが強制終了してしまいます。
[対策]
Permanent領域のサイズを指定するには-XX:MaxPermSizeオプションを利用します。
-Xmxオプションはヒープのメモリサイズを設定するオプションですので、
Permanent領域のサイズとは別になることにご注意ください。
この記事の詳細な情報をJTSメールマガジンにて配信しています。
情報を取得したい方は、メールマガジンのバックナンバーを参照して下さい。
＜Q23-6＞メモリが不足していないのに、OutOfMemoryErrorが発生します。
アプリケーションでOutOfMemoryErrorが発生しています。
jstatやhprofでメモリの使用状況を確認しましたが、特にメモリリークはしていない様です。
ソースコードにも、メモリリークを引き起こすような問題は見付かりません。
| ＜発生環境＞ |
| OS |
Any |
| JDK |
5.0 Update6 |
| Vender |
Sun |
＜Q23-7＞-XX:+PrintClassHistogramを指定しても、ヒストグラムが表示されません。
アプリケーションの起動時に以下のパラメータを指定し、
クラスヒストグラムを出力しようとしましたが、
クラスヒストグラムが表示されません。
-XX:+PrintClassHistogram -XX:+UseParallelOldGC
PrintClassHistogramについては、
JTSメールマガジンを参照してください。
| ＜発生環境＞ |
| OS |
Any |
| JDK |
JDK5.0 update 6 |
| Vender |
Sun |
- ＜A23-7＞
- JDK5.0では、
パラメータに -XX:+PrintClassHistogram を利用しても、
JavaのバージョンとGCアルゴリズムによっては、
PrintClassHistogramが有効にならない場合があります。
java -XX:+PrintClassHistogram -XX:+UseParallelOldGC Hello
Full thread dump Java HotSpot(TM) Client VM (1.5.0_06-b05 mixed mode):
"Low Memory Detector" daemon prio=1 tid=0x08336730 nid=0x3c8a runnable [0x00000000..0x00000000]
"CompilerThread0" daemon prio=1 tid=0x08335188 nid=0x3c89 waiting on condition [0x00000000..0x00000000]
"Signal Dispatcher" daemon prio=1 tid=0x08334260 nid=0x3c88 runnable [0x00000000..0x00000000]
(中略)
"VM Thread" prio=1 tid=0x08325fa8 nid=0x3c85 runnable
"GC task thread#0 (ParallelGC)" prio=1 tid=0x082b45c0 nid=0x3c84 runnable
"VM Periodic Task Thread" prio=1 tid=0x08337c18 nid=0x3c8b waiting on condition
この問題を解決するためには、
パラメータで指定するGCアルゴリズムを
PrintClassHistogramが使えるものに変更する必要があります。
PrintClassHistogramが使えるGCアルゴリズムは以下の通りです。
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-Xincgc
-Xconcgc
-Xnoincgc
java -XX:+PrintClassHistogram -XX:+UseConcMarkSweepGC Hello
Full thread dump Java HotSpot(TM) Client VM (1.5.0_06-b05 mixed mode, sharing):
"Low Memory Detector" daemon prio=1 tid=0x090010a8 nid=0x3dea runnable [0x00000000..0x00000000]
"CompilerThread0" daemon prio=1 tid=0x08fffb00 nid=0x3de9 waiting on condition [0x00000000..0xb227e9c8]
"Signal Dispatcher" daemon prio=1 tid=0x08ffeba0 nid=0x3de8 runnable [0x00000000..0x00000000]
(中略)
"VM Thread" prio=1 tid=0x08ff48e8 nid=0x3de5 runnable
"VM Periodic Task Thread" prio=1 tid=0x0901be80 nid=0x3deb waiting on condition
num #instances #bytes class name
--------------------------------------
1: 163 42752 [C
2: 13 33992 [B
3: 29 8816 <objArrayKlassKlass>
4: 203 7600 [Ljava.lang.Object;
5: 156 3744 java.lang.String
6: 41 3608 java.lang.Class
(中略)
149: 1 8 sun.net.www.protocol.file.Handler
150: 1 8 sun.reflect.ReflectionFactory
151: 1 8 java.lang.ref.Reference$Lock
152: 1 8 java.lang.Terminator$1
153: 1 8 java.util.Hashtable$EmptyEnumerator
Total 19223 1534624
なお、Java5.0以降ではJavaVMの実行環境がサーバークラスマシンとして検出されると、
自動的にGCアルゴリズムがParallelGCに変更されてしまいます。
http://java.sun.com/j2se/1.5.0/ja/docs/ja/guide/vm/server-class.html
http://java.sun.com/j2se/1.5.0/ja/docs/ja/guide/vm/gc-ergonomics.html
この場合にもPrintClassHistogramが動作しなくなるため、注意が必要です。
参考URL：
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6441368
このバグは既に修正されています。
Java5.0u10以降やJava6.0を利用することで回避できます。
＜Q23-8＞-XX:+HeapDumpOnOutOfMemoryErrorを指定すると、JVMが起動できません。
Javaのヒープダンプを取得するために、
オプションに"-XX:+HeapDumpOnOutOfMemoryError"を指定し、
アプリケーションを起動しましたが、
以下のエラーが発生し、プログラムが起動しません。
HeapDumpOnOutOfMemoryErrorについては、JTSメールマガジンを
参照してください。
Unrecognized VM option '+HeapDumpOnOutOfMemoryError'
Could not create the Java virtual machine.
| ＜発生環境＞ |
| OS |
Any |
| JDK |
JDK5.0 update 6 |
| Vender |
Sun |
- ＜A23-8＞
- オプション "+HeapDumpOnOutOfMemoryError" は、
JDK5.0u6までのJDK5.0ではサポートされていません。
そのため、オプションに"-XX:+HeapDumpOnOutOfMemoryError"を指定しても、
無効なオプションとみなされ、JavaVMが起動しません。
HeapDumpOnOutOfMemoryErrorは、以下のバージョンで利用できます。
Java1.4.2_12以降, Java5.0u7以降, Java6.0の全てのバージョンで利用することができます。
＜Q23-9＞jstack, jmapコマンドで情報が取得できません。
今まで稼働していたJavaプロセスが、突然操作を受け付けなくなりました。
そこで、反応しなくなったJavaプロセスの情報を取得しようとしています。
スタックトレースを表示するjstackコマンドや
ヒープ情報を表示するjmapコマンドを利用しようとしましたが
以下のように、コマンドが異常終了してしまいます。
% jstack 5535
5535: well-known file is not secure
% jstack 5535
5535: Unable to open socket file: target process not responding or
HotSpot VM not loaded
The -F option can be used when the target process is not responding
※jmapコマンドについては、
メールマガジン第4号
を参考にしてください。
| ＜発生環境＞ |
| OS |
Solaris, Linux
|
| JDK |
JDK6.0以降 |
- ＜A23-9＞
- Java SE 5.0から提供されているjstackコマンド, jmapコマンドでは、
JavaVMの状態によってはコマンドが正常に動作しない場合があります。
この現象に対処するためにJava SE 6.0より
jstackコマンドやjmapコマンドに-Fオプションが追加されています。
-Fオプションを指定した場合にはJavaVMが提供する機能を利用することなく、
JavaVMの情報を取得することができます。
そのため、JavaVMが異常動作している場合にも情報取得が可能となります。
以下は、-Fオプションを利用した場合のjstackの適用例です。
% jstack -F 9813
Attaching to process ID 9813, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 11.2-b01
Deadlock Detection:
No deadlocks found.
Thread 8739: (state = BLOCKED)
Thread 8549: (state = BLOCKED)
(後略)
参考:
このjstackコマンド, jmapコマンドの-FオプションはJDK6u12現在では Solaris, Linuxでのみ利用可能です。
Windowsでは利用できないため、ご注意ください。
また-Fオプションを指定した場合のjstackコマンドにはいくつか制限があります。
詳細は、メールマガジン第11号を参照してください。
注意：本文書の内容に誤りがあり、またこの文書によって不利益を被っても、
Acroquest Technology 株式会社は一切関知いたしません。
Copyright(c) Acroquest Technology Co., Ltd. All Rights Reserved.