5.11.3　出力レベルがnormalの場合に出力される内容

(a)　出力の契機

GCの終了です。

(b)　出力形式

[ENS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>)][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][cause:<CAUSE>][CF: <CF_CNT>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENS]<Thu Oct 21 14:55:50 2007>[EH: 150528K->162816K(162816K/1048576K)][E/F/D: 200/0/0][cause:GC][CF: 0]

この出力例では次の内容が確認できます。

• 出力契機は2007年10月21日(木)14時55分50秒に発生したCopyGCです。

• GCでExplicitヒープへの移動が発生して，Explicitヒープの利用済みサイズが150,528Kから162,816Kに変化しました。

• GC発生後のExplicitヒープの確保済みサイズは162,816Kです。Explicitヒープの最大サイズは1,048,576Kです。

• GC発生後，サブ状態がEnableであるExplicitメモリブロックは200個あります。

(a)　出力の契機

Explicitメモリブロックの明示解放処理です。

Explicitメモリブロックの明示解放は，GC直後に発生します。このため，ここで示すログは，「(1)　GC発生（Explicitヒープ利用状況出力）」で示したログのあとに出力されます。

(b)　出力形式

[ENS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>), <ELAPSED> secs][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>]\
[DefNew::Eden: <ED_USED_BF>-><ED_USED_AF>(<ED_TOTAL>)][DefNew::Survivor: <SV_USED_BF>-><SV_USED_AF>(<SV_TOTAL>)]\
[Tenured: <TN_USED_BF>-><TN_USED_AF>(<TN_TOTAL>)][User: <USERCPU> secs][Sys: <SYSCPU> secs][cause:<CAUSE>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 150528K->149528K(162816K/1048576K), 0.1129602 secs][E/F/D: 523/0/0]\
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103400K(556800K)]\
[User: 0.0900000 secs][Sys: 0.0200000 secs][cause:Reclaim]

この出力例では次の内容が確認できます。

• 出力契機は2007年7月24日(火)1時23分51秒に発生したExplicitメモリブロックの明示解放処理です。

• Explicitメモリブロックの明示解放処理によって，Explicitヒープ利用済みサイズが150,528Kから149,528Kに減少しました。

• Explicitメモリブロックの明示解放処理後のExplicitヒープの確保済みサイズは162,816Kです。Explicitヒープの最大サイズは1,048,576Kです。

• Explicitメモリブロックの明示解放処理に，0.1129602秒掛かりました。

• Explicitメモリブロックの明示解放処理後，サブ状態がEnableであるExplicitメモリブロックは523個あります。

• Explicitメモリブロックの明示解放処理によるJavaヒープの各領域の変化はありません。つまり，Javaヒープに移動したオブジェクトはありません。

• Explicitメモリブロックの明示解放処理に，ユーザCPU時間が0.0900000秒，システムCPU時間が0.0200000秒掛かりました。

(a)　出力の契機

Explicitメモリブロックの明示解放処理時にExplicitヒープからJavaヒープへのオブジェクトの移動が発生し，Javaヒープがあふれた場合です。

(b)　出力形式

[ENS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EM_TOTAL>/<EH_MAX>), <ELAPSED> secs][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>]\
[DefNew::Eden: <ED_USED_BF>-><ED_USED_AF>(<ED_TOTAL>)][DefNew::Survivor: <SV_USED_BF>-><SV_USED_AF>(<SV_TOTAL>)]\
[Tenured: <TN_USED_BF>-><TN_USED_AF>(<TN_TOTAL>)][User: <USERCPU> secs][Sys: <SYSCPU> secs][cause:<CAUSE>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 706728K->706728K(706728K/1048576K), 0.1129602 secs][E/F/D: 523/0/0]\
[DefNew::Eden: 0K->243600K(243600K)][DefNew::Survivor: 0K->17400K(17400K)][Tenured: 278000K->556800K(556800K)]\
[User: 0.0900000 secs][Sys: 0.0200000 secs][cause:Reclaiming]
[ENS]<Tue Jul 24 01:23:51 2007>[EH: 706728K->706728K(706728K/1048576K)][E/F/D: 523/0/0][cause:Full GC][CF: 0]
[ENS]<Tue Jul 24 01:23:53 2007>[EH: 706728K->148528K(148528K/1048576K), 0.0123405 secs][E/F/D: 521/0/0]\
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 551800K->552800K(556800K)]\
[User: 0.0090000 secs][Sys: 0.0020000 secs][cause:Reclaim]

この出力例では次の内容が確認できます。

• 出力契機は2007年7月24日(火)1時23分51秒に発生したExplicitメモリブロックの明示解放処理でのJavaヒープあふれです。

• Explicitメモリブロックの明示解放処理開始からJavaヒープがあふれるまでに，0.1129602秒掛かりました。

• Javaヒープがあふれたあとでサブ状態がEnableであるExplicitメモリブロックは523個あります。

• Explicitメモリブロックの明示解放処理によって，5,398,00KがJavaヒープに移動したため，Javaヒープがあふれました。

• Explicitメモリブロックの明示解放処理開始からJavaヒープがあふれるまでに，ユーザCPU時間が0.0900000秒，システムCPU時間が0.020000秒掛かりました。

また，出力例の3行目の[ENS]以降の出力内容は，Explicitメモリブロックの明示解放処理によって出力されたログです。Javaヒープあふれによって出力されたログのあとには，必ずExplicitメモリブロックの明示解放処理によってログが出力されます。この例では，次の内容が出力されています。

• 2007年7月24日(火)1時23分53秒にExplicitメモリブロックの明示解放処理を再開して，このログを出力しました。

• 再開したExplicitメモリブロックの明示解放処理によって，Explicitヒープの利用済みサイズが706,728Kから148,528Kに減少しました。

• 再開したExplicitメモリブロックの明示解放処理を実行したあとでのExplicitヒープの確保済みサイズは148,528Kです。Explicitヒープの最大サイズは1,048,576Kです。

• 再開したExplicitメモリブロックの明示解放処理に，0.0123405秒掛かりました。

• 再開したExplicitメモリブロックの明示解放処理後，サブ状態がEnableであるExplicitメモリブロックは521個あります。

• 再開したExplicitメモリブロックの明示解放処理によって，JavaヒープのTenured領域の使用サイズが，551,800Kから552,800Kに増加しました。

• 再開したExplicitメモリブロックの明示解放処理に，ユーザCPU時間が0.0090000秒，システムCPU時間が0.0020000秒掛かりました。

(a)　出力の契機

Explicitメモリブロックの自動解放自動予約，自動解放明示予約，およびExplicitメモリブロックの自動解放処理が起きた場合です。

(b)　出力形式

[ENS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>), <ELAPSED> secs][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>]\
[DefNew::Eden: <ED_USED_BF>-><ED_USED_AF>(<ED_TOTAL>)]
[DefNew::Survivor: <SV_USED_BF>-><SV_USED_AF>(<SV_TOTAL>)]\
[Tenured: <TN_USED_BF>-><TN_USED_AF>(<TN_TOTAL>)][target:<EH_MIG_TRG>/<EH_MIG_DED>/<EH_MIG_LIV>]\
[User: <USERCPU> secs][Sys: <SYSCPU> secs][cause:<CAUSE>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENS]<Tue Jul 14 02:31:22 2009>[EH: 256512K->256128K(256256K/1048576K), 0.1124626 secs][E/F/D: 423/0/0]\
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103400K(556800K)][target:584K/384K/200K]\
[User: 0.0900000 secs][Sys: 0.0200000 secs][cause:Migrate]

この出力例では次の内容が確認できます。

• 出力契機は2009年7月14日（火）2時31分22秒に発生したGCでのExplicitメモリブロックの自動解放処理です。

• 自動解放処理によってExplicitヒープの利用済みサイズが256,512Kから256,128Kに変化しました。

• 自動解放処理後のExplicitヒープの確保済みサイズは256,256K，最大サイズは1,048,576Kです。

• 自動解放処理に，0.1124626秒掛かりました。

• 自動解放処理後の，サブ状態がEnableであるExplicitメモリブロックは423個です。

• 自動解放処理によって，Explicitヒープの利用済みサイズのうち584Kに対して自動解放が行われました。減少したサイズは384K，減少しなかったサイズは200Kでした。

• Explicitメモリブロックの自動解放処理による，Javaヒープ各領域の変化はありませんでした。

• 自動解放処理に，ユーザCPU時間が0.0900000秒，システムCPU時間が0.0200000秒掛かりました。

(a)　出力の契機

Explicitメモリブロックの自動解放処理中に，Explicitヒープ領域の空き領域が不足すると，Javaヒープへのオブジェクトの移動が発生します。このとき，Javaヒープがあふれた場合です。

(b)　出力形式

[ENS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>), <ELAPSED> secs][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>]\
[DefNew::Eden: <ED_USED_BF>-><ED_USED_AF>(<ED_TOTAL>)]
[DefNew::Survivor: <SV_USED_BF>-><SV_USED_AF>(<SV_TOTAL>)]\
[Tenured: <TN_USED_BF>-><TN_USED_AF>(<TN_TOTAL>)][target:<EH_MIG_TRG>/<EH_MIG_DED>/<EH_MIG_LIV>]\
[User: <USERCPU> secs][Sys: <SYSCPU> secs][cause:<CAUSE>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENS]<Tue Jul 14 02:31:22 2009>[EH: 706728K->706728K(706728K/706728K), 0.1129602 secs][E/F/D: 522/0/1]\
[DefNew::Eden: 0K->243600K(243600K)][DefNew::Survivor: 0K->17400K(17400K)][Tenured: 278000K->556800K(556800K)]\
[target:372000K/0K/339800K] [User: 0.0900000 secs][Sys: 0.0200000 secs][cause:Migrating]

この出力例では次の内容が確認できます。

• 出力契機は2009年7月14日(火)2時31分22秒に発生したGCでのExplicitメモリブロックの自動解放処理時のJavaヒープあふれです。

• 自動解放処理によってExplicitヒープの利用済みサイズが706,728Kから変化ありません。

• 自動解放処理後のExplicitヒープの確保済みサイズは706,728K，最大サイズは706,728Kです。

• 自動解放処理に，0.1129602秒掛かりました。

• 自動解放処理後の，サブ状態がEnableであるExplicitメモリブロックは522個です。サブ状態がDisableであるExplicitメモリブロックは1個です。

• 自動解放処理によって，Explicitヒープの利用済みサイズのうち372,000Kに対して自動解放が実行されました。Javaヒープあふれの時点までに339,800Kが減少しませんでした。

• 自動解放処理時のJavaヒープあふれによって，Javaヒープの利用済みサイズが各領域の上限に到達しました。

• Explicitメモリブロックの自動解放処理開始からJavaヒープがあふれるまでに，ユーザCPU時間が0.0900000秒，システムCPU時間が0.0200000秒掛かりました。

(a)　出力の契機

明示管理ヒープ自動配置設定ファイルのオープンや読み込みに失敗した場合です。例えば，ファイルが存在しない場合，ファイルの読み込み権限がない場合，ファイル読み込み中に予期しないIOエラーが発生した場合があります。

(b)　出力形式

[ENA]<ctime> failed to open file. [file=<FILENAME>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENA]<Tue Jul 24 01:23:51 2007> failed to open file. [file=usrexmem.cfg]

この出力例では次の内容が確認できます。

• 2007年7月24日(火)1時23分51秒に，明示管理ヒープ自動配置設定ファイルのオープンに失敗しました。

(a)　出力の契機

明示管理ヒープ自動配置設定ファイルのパースに失敗した行がある場合です。ファイルの複数行で記述フォーマットエラーがある場合，複数回ログ出力されます。

(b)　出力形式

[ENA]<ctime> parsed error line. [file=<FILENAME> line=<LINENO>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENA]<Tue Jul 24 01:23:51 2007> parsed error line. [file=usrexmem.cfg line=25]

この出力例では次の内容が確認できます。

• 2007年7月24日(火)1時23分51秒に，明示管理ヒープ機能自動配置設定ファイルのパースに25行目で失敗しました。

(a)　出力の契機

明示管理ヒープ機能によって指定したクラスが，明示管理ヒープへの自動配置に失敗した場合です。

(b)　出力形式

[ENA]<ctime> creation <CLASS_LIST> class's object in explicit memory is failed. [target=<CLASS_METHOD> \
detail=<MESSAGE>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENA]<Tue Jul 24 01:23:51 2007> creation java.util.HashMap, java.util.LinkedList \
class's object in explicit memory is failed. [target=com.sample.MainClass.main \
detail=Invalid class file format. (max_stack = 65536, max = 65535, min = 0)]

この出力例では次の内容が確認できます。

• 2007年7月24日(火)1時23分51秒に，明示管理ヒープ機能がクラスjp.co.sample.Mainの明示管理ヒープ上への自動配置に失敗しました。

(a)　出力の契機

明示管理ヒープ機能適用除外クラス指定機能の設定ファイルのオープンや読み込みに失敗した場合です。例えば，ファイルが存在しない場合，ファイルの読み込み権限がない場合，ファイル読み込み中に予期しないIOエラーが発生した場合があります。

(b)　出力形式

[ENO]<ctime> failed to open file. [<TYPE>] [file=<FILENAME>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENO]<Fri Aug 10 17:41:51 2012> failed to open file. [USR] [file=javamove.cfg]

この出力例では次の内容が確認できます。

• 2012年8月10日(金)17時41分51秒に，JavaVM起動オプションで指定したファイルパスの設定ファイルのオープンに失敗しました。

(a)　出力の契機

明示管理ヒープ機能適用除外クラス指定機能の設定ファイルのパースに失敗した行がある場合です。ファイルの複数行で記述フォーマットエラーがある場合，複数回ログ出力されます。

(b)　出力形式

[ENO]<ctime> parsed error line. [TYPE] [file=<FILENAME> line=<LINENO>]

(c)　出力項目

「(b)　出力形式」で示した各項目について説明します。

(d)　出力例

出力例を示します。

[ENO]<Fri Aug 10 17:41:51 2012> parsed error line. [USR] [file=javamove.cfg line=25]

この出力例では次の内容が確認できます。

• 2012年8月10日(金)17時41分51秒に，JavaVM起動オプションでファイルパスを指定した設定ファイルのパースに25行目で失敗しました。