ページの先頭行へ戻る
Interstage Application Server V12.0.0 チューニングガイド
FUJITSU Software

10.5.7 FJVMログ

FJVMでは「Java VM異常終了時のログ出力機能」の強化を行っています。
何らかの原因でJavaプロセスが異常終了した場合、Java VM異常終了時のログとしてFJVMログが出力されます。
Javaプロセスが異常終了した原因の調査のために、このFJVMログを活用することができます。

FJVMログの出力先

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

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

IJServerクラスタ使用時のカレントディレクトリの詳細は、“Java EE 7 設計・構築・運用ガイド”の“IJServerクラスタ”を参照してください。

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

FJVMログの調査

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

10.5.7.1 異常終了箇所の情報

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

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

  1. 異常終了時に発生した例外に関する情報(シグナルコードおよび例外発生アドレス)

    ログの先頭部分に表示される情報です。以下の出力例の(1)の情報です。

  2. 異常終了した関数名(実際には異常終了したアドレスに一番近いシンボル名)

    ログの先頭部分に表示される情報です。以下の出力例の(2)の情報です。

  3. 異常終了した関数を含むライブラリ名

    ログの先頭部分に表示される情報です。以下の出力例の(2)の情報です。

  4. 異常終了時のJavaスレッドのスタックトレース

    「Java frames:」から始まる情報です。以下の出力例の(3)の情報です。

  5. 異常終了時のダイナミックライブラリ一覧

    「Dynamic libraries:」から始まる情報です。以下の出力例の(4)の情報です。

  6. 発生時間

    「time:」から始まる情報です。以下の出力例の(5)の情報です。

    出力例

    #
    # A fatal error has been detected by the Java Runtime Environment:
    #
    (1) # SIGSEGV (0xb) at pc=0xffffffff1db00684, pid=12046, tid=0x0000000000000002
    #
    # JRE version: Java(TM) SE Runtime Environment (8.0_***-b**) (build 1.8.0_***-b**_Fujitsu_***-**-***)
    # Java VM: Java HotSpot(TM) 64-Bit Server VM (1.8.0_***_FUJITSU_MODIFIED-B**[**.**.**] mixed mode solaris-sparc compressed oops)
    #
    # Problematic frame:
    (2) # C [libfjapp.so+0x684] Java_com_fujitsu_jdk_ap_GW00D00100_calcStatus+0x14
    #
    # Core dump written. Default location: /tmp/core or core.12046
    #

    ~~~~~~~

    ~~~~~~~
    (3) Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
    j com.fujitsu.jdk.ap.GW00D00100.calcStatus()V+0
    j com.fujitsu.jdk.ap.AL00C00253.jni_calc(II)V+13
    j com.fujitsu.jdk.ap.AL00B00221.execute(II)V+15
    j com.fujitsu.jdk.ap.AL00A00001.main([Ljava/lang/String;)V+31
    v ~StubRoutines::call_stub
    ~~~~~~~

    ~~~~~~~
    (4) Dynamic libraries:
    0x0000000100000000 /opt/FJSVawjbk/jdk8/bin/java
    0xffffffff7f000000 opt/FJSVawjbk/jdk8/bin/../lib/sparcv9/jli/libjli.so
    0xffffffff7f200000 /usr/lib/libthread.so.1
    0xffffffff7ed00000 /usr/lib/libdl.so.1
    ~~~~~~~

    ~~~~~~~
    (5) time: Wed Mar 22 13:11:40 2017
    ~~~~~~~

    ~~~~~~~

調査手順

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

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

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

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

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

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

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

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

  1. 「EXCEPTION_STACK_OVERFLOW」

  2. 「EXCEPTION_ACCESS_VIOLATION (Stack Overflow ?)」

  1. 「SIGSEGV (Stack Overflow)」

  2. 「SIGSEGV (Stack Overflow ?)」

注意

Windowsエラー報告(Windows Error Reporting(WER))の分析

スタックオーバーフローが原因で発生した異常終了の場合、OS側からFJVM側の処理へ制御が渡らず、そのままWindowsエラー報告へ制御が渡されることがあります。この場合は、FJVMログが出力されないため、Windowsエラー報告を確認してください。
Windowsエラー報告に以下の例外番号が出力されている場合には、スタックオーバーフローが原因と考えられます。
なお、Windowsエラー報告の説明は、“10.5.8.1 クラッシュダンプ”を参照してください。

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

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

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

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

表10.9 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)
SIGXFSZ (注3)

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

注1)

-Xrsオプションで操作対象となるシグナルです。

注2)

Java VMでリザーブしているシグナルです。

注3)

Java VMで使用されているシグナルです。

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

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

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

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

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

10.5.7.4 出力例と調査例

出力例を元に説明します。

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

異常終了箇所に関する情報が確認できます。
libfjapp.soのJava_com_fujitsu_jdk_ap_GW00D00100_calcStatus関数の近くでSIGSEGV(メモリアクセスで不正なセグメントを参照)が発生しています。
本例の場合、ネイティブライブラリで異常が発生していると判断し、異常発生時のスタックトレース情報を調査します。
com.fujitsu.jdk.ap.AL00C00253.jni_calc()の延長で呼び出しているネイティブメソッドのcom.fujitsu.jdk.ap.GW00D00100.calcStatus()で不正なメモリアクセスが発生しているので、ネイティブコード内で不正なメモリアクセスを招きそうな箇所がないか調べます。

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0xffffffff1db00684, pid=12046, tid=0x0000000000000002
#
# JRE version: Java(TM) SE Runtime Environment (8.0_***-b**) (build 1.8.0_***-b**_Fujitsu_**-**-****) 
# Java VM: Java HotSpot(TM) 64-Bit Server VM (1.8.0_***_FUJITSU_MODIFIED-B**[**.**.**] mixed mode solaris-sparc compressed oops)
#
# Problematic frame: 
# C  [libfjapp.so+0x684]  Java_com_fujitsu_jdk_ap_GW00D00100_calcStatus+0x14
#
# Core dump written. Default location: /tmp/core or core.12046
#

>>>> Start of VM status report

##>> Thread: 
Current thread (0x000000010010e800):  JavaThread "main" [_thread_in_native, id=2, stack(0xffffffff7b900000,0xffffffff7ba00000)] 
~~~~~~~
略
~~~~~~~
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code) 
j  com.fujitsu.jdk.ap.GW00D00100.calcStatus()V+0
j  com.fujitsu.jdk.ap.AL00C00253.jni_calc(II)V+13
j  com.fujitsu.jdk.ap.AL00B00221.execute(II)V+15
j  com.fujitsu.jdk.ap.AL00A00001.main([Ljava/lang/String;)V+31
v  ~StubRoutines::call_stub

##>> Process: 
~~~~~~~
略
~~~~~~~

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

異常終了時のJavaヒープ領域およびメタスペースに関する情報が確認できます。
パラレルGC使用時:
「PSYoungGen」が「New世代領域」、
「ParOldGen」が「Old世代領域」、
「Metaspace」が「メタスペース」
に関する情報です。

CMS付きパラレルGC使用時:
「par new generation」が「New世代領域」、
「concurrent mark-sweep generation」が「Old世代領域」、
「Metaspace」が「メタスペース」
に関する情報です。
なお「Old世代領域」における「object space」についての情報は出力されません。

シリアルGC使用時:
「def new generation」が「New世代領域」、
「tenured generation」が「Old世代領域」、
「Metaspace」が「メタスペース」
に関する情報です。

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

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

Heap: 
 PSYoungGen      total 2048K, used 896K [0xffffffff67980000, 0xffffffff67c00000, 0xffffffff6a400000) 
  eden space 1536K, 58% used [0xffffffff67980000,0xffffffff67a60308,0xffffffff67b00000) 
  from space 512K, 0% used [0xffffffff67b80000,0xffffffff67b80000,0xffffffff67c00000) 
  to   space 512K, 0% used [0xffffffff67b00000,0xffffffff67b00000,0xffffffff67b80000) 
 ParOldGen       total 5632K, used 0K [0xffffffff62400000, 0xffffffff62980000, 0xffffffff67980000) 
  object space 5632K, 0% used [0xffffffff62400000,0xffffffff62400000,0xffffffff62980000) 
 Metaspace       used 2767K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 293K, capacity 386K, committed 512K, reserved 1048576K
~~~~~~~
略
~~~~~~~

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

異常終了時のシグナルハンドラに関する情報が確認できます。

Signal Handlers: 
SIGSEGV: [libjvm.so+0xc4d80c], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_ONSTACK|SA_RESTART|SA_SIGINFO
SIGBUS: [libjvm.so+0xc4d80c], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGFPE: [libjvm.so+0xa26340], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGPIPE: [libjvm.so+0xa26340], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGXFSZ: [libjvm.so+0xa26340], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGILL: [libjvm.so+0xa26340], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGUSR1: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGUSR2: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGQUIT: [libjvm.so+0xa20cb0], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGHUP: [libjvm.so+0xa20cb0], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGINT: [libjvm.so+0xa20cb0], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGTERM: [libjvm.so+0xa20cb0], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART
SIG39: [libjvm.so+0xa26390], sa_mask[0]=00000000000000000000000000000000, sa_flags=SA_SIGINFO
SIG40: [libjvm.so+0xa26340], sa_mask[0]=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO