More than 1 year has passed since last update.

第2回です。

なかなか更新できる時間がないですが

マイペースで書いていこうと思います。

ストックやフォローをして頂けると励みになります。

 

さて前回は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ログファイルをドラッグ&ドロップしてみてください。

gc_ng.png

これはダメな例。

いくつか表示項目を絞ってますが、上半分の黄色がNew領域、下半分のピンクがOld領域です。

New領域はまぁ、良いですがOld領域が100%に張り付いてます。
(ピンク背景にピンクの線なので見難いですね。。画像をクリックして拡大表示してください)

何やらリークを起こしているんすかねー?



もろもろ調査をした結果、リークの疑いがある個所があったので

改善してみました。
(こちらの詳細も次回のヒープダンプと合わせて)

さてもう一度、ログを取り直してVIEWERで見てましょう。

gc_ng2.png

張り付きは改善されましたがまだ推移が高いですね。
画像には表示されてませんが、
コンカレントGCが30秒に1度くらいのペースで発生しています。

ヒープ設定の見直し

メモリリークを改善してもこういう状態ということは

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の合計2GBあれば

大丈夫そうなのでひとまずOldを2GBにしてみましょう。
(1GBもNew領域いらないのでは・・・という感じもしますが。)

-XX:NewSize=1024mに設定すると残りがOld領域になるので

-Xms:3074m、-Xmx:3074mにして再度GCViewerを見てみましょう。

gc1.png

おお!いい感じじゃないですか。

少しずつ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時間に1秒なら全然許容範囲です。

New領域もGC前後の最大値、最小値が一定になっています。

さらにチューニングするのであれば、

New領域⇒Old領域に移動する設定値(マイナーGCで何度生き残ったらOldに移動させるか)や

コンカレントGCが実行される閾値などを細かく設定するとよりパフォーマンスの良いシステムなりますが

まずは問題が解決できたので合格ラインじゃないでしょうか。

 
では次回はヒープダンプの出力と解析です。

Sign up for free and join this conversation.
Sign Up
If you already have a Qiita account log in.