新しくなったG1ガベージコレクタがすばらしい

1年近く前にG1ガベージコレクタに対して軽く検証を行った。

• http://d.hatena.ne.jp/shin/20090216/p2
• http://d.hatena.ne.jp/shin/20090608/p1
• http://d.hatena.ne.jp/shin/20090609/p1

そのときの結論としては、このままの方向ならばバグかなくなったり多少パフォーマンスがよくなった程度ではコンカレントGCから乗り換える必要は無いというものだった。

で、VMのバージョンが上がりG1GCもまだ完全版ではないが、バージョンアップした。これは試すしかないだろう。

先に結論を言うと世代別＆コンカレントGCの時代は終わったかなというとこまできた。Java SE 7では標準搭載される見込みなのでそのころはかなり使いやすくなっているはず。sun以外のVMも追従しないとsunに対して大きく劣ってしまうレベル。

以下いつものようにShinGL3サンプルであるPureWindの2面開始までのログ。ヒープメモリがコンカレントGC時代のチューニングになってるので新世代のGCがまにあわずFullGCが発生しているがそこは気にしないでおいてほしい。

オプションは以下のようになっている。

• verbose:gc -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxTenuringThreshold=1 -XX:MaxGCPauseMillis=1 -Xms32M -Xmx32M -noclassgc

update15のログ

init:
Deleting: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
deps-jar:
Updating property file: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
ShinGL3.init:
ShinGL3.deps-jar:
ShinGL3.compile:
ShinGL3.jar:
compile:
run:
[GC pause (young) 1024K->484K(32M), 0.0029240 secs]
[GC pause (young) 1463K->794K(32M), 0.0033599 secs]
[GC pause (young) 1813K->1023K(32M), 0.0018307 secs]
[GC pause (young) 1934K->1056K(32M), 0.0028940 secs]
ジョイスティックが見つかりました。
カーソルを非表示にします。
初期化開始
[GC pause (young) 4126K->1675K(32M), 0.0024391 secs]
[GC pause (young) 4747K->2471K(32M), 0.0014431 secs]
LOAD SE:se/powerup.wav
LOAD SE:se/bom.wav
LOAD SE:se/bom2.wav
LOAD SE:se/bom3.wav
LOAD SE:se/shot.wav
LOAD SE:se/bossshot.wav
LOAD SE:se/bonus.wav
LOAD SE:se/subweapon.wav
LOAD SE:se/laser.wav
LOAD SE:se/homing.wav
LOAD SE:se/1up.wav
LOAD SE:se/edamage.wav
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
BGM PLAY:Buffer=88200
[Full GC 31M->2771K(32M), 0.0383239 secs]
[GC pause (young) 3795K->2803K(32M), 0.0042807 secs]
audioデータ読込準備完了
[Full GC 30M->2438K(32M), 0.0392257 secs]
[GC pause (young) 3462K->2462K(32M), 0.0041798 secs]
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
BGM PLAY:Buffer=88200
audioデータ読込準備完了
[GC pause (young) 25M->3832K(32M), 0.0014071 secs]
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
audioデータ読込準備完了
BGM PLAY:Buffer=88200
構築成功 (合計時間: 2 分 37 秒)

update18のログ

init:
Deleting: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
deps-jar:
Updating property file: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
ShinGL3.init:
ShinGL3.deps-jar:
ShinGL3.compile:
ShinGL3.jar:
compile:
run:
[GC pause (young) 1024K->501K(32M), 0.0029571 secs]
[GC pause (young) 1525K->889K(32M), 0.0035438 secs]
[GC pause (young) 1912K->1048K(32M), 0.0017046 secs]
[GC pause (young) 2072K->1072K(32M), 0.0184528 secs]
ジョイスティックが見つかりました。
カーソルを非表示にします。
初期化開始
[GC pause (young) 6725K->2148K(32M), 0.0027776 secs]
LOAD SE:se/powerup.wav
LOAD SE:se/bom.wav
LOAD SE:se/bom2.wav
LOAD SE:se/bom3.wav
LOAD SE:se/shot.wav
LOAD SE:se/bossshot.wav
LOAD SE:se/bonus.wav
LOAD SE:se/subweapon.wav
LOAD SE:se/laser.wav
LOAD SE:se/homing.wav
LOAD SE:se/1up.wav
LOAD SE:se/edamage.wav
STOP
PLAY
[GC pause (young) 10163K->3168K(32M), 0.0021135 secs]
audioデータ読込準備完了
ラインの準備・・・完了
BGM PLAY:Buffer=88200
[GC pause (young) 9309K->4532K(32M), 0.0021675 secs]
[GC pause (young) 9638K->4548K(32M), 0.0008708 secs]
[GC pause (young) 8633K->4580K(32M), 0.0008081 secs]
[GC pause (young) 7644K->4596K(32M), 0.0008624 secs]
[GC pause (young) 7658K->4620K(32M), 0.0008526 secs]
[GC pause (young) 6667K->4653K(32M), 0.0008079 secs]
[GC pause (young) 6694K->4669K(32M), 0.0007853 secs]
[GC pause (young) 6710K->4701K(32M), 0.0008669 secs]
[GC pause (young) 6743K->4725K(32M), 0.0008444 secs]
[GC pause (young) 5749K->4741K(32M), 0.0007894 secs]
[GC pause (young) 5765K->4773K(32M), 0.0007818 secs]
[GC pause (young) 5797K->4789K(32M), 0.0008454 secs]
[GC pause (young) 5811K->4937K(32M), 0.0008811 secs]
[GC pause (young) 5939K->5789K(32M), 0.0009412 secs]
audioデータ読込準備完了
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
BGM PLAY:Buffer=88200
[Full GC 31M->3382K(32M), 0.0385741 secs]
[GC pause (young) 4405K->3703K(32M), 0.0046351 secs]
audioデータ読込準備完了
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
audioデータ読込準備完了
BGM PLAY:Buffer=88200
構築成功 (合計時間: 2 分 20 秒)

見てわかるとおり1msいかに抑えろ！という時間指定が今回は効いている。絶対的な数値として効いているというところまではいってないが、ほぼ1ms以内で終わっておりこれなら十分許容範囲内だ。

上でメモリが足りていないのがわかったので今度はヒープを48MBまで増やしてみる。

init:
Deleting: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
deps-jar:
Updating property file: C:\_product\pw\old\program\20070922\PureWind\build\built-jar.properties
ShinGL3.init:
ShinGL3.deps-jar:
ShinGL3.compile:
ShinGL3.jar:
compile:
run:
[GC pause (young) 1024K->509K(48M), 0.0029256 secs]
[GC pause (young) 1521K->814K(48M), 0.0033873 secs]
[GC pause (young) 1838K->1040K(48M), 0.0018664 secs]
[GC pause (young) 2064K->1064K(48M), 0.0007635 secs]
ジョイスティックが見つかりました。
カーソルを非表示にします。
初期化開始
[GC pause (young) 7915K->2255K(48M), 0.0027752 secs]
LOAD SE:se/powerup.wav
LOAD SE:se/bom.wav
LOAD SE:se/bom2.wav
LOAD SE:se/bom3.wav
LOAD SE:se/shot.wav
LOAD SE:se/bossshot.wav
LOAD SE:se/bonus.wav
LOAD SE:se/subweapon.wav
LOAD SE:se/laser.wav
LOAD SE:se/homing.wav
LOAD SE:se/1up.wav
LOAD SE:se/edamage.wav
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
[GC pause (young) 10M->4122K(48M), 0.0036970 secs]
BGM PLAY:Buffer=88200
[GC pause (young) 11M->4348K(48M), 0.0021713 secs]
[GC pause (young) 9443K->4292K(48M), 0.0013486 secs]
[GC pause (young) 8375K->4316K(48M), 0.0007999 secs]
[GC pause (young) 8408K->4348K(48M), 0.0011972 secs]
[GC pause (young) 7420K->4364K(48M), 0.0011964 secs]
[GC pause (young) 6412K->4396K(48M), 0.0010879 secs]
[GC pause (young) 6444K->4420K(48M), 0.0011016 secs]
[GC pause (young) 6468K->4436K(48M), 0.0012162 secs]
[GC pause (young) 6478K->4460K(48M), 0.0010656 secs]
[GC pause (young) 5484K->4492K(48M), 0.0011752 secs]
[GC pause (young) 5511K->4544K(48M), 0.0012754 secs]
[GC pause (young) 5568K->5464K(48M), 0.0014038 secs]
audioデータ読込準備完了
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
BGM PLAY:Buffer=88200
audioデータ読込準備完了
[GC pause (young) 36M->7254K(48M), 0.0036221 secs]
STOP
PLAY
audioデータ読込準備完了
ラインの準備・・・完了
audioデータ読込準備完了
BGM PLAY:Buffer=88200
構築成功 (合計時間: 2 分 18 秒)

36MからのGCが動いているのが見える。やはり停止時間1mで32Mでは足りなかったらしい。しかもこの最悪の値で3.6msだ。十分ではないか。やや全体的にGC時間は増えているものの十分許容範囲。

これなら前回と違いチューニングしてちゃんと動かせるというところまで持っていけそうな気がする。

というわけでチューニングした結果、停止時間10ms指定（指定なしでもいいかも）ヒープ28MBでFullGCが無くなった。どうも旧世代の停止時間指定にコンカレント部分も含んでしまっているようであまりにも短いと間に合わなくてFullGCが走っているようだ。

以前は指定時間なしだとGCはできるだけやってしまい、新世代でも停止時間が長かったのに対して、update18はGC回数が増えてでもレスポンス重視になっていると考えるといいかもしれない。あいかわらずFullGCは従来の世代別GCに比べて大幅に早い。

あとは安定さえすればクライアントサイド、サーバーサイドでもG1GCがデフォになって大丈夫っぽい。そしてヒープ容量以外のチューニングはほぼしなくてもいい感じで。

G1GCの評価がぐんぐん上昇中。