7.11.4 アプリケーション開発・運用時の確認・調査

次のような場合には,ログに出力された内容やAPIで取得した内容を基に,メモリサイズをチューニングします。

これらの場合に必要な確認・調査方法について説明します。

<この項の構成>
(1) Explicitヒープのある時点での利用状況(スナップショット)の調査
(2) 利用状況の推移の調査
(3) Explicitヒープあふれが発生した場合の確認と対処
(4) Explicitメモリブロックの初期化が失敗した場合の確認と対処
(5) Explicitメモリブロック解放処理時にJavaヒープへのオブジェクト移動が発生した場合の確認と対処

(1) Explicitヒープのある時点での利用状況(スナップショット)の調査

Explicitヒープのある時点での利用状況(スナップショット)を調査する方法には,スレッドダンプを確認する方法と,Java APIで情報を取得する方法があります。

(2) 利用状況の推移の調査

Explicitヒープの利用状況の推移を調査する方法には,明示管理ヒープ機能のイベントログを確認する方法と,Java APIで情報を取得する方法があります。Java APIを使用する方法については,「(1) Explicitヒープのある時点での利用状況(スナップショット)の調査」で示したAPIを使用します。

ここでは,明示管理ヒープ機能のイベントログを使用した調査方法について説明します。

(a) Explicitヒープの利用状況の推移

JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「normal」を指定します。これによって,次のタイミングでExplicitヒープの利用状況が出力されます。

また,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定すると,「normal」で出力されるタイミングに加えて,次のタイミングでExplicitヒープの利用状況が出力されるようになります。

出力例を次に示します。

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

太字で示した「EH:」で始まる部分が,Explicitヒープの利用状況を示します。ログに出力された内容のうち,Explicitヒープの利用状況を示す行には,必ず太字に該当する情報が含まれます。この値をグラフなどに記してプロットすることによって,利用状況の推移を確認できます。

なお,利用状況を示すログの先頭は,[ENS]または[EVS]で開始されます。この文字列でイベントログをフィルタリングすると,利用状況を確認しやすくなります。

(b) Explicitメモリブロックごとの利用状況の推移

JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定します。これによって,次のタイミングでサイズ変化のあったExplicitメモリブロックの利用状況が出力されます。

出力例を示します。

[ENS]<Thu Oct 21 14:55:50 2007>[EH: 11422K->12800K(12800K/65536K)][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->200K(256K)]¥
["Session1" eid=8/R: 30K->250K(256K)]["Session2" eid=10/R: 30K->250K(256K)]
[EVS]["Session3" eid=12/R: 30K->510K(512K)]

太字で示した部分が,「"REM2"」という名称の一つのExplicitメモリブロックについての利用状況を示します。

また,-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定した場合,Explicitメモリブロックの解放時に,解放したExplicitメモリブロックの情報が出力されます。出力例を示します。

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 12800K->11776K(11776K/65536K), 0.1129602 secs][E/F/D: 523/0/0]¥
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 12K->0K(17400K)][Tenured: 103400K->103400K(556800K)][cause:Reclaim]
[EVS]["REM2" eid=2/R: 320K]["BEM3" eid=5/B: 320K]["BEM1" eid=7/B: 384K]

太字で示した部分が,解放された「"REM2"」という名称のExplicitメモリブロックの情報を示しています。「320K」は,解放されたメモリのサイズ(確保済みだったExplicitメモリブロックのサイズ)です。

これらの値をグラフなどに記してプロットすることによって,Explicitメモリブロックごとの利用状況の推移を確認できます。なお,個々のExplicitメモリブロックのサイズは,解放するまで単調増加します。

(3) Explicitヒープあふれが発生した場合の確認と対処

Explicitヒープあふれが発生した場合の確認と対処について説明します。

Explicitヒープあふれとは,次の状態を示します。

Explicitヒープあふれが発生すると,発生後に領域を拡張しようとしたExplicitメモリブロックのサブ状態が,「Enable」から「Disable」に変わります。「Disable」になったExplicitメモリブロックには,オブジェクトを配置できません。

Explicitヒープあふれが発生しているかどうかは,明示管理ヒープ機能のイベントログまたはスレッドダンプの内容から調査できます。また,Java APIで取得した情報で確認することもできます。

Explicitヒープあふれが発生した場合は,次の対処を実施してください。

Explicitヒープあふれが発生した場合の対処

ここでは,Explicitヒープあふれが発生しているかどうかの確認方法について説明します。

(a) 明示管理ヒープ機能のイベントログの調査

明示管理ヒープ機能のイベントログで調査をするためには,あらかじめJavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「normal」を指定しておく必要があります。これによって,ガーベージコレクションが発生するごとに,明示管理ヒープ機能のイベントログにExplicitメモリブロックの利用状況が出力されるようになります。

出力例を示します。

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

太字で示した部分が,Explicitメモリブロックの数を示しています。「E」および「D」は,Explicitメモリブロックのサブ状態である「Enable」および「Disable」を表します。「Disable」のExplicitメモリブロックがある場合は,Explicitヒープあふれが発生しています。この例の場合は,「Enable」のExplicitメモリブロックが200個あり,「Disable」のExplicitメモリブロックはないことがわかります。なお,「Disable」のExplicitメモリブロックがある場合は,Explicitヒープ最大サイズとの関係を確認してください。Explicitヒープ最大サイズまでに余裕があるときには,OSからのメモリ確保に失敗していることが考えられます。

また,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定した場合,Explicitメモリブロックのサブ状態が「Disable」になった要因も出力されます。

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[alloc failed(Disable)][EH: 32760K(0K)/32768K/65536K][E/F/D: 321/0/1][cause:GC]¥
["BasicExplicitMemory-3" eid=3/B: 128K(0K)/128K][Thread: 0x00035a60]
[EVO][Thread: 0x00035a60] at ExplicitMemory.newInstance0(Native Method)
[EVO][Thread: 0x00035a60] at BasicExplicitMemory.newInstance(Unknown Source)
[EVO][Thread: 0x00035a60] at AllocTest.test(AllocTest.java:64)
[EVO][Thread: 0x00035a60] at java.lang.Thread.run(Thread.java:2312)

この例は,Explicitヒープあふれが発生した場合の例です。

太字で示した部分のうち,[alloc failed(Disable)]が,Explicitメモリブロックのサブ状態が「Disable」になった要因を示します。["BasicExplicitMemory-3" eid=3/B: 128K(0K)/128K]は,「Disable」になったExplicitメモリブロックの情報を示します。また,[EVO][Thread: 0x00035a60]で始まる行は,イベントが発生した時のスタックトレースを表しています。ただし,ガーベージコレクションによるオブジェクトの移動でExplicitヒープあふれが発生した場合,スタックトレースは出力されません。

(b) スレッドダンプで出力されたログファイルからの調査

cjdumpsvコマンドなどを使用してスレッドダンプを出力することによって,各Explicitメモリブロックのサブ状態を出力できます。

出力例を次に示します。

Explicit Heap Status
--------------------
max 65536K, total 21888K, used 20992K, garbage 1288K (32.0% used/max, 95.9% used/total, 6.1% garbage/used), 2 spaces exist

Explicit Memories(0x12345678)

 "EJBMgrData" eid=1(0x02f25610)/R, total 21376K, used 20480K, garbage 1234K (95.8% used/total, 6.0% garbage/used, 0 blocks) Enable

 "ExplicitMemory-4" eid=4(0x02f45800)/B, total 512K, used 512K, garbage 54K (100.0% used/total, 10.5% garbage/used, 0 blocks) Disable

太字で示した部分が,それぞれのExplicitメモリブロックのサブ状態を表しています。

(c) JavaのAPIからの調査

次に示すメソッドを使用して,Explicitメモリブロックのサブ状態を調査できます。

これらのメソッド両方の戻り値がfalseの場合,そのExplicitメモリブロックのサブ状態はDisableと判断できます。

(4) Explicitメモリブロックの初期化が失敗した場合の確認と対処

Explicitメモリブロックの初期化が失敗した場合の確認と対処について説明します。

Explicitメモリブロックの数が最大になると,それ以上Explicitメモリブロックを初期化できなくなります。

この場合は,Explicitメモリブロックの数を減らしてください。

ここでは,Explicitメモリブロックの初期化が失敗しているかどうかの確認方法について説明します。

(a) 明示管理ヒープ機能イベントログからの調査

明示管理ヒープ機能イベントログで調査をするためには,あらかじめJavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「normal」を指定しておく必要があります。これによって,ガーベージコレクションが発生するごとに,Explicitメモリブロックの初期化に失敗した回数が明示管理ヒープ機能イベントログに出力されるようになります

出力例を示します。

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

太字で示した部分が,前回の出力から今回の出力までの間にExplicitメモリブロックの初期化に失敗した回数です。この例の場合は,「0」です。初期化失敗が発生していない,問題のない状態です。

また,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定した場合,Explicitメモリブロックの初期化失敗イベントについての情報も出力されます。

出力例を示します。

[EVO]<Tue Jul 24 01:23:51 2007>[Creation failed][EH: 32760K(0K)/32768K/65536K][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)

太字で示した部分で,Explicitメモリブロック初期化に失敗したことが確認できます。また,[EVO][Thread: 0x00035a60]で始まる行は,イベントが発生した時のスタックトレースを示しています。

さらに,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「debug」を指定した場合,初期化に失敗したイベント以外のExplicitメモリブロック初期化イベントの詳細情報が出力されます。Explicitメモリブロック数が一定以上になると,初期化は失敗します。このため,初期化に失敗する前の初期化イベントの情報が,調査に役立つことがあります。

出力例を次に示します。

[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)
[EVO][Thread: 0x00035a60] at java.lang.Thread.run(Thread.java:2312)

太字で示した部分で,Explicitメモリブロック初期化イベントであることが確認できます。また,[EDO][Thread: 0x00035a60]で始まる行は,イベントが発生した時のスタックトレースを示しています。

(b) スレッドダンプで出力されたログファイルからの調査

スレッドダンプで出力された情報からは,Explicitメモリブロック初期化失敗の直接要因は確認できませんが,Explicitメモリブロックの個数は調べられます。

出力例を次に示します。

Explicit Heap Status
--------------------
max 65536K, total 21888K, used 20992K, garbage 1288K (32.0% used/max, 95.9% used/total, 6.1% garbage/used), 2 spaces exist

Explicit Memories(0x12345678)

 "EJBMgrData" eid=1(0x02f25610)/R, total 21376K, used 20480K, garbage 1234K (95.8% used/total, 6.0% garbage/used, 0 blocks) Enable

 "ExplicitMemory-4" eid=4(0x02f45800)/B, total 512K, used 512K, garbage 54K (100.0% used/total, 10.5% garbage/used, 0 blocks) Disable

太字で示した部分がExplicitメモリブロックの個数を示しています。

(c) JavaのAPIからの調査

次に示すメソッドを使用して,Explicitメモリブロックの個数を調査できます。

ただし,このAPIでは,Explicitメモリブロック初期化失敗の直接の要因は確認できません。

(5) Explicitメモリブロック解放処理時にJavaヒープへのオブジェクト移動が発生した場合の確認と対処

Explicitメモリブロックの解放処理時に,解放対象のExplicitヒープ内のオブジェクトに対する参照があると,参照されているオブジェクトおよびそのオブジェクトから直接または間接的に参照されているオブジェクトがJavaヒープに移動します。オブジェクトは,Tenured領域に優先的に移動されます。このため,移動が多いとTenured領域の利用済みサイズが増加して,フルガーベージコレクション発生の要因となってしまいます。

Javaヒープへの移動が発生したかどうかは,日立JavaVMログファイルの拡張verbosegc情報または明示管理ヒープイベントログで調査できます。

(a) 拡張verbosegc情報を使用した確認

明示管理ヒープ機能を利用しない場合,Tenured領域の利用済みサイズの増加は,コピーガーベージコレクションだけで発生します。このため,N回目のコピーガーベージコレクション終了後のTenured領域利用済みサイズは,N+1回目のコピーガーベージコレクション開始前のTenured領域利用済みサイズと一致します。

これに対して,ExplicitヒープからJavaヒープへのオブジェクトの移動が発生した場合は,Explicitヒープ解放時にTenured領域の利用済みサイズが増加します。この差分から,Explicitメモリブロック解放処理時にオブジェクトの移動が発生したことが確認できます。

N回目のコピーガーベージコレクション終了後のExplicitメモリブロック解放処理時にJavaヒープに移動したオブジェクトのサイズは,次の式で算出できます。

ExplicitヒープからJavaヒープに移動したオブジェクトのサイズ
=N+1回目のCopy GC前のTenured領域利用済みサイズ
-N回目のCopy GC後のTenured領域利用済みサイズ

(b) 明示管理ヒープのイベントログを使用した確認

JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「none」以外を指定した場合,Explicitメモリブロックの解放処理についてのログが出力されます。このログでは,Explicitメモリブロック解放処理時のTenured領域利用済みサイズの増加を直接確認できます。

出力例を次に示します。

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 12800K->11776K(11776K/65536K), 0.1129602 secs][E/F/D: 523/0/0]¥
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103464K(556800K)][cause:Reclaim]

太字で示した部分のうち,[cause:Reclaim]は,Explicitメモリブロック解放処理時に出力された情報であることを示します。また,[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103464K(556800K)]の部分は,Explicitメモリブロック解放処理時のJavaヒープの変化を示しています。この例の場合は,Tenured領域のメモリサイズが103,400キロバイトから103,464キロバイトに,64キロバイト分増えています。このことから,Explicitメモリブロックの解放処理で,64キロバイトのオブジェクトがJavaヒープに移動していることがわかります。

また,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「verbose」を指定した場合,解放されたExplicitメモリブロックについての情報も出力されます。これによって,どのExplicitメモリブロックの解放でTenured領域利用済みサイズが増加したかを確認できます。

出力例を次に示します。

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 12800K->11776K(11776K/65536K), 0.1129602 secs][E/F/D: 523/0/0]¥
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103464K(556800K)][cause:Reclaim]
[EVS]["REM2" eid=2/R: 320K]["BEM3" eid=5/B: 320K]["BEM1" eid=7/B: 384K]

太字で示した部分が,解放されたExplicitメモリブロックを示しています。出力内容から,Javaヒープに移動した64キロバイトのオブジェクトが,「REM2」「BEM3」「BEM1」のどれかのExplicitメモリブロックから移動したことがわかります。

さらに,JavaVMの-XX:HitachiExplicitMemoryLogLevelオプションに「debug」を指定した場合,解放処理をしたときに解放対象Explicitヒープ内のオブジェクトを参照していたオブジェクトが確認できます。

出力例を次に示します。

[EDO][eid=3: Reference to ClassZ(0x1234680), total 64K]
[EDO]   ClassU(0x1233468)(Tenured)

[eid=3: Reference to ClassZ(0x1234680), total 64K]の部分から,次のことがわかります。

また,「ClassU(0x1233468)(Tenured)」の部分から,"ClassZ"のインスタンスを参照しているオブジェクトが"ClassU"のインスタンスであることがわかります。

これらの情報を基に,Explicitメモリブロック解放処理時にそのExplicitメモリブロック内のオブジェクトへの参照をなくすように,Javaプログラムを修正してください。