GCをみる

Java Performance

GCの動きを見たいときは -Xloggc: や -XX:+PrintGCDetails をつけて、GCViewer で見ていた。
これは時系列でのGCの動きや、メモリの推移を知るには便利だけど、細かい動きについては解り辛い。概要を知るには便利だけど、細かく知りたい時は不便という感じ。
# 使いこなせていないだけかもしれないけど。

GCが起きるメモリリークプログラムをさくっと書いてみる。

import java.util.List;
import java.util.ArrayList;

public class GCTest {
	public static void main(String[] args){
		List<String> list = new ArrayList<String>();
		
		for(;;){
			String str = new String("hoge");
			list.add(str);
		}
	}
}

こいつを以下のオプションをつけて実行する。

-Xloggc:<file>
-XX:+PrintGCDetails

実行すると、OutOfMemoryErrorが起きる。

> java -Xloggc:gc.log -XX:+PrintGCDetails GCTest
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

こんな感じのログがでてくる。

1.831: [GC 1.831: [DefNew: 4096K->4096K(4544K), 0.0000118 secs]1.831: [Tenured: 56595K->60544K(60544K), 0.2608705 secs] 60691K->60689K(65088K), 0.2610212 secs]
2.097: [Full GC 2.097: [Tenured: 60544K->60544K(60544K), 0.2638188 secs] 62056K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2639318 secs]
2.361: [Full GC 2.361: [Tenured: 60544K->60544K(60544K), 0.2532709 secs] 61982K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2533446 secs]

最後のほうで、FullGCが走っている。でもメモリ領域は全然開放されていない。


メモリリークを確認するだけなら、上記のログで問題ないかもしれない。
でもメモリチューニングをするには、ちょっと足りない。
全体のサイズ、NewとOldのサイズ、EdenとSurvivorの比率なんかを決めなきゃいけないけど、さっぱりわからない。


というわけで、いろいろオプションを追加してみる。

-Xloggc:/tmp/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+TraceGen0Time
-XX:+TraceGen1Time

だんだんコマンドが長くなる。

> java -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+TraceGen0Time -XX:+TraceGen1Time GCTest
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
[Accumulated GC generation 0 time 0.4289908 secs, 39 GC's, avg GC time 0.0109998]
[Accumulated GC generation 1 time 2.0735346 secs, 14 GC's, avg GC time 0.1481096]

でてくるログはこれ。

2.000: [GC {Heap before gc invocations=38:
 def new generation   total 4544K, used 4096K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K, 100% used [0x22bd0000, 0x22fd0000, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 56595K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K,  93% used [0x230b0000, 0x267f4c58, 0x267f4e00, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.001: [DefNew: 4096K->4096K(4544K), 0.0000103 secs]2.001: [Tenured: 56595K->60544K(60544K), 0.2871982 secs] 60691K->60689K(65088K)Heap after gc invocations=39:
 def new generation   total 4544K, used 145K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,   3% used [0x22bd0000, 0x22bf4660, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2874919 secs]
2.292: [Full GC {Heap before gc invocations=39:
 def new generation   total 4544K, used 1512K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  36% used [0x22bd0000, 0x22d4a0f8, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.293: [Tenured: 60544K->60544K(60544K), 0.2792200 secs] 62056K->61982K(65088K), [Perm : 262K->262K(8192K)]Heap after gc invocations=40:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2795012 secs]
2.572: [Full GC {Heap before gc invocations=40:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.572: [Tenured: 60544K->60544K(60544K), 0.2868222 secs] 61982K->61982K(65088K), [Perm : 262K->262K(8192K)]Heap after gc invocations=41:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2870730 secs]

最初のログと同様、最後の3回のGCログ。大量発生。
でもこれすごく便利。
GC前後のメモリ領域がわかる。
各領域の使用量がわかる。
Permanent領域の使用量がわかる。
最初に追加したログ出力オプションと比較しても、オーバヘッドがあまりないような気がする。
これだけわかれば、チューニングもしやすい。
このログを tail -f で見てると、眠くなるけどなんとなく問題がわかってくる。
これだと、FullGCが起きてもメモリ領域が開放されていない。
オブジェクトの開放漏れがあったり、Heapが小さすぎるのかもしれない。あるいはNew領域が小さくてScavenge GCがすぐに発生してしまい、Old領域を圧迫しているかもしれない。
# このサンプルプログラムだと開放漏れだけど。


GCViewerでGCの発生状況を確認して、ポイントを絞ってオプションを追加して詳細を調べる。
これはなかなかいい感じ。


恥ずかしながら、今回初めてしった事実。-Xloggc: と -verbose:gc で出てくるログって、同じものだったんだ･･･。後者のほうが、詳細なのかと思ってた･･･。

参考

ガベージコレクタをビジュアライズ GCViewer - メモリリーク発見にも
@IT - Webアプリの問題点を「見える化」する7つ道具
@IT - チューニングのためのJavaVM講座（前編）
@IT - Javaのヒープ・メモリ管理の仕組み
SMG - -verbose:gcで出力される情報がたりません。
SMG - HPROFによるJavaプロファイリング


＜追記＞
最近ではこの本がでて、解析の仕方やツールの使い方ががっつり書いてあっていい感じ。

現場で使えるデバッグ & トラブルシュート Java編
現場で使えるデバッグ & トラブルシュート Java編
posted with amazlet at 10.06.16
小堀 一雄 茂呂 範 佐藤 聖規 石垣 一 飯山 教史
翔泳社
売り上げランキング: 40179
Amazon.co.jp で詳細を見る