LoginSignup
151

More than 5 years have passed since last update.

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

Last updated at Posted at 2015-12-13

第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が実行される閾値などを細かく設定するとよりパフォーマンスの良いシステムなりますが

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

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

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
151