Java開発の性能改善！ その２ GCログの解析とHeapの設定

第２回です。

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

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

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

　

さて前回は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](https://github.com/chewiebug/GCViewer/wiki/Changelog "GCViewer")というツールでグラフィカルに一次解析をしましょう。

jarでできているのでダブルクリックやjavaコマンドなどで実行して
GCログファイルをドラッグ＆ドロップしてみてください。

![gc_ng.png](https://qiita-image-store.s3.amazonaws.com/0/102999/138f2517-361e-6136-4c6b-25d197c5952d.png)

これはダメな例。

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

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

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

・
・
・

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

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

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

![gc_ng2.png](https://qiita-image-store.s3.amazonaws.com/0/102999/f19ab2f5-7f18-8e70-c882-62d64565c790.png)

張り付きは改善されましたがまだ推移が高いですね。
画像には表示されてませんが、
コンカレント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を見てみましょう。

![gc1.png](https://qiita-image-store.s3.amazonaws.com/0/102999/2369c011-c3ed-f24a-0dc9-982e9379effd.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時間に１秒なら全然許容範囲です。

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

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

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

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

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

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


- [Java開発の性能改善！ その１ jstatによるヒープ/GCの確認](http://qiita.com/i_matsui/items/4997ebedbdd7a6495509 "Java開発の性能改善！ その１ jstatによるヒープ/GCの確認")
- [Java開発の性能改善！ その２ GCログの解析とHeapの設定](http://qiita.com/i_matsui/items/aabbdaa169c6ae51ecb3 "Java開発の性能改善！ その２ GCログの解析とHeapの設定")
- [Java開発の性能改善！ その３ ヒープダンプを取ろう](http://qiita.com/i_matsui/items/0d1ae2c7e9d17b6c04e0 "Java開発の性能改善！ その３ ヒープダンプを取ろう")