いよいよおまちかね！GF決勝大会レディーゴ(ry
GFは世界の覇権をかけたガベージコレクト・ファイトの略だろJK
…少しGガンダムに毒されてしまったようだ…
ガベージコレクションの性能を検証したのをあげたのはJ2SE 5.0が出た直後あたりが最後だったっけ。もう5年近く前か。
http://shin.cside.com/diary/2004/10.htm#1
JavaSE 6 update14にてG1ガベージコレクタが入ったようなのでこれを試してみる。
ベンチに使うのはいつもどおりの自作STG。
GCのログも全部掲載してるので長文です。
インクリメンタルガベージコレクタ
まず一番最適化してるインクリメンタルGCでの設定。なおインクリメンタルGCは5.0のときに実装がまるごとコンカレントGCにさしかえられているのでコンカレントGCを使っているという認識でOK。単に長いオプション名を暗記していないというのもある。インクリメンタルGCはXXオプションではなくXオプションなため、長く有効になっていてOSに依存しにくいオプションだと思う。アルゴリズムは何であれ、スループットより安定したレスポンス重視と思ってよい。具体的にはFullGCが消える。
起動オプション
-Xconcgc -XX:MaxTenuringThreshold=1 -XX:+UseParNewGC -Xms28M -Xmx28M -XX:NewSize=5M -XX:MaxNewSize=5M -XX:SurvivorRatio=2 -noclassgc
GCログ
run: [GC 2560K->1059K(27392K), 0.0082459 secs] ジョイスティックが見つかりました。 カーソルを非表示にします。 [GC 3597K->1554K(27392K), 0.0050647 secs] 初期化開始 [GC 4114K->1590K(27392K), 0.0017130 secs] [GC 4150K->1650K(27392K), 0.0010417 secs] [GC 4210K->1573K(27392K), 0.0004809 secs] [Full GC 2138K->1285K(27392K), 0.0378251 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 3832K->1725K(27392K), 0.0008966 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 4277K->2765K(27392K), 0.0009735 secs] BGM PLAY:Buffer=88200 [GC 5320K->3342K(27392K), 0.0011791 secs] [GC 5902K->3258K(27392K), 0.0004956 secs] [GC 5818K->2974K(27392K), 0.0002784 secs] [GC 5534K->2824K(27392K), 0.0003005 secs] [GC 5379K->2776K(27392K), 0.0002375 secs] [GC 5336K->2776K(27392K), 0.0002350 secs] [GC 5336K->2776K(27392K), 0.0003177 secs] [GC 5334K->2766K(27392K), 0.0002365 secs] [GC 5326K->2774K(27392K), 0.0002253 secs] [GC 5334K->2778K(27392K), 0.0002263 secs] [GC 5332K->2767K(27392K), 0.0002248 secs] [GC 5324K->2768K(27392K), 0.0002194 secs] [GC 5328K->2888K(27392K), 0.0002803 secs] audioデータ読込準備完了 [GC 5448K->3983K(27392K), 0.0007186 secs] [GC 6543K->4063K(27392K), 0.0010576 secs] [GC 6623K->4055K(27392K), 0.0002770 secs] [GC 6615K->4014K(27392K), 0.0002285 secs] [GC 6566K->3995K(27392K), 0.0003704 secs] [GC 6555K->4005K(27392K), 0.0002516 secs] [GC 6564K->3997K(27392K), 0.0002247 secs] [GC 6557K->4007K(27392K), 0.0002447 secs] STOP PLAY [GC 6462K->4330K(27392K), 0.0004129 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 6884K->5402K(27392K), 0.0007594 secs] BGM PLAY:Buffer=88200 [GC 7956K->5975K(27392K), 0.0010555 secs] [GC 8493K->5988K(27392K), 0.0004958 secs] audioデータ読込準備完了 [GC 8548K->7026K(27392K), 0.0010300 secs] [GC 9586K->7355K(27392K), 0.0008977 secs] [GC 9915K->6964K(27392K), 0.0003081 secs] [GC 9524K->6756K(27392K), 0.0002550 secs] [GC 9309K->6664K(27392K), 0.0002549 secs] [GC 9217K->6643K(27392K), 0.0002349 secs] [GC 9196K->6641K(27392K), 0.0002306 secs] [GC 9201K->6651K(27392K), 0.0002448 secs] [GC 9211K->6649K(27392K), 0.0002495 secs] [GC 9209K->6648K(27392K), 0.0002537 secs] [GC 9204K->6641K(27392K), 0.0004274 secs] [GC 9201K->6643K(27392K), 0.0002325 secs] [GC 9203K->6651K(27392K), 0.0002371 secs] [GC 9211K->6640K(27392K), 0.0002325 secs] STOP PLAY [GC 9185K->7284K(27392K), 0.0004131 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 9840K->8221K(27392K), 0.0008928 secs] audioデータ読込準備完了 [GC 10779K->8602K(27392K), 0.0008806 secs] BGM PLAY:Buffer=88200 構築成功 (合計時間: 3 分 6 秒)
1面ボス撃破まで。BGMのPLAYが極の切り替え場所なのでわかるはず。最後のPLAYは2面の曲の再生部分。
見て分かるとおり、FullGCが最初に出以外は出ていない。コンカレントGCはメモリの使用頻度を把握していればFullGCはでない。ずっとゲームをプレイし続けていても一切でない。起動時のメモリ関係の負荷が厳しい1回のみだ。これはバックグラウンドでのGCスレッドのマーキングフェーズが完了していないことが原因だと思われる。
2面ボスあたりで旧世代が完全に消える。以下抜粋。つまりここが一番負荷がかかっている部分。
audioデータ読込準備完了 ラインの準備・・・完了 [GC 13569K->12100K(27392K), 0.0007000 secs] BGM PLAY:Buffer=88200 [GC 14660K->12800K(27392K), 0.0012570 secs] [GC 12821K(27392K), 0.0003448 secs] [GC 12823K(27392K), 0.0004777 secs] [GC 5743K->3332K(27392K), 0.0004820 secs] audioデータ読込準備完了
見て分かるとおりゲーム開始後GC時間は1ms以下が9割以上でそのほとんどが0.5ms以下だ。最悪値でも1.3msもかかってるGCはない
世代別ガベージコレクタ
JavaSEデフォのGC。新世代はめちゃくちゃ早い変わりにFullGCが走ると非常に遅くなるという特徴がある。メモリの使用量や旧世代へいくオブジェクトの生成頻度を把握してコンカレントGCを設定したほうが良い。
個人的にはかなりオススメできない。ゲームのみならずIDEやアプリケーションサーバー等ヒープの使用量が多いアプリの場合FullGCの停止時間が馬鹿にならないためだ。例えばWebアプリで普段1秒でGCが終了しているところに、たまに1分くらいまたされるGCが発生した場合どうなるだろう。フリーズしたとユーザーは考えるのではないだろうか。
起動オプション
-XX:MaxTenuringThreshold=1 -Xms28M -Xmx28M -noclassgc
GCログ
run: [GC 1792K->684K(28480K), 0.0055733 secs] [GC 2466K->950K(28480K), 0.0045169 secs] ジョイスティックが見つかりました。 カーソルを非表示にします。 [GC 2742K->1110K(28480K), 0.0026793 secs] 初期化開始 [GC 2902K->1460K(28480K), 0.0019204 secs] [GC 3230K->1586K(28480K), 0.0008516 secs] [GC 3378K->1611K(28480K), 0.0006023 secs] [GC 3403K->1616K(28480K), 0.0004417 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 [GC 3408K->1793K(28480K), 0.0006823 secs] 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 3585K->2159K(28480K), 0.0014080 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 3850K->2663K(28480K), 0.0010613 secs] BGM PLAY:Buffer=88200 [GC 4455K->3942K(28480K), 0.0012867 secs] [GC 5733K->4264K(28480K), 0.0006289 secs] [GC 6055K->4346K(28480K), 0.0004544 secs] [GC 6134K->4265K(28480K), 0.0003372 secs] [GC 6053K->4164K(28480K), 0.0003244 secs] [GC 5955K->4163K(28480K), 0.0002886 secs] [GC 5953K->4164K(28480K), 0.0002937 secs] [GC 5956K->4175K(28480K), 0.0003055 secs] [GC 5967K->4172K(28480K), 0.0003822 secs] [GC 5964K->4173K(28480K), 0.0002918 secs] [GC 5961K->4162K(28480K), 0.0002558 secs] [GC 5954K->4165K(28480K), 0.0002672 secs] [GC 5957K->4174K(28480K), 0.0002915 secs] [GC 5960K->4165K(28480K), 0.0002705 secs] [GC 5957K->4176K(28480K), 0.0002913 secs] [GC 5968K->4165K(28480K), 0.0002801 secs] [GC 5957K->4172K(28480K), 0.0003707 secs] [GC 5964K->4171K(28480K), 0.0002858 secs] [GC 5931K->5023K(28480K), 0.0008390 secs] audioデータ読込準備完了 [GC 6791K->6024K(28480K), 0.0011214 secs] [GC 7808K->6065K(28480K), 0.0004617 secs] [GC 7855K->6065K(28480K), 0.0003173 secs] [GC 7857K->6074K(28480K), 0.0002909 secs] [GC 7860K->6065K(28480K), 0.0002664 secs] [GC 7857K->6075K(28480K), 0.0002808 secs] [GC 7865K->6067K(28480K), 0.0002728 secs] [GC 7852K->6065K(28480K), 0.0002689 secs] [GC 7857K->6076K(28480K), 0.0002825 secs] [GC 7866K->6066K(28480K), 0.0002687 secs] [GC 7857K->6066K(28480K), 0.0003320 secs] STOP PLAY [GC 7857K->6908K(28480K), 0.0007764 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 8697K->7973K(28480K), 0.0009194 secs] BGM PLAY:Buffer=88200 [GC 9759K->8611K(28480K), 0.0007591 secs] [GC 10403K->9038K(28480K), 0.0006184 secs] [GC 10817K->10070K(28480K), 0.0009078 secs] audioデータ読込準備完了 [GC 11862K->11251K(28480K), 0.0011170 secs] [GC 13043K->11527K(28480K), 0.0005651 secs] [GC 13319K->11575K(28480K), 0.0004147 secs] [GC 13367K->11422K(28480K), 0.0003204 secs] [GC 13214K->11414K(28480K), 0.0002980 secs] [GC 13206K->11415K(28480K), 0.0003041 secs] [GC 13202K->11408K(28480K), 0.0002946 secs] [GC 13200K->11416K(28480K), 0.0003228 secs] [GC 13207K->11410K(28480K), 0.0002956 secs] [GC 13196K->11409K(28480K), 0.0002984 secs] [GC 13201K->11415K(28480K), 0.0002917 secs] [GC 13207K->11405K(28480K), 0.0002766 secs] STOP PLAY [GC 13196K->12140K(28480K), 0.0006076 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC 13892K->13111K(28480K), 0.0008072 secs] [GC 14885K->14257K(28480K), 0.0010492 secs] audioデータ読込準備完了 [GC 16041K->15555K(28480K), 0.0010897 secs] BGM PLAY:Buffer=88200 構築成功 (合計時間: 2 分 56 秒)
見て分かるとおり新世代のGC時間は非常に短い。ただし、旧世代のGCがバカ長いのもご存知のとおり。1面で普通にプレイしただけでは発生しないので2面でFullGC発生した場所も掲載してみる。
PLAY [GC 26642K->25269K(28480K), 0.0004560 secs] audioデータ読込準備完了 ラインの準備・・・完了 [GC, 0.0011495 secs] [Full GC 28475K->4080K(28480K), 0.1903505 secs] BGM PLAY:Buffer=88200 [GC 5872K->4735K(28480K), 0.0006747 secs]
190msもかかってる。ヒープ28MBしかないのに。普段のGCの軽さしかチェックしていないとこの重さに気がつかないこともあるかもしれない。最悪値は100倍を超えるというのを理解して使うようにしよう。
G1ガベージコレクタ
今大会の主役。
アルゴリズムとしては世代別GCをさらに進化させて効率よく、融通が利くようになったものと考えると良い。
起動オプション
-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxTenuringThreshold=1 -Xms28M -Xmx28M -noclassgc
GCログ
run: ジョイスティックが見つかりました。 カーソルを非表示にします。 初期化開始 [GC pause (young) 6966K->1539K(28M), 0.0066870 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) 9729K->3048K(28M), 0.0023869 secs] audioデータ読込準備完了 ラインの準備・・・完了 BGM PLAY:Buffer=88200 [GC pause (young) 11M->4376K(28M), 0.0022813 secs] [GC pause (young) 18M->4408K(28M), 0.0009626 secs] audioデータ読込準備完了 [GC pause (young) 20M->5665K(28M), 0.0015530 secs] [GC pause (young) 21M->5669K(28M), 0.0013600 secs] STOP PLAY audioデータ読込準備完了 ラインの準備・・・完了 BGM PLAY:Buffer=88200 audioデータ読込準備完了 [GC pause (young) 21M->7155K(28M), 0.0015024 secs] [GC pause (young) 20M->7184K(28M), 0.0009271 secs] [GC pause (young) 20M->7200K(28M), 0.0007995 secs] STOP PLAY audioデータ読込準備完了 ラインの準備・・・完了 audioデータ読込準備完了 BGM PLAY:Buffer=88200 構築成功 (合計時間: 3 分 1 秒)
1面クリア時点では1回もFullGCがでなかった。そのままゲームクリアするもあらわれず。一度タイトルに戻り2回目のプレイで2面にはいってやっと現れた。ということでまずメモリ使用効率が世代別GCに比べて非常に良いというのがわかる。これは。
そのときのログ。
[GC pause (young) (initial-mark) 23M->18M(28M), 0.0013903 secs] [GC concurrent-mark-start] audioデータ読込準備完了 ラインの準備・・・完了 [GC concurrent-mark-end, 0.0047700 sec] [GC remark, 0.0009821 secs] [GC concurrent-count-start] [GC concurrent-count-end, 0.0010500] audioデータ読込準備完了 [GC pause (young) 22M->20M(28M), 0.0014944 secs] BGM PLAY:Buffer=88200 [GC cleanup 20M->16M(28M), 0.0002012 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0000112] [Full GC 27M->2555K(28M), 0.0364801 secs] [GC pause (young) 14M->2579K(28M), 0.0044827 secs]
まずぱっとみでログが非常に見やすくなったのがわかると思う。従来のGCもログの表記を変えて欲しいと思ったけど、互換性のために同じようにしてたんだろうね。
あとFullGCの前にコンカレントGCみたいな動きがあるっぽいことが分かる。でもコンカレントGCがちゃんとうごいてるならFullGCは発生しないはず。もしかして並列GCの作業中にメモリが足りなくなっちゃってFullGCおきてるのかな。
プレイするのもだるいのでやられても自機が減らないように修正。そのまま2面ボスまで放置。
[GC pause (young) (initial-mark) 22M->19M(28M)[GC concurrent-mark-start] , 0.0015077 secs] [GC concurrent-mark-end, 0.0046597 sec] [GC remark, 0.0009168 secs] [GC concurrent-count-start] [GC concurrent-count-end, 0.0009808] [GC cleanup 20M->17M(28M), 0.0001222 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0000105] [GC pause (young) 18M->17M(28M), 0.0010680 secs] [GC pause (partial) 18M->4458K(28M), 0.0045595 secs] [GC pause (young) 18M->4482K(28M), 0.0008584 secs]
ふむ。FullGCが今回は起きていない。これなら大丈夫。チューニングはインクリメンタルGCにあわせてるのでG1ガベージコレクタとは相性が悪かったのだろう。うまくやれば確かに早いはずだ。
あとは何も設定せずともFullGCが入った最悪値も通常の世代別GCより5倍くらい早いようだ。ということは話半分と考えても世代別GCからはほぼデメリットなしで乗り換えてよい気がする。すでにインクリメンタルGCやコンカレントGCを設定してチューニングしている人は乗り換えるメリットが無いというか、設定値が大きく違う、つまり癖が違うので良く考えてから使うほうが良いだろう。
時間指定オプションも今回に限らず以前からあるのだが、従来はほとんどきいてなかった。今回はある程度はきいてる感じ。なおXX:GCPauseIntervalMillisオプションは入れるとかならずVMがおちるようだ。注意すべし。
XX:MaxGCPauseMillis=1をいれてみるとなぜかFullGCばっかりかかるようになってしまった。どうもFullGCでかかった時間も含めてGC時間を平均1msにするように新世代GCをやってないくさい。なんじゃこりゃぁ。CPUの性能みて設定しないと大変なことになるくさい。
