まじめにJVMチューニング: 第2回 GCログをみる

きほんのきです。
まずはログを見ます。
GCログを出すようにしていない場合は、GCログを出すようにします。

-Xloggc:/var/log/gc.log  # 出力先パス
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps

の３つのパラメータを指定してjavaを起動します。

java -XmsXXXXM -XmxXXXXM -Xloggc:/var/log/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -classpath <クラスパスとか> <プラグラム> <引数>

このようにして実行しGCログを採取します。
(上記の例では/var/log/gc.log)
で、開いてみると、こんな感じの文字列がつらつらと並んでいます。
※私の環境では、GCアルゴリズムをコンカレントGCとしています。

2014-01-23T11:20:28.044+0900: 3.310: [GC [PSYoungGen: 333353K->2202K(382976K)] 333361K->2218K(1256960K), 0.0063750 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2014-01-23T11:20:28.145+0900: 0.867: [Full GC (System) 0.867: [CMS: 0K->1604K(9437184K), 0.1579170 secs] 157287K->1604K(14024704K), [CMS Perm : 11261K->11251K(131072K)], 0.1580240 secs] [Times: user=0.10 sys=0.09, real=0.16 secs]
2014-01-23T11:20:28.334+0900: 3.599: [GC [PSYoungGen: 330906K->2880K(382976K)] 330922K->2904K(1256960K), 0.0117440 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

とか

2014-01-23T11:20:38.173+0900: 348.895: [GC [1 CMS-initial-mark: 475981K(943718K)] 553518K(1402470K), 0.9860010 secs] [Times: user=0.96 sys=0.01, real=0.99 secs]
2014-01-23T11:49:39.159+0900: 349.882: [CMS-concurrent-mark-start]
2014-01-23T11:49:40.060+0900: 350.782: [CMS-concurrent-mark: 0.900/0.900 secs] [Times: user=6.27 sys=0.72, real=0.90 secs]
2014-01-23T11:49:40.060+0900: 350.782: [CMS-concurrent-preclean-start]
2014-01-23T11:49:40.098+0900: 350.820: [CMS-concurrent-preclean: 0.037/0.038 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]
2014-01-23T11:49:40.098+0900: 350.820: [CMS-concurrent-abortable-preclean-start]
2014-01-23T11:49:45.252+0900: 355.974: [GC 355.974: [ParNew: 458752K->65536K(458752K), 0.3937000 secs] 934733K->557416K(1402470K), 0.3939170 secs] [Times: user=2.88 sys=0.04, real=0.39 secs] CMS: abort preclean due to time 2014-01-23T11:49:45.965+0900: 356.687: [CMS-concurrent-abortable-preclean: 5.467/5.867 secs] [Times: user=22.39 sys=2.98, real=5.86 secs]
2014-01-23T11:49:45.966+0900: 356.688: [GC[YG occupancy: 100010 K (458752 K)]356.688: [Rescan (parallel) , 0.1240610 secs]356.812: [weak refs processing, 0.0002340 secs] [1 CMS-remark: 491880K(943718K)] 591891K(1402470K), 0.1245440 secs] [Times: user=1.06 sys=0.00, real=0.13 secs]
2014-01-23T11:49:46.091+0900: 356.813: [CMS-concurrent-sweep-start]
2014-01-23T11:49:52.248+0900: 362.970: [GC 362.970: [ParNew: 458752K->65536K(458752K), 0.3734610 secs] 644668K->269036K(1402470K), 0.3737130 secs] [Times: user=2.77 sys=0.01, real=0.37 secs]
2014-01-23T11:49:55.057+0900: 365.779: [CMS-concurrent-sweep: 8.577/8.965 secs] [Times: user=34.33 sys=4.74, real=8.96 secs]
2014-01-23T11:49:55.057+0900: 365.779: [CMS-concurrent-reset-start]
2014-01-23T11:49:55.078+0900: 365.800: [CMS-concurrent-reset: 0.021/0.021 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]とかを見ると、GCっぽいことが行われていることがわかります。

とかを見ると、GCっぽいことが行われていることがわかります。
が、このファイルだけからメモリの使われ方を追うのはつらいので、グラフ化します。

GCViewerという便利なツールがあるので、これを使います。

このツールをダウンロードして、
出力したGCログファイルを読み込みます。
すると、下記のようなグラフが表示されます。

フルGCが発生している様子を確認できます。
しかし、フルGCではなくコンカレントGCの箇所においても使用中Old領域のサイズが減少していることが見て取れます。

更に、GCの様子をモニタリングしてみます。

JDKをインストールするとjstatやjps等のjvm監視ツール等も一緒にインストールされます。
これらを使ってGCが行われる様子をモニタリングします。
※JREには付属していません。JDKが必要です。

まず、jpsを使って監視したいjvmプロセスのidを取得します。

$ jps -l
2019 sun.tools.jps.Jps
1950 com.inkenkun.x1.App

jps -lと打つと上記のようにプロセスidとメインクラスのフルパッケージ名が出力されます。
※詳しいオプションは上記のURLに掲載されています。

1950 com.inkenkun.x1.Appを監視してみます。
jstatに-gccauseオプションをつけて実行し、GCの統計データとGC理由を出力します。

jstat <オプション> <プロセスid> <モニタリング間隔ms> <回数>

$ jstat -gccause -t 1950 100
Timestamp         S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
	         3906.7   0.00  50.00  40.28   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3906.9   0.00  50.00  42.29   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.0   0.00  50.00  42.29   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.1   0.00  50.00  44.31   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.2   0.00  50.00  46.32   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.3   0.00  50.00  48.33   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.4   0.00  50.00  50.35   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.5   0.00  50.00  50.35   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.6   0.00  50.00  52.36   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC
	         3907.7   0.00  50.00  54.38   1.96   3.59    607   15.757     1    0.000   15.757 unknown GCCause      No GC

列	説明
S0	Survivor領域0の使用率(現在の容量に対するパーセンテージ)
S1	Survivor領域1の使用率(現在の容量に対するパーセンテージ)
E	Eden領域の使用率(現在の容量に対するパーセンテージ)
O	Old領域の使用率(現在の容量に対するパーセンテージ)
P	Permanent領域の使用率(現在の容量に対するパーセンテージ)
YGC	若い世代のGCイベント数
YGCT	若い世代のガベージコレクション時間
FGC	フルGCイベント数
FGCT	フルガベージコレクション時間
GCT	ガベージコレクション総時間

jstatに他のパラメータ及び詳細な説明がのっています。

上記は、プロセスid1950に対して100ms間隔でモニタリングを行っています。
マイナーGCが607回(YGC列)発生、フルGCは1回発生していることがわかります。
コンカレントGCはマイナーGCとして扱われるんですねー。

私は当初、jstatでのモニタリングしたフルGCのタイミングと、GCViewerでみた使用中Old領域の減少タイミングが合わないことで、どちらかにバグがあるのではないかと思っていました。

しかし、コンカレントGCは
フルGCと変わらない負荷/処理時間を伴うOld世代のメジャーGCだったんですΣ(￣□￣; )
詳しくはこちらのブログに、、、

http://wall-climb.com/2009/10/12/%E3%82%B3%E3%83%B3%E3%82%AB%E3%83%AC%E3%83%B3%E3%83%88gc%E3%81%AE%E6%B3%A8%E6%84%8F%E7%82%B9/

GCアルゴリズムをコンカレントGCとしている場合、対策を講ずるべきは主にコンカレントGCの発生です。
「フルGC」としてキロクされるフルGCは予想以上に少ないです。

次回、実際にパラメータを変更してGC対策を行います。

方針たててパラメータいじってみるへ

こちらの動画で詳しいチューニングのやり方も解説しています。

VisualVMでjavaプロセスを可視化してみよう part1