7.2.1 Java VM異常終了時のログ出力機能

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

出力先

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

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

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

hs_err_pidログのコンソール出力機能

Java VMが異常を検知したときは、hs_err_pidファイルとコンソールにサマリー部分が出力されます。hs_err_pidファイルと同様のエラー内容すべてをコンソールに出力する機能を提供します。

製品導入時、機能は有効となっています。hs_err_pidログのコンソール出力機能を無効にしたい場合は、以下を指定してください。

オプション

-XX:-VerboseConsoleOnFatalError

調査

hs_err_pidログにJavaプロセス異常終了時の各種情報が格納されます。

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

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

異常終了時に発生した例外に関する情報(シグナルコードおよび例外発生アドレス)
「Unexpected Signal:」から始まる情報です。
異常終了した関数名(実際には異常終了したアドレスに一番近いシンボル名)
「Function=」から始まる情報です。
異常終了した関数を含むライブラリ名
「Library=」から始まる情報です。
異常終了時のJavaスレッドのスタックトレース
「Current Java thread:」から始まる情報です。
異常終了時のダイナミックライブラリ一覧
「Dynamic libraries:」から始まる情報です。「Thread：」内に含まれています。
発生時間
「time:」から始まる情報です。

調査手順

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

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

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

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

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

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

表7.1 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で使用されているシグナルです。

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

登録されているシグナルハンドラのアドレス
sa_maskおよびsa_flags

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

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

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

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

出力例と調査例

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

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007fadf1def69d, pid=12063, nid=140385542067968, tid=0x00007fae08009800
#
# JRE version: OpenJDK Runtime Environment (8.0_272-b09) (build 1.8.0_272-2020-10-09-Fujitsu-B01-b09)
# Java VM: OpenJDK 64-Bit Server VM (25.272-b09 mixed mode linux-amd64 compressed oops) 
# Problematic frame:
# C  [libfjapp.so+0x69d]  Java_com_fujitsu_jdk_ap_GW00D00100_calcStatus+0x18
#
# Core dump written. Default location: /tmp/core or core.12063
#
～～～略～～～～
(1)
～～～略～～～～
(2)
～～～略～～～～
(3)

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

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

libfjapp.soのJava_com_fujitsu_jdk_ap_GW00D00100_calcStatus関数の近くでSIGSEGV(メモリアクセスで不正なセグメントを参照)が発生しています。

本例の場合、ネイティブライブラリで異常が発生していると判断し、異常発生時のスタックトレース情報を調査します。

Unexpected Signal : SIGSEGV [0xb] occurred at PC=0x00007fadf1def69d, pid=12063, nid=140385542067968
An unexpected exception has been detected in native code outside the VM.
Function=Java_com_fujitsu_jdk_ap_GW00D00100_calcStatus+0x18
Library=/tmp/libfjapp.so+0x69d

Current Java thread:
      at com.fujitsu.jdk.ap.GW00D00100.calcStatus(Native Method)
      at com.fujitsu.jdk.ap.AL00C00253.jni_calc(AL00A00001.java:29)
      at com.fujitsu.jdk.ap.AL00B00221.execute(AL00A00001.java:21)
      at com.fujitsu.jdk.ap.AL00A00001.main(AL00A00001.java:13)

time: Fri Oct 16 02:41:28 2020
timezone: UTC
elapsed time: 0.108906 seconds (0d 0h 0m 0s)

～～～略～～～～
---------------  P R O C E S S  ---------------
～～～略～～～～

(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で最大量が指定される領域)には、空きがあることがわかります。
また「メタスペース」に対しても、余裕があることがわかります。

注意

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

Heap: 
 PSYoungGen      total 2048K, used 467K [0xffffffff67980000, 0xffffffff67c00000, 0xffffffff6a400000) 
  eden space 1536K, 30% used [0xffffffff67980000,0xffffffff679f4c68,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 2609K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 276K, capacity 386K, committed 512K, reserved 1048576K

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

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

Signal Handlers: 
SIGSEGV: [libjvm.so+0xc57e54], sa_mask0=11111111011111111111110111111111, sa_flags=SA_ONSTACK|SA_RESTART|SA_SIGINFO
SIGBUS: [libjvm.so+0xc57e54], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGFPE: [libjvm.so+0xa2ef80], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGPIPE: [libjvm.so+0xa2ef80], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGXFSZ: [libjvm.so+0xa2ef80], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
SIGILL: [libjvm.so+0xa2ef80], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO
INTERRUPT_SIGNAL: SIG_DFL, sa_mask0=00000000000000000000000000000000, sa_flags=none
ASYNC_SIGNAL: SIG_DFL, sa_mask0=00000000000000000000000000000000, sa_flags=none
SIGQUIT: [libjvm.so+0xa298f0], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGHUP: [libjvm.so+0xa298f0], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGINT: [libjvm.so+0xa298f0], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART
SIGTERM: [libjvm.so+0xa298f0], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART
ALT_INTERRUPT_SIGNAL: [libjvm.so+0xa2efd0], sa_mask0=00000000000000000000000000000000, sa_flags=SA_SIGINFO
ALT_ASYNC_SIGNAL: [libjvm.so+0xa2ef80], sa_mask0=11111111011111111111110111111111, sa_flags=SA_RESTART|SA_SIGINFO