ページの先頭行へ戻る
Interstage Application Server/Interstage Web Server チューニングガイド

7.2.11 FJVMログ

  何らかの原因でJavaプロセスが異常終了した場合、FJVMログが出力されます。
  Javaプロセスが異常終了した原因の調査のために、このFJVMログを活用することができます。

FJVMログの出力先

  FJVMログは、Javaプロセスのカレントディレクトリに、図1のファイル名で出力されます。

1 FJVMのファイル名

fjvm_pid***.log (***は異常終了したJavaプロセスのプロセスID)

  IJServer使用時のカレントディレクトリの詳細は、“J2EE ユーザーズガイド”の“J2EEアプリケーションが運用される環境(IJServer)”を参照してください。

FJVMログの調査

  FJVMログとしてJavaプロセス異常終了時の各種情報が格納されますが、その中から以下の情報を原因調査用の情報として使用することができます。

  各情報の内容について、以下で説明します。

7.2.11.1 異常終了箇所の情報

  異常終了箇所に関する図1の情報が確認できます。

1 異常終了箇所に関する情報

  1. 異常終了時に発生した例外に関する情報(シグナルコードおよび例外発生アドレス)
      「Unexpected Signal :」から始まる情報です。

  2. 異常終了した関数名(実際には異常終了したアドレスに一番近いシンボル名)    
      「Function name=」から始まる情報です。

  3. 異常終了した関数を含むライブラリ名
      「Library=」から始まる情報です。

  4. 異常終了時のJavaスレッドのスタックトレース
      「Current Java thread:」から始まる情報です。

  5. 異常終了時のダイナミックライブラリ一覧
      「Dynamic libraries:」から始まる情報です。

  6. 発生時間
      「Local Time =」から始まる情報です。

■調査手順

  まず、図1の1~3の情報で異常終了した関数を特定し、実行しているJavaアプリケーションから呼び出す関数かどうかを確認します。ただし、図1の2の異常終了した関数名として出力される名前は、異常終了したアドレスに一番近いシンボル名情報であるため、実際に異常終了した関数とは別の名前が出力されている場合がありますので注意してください。
  そして、実行しているJavaアプリケーションが使用する関数の場合には、当該関数使用に際して何らかの問題がないか確認します。
  実行しているJavaアプリケーションで使用していない関数の場合には、図1の4のスタックトレースを調査します。

スタックトレース情報の最初のメソッドがネイティブメソッドだった場合(メソッド名の後ろに「(Native Method)」が付加されている場合)はJNI処理に関係した問題である可能性が高いため、スタックトレース情報で出力された処理のJNI処理に関わる制御で何らかの問題がないか確認します。

  また異常終了した関数を含むライブラリ名が利用者作成のライブラリである場合は、利用者側作成のライブラリ内の問題である可能性が高いため、当該ライブラリ内の処理および当該ライブラリを呼び出すJNI処理に何らかの問題がないか確認します。

  スタックトレースの調査方法は、“7.3.2 スタックトレース”を参照してください。

■スタックオーバーフローの検出

  図1の1の異常終了時に発生した例外に関する情報に、図2のシグナルコードの表記がある場合、例外が発生したスレッドでスタックオーバーフローが発生した(図2の1、3の表記)、または発生した可能性がある(図2の2、4の表記)ことを示しています。
  この場合、例外が発生したスレッドに対するスタックのサイズを大きくすることで問題が解決する可能性があります。

  スタックオーバーフロー発生の原因が、Java APIで生成されたスレッドに対するスタックのサイズにある場合は、“7.5.1 スタックのチューニング”を参照して、Java APIで生成されるスレッドに対するスタックのサイズをチューニングしてください。

2 スタックオーバーフローを示すシグナルコード


1)「EXCEPTION_STACK_OVERFLOW」
2)「EXCEPTION_ACCESS_VIOLATION (Stack Overflow ?)」


3)「SIGSEGV (Stack Overflow)」
4)「SIGSEGV (Stack Overflow ?)」

ワトソンログの分析

  スタックオーバーフローが原因で発生した異常終了の場合、OS側からFJVM側の処理へ制御が渡らず、そのままワトソン博士へ制御が渡されることがあります。この場合は、FJVMログが出力されないため、ワトソン博士のログファイルを確認してください。
  ワトソンログに図3の例外番号が出力されている場合には、スタックオーバーフローが原因と考えられます。
  なお、ワトソン博士の説明は、“7.3.4 クラッシュダンプ・コアダンプ”を参照してください。

3 スタックオーバーフローを示す例外番号

c00000fd (スタックオーバーフロー)

7.2.11.2 異常終了時のシグナルハンドラ情報

  Java VMの実行制御で必要となる“表7.3 Java VMの制御で必要となるシグナル”の各シグナルに対するシグナルハンドラ情報が確認できます。

表7.3 Java VMの制御で必要となるシグナル

Solaris版Java VM

Linux版Java VM

SIGSEGV
SIGPIPE
SIGBUS
SIGILL
SIGFPE
INTERRUPT_SIGNAL (デフォルトはSIGUSR1)
ASYNC_SIGNAL (デフォルトはSIGUSR2)
SIGQUIT (1)
SIGINT (1)
SIGHUP (1)
SIGTERM (1)

SIGSEGV
SIGPIPE
SIGBUS
SIGILL
SIGFPE
INTERRUPT_SIGNAL (デフォルトはSIGUSR1) (2)
SR_SIGNUM (デフォルトはSIGUSR2)
SIGQUIT (1)
SIGINT (1)
SIGHUP (1)
SIGTERM (1)

注1) -Xrsオプションで操作対象となるシグナルです。
注2) Java VMでリザーブしているシグナルです。
これらのシグナルに関するシグナルハンドラ情報は出力しません。

  シグナルハンドラ情報として、以下の情報が出力されています。

表7.3 Java VMの制御で必要となるシグナル”のシグナルハンドラがJava VM以外の処理で登録されていた場合、Java VMは正常に動作しません。この場合、当該シグナルハンドラを登録しないようにアプリケーションを修正してください。

7.2.11.3 異常終了時のJavaヒープに関する情報

  異常終了時のJavaヒープの使用状況が確認できます。

  Javaヒープのサイズによる異常終了の場合、異常終了時にどのJavaヒープの枯渇により異常終了が発生したのかが確認できます。

7.2.11.4 出力例と調査例

  ここでは、Solaris版JDK/JRE 5.0での出力例を元に説明します。

--------------------------------------------------------------------------------
#### Java VM: Java HotSpot(TM) Server VM (1.5.0_FUJITSU_MODIFIED-B**[*****] mixed mode)
>>>> Logging process start. [pid=27758] Time=Fri Jan 12 20:37:57 2007

(1) 異常終了箇所の情報

  異常終了箇所に関する情報が確認できます。
  libjvm.soのsysThreadAvailableStackWithSlack関数の近くでSIGSEGV(メモリアクセスで不正なセグメントを参照)が発生しています。
  本例の場合、Java VM内で異常が発生していると判断します。
  異常終了箇所がJavaアプリケーション内でないため、異常発生時のスタックトレース情報を調査します。
  本例の場合、com.appli.ap.business.AL02ABB00000.toStringの延長で不正なアクセスが発生しているので、そこからAL02ABB00000.javaの489行目で不正なアクセスを招きそうな箇所がないか調べます。

Unexpected Signal : SIGSEGV [0xb] occurred at PC=0xff092068, pid=27758, nid=1
Function name=sysThreadAvailableStackWithSlack
Library=/opt/FJSVawjbk/jdk5/jre/lib/sparc/fjvm/libjvm.so

Current Java thread:
0xfb8e2850 - 0xfb8e4b7c at com.appli.ap.business.AL02ABB00000.toString(AL02ABB00000.java:489)
0xfb8e2850 - 0xfb8e4b7c at com.appli.ap.business.AL02ABB00000.toString(AL02ABB00000.java:520)
                        at java.lang.String.valueOf(String.java:1942)
                        at java.lang.StringBuffer.append(StringBuffer.java:365)
- locked <f6db38d8> (a java.lang.StringBuffer)
                        at com.appli.ap.business.AL02ABB25201.doExecute(AL02ABB25201.java:774)
                        at com.appli.ap.formula.AFCC6842.doDelegate(AFCC6842.java:221)
                        at com.appli.ap.formula.ejb.session.AFSF6801.doExecuteOrdinarily(AFSF6801.java:381)
                        at com.appli.ap.formula.ejb.session.FJAFSF6801_AFSF6801RemoteImpl.doExecuteOrdinarily(FJAFSF6801_AFSF6801RemoteImpl.java:464)
- locked <df672838> (a com.appli.ap.formula.ejb.session.FJAFSF6801_AFSF6801RemoteImpl)
                        at com.appli.ap.formula.ejb.session._FJAFSF6801_AFSF6801RemoteImpl_Tie._invoke(_FJAFSF6801_AFSF6801RemoteImpl_Tie.java:76)
0xfb98c930 - 0xfb98cc68 at com.fujitsu.ObjectDirector.CORBA.ServerRequest.call_invoke(ServerRequest.java:961)
                        at com.fujitsu.ObjectDirector.PortableServer.POA.MsgRecv(POA.java:2578)
                        at com.fujitsu.ObjectDirector.PortableServer.POAManager.MsgRecv(POAManager.java:1061)
                        at com.fujitsu.ObjectDirector.PortableServer.POAnc.MsgRecv(POAnc.java:163)

Dynamic libraries:
0x10000 /opt/FJSVawjbk/jdk5/bin/java
0xff370000 /usr/lib/libthread.so.1
0xff3fa000 /usr/lib/libdl.so.1
~~~~~~~
略
~~~~~~~
0xbef70000 /lib/libgen.so.1
0xbd6b0000 /lib/libextpiswu.so
0xbef50000 /opt/FJSVawjbk/jdk5/jre/lib/sparc/libioser12.so

Local Time = Fri Jan 12 20:37:57 2007
Elapsed Time = 9885

注意:

  Error IDの行が出力されている場合、Error IDとして出力されている値は、Java VMが内部処理矛盾を自己検出した場合に出力する内部情報コードです。SIGSEGVやSIGBUSなどOSが検出した異常の場合には、常に同じ値(4F530E435050****)が出力されます。そのためError IDの先頭が「4F530E435050」で始まるコードの場合は、通常、意味を持ちません。Error IDの先頭が「4F530E435050」以外で始まるコードの場合には、障害情報検索時や判断時のキーワード情報としての意味を持ちます。

#
# HotSpot Virtual Machine Error : SIGSEGV (0xb)
#  [ pc=0xff092068, pid=27758(0x6c6e), nid=1(0x00000001), tid=0x00034d10 ]
#
# Please report this error to FUJITSU
#
# Java VM: Java HotSpot(TM) Server VM (1.5.0_FUJITSU_MODIFIED-B** mixed mode)
~~~~~~~
略
~~~~~~~

(2)異常終了時のシグナルハンドラ情報

  異常終了時のシグナルハンドラに関する情報が確認できます。
  本例では、すべて「(in VM)」表示なので、シグナルハンドラの登録変更に関する問題はありません。

##>> Signal Handlers
 VM signal handler[1]=0xfe1ec0a0, VM signal handler[2]=0xfe4ff780, SIG_DFL= 0x00000000, SIG_IGN=0x00000001, INT_SIG=(16,16), ASYNC_SIG=(17,17)
  SIGSEGV :signal handler=0xfe4ff780 (in VM *)
  SIGPIPE :signal handler=0xfe1ec0a0 (in VM)
  SIGBUS :signal handler=0xfe1ec0a0 (in VM *)
  SIGILL :signal handler=0xfe1ec0a0 (in VM)
  SIGFPE :signal handler=0xfe1ec0a0 (in VM)
  INTERRUPT_SIGNAL :signal handler=0xfe4ff010 (in VM +)
  ASYNC_SIGNAL :signal handler=0xfe1ec0a0 (in VM)

(3)異常終了時のJavaヒープ領域に関する情報

  異常終了時のJavaヒープ領域に関する情報が確認できます。

  JDK/JRE 5.0、6のFJVMの場合:
    パラレルGC使用時:
      「PSYoungGen」が「New世代領域」、
      「PSOldGen」が「Old世代領域」、
      「PSPermGen」が「Permanent世代領域」
      に関する情報です。

    FJGC使用時(JDK/JRE 5.0の場合のみ):
      「split eden generation」が「New世代領域」、
      「tenured generation」が「Old世代領域」、
      「compacting perm gen」が「Permanent世代領域」
      に関する情報です。

    シリアルGC使用時:
      「def new generation」が「New世代領域」、
      「tenured generation」が「Old世代領域」、
      「compacting perm gen」が「Permanent世代領域」
      に関する情報です。

  JDK/JRE 1.4のFJVMの場合:
    FJGC使用時:
      「split eden generation」が「New世代領域」、
      「tenured generation」が「Old世代領域」、
      「compacting perm gen」が「Permanent世代領域」
      に関する情報です。

    シリアルGC使用時:
      「def new generation」が「New世代領域」、
      「tenured generation」が「Old世代領域」、
      「compacting perm gen」が「Permanent世代領域」
      に関する情報です。

  本例の場合、異常終了時点における「New世代領域」+「Old世代領域」の領域(-Xmxで最大量が指定される領域)には、空きがあることがわかります。
  また「Permanent世代領域」に対しても、余裕があることがわかります。

注意:
  パーセントで示されている値は、異常終了した時点でFJVMがJavaヒープ用に利用可能な状態にしている(コミットしている)メモリ量に対する比率です。利用可能な上限値に対する比率ではありません。
  パーセントで示されている値は参照せず、K(キロ)単位で表示されているメモリ使用量の値と、オプションで指定された値(デフォルト値を含む)とを比較して判断してください。

注意:
  パラレルGCを使用していた場合、以下の「-Xms=」に続いて表示される値は、-Xmsオプションで指定された値などを元に、FJVMがJavaヒープの初期値として計算し直した値であるため、-Xmsオプションで指定した値とは異なりますので注意してください。

##>> Heap
  PSYoungGen      total 15488K, used 14480K [0xf62b0000, 0xf76e0000, 0xf7800000]
  eden space 15232K, 94% used [0xf62b0000,0xf70cc180,0xf7190000]
  from space 256K, 12% used [0xf7660000,0xf7668000,0xf76a0000]
  to   space 192K, 0% used [0xf76b0000,0xf76b0000,0xf76e0000]
 PSOldGen        total 1408K, used 156K [0xf3800000, 0xf3960000, 0xf62b0000]
  object space 1408K, 11% used [0xf3800000,0xf3827198,0xf3960000]
 PSPermGen       total 16384K, used 2173K [0xef800000, 0xf0800000, 0xf3800000]
  object space 16384K, 13% used [0xef800000,0xefa1f698,0xf0800000]
(-Xms=5504K, -Xmx=65536K, -XX:PermSize=16384K, -XX:MaxPermSize=65536K)