5.11.5 出力レベルがdebugの場合に出力される内容
ここでは,ログ出力レベルにdebugを指定した場合に出力される内容をイベントごとに説明します。
- 補足
-
debugは,デバッグなどを実施する場合に,verboseで出力する内容よりもさらに詳細な情報が必要なときに使用します。debugで出力するログには,出力するためにFullGC実行時以上のオーバーヘッドが必要なログもあります。
- 〈この項の構成〉
(1) Explicitメモリブロックの明示解放によるJavaヒープへのオブジェクトの移動
Explicitメモリブロックを明示解放する場合に,Explicitメモリブロック内のオブジェクトが明示解放対象のExplicitメモリブロック以外から参照されているとき,そのオブジェクトはJavaヒープに移動します。このログでは,Javaヒープに移動したオブジェクトとその参照元のオブジェクトの情報が出力されます。
(a) 出力の契機
Explicitメモリブロックの明示解放処理で,Javaヒープへのオブジェクトの移動が発生した場合です。
(b) 出力形式
[EDO][eid=<EID>: Reference to <REFED_NAME>(<REFED_PTR>), total <R_SIZE>] [EDO] <REF_NAME>(<REF_PTR>)<REF_GEN>
- 注
-
明示解放対象のExplicitメモリブロック以外から参照されているオブジェクトごとに出力されます。
(c) 出力項目
「(b) 出力形式」で示した各項目について説明します。
出力項目 |
出力内容 |
意味 |
---|---|---|
<EID> |
<const> |
Explicitメモリブロックの明示解放処理時に,明示解放対象のExplicitヒープ以外から参照されているオブジェクトを含むExplicitメモリブロックのIDが出力されます。 |
<REFED_NAME> |
<letters> |
Explicitメモリブロックの明示解放処理時に,明示解放対象のExplicitヒープ以外のオブジェクト(<REF_NAME>(<REF_PTR>)で示すオブジェクト)から参照されているオブジェクトの完全クラス名が出力されます。 |
<REFED_PTR> |
<ptr> |
<REFED_NAME>が示すオブジェクトのJavaヒープへの移動前のメモリアドレスが出力されます。 |
<R_SIZE> |
<const>K |
<REF_NAME>(<REF_PTR>)から参照されていることによって,Javaヒープに移動することになるオブジェクトの総サイズが出力されます。<REF_NAME>(<REF_PTR>)から間接参照している,明示解放対象Explicitメモリブロック内のオブジェクトも含めた値になります※。単位はキロバイトです。 |
<REF_NAME> |
<letters>|JVM |
<REFED_NAME>(<REFED_PTR>)を参照しているオブジェクトの完全クラス名が出力されます。ただし,参照元がスタックやJavaVM内部の場合は,"JVM"と出力されます。 |
<REF_PTR> |
<ptr> |
<REF_NAME>が示すオブジェクト,スタックまたはJavaVM内部のメモリアドレスが出力されます。 |
<REF_GEN> |
(eid=<EID>)|(DefNew)|(Tenured)|(JVM) |
<REF_NAME>(<REF_PTR>)の属する領域または世代の名称が出力されます。Explicitメモリブロックの場合はExplicitメモリブロックのIDが出力されます。スタックやJavaVM内部から参照されている場合は"JVM"と出力されます。 |
- 補足
-
Javaヒープに移動するオブジェクトへの参照経路が複数ある場合について説明します。
ここでは,次の図を例にして説明します。
図5‒9 Javaヒープに移動するオブジェクトへの参照経路が複数ある例 - Javaヒープに移動するオブジェクトが複数のオブジェクトから参照されている場合の出力
-
Javaヒープに移動するオブジェクトは,複数のオブジェクトから参照されていることがあります。図の場合,オブジェクトBに対して,A→B,E→Bの2種類の参照経路があります。
この場合,ログには,A→B,E→Bの参照についての情報が別々に出力されます。
- 複数のオブジェクトから間接参照されている場合の<R_SIZE>の算出
-
<R_SIZE>には,<REF_NAME>(<REF_PTR>)から間接参照している,明示解放対象Explicitメモリブロック内のオブジェクトも含めた値が出力されます。ただし,Javaヒープに移動するオブジェクトが複数のオブジェクトから間接参照されている場合は,算出方法が異なります。
図の場合,オブジェクトDは,次の3種類の経路で間接参照されています。
-
A→B→D
-
E→B→D
-
E→F→D
複数の経路で参照される場合,最初に算出される参照関係の<R_SIZE>にオブジェクトのサイズが計上されます。例えば,A→B,E→B,E→Fの順で参照関係が出力される場合,オブジェクトDのサイズは,A→Bの<R_SIZE>に計上されます。この場合の各参照関係の<R_SIZE>の出力は次のようになります。
-
A→B
オブジェクトBとオブジェクトDのサイズの合計で4Kになります。
-
E→B
オブジェクトBのサイズである2Kになります。
-
E→F
オブジェクトFのサイズである1Kになります。
-
(d) 出力例
出力例を示します。
[EDO][eid=5: Reference to java.lang.HashMap$Entry(0x1234568), total 125K] [EDO] java.util.HashMap$KeyIterator(0x1134428)(eid=1) [EDO][eid=5: Reference to ClassA(0x1234580), total 19250K] [EDO] ClassV(0x1234468)(Tenured) [EDO][eid=5: Reference to ClassZ(0x1234680), total 12K] [EDO] ClassU(0x1233468)(DefNew) [EDO][eid=9: Reference to JP.co.Hitachi.soft.jvm.BBB(0x1034428), total 1250K] [EDO] JVM(0x23456780)(JVM)
この出力例では次の内容が確認できます。
-
eid=5のExplicitメモリブロック内にあるjava.lang.HashMap$Entryのオブジェクトは,明示解放対象ではないeid=1のExplicitメモリブロック内のjava.util.HashMap$KeyIteratorのオブジェクトから参照されています。このため,125キロバイトのオブジェクトがJavaヒープに移動しました。
-
eid=5のExplicitメモリブロック内にあるClassAのオブジェクトは,Tenured領域内のClassVのオブジェクトから参照されています。このため,19,250キロバイトのオブジェクトがJavaヒープに移動しました。
-
eid=5のExplicitメモリブロック内にあるClassZのオブジェクトは,New領域内のClassUのオブジェクトから参照されています。このため,12キロバイトのオブジェクトがJavaヒープに移動しました。
-
eid=9のExplicitメモリブロック内にあるJP.co.Hitachi.soft.jvm.BBBのオブジェクトは,スタックまたはJavaVM内部から参照されています。このため,1,250キロバイトのオブジェクトがJavaヒープに移動しました。
(2) Explicitメモリブロックの初期化(詳細情報出力)
新たにExplicitメモリブロックを初期化した場合の詳細な情報が出力されます。「5.11.4(1) Explicitメモリブロックの初期化」で示した出力内容に加えて,初期化処理を実行したJavaプログラムのスタックトレースが出力されます。このログは,複数行にわたって,Javaプログラムの実行と非同期に出力されます。このため,各行の間に別なログが出力されることがあります。ただし,1行中にほかのログが出力されることはありません。
(a) 出力の契機
Explicitメモリブロックの初期化です。
(b) 出力形式
<Explicitメモリブロックの初期化の情報(verbose)>※[Thread: <TH_PTR>] [EDO][Thread: <TH_PTR>] at <FRAME><SOURCE> ...
- 注※
-
出力項目については,「5.11.4(1) Explicitメモリブロックの初期化」を参照してください。
(c) 出力項目
「(b) 出力形式」で示した各項目について説明します。
出力項目 |
出力内容 |
意味 |
---|---|---|
Explicitメモリブロックの初期化時の情報(vervose) |
「5.11.4(1) 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>[Created]["BasicExplicitMemory-2" eid=2(0x1234568)/B][Thread: 0x00035a60] [EDO][Thread: 0x00035a60] at ExplicitMemory.registerExplicitMemory(Native Method) [EDO][Thread: 0x00035a60] at BasicExplicitMemory.<init>(Unknown Source) [EDO][Thread: 0x00035a60] at AllocTest.test(AllocTest.java:64) [EDO][Thread: 0x00035a60] at java.lang.Thread.run(Thread.java:2312)
この出力例では次の内容が確認できます。
-
出力契機は2007年7月24日(火)1時23分51秒に実行したメモリブロックの初期化です。Explicitメモリブロックの名称は"BasicExplicitMemory-2"です。ExplicitメモリブロックのIDはeid=2です。
-
AllocTest.javaの64行目でBasicExplicitMemoryクラスのコンストラクタを実行して,Explicitメモリブロックの初期化を試みています。
(3) Explicitメモリブロックの自動解放処理の詳細(詳細情報出力)
Explicitメモリブロックの自動解放処理が起こった場合の詳細情報を出力します。「5.11.3(4) Explicitメモリブロックの自動解放処理」で示した出力内容に加えて,自動解放処理を実施したExplicitメモリブロックのEID情報を出力します。Explicitメモリブロックの自動解放処理は,オブジェクトの移動が発生しない自動解放処理,多対1の自動解放処理,および1対1の自動解放処理が実行されることがあります。このため,オブジェクトの移動が発生しなかったEID,多対1のEID,および1対1のEIDの情報を出力します。
(a) 出力の契機
Explicitメモリブロックの自動解放処理が起こった場合です。
(b) 出力形式
[EDO][migrate:(<EID_DEL>{,<EID_DEL>}*|)/(<EID_MBF>{,<EID_MBF>}*-><EID_MAF>|)/(<EID_MIG>{,<EID_MIG>}*|)]
(c) 出力項目
「(b) 出力形式」で示した各項目について説明します。
出力項目 |
出力内容 |
意味 |
---|---|---|
<EID_DEL> |
<const> |
Explicitメモリブロックの自動解放処理によって解放されるExplicitメモリブロックのうち,オブジェクトの移動が発生しなかったExplicitメモリブロックのEIDを出力します。 |
<EID_MBF> |
<const> |
Explicitメモリブロックの自動解放処理によって解放されるExplicitメモリブロックのうち,多対1の自動解放が起こったExplicitメモリブロックの自動解放予約される前のEIDを出力します。 |
<EID_MAF> |
<const> |
Explicitメモリブロックの自動解放処理によって生成されるExplicitメモリブロックのうち,多対1の自動解放によって生成されたExplicitメモリブロックのEIDを出力します。 |
<EID_MIG> |
<const> |
Explicitメモリブロックの自動解放処理によって解放されるExplicitメモリブロックのうち,1対1の自動解放が起こったExplicitメモリブロックのEIDを出力します。 |
(d) 出力例
出力例を示します。
[EVS]<Tue Jul 14 02:31:22 2009>[EH: 256512K->256128K(256256K/1048576K), 0.1124626 secs][E/F/D: 423/0/0][target:584K/384K/200K]\ [cause:Migrate] [EDO][migrate:()/(2,4,6,9->10)/(1,8)]
この出力例では次の内容が確認できます。
-
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に対して自動解放処理を実行しました。
-
ID(2,4,6,9)のExplicitメモリブロックがID(10)のExplicitメモリブロックに移動しています。
-
ID(1,8)のExplicitメモリブロックが,同じID(1,8)に移動しています。