トップページ >  Oracle AS >  GCログの見かた
初版2007/03/23: 最終更新日2007/03/23
GCログの見かた
目次
GCログの見かた
compaction発生時のログ
GCログの見かた
JVMに引数を与えることによりGCのログを表示することが出来ます。
ログは、$ORACLE_HOME/opmn/logs/配下のJVMごとのファイルに出力されます。
ログは以下のように出力されます。

<AF[31]: Allocation Failure. need 8192 bytes, 431346 ms since last AF>
<AF[31]: managing allocation failure, action=1 (0/794771184) (10265048/10468112)>
  <GC(48): freeing class sun.reflect.GeneratedSerializationConstructorAccessor23(301cba68)>
  <GC(48): unloaded and freed 1 class>
  <GC(48): GC cycle started Thu Apr 19 11:15:23 2007
  <GC(48): freed 712889680 bytes, 89% free (723154728/805239296), in 176 ms>
  <GC(48): mark: 165 ms, sweep: 11 ms, compact: 0 ms>
  <GC(48): refs: soft 3 (age >= 32), weak 0, final 4562, phantom 0>
<AF[31]: completed in 176 ms>
最初の行は8192bytesのメモリ割り当てに失敗、前回のメモリ割り当て失敗から431346ms時間経過しています、という意味です。
AF[31]というのはJVM起動してから31回目のメモリ割り当て失敗を意味します。
このメモリ割り当て失敗によってGCが実行されます。GC(48)は、48回目のGCという意味です。

2行目は、メモリ割り当ての結果実行したアクションを数字の0~6で表示しています。
GC cycle~は、GCの開始時間になります。
その次の行で、freed ??? bytes~とありますが、これがGCによって確保した新規ヒープメモリで、その結果89%使用可能という意味です。
723154728を805239296で割ると89となるはずです。端数は切り捨てのようです。このGCに176ms掛かっています。

markは使用中のオブジェクトを調査するのに掛かった時間が表示されます。
この処理で、使用されていないと判断されたオブジェクトがチェックされます。
sweepは使用済みのオブジェクトを削除するのに掛かった時間が表示されます。
この処理で、使用されていないと判断されているオブジェクトが削除されます。
compactはjava heapの空き領域の整理を行うのに掛かった時間が表示されます。
但し、JVMは、空き領域の整理には時間がかかるため、通常行われません。

refsの行はよくわかりませんが、GC中に確認されたオブジェクトの個数を表しているようです。

compaction発生時のログ
GC時にcompactionが発生した場合、ログに以下のような1行が表示されます。

<GC(105): moved 422899 objects, 20684680 bytes, reason=4, used 328 more bytes>
compaction実行時に422899このオブジェクトを移動し、328bytes空き領域が増えたことを意味します。
reasonは1~15まであります。詳しくはわかりません。