Cosminexus アプリケーションサーバ V8 機能解説 保守/移行/互換編

[目次][用語][索引][前へ][次へ]

5.11.4 出力レベルがverboseの場合に出力される内容

ここでは,ログ出力レベルにverboseを指定した場合に出力される内容をイベントごとに説明します。verboseは,障害解析などに必要な詳細情報を出力するためのログ出力レベルです。

補足
verboseでは,normalで出力する内容に加えて,normalでは出力しない詳細なログを出力します。ログ出力のオーバーヘッドが掛かるため,通常運用時に指定するとスループットが低下するおそれがあります。
<この項の構成>
(1) Explicitメモリブロックの初期化
(2) Explicitメモリブロックの初期化失敗
(3) Explicitメモリブロックのサブ状態のDisable化
(4) Explicitメモリブロックへのオブジェクト生成
(5) Explicitメモリブロックへの移動(詳細情報出力)
(6) Explicitメモリブロック解放処理(詳細情報出力)
(7) ファイナライザによるExplicitメモリブロックの解放予約
(8) 明示管理ヒープへの自動配置

(1) Explicitメモリブロックの初期化

新たにExplicitメモリブロックを初期化した場合に,初期化したExplicitメモリブロックの名称,ID,およびExplicitメモリブロックの種類を出力します。

(a) 出力の契機

Explicitメモリブロックの初期化です。

(b) 出力形式
[EVO]<ctime>[Created]["<EM_NAME>" eid=<EID>(<EM_PTR>)/<EM_TYPE>]
(c) 出力項目

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

表5-41 出力項目(Explicitメモリブロックの初期化)

出力項目 出力内容 意味
<ctime> <letters> Explicitメモリブロックを初期化した日時を示します。拡張verbosegc情報と同じ形式で出力されます。
-XX:+HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<EM_NAME> <letters> 初期化したExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> 初期化したExplicitメモリブロックのIDが出力されます。
<EM_PTR> <ptr> Explicitメモリブロックの内部状態を示す値が出力されます。
<EM_TYPE> R|B 初期化したExplicitメモリブロックの種類が出力されます。
Rは,アプリケーションサーバの内部で利用されているExplicitメモリブロックを示します。Bは,ExplicitメモリブロックのJavaVM内部での種別を示します。
(d) 出力例

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[Created]["BasicExplicitMemory-2" eid=2(0x1234568)/B]

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

(2) Explicitメモリブロックの初期化失敗

Explicitメモリブロックの初期化時に,Explicitメモリブロックの初期化が失敗した場合に出力されます。失敗の原因はExplicitメモリブロックの最大数に達したことです。その時点のExplicitメモリブロックの数と,初期化に失敗したJavaプログラム上のスタックトレースが出力されます。

なお,このログは複数行にわたって出力されます。また,Javaプログラムの実行とは非同期に出力されます。このため,各行の間に別のログが出力されることがあります。ただし,1行の中にほかのログが出力されることはありません。

(a) 出力の契機

Explicitメモリブロックの上限に達して,Explicitメモリブロックの初期化に失敗した場合です。

(b) 出力形式
[EVO]<ctime>[Creation failed][EH: <EH_USED>(<EH_GARB>)/<EH_TOTAL>/<EH_MAX>][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][Thread: <TH_PTR>]
[EVO][Thread: <TH_PTR>] at <FRAME><SOURCE>
…
(c) 出力項目

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

表5-42 出力項目(Explicitメモリブロックの初期化失敗)

出力項目 出力内容 意味
<ctime> <letters> Explicitメモリブロックを初期化が失敗した日時を示します。拡張verbosegc情報と同じ形式で出力されます。
-XX:+HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<EH_USED> <const>K Explicitメモリブロック初期化失敗時のExplicitヒープの利用済みサイズが出力されます。単位はキロバイトです。
<EH_GARB> <const>K Explicitヒープの内部状態が出力されます。
<EH_TOTAL> <const>K Explicitメモリブロック初期化失敗時のExplicitヒープの確保済みサイズが出力されます。単位はキロバイトです。
<EH_MAX> <const>K Explicitヒープ最大サイズが出力されます。単位はキロバイトです。
<AC_NUM> <const> Explicitメモリブロック初期化失敗時にサブ状態がEnableであるExplicitメモリブロックの数が出力されます。
<FL_NUM> <const> 常に0が出力されます。
<DA_NUM> <const> Explicitメモリブロック初期化失敗時にサブ状態がDisableであるExplicitメモリブロックの数が出力されます。
<TH_PTR> <ptr> Explicitメモリブロックの初期化に失敗したスレッドのスレッドIDが出力されます。スレッドダンプに出力されるtidと同一です。
<FRAME> <letters>.<letters> Explicitメモリブロック初期化失敗時のスタックトレース中の1フレームが出力されます。完全クラス名とメソッド名が"."で区切られて出力されます。
<SOURCE> (<letters>:<const>)|(Native Method)|(Unknown Source) <FRAME>で出力されたメソッドが記述されているソースファイル名と,スタックトレースと一致する行番号が出力されます。ファイル名と行番号は":"で区切られて出力されます。
ネイティブメソッドの場合は,"(Native Method)"と出力されます。ソースファイル名が取得できない場合は,"(Unknown Source)"と出力されます。
(d) 出力例

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[Creation failed][EH: 12000K(0K)/15000K/30000K][E/F/D: 65535/0/0][Thread: 0x00035a60]
[EVO][Thread: 0x00035a60] at ExplicitMemory.registerExplicitMemory(Native Method)
[EVO][Thread: 0x00035a60] at BasicExplicitMemory.<init>(Unknown Source)
[EVO][Thread: 0x00035a60] at AllocTest.test(AllocTest.java:64)
[EVO][Thread: 0x00035a60] at java.lang.Thread.run(Thread.java:2312)

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

(3) Explicitメモリブロックのサブ状態のDisable化

Explicitメモリブロックのサブ状態がDisableに変更になった場合に,その時点でのExplicitヒープの利用状況と,サブ状態がDisableに変更されたExplicitメモリブロックの情報が出力されます。このログは,複数行にわたって,Javaプログラムの実行と非同期に出力されます。このため,各行の間に別なログが出力されることがあります。ただし,1行中にほかのログが出力されることはありません。

(a) 出力の契機

Explicitメモリブロックのサブ状態がDisableになり,そのExplicitメモリブロックにオブジェクトを配置できなくなった場合です。

(b) 出力形式
[EVO]<ctime>[Alloc failed(Disable)][EH: <EH_USED>(<EH_GARB>)/<EH_TOTAL>/<EH_MAX>][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][cause:<CAUSE>]\
["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED>(<EM_GARB>)/<EM_TOTAL>][Thread: <TH_PTR>]
[EVO][Thread: <TH_PTR>] at <FRAME><SOURCE>

注 下線部分はNewの場合にだけ出力されます。


(c) 出力項目

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

表5-43 出力項目(Explicitメモリブロックのサブ状態のDisable化)

出力項目 出力内容 意味
<ctime> <letters> <EID>が示すExplicitメモリブロックのサブ状態がDisableになった日時を示します。拡張verbosegc情報と同じ形式で出力されます。
-XX:+HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<EH_USED> <const>K <EID>が示すExplicitメモリブロックのサブ状態がDisableになったときのExplicitヒープの利用済みサイズが出力されます。単位はキロバイトです。
<EH_GARB> <const>K Explicitヒープの内部状態を示す値が出力されます。
<EH_TOTAL> <const>K <EID>が示すExplicitメモリブロックのサブ状態がDisableになったときのExplicitヒープの確保済みサイズが出力されます。単位はキロバイトです。
<EH_MAX> <const>K Explicitヒープ最大サイズが出力されます。単位はキロバイトです。
<AC_NUM> <const> <EID>が示すExplicitメモリブロックのサブ状態がDisableになったあとで,サブ状態がEnableであるExplicitメモリブロックの数が出力されます。
<FL_NUM> <const> 常に0が出力されます。
<DA_NUM> <const> <EID>が示すExplicitメモリブロックのサブ状態がDisableになったあとで,サブ状態がDisableであるExplicitメモリブロックの数が出力されます。
<CAUSE> New|GC|Full GC サブ状態がDisableになった原因の処理が出力されます。
出力内容と原因の対応は次のとおりです。
  • "New"
    newInstance()などによるExplicitヒープへのオブジェクト直接生成が原因です。
  • "GC"
    コピーガーベージコレクションによるExplicitヒープへのオブジェクト移動が原因です。
  • "Full GC"
    フルガーベージコレクションによるExplicitヒープへのオブジェクト移動が原因です。
<EM_NAME> <letters> サブ状態がDisableになったExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> サブ状態がDisableになったExplicitメモリブロックのIDが出力されます。
<EM_TYPE> R|B|A サブ状態がDisableになったExplicitメモリブロックの種類が出力されます。
Rは,アプリケーションサーバの内部で利用されているExplicitメモリブロックを示します。Bは,ExplicitメモリブロックのJavaVM内部での種別を示します。Aは,自動配置設定ファイルを使って指定したExplicitメモリブロックを示します。
<EM_USED> <const>K サブ状態がDisableになったExplicitメモリブロックの利用済みサイズが出力されます。単位はキロバイトです。
<EM_GARB> <const>K Explicitメモリブロックの内部状態を示す値が出力されます。
<EM_TOTAL> <const>K サブ状態がDisableになったExplicitメモリブロックの確保済みサイズが出力されます。単位はキロバイトです。
<TH_PTR> <ptr> サブ状態がDisableになった原因である,Explicitヒープへのオブジェクト生成を実行したスレッドのスレッドIDが出力されます。スレッドダンプに出力されるtidと同一です。
この項目は,<CAUSE>が"New"の場合だけに出力されます。
<FRAME> <letters>.<letters> Explicitヒープへのオブジェクト直接生成によってサブ状態がDisableになった場合に,オブジェクト直接生成で出力されたスタックトレース中の1フレームが出力されます。
完全クラス名とメソッド名が"."で区切られて出力されます。
この項目は,<CAUSE>が"New"の場合だけに出力されます。
<SOURCE> (<letters>:<const>)|(Native Method)|(Unknown Source) <FRAME>で出力されたメソッドが記述されているソースファイル名と,スタックトレースと一致する行番号が出力されます。ファイル名と行番号は":"で区切られて出力されます。
ネイティブメソッドの場合は,"(Native Method)"と出力されます。
ソースファイル名が取得できない場合は,"(Unknown Source)"と出力されます。
この項目は,<CAUSE>が"New"の場合だけに出力されます。
(d) 出力例

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[Alloc failed(Disable)][EH: 12000K(1258K)/15000K/30000K][E/F/D: 321/0/1][cause:GC]\
["ReferenceExplicitMemory-3" eid=3/R: 108K(20K)/108K]

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

(4) Explicitメモリブロックへのオブジェクト生成

ExplicitMemory.newInstance()などを使用してExplicitメモリブロックに直接オブジェクトを生成した場合に出力されます。

(a) 出力の契機

Explicitメモリブロックにオブジェクトが生成された時です。

(b) 出力形式
[EVS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>)][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][cause:<CAUSE>]\
["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED_BF>-><EM_USED_AF>(<EM_TOTAL>)]
(c) 出力項目

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

表5-44 出力項目(Explicitメモリブロックへのオブジェクト生成)

出力項目 出力内容 意味
<ctime> <letters> Explicitメモリブロックにオブジェクトが生成された日時を示します。拡張verbosegc情報と同じ形式で出力されます。
-XX:+HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<EH_USED_BF> <const>K オブジェクト生成前のExplicitヒープの利用済みサイズが出力されます。単位はキロバイトです。
<EH_USED_AF> <const>K オブジェクト生成後のExplicitヒープの利用済みサイズが出力されます。単位はキロバイトです。
<EH_TOTAL> <const>K オブジェクト生成後のExplicitヒープの確保済みサイズが出力されます。単位はキロバイトです。
<EH_MAX> <const>K Explicitヒープの最大サイズが出力されます。単位はキロバイトです。
<AC_NUM> <const> オブジェクト生成後にサブ状態がEnableであるExplicitメモリブロックの数が出力されます。
<FL_NUM> <const> 常に0が出力されます。
<DA_NUM> <const> オブジェクト生成後にサブ状態がDisableであるExplicitメモリブロックの数が出力されます。
<CAUSE> New 必ず"New"と出力されます。
Explicitメモリブロックへのオブジェクトへの移動がJavaプログラムから実行されたことを示します。
<EM_NAME> <letters> オブジェクトを生成したExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> オブジェクトを生成したExplicitメモリブロックのIDが出力されます。
<EM_TYPE> R|B|A オブジェクトを生成したExplicitメモリブロックの種類が出力されます。
Rは,アプリケーションサーバの内部で利用されているExplicitメモリブロックを示します。Bは,ExplicitメモリブロックのJavaVM内部での種別を示します。Aは,自動配置設定ファイルを使って指定したExplicitメモリブロックを示します。
<EM_USED_BF> <const>K オブジェクト生成前の生成先Explicitメモリブロックの利用済みサイズが出力されます。単位はキロバイトです。
<EM_USED_AF> <const>K オブジェクト生成後の生成先Explicitメモリブロックの利用済みサイズが出力されます。単位はキロバイトです。
<EM_TOTAL> <const>K オブジェクト生成後の生成先Explicitメモリブロックの確保済みサイズが出力されます。単位はキロバイトです。
(d) 出力例

出力例を示します。

[EVS]<Thu Oct 21 14:55:50 2007>[EH: 150528K->150529K(150532K/1048576K)][E/F/D: 200/0/0][cause:New]["BEM" eid=2/B: 30K->31K(32K)]

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

(5) Explicitメモリブロックへの移動(詳細情報出力)

Explicitメモリブロックにオブジェクトが移動する場合の詳細な情報が出力されます。「5.11.3(1) ガーベージコレクション発生(Explicitヒープ利用状況出力)」で示した出力内容に加えて,移動先になったExplicitメモリブロックすべての利用状況が出力されます。

(a) 出力の契機

ガーベージコレクション発生による,Explicitメモリブロックへのオブジェクトの移動です。

(b) 出力形式
<ガーベージコレクション発生時のExplicitヒープ利用状況>
[EVS]{["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED_BF>-><EM_USED_AF>(<EM_TOTAL>)]}{1,5}
...

注 Explicitメモリブロックの情報が5個出力されるごとに改行されます。

注※ 出力項目については,「5.11.3(1) ガーベージコレクション発生(Explicitヒープ利用状況出力)」を参照してください。


(c) 出力項目

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

表5-45 出力項目(Explicitメモリブロックへの移動(詳細情報出力))

出力項目 出力内容 意味
ガーベージコレクション発生時のExplicitヒープ利用状況 5.11.3(1) ガーベージコレクション発生(Explicitヒープ利用状況出力)」を参照してください。
<EM_NAME> <letters> ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックのIDが出力されます。
<EM_TYPE> R|A ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックの種別が出力されます。
RまたはAが出力されます。Rは,ExplicitメモリブロックのJavaVM内部での種別を示します。Aは,自動配置設定ファイルを使って指定したExplicitメモリブロックを示します。
<EM_USED_BF> <const>K ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックの,ガーベージコレクション発生前の利用済みサイズが出力されます。単位はキロバイトです。
<EM_USED_AF> <const>K ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックの,ガーベージコレクション発生後の利用済みサイズが出力されます。単位はキロバイトです。
<EM_TOTAL> <const>K ガーベージコレクション発生時にオブジェクト移動先となったExplicitメモリブロックの,ガーベージコレクション発生後の確保済みサイズが出力されます。単位はキロバイトです。
(d) 出力例

出力例を示します。

[ENS]<Thu Oct 21 14:55:50 2007>[EH: 150528K->162816K(162816K/1048576K)][E/F/D: 200/0/0][cause:GC][CF: 0]
[EVS]["REM2" eid=2/R: 0K->88K(128K)]["REM3" eid=3/R: 30K->230K(256K)]["REM6" eid=6/R: 30K->2030K(2048K)]\
["Session1" eid=8/R: 30K->2530K(2548K)]["Session2" eid=10/R: 30K->2530K(2548K)]
[EVS]["Session3" eid=12/R: 30K->5030K(5048K)]

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

(6) Explicitメモリブロック解放処理(詳細情報出力)

Explicitメモリブロックの解放処理が起こった場合の詳細な情報が出力されます。「5.11.3(2) Explicitメモリブロック解放処理」で示した出力内容に加えて,解放したすべてのExplicitメモリブロックの情報が出力されます。

Explicitメモリブロックの解放時にJavaヒープがあふれた場合は,あふれる前に解放したExplicitメモリブロックの情報が追加されて出力されます。ただし,「5.11.3(3) Explicitメモリブロック解放処理時のJavaヒープあふれ」で示した出力内容には,ここで説明する情報は追加出力されません。

(a) 出力の契機

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

(b) 出力形式
<Explicitメモリブロック解放処理>
[EVS]{["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_TOTAL>]}{1,5}
...

注 Explicitメモリブロックの情報が5個出力されるごとに改行されます。

注※ 出力項目については,「5.11.3(2) Explicitメモリブロック解放処理」を参照してください。


(c) 出力項目

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

表5-46 出力項目(Explicitメモリブロック解放処理(詳細情報出力))

出力項目 出力内容 意味
Explicitメモリブロックの解放処理で出力される情報 5.11.3(2) Explicitメモリブロック解放処理」を参照してください。
<EM_NAME> <letters> 解放したExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> 解放したExplicitメモリブロックのIDが出力されます。
<EM_TYPE> R|B|A 解放したExplicitメモリブロックの種別が出力されます。
Rは,アプリケーションサーバの内部で利用されているExplicitメモリブロックを示します。Bは,ExplicitメモリブロックのJavaVM内部での種別を示します。Aは,自動配置設定ファイルを使って指定したExplicitメモリブロックを示します。
<EM_TOTAL> <const>K 解放したExplicitメモリブロックによって確保済みだったメモリサイズ(解放処理によって解放されたメモリサイズ)が出力されます。単位はキロバイトです。
(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)][cause:Reclaim]
[EVS]["REM2" eid=3/R: 300K]["BEM3" eid=5/B: 300K]["BEM1" eid=7/B: 400K]

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

(7) ファイナライザによるExplicitメモリブロックの解放予約

ExplicitMemoryインスタンスへの参照切れによって,ExplicitMemoryクラスのfinalizeメソッドで対応するExplicitメモリブロックが解放予約された場合に出力されます。

(a) 出力の契機

ExplicitMemory.finalize()メソッドによってExplicitメモリブロックの解放が予約された場合です。

(b) 出力形式
[EVO]<ctime>[Finalized]["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_TOTAL>]
(c) 出力項目

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

表5-47 出力項目(ファイナライザによるExplicitメモリブロックの解放予約)

出力項目 出力内容 意味
<ctime> <letters> 解放が予約された日時を示します。拡張verbosegc情報と同じ形式で出力されます。
-XX:+HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<EM_NAME> <letters> 解放予約したExplicitメモリブロックの名称が出力されます。
Explicitメモリブロックの名称に多バイト文字が含まれている場合,出力内容は不定です(通常は文字化けして出力されます)。
<EID> <const> 解放予約したExplicitメモリブロックのIDが出力されます。
<EM_TYPE> B 解放予約したExplicitメモリブロックの種別が出力されます。
Bは,ExplicitメモリブロックのJavaVM内部での種別を示します。アプリケーションサーバのバージョンが08-50より前の場合は,アプリケーションが利用しているExplicitメモリブロックを示します。
<EM_TOTAL> <const>K 解放を予約したExplicitメモリブロックによって確保済みサイズ(解放処理によって解放されるメモリサイズ)が出力されます。単位はキロバイトです。
(d) 出力例

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[Finalized]["REM1" eid=3/R: 512K]

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

(8) 明示管理ヒープへの自動配置

指定したクラスが明示管理ヒープ上への自動配置に成功した場合,ログメッセージが出力されます。

(a) 出力の契機

指定したクラスが明示管理ヒープ上への自動配置に成功した場合です。

(b) 出力形式
[EVA]<ctime> creation in explicit memory is succeeded. [class=<CLASSNAME>]
(c) 出力項目

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

表5-48 出力項目(明示管理ヒープへの自動配置)

出力項目 出力内容 意味
<ctime> <letters> 指定したクラスが明示管理ヒープ上への自動配置に成功した日時を示します。拡張VerboseGC機能で出力しているものと同一の時刻形式で出力されます。HitachiOutputMilliTimeオプションが設定されている場合は,ミリ秒単位まで出力されます。
<CLASSNAME> <letters> 明示管理ヒープへの自動配置に成功したクラスの完全修飾クラス名が出力されます。
(d) 出力例

出力例を示します。

[EVA]<Tue Jul 24 01:23:51 2007> creation in explicit memory is succeeded. [class=jp.co.sample.Main]

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