第２回です。
なかなか更新できる時間がないですが
マイペースで書いていこうと思います。
ストックやフォローをして頂けると励みになります。
さて前回はGCの仕組みの概要説明とjstatでのモニタリングでした。
今回はCGログの分析をしてみようと思います。
JVMのGCログ設定
まずはGCログが取得できるように設定しないと始まりませんね。
以下のようなオプションをjavaの起動コマンドに付与すると
GCの情報を取れるようになります。
- -verbose:gc
[GC 919089K->41941K(943744K), 0.2300771 secs]
こんな感じのGCログが出ます。
- -XX:+PrintGCDetails
- -XX:+PrintGCDateStamps
[GC2015-12-10T07:06:41.209+0900: 308.418: [ParNew: 903392K->50610K(943744K), 0.2480070 secs] 1722365K->874495K(3040896K), 0.2482590 secs] [Times: user=0.15 sys=0.00, real=0.25 secs]
-verbose:gcより詳細なログ情報が出力されます。
- -Xloggc:/var/log/xxx/gc.log
- -XX:+UseGCLogFileRotation
- -XX:NumberOfGCLogFiles=10
- -XX:GCLogFileSize=10M
ログの場所やローテーション設定など。
- --XX:+HeapDumpOnOutOfMemoryError
- -XX:HeapDumpPath=/tmp/heapdump/
このオプションをつけるとOutOfMemoryError発生時に
ヒープダンプを出力してくれます。
(ヒープダンプは次回説明します)
GCログの解析
さてファイルが出力されるようになったら解析ですが、
ファイルを目視して解析・・・というのはけっこう面倒です。
うまくGCが動作していればきれいなGCログになるのですが
メジャーGC、マイナーGCやコンカレントGC(CMS)が五月雨に大量発生して
メモリもうまく開放されていない場合は苦労します。
そういう場合はまずGCViewerというツールでグラフィカルに一次解析をしましょう。
jarでできているのでダブルクリックやjavaコマンドなどで実行して
GCログファイルをドラッグ＆ドロップしてみてください。
これはダメな例。
いくつか表示項目を絞ってますが、上半分の黄色がNew領域、下半分のピンクがOld領域です。
New領域はまぁ、良いですがOld領域が100%に張り付いてます。
(ピンク背景にピンクの線なので見難いですね。。画像をクリックして拡大表示してください)
何やらリークを起こしているんすかねー？
・
・
・
もろもろ調査をした結果、リークの疑いがある個所があったので
改善してみました。
（こちらの詳細も次回のヒープダンプと合わせて）
さてもう一度、ログを取り直してVIEWERで見てましょう。
張り付きは改善されましたがまだ推移が高いですね。
画像には表示されてませんが、
コンカレントGCが30秒に１度くらいのペースで発生しています。
ヒープ設定の見直し
メモリリークを改善してもこういう状態ということは
Heapの割り当て設定が適切ではない疑いがありますね。
設定を見直してみましょう。
・
・
・
- -XX:PermSize=1024m
- -XX:MaxPermSize=1024m
- -Xms:2048m
- -Xmx:2048m
- -XX:NewSize=1024m
- -XX:MaxNewSize=1024m
どうやらHeapに2GB割り当てていて、NewとOldの比率が1:1のようですね。
Heapのメモリ領域の検討のOld領域の値の検討から始めるのがセオリーのようです。
上述のGCViewerからこのアプリケーションは1GB弱のメモリを
アプリケーション自体が必要としているようです。
Old領域はアプリが必要な容量＋New領域の容量が基本値です。
そうしないとNew領域からOldにコピーされた際に溢れてしまいます。
今回であればNew領域に1GB割り当てているので
アプリで必要な容量1GB+Newから移動される可能性のある容量1GBの合計２GBあれば
大丈夫そうなのでひとまずOldを2GBにしてみましょう。
(1GBもNew領域いらないのでは・・・という感じもしますが。)
-XX:NewSize=1024mに設定すると残りがOld領域になるので
-Xms:3074m、-Xmx:3074mにして再度GCViewerを見てみましょう。
おお！いい感じじゃないですか。
少しずつOld領域が上昇していきますが起動から8時間後に初めてコンカレントGCが発生して
OLD領域がガクンと落ちています。
(CMS発生の閾値をOld領域が80%になったらに設定しているので正常です！)
そしてコンカレントGCの中でアプリを停止(Stop The Word)している期間は約1秒でした。
[GC [1 CMS-initial-mark: 1677742K(2097152K)] 1700713K(3040896K), 0.0577420 secs] [Times: user=0.02 sys=0.01, real=0.06 secs]
[1 CMS-remark: 1677742K(2097152K)] 2262523K(3040896K), 0.9530250 secs]
1秒はまぁ、遅いですが8時間に１秒なら全然許容範囲です。
New領域もGC前後の最大値、最小値が一定になっています。
さらにチューニングするのであれば、
New領域⇒Old領域に移動する設定値(マイナーGCで何度生き残ったらOldに移動させるか)や
コンカレントGCが実行される閾値などを細かく設定するとよりパフォーマンスの良いシステムなりますが
まずは問題が解決できたので合格ラインじゃないでしょうか。
では次回はヒープダンプの出力と解析です。