Norikra等JavaアプリケーションのGCをチューニングしたい #Java

Javaアプリケーションを運用していると必ず突き当たるのがGCの問題である。JVMの上で生きている限りこの問題を避けて通ることはできない（し、この問題に手をつけたら終わりだとも聞いたことがある）。NorikraはJRubyで記述されているJavaアプリケーションであり、用途からして大量のオブジェクトを作って破棄していることが容易に想像できるので、GCのチューニングは重要であることが考えられる。

GCのログをとりたい

チューニングしたいのであれば、まずはともあれロギングである。ログなくしてチューニングすることなどできない。ということでまずはGCのログをとる。

$ norikra start -Xmx4g -Xms4g -Xloggc:/var/log/norikra/gc.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails

それぞれのオプションの意味は次のような感じだ。

オプション	説明
-XX:+PrintGCDetails	GCの詳細情報を出力する
-XX:+PrintGCDateStamps	GCの詳細情報にタイムスタンプをつける
-Xloggc:/var/log/norikra/gc.log	GCログを指定したファイルに出力する

これをつけて起動すると、/var/log/norikra/gc.logに以下のようなログが出力される。

...
2013-12-12T12:54:37.139+0900: 306.165: [GC [PSYoungGen: 1205561K->89489K(1264960K)] 3709635K->2662454K(4061184K), 0.3115900 secs] [Times: user=1.07 sys=0.03
, real=0.31 secs]
2013-12-12T12:54:47.003+0900: 316.029: [GC [PSYoungGen: 1217873K->84239K(1261504K)] 3790838K->2725665K(4057728K), 0.2903750 secs] [Times: user=0.90 sys=0.04
, real=0.29 secs]
2013-12-12T12:54:56.953+0900: 325.978: [GC [PSYoungGen: 1212623K->84559K(1273792K)] 3854049K->2792997K(4070016K), 0.3223320 secs] [Times: user=1.06 sys=0.05
, real=0.32 secs]
2013-12-12T12:55:08.919+0900: 337.945: [GC [PSYoungGen: 1229839K->91264K(1269568K)] 3938277K->2867002K(4065792K), 0.2895880 secs] [Times: user=0.89 sys=0.07
, real=0.29 secs]
2013-12-12T12:55:09.209+0900: 338.234: [Full GC [PSYoungGen: 91264K->0K(1269568K)] [ParOldGen: 2775737K->530186K(2796224K)] 2867002K->530186K(4065792K) [PSP
ermGen: 43813K->43796K(83968K)], 6.0499510 secs] [Times: user=20.62 sys=0.00, real=6.05 secs]
...

[GC [PSYoungGen ... ] ... ]はNEW世代のGCが行われたことを示している。NEW世代のGCはマイナーGCとも呼ばれ、比較的高速に実行される。最終行にある[Full GC ... ]は、OLD世代のMark-Sweep GCが行われたことを示している。Full GCはメジャーGCと呼ばれ、すべてのアプリケーションスレッドが停止する。ログによると6.05 secで、実に6秒間もアプリケーションが停止してしまっていたことがわかる。この現象はStop the Worldと呼ばれる。この間、アプリケーションは処理できなくなってしまうため、スループットが問題となるアプリケーションでは、これを防ぐことが重要になる。

コンカレントGCを有効にする

Full GCによるStop the Worldを防ぐには、メジャーGCにコンカレントGCを使う方法がある。コンカレントGCはアプリケーションスレッドと並列してGCを行うことにより、Full GCによるStop the Worldを起こしづらくする技術である。コンカレントGCについては以下の記事が詳しい。

追記:
Java7からはコンカレントGCの後継としてG1GCが搭載されている。まだ使ったことないが、メモリ容量が多い環境ではこちらの方がよいようだ。せっかく書いたのでコンカレントGCの記事も残しておく。

コンカレントGCを有効にするには次のオプションを指定しよう。

$ norikra start -Xmx4g -Xms4g -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=32 -Xloggc:/var/log/norikra/gc.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails

オプション	説明
-XX:+UseConcMarkSweepGC	コンカレントGCを有効にする
-XX:+CMSIncrementalMode	コンカレントGCをインクリメンタルモードにする

起動するとログが次のように変化した。

...
2013-12-12T15:21:57.419+0900: 10.752: [GC 10.752: [ParNew: 272640K->34047K(306688K), 0.1139700 secs] 272640K->36349K(4160256K), 0.1140630 secs] [Times: user
=0.37 sys=0.02, real=0.11 secs]
2013-12-12T15:22:32.387+0900: 45.720: [GC [1 CMS-initial-mark: 2301K(3853568K)] 159066K(4160256K), 0.1787990 secs] [Times: user=0.17 sys=0.00, real=0.18 sec
s]
2013-12-12T15:22:32.566+0900: 45.900: [CMS-concurrent-mark-start]
2013-12-12T15:22:32.697+0900: 46.030: [CMS-concurrent-mark: 0.130/0.130 secs] [Times: user=0.24 sys=0.01, real=0.13 secs]
2013-12-12T15:22:32.697+0900: 46.030: [CMS-concurrent-preclean-start]
2013-12-12T15:22:32.719+0900: 46.052: [CMS-concurrent-preclean: 0.022/0.022 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
2013-12-12T15:22:32.719+0900: 46.052: [CMS-concurrent-abortable-preclean-start]
2013-12-12T15:22:36.115+0900: 49.448: [GC 49.448: [ParNew: 306687K->34048K(306688K), 0.4398020 secs] 308989K->84286K(4160256K), 0.4399170 secs] [Times: user
=1.23 sys=0.04, real=0.44 secs]
2013-12-12T15:22:39.490+0900: 52.824: [GC 52.824: [ParNew: 306688K->34048K(306688K), 0.3301140 secs] 356926K->176870K(4160256K), 0.3302240 secs] [Times: use
r=1.07 sys=0.04, real=0.34 secs]
2013-12-12T15:22:40.966+0900: 54.299: [GC 54.299: [ParNew: 306688K->31815K(306688K), 0.1511760 secs] 449510K->208026K(4160256K), 0.1513180 secs] [Times: use
r=0.46 sys=0.02, real=0.15 secs]
 CMS: abort preclean due to time 2013-12-12T15:22:41.602+0900: 54.936: [CMS-concurrent-abortable-preclean: 1.285/8.883 secs] [Times: user=15.27 sys=0.53, re
al=8.89 secs]
2013-12-12T15:22:41.603+0900: 54.936: [GC[YG occupancy: 161361 K (306688 K)]54.936: [Rescan (parallel) , 0.2532580 secs]55.190: [weak refs processing, 0.0000100 secs]55.190: [scrub string table, 0.0016820 secs] [1 CMS-remark: 176211K(3853568K)] 337573K(4160256K), 0.2551140 secs] [Times: user=0.90 sys=0.00, real=0.25 secs]
2013-12-12T15:22:41.858+0900: 55.191: [CMS-concurrent-sweep-start]
2013-12-12T15:22:42.449+0900: 55.782: [GC 55.782: [ParNew: 304455K->34048K(306688K), 0.0976200 secs] 479041K->208668K(4160256K), 0.0977740 secs] [Times: user=0.31 sys=0.00, real=0.10 secs]
2013-12-12T15:22:43.069+0900: 56.402: [CMS-concurrent-sweep: 0.129/1.211 secs] [Times: user=1.87 sys=0.12, real=1.21 secs]
2013-12-12T15:22:43.069+0900: 56.403: [CMS-concurrent-reset-start]
2013-12-12T15:22:43.139+0900: 56.473: [CMS-concurrent-reset: 0.070/0.070 secs] [Times: user=0.12 sys=0.06, real=0.07 secs]
2013-12-12T15:22:43.646+0900: 56.979: [GC 56.979: [ParNew: 306688K->34048K(306688K), 0.1283140 secs] 481308K->224544K(4160256K) icms_dc=25 , 0.1284660 secs] [Times: user=0.38 sys=0.02, real=0.13 secs]
...

コンカレントGCが実行されるとCMSから始まるログが出力される。それぞれのフェーズは次の通りだ。

CMS-initial-mark --- rootになるobjectをマークする
CMS-concurrent-mark-start
CMS-concurrent-mark --- 並列マーキング終わり
CMS-concurrent-preclean-start
CMS-concurrent-preclean --- 事前クリーニング終わり
CMS-concurrent-abortable-preclean-start
CMS-concurrent-abortable-preclean
CMS-remark --- 並列マーキングしたものをもういちどマーキングする
CMS-concurrent-sweep-start
CMS-concurrent-sweep --- sweep処理終わり
CMS-concurrent-reset-start
CMS-concurrent-reset --- リセット終わり

このうちStop the Worldが発生するのはCMS-remarkのフェーズである。先ほどのFull GCに比べるとかなり短くなってるのがわかると思う。ちなみに、2コア以上あるマシンでは並列実行されている。これ以外の時間はアプリケーションスレッドと並列実行されている。しかし、アプリケーションスレッドと並列実行できているだけで、結局その時間スループットが落ちていることに注意しなければならない。結局のところメジャーGCの頻度を減らす努力が必要になることには変わりない。

各メモリ領域をチューニングする

JVMのGCはかなり柔軟にチューニングできる、プラットフォームによってデフォルト値が違ったりして難しい。ちゃんと理解できてるか怪しいが、図にすると次の様になっている。

オブジェクトが生成されるとEden領域に入る。Eden領域がいっぱいになるとGCが行われて、まだ使用中だったらSurvivor領域のTo領域に移動させられる。To領域とFrom領域はGCが行われるたびに交換される。Survivor領域にあるオブジェクトが、MaxTenuringThresholdの回数GCを生き延びた場合はOLD領域に移される。

これらは次のオプションで指定できる。

オプション	説明
-Xmx4g	ヒープメモリの最大値を指定する
-Xms4g	ヒープメモリの初期サイズを指定する
-XX:NewRatio=4	NEWとOLDの比率を指定する(NEW:OLD = 1:4)

次のオプションはJava5まではチューニングの必要があったが、Java6、Java7ではほとんどの場合デフォルトでも問題ない。

オプション	説明
-XX:SurvivorRatio=8	EdenとSurvivorの比率を指定する(Eden:Survivor = 1:8)
-XX:TargetSurvivorRatio=90	Survivorがいっぱいだと判断される比率 (90%以上使用するとOLDに移動される)

まとめ

JVMのチューニングは難しいし、できれば考えたくない。

チューニングを考えたくない人はAZUL Zingを使うという手段もある。