[メモ]CMS GCログの見方

1. 基本おさらい
2. 実験するためのプログラム
3. CMSログの見方
4. 参考

1 基本おさらい

CMSとは Concurrent Mark & Sweep 、JVM OLD領域GC処理アルゴリズムの一種です。 CMSはアプリケーションを停止する時間を削減することが出来ます。処理の流れは下図に示す。

※Concurrentは同時という意味です。

       ①        ②          ③    ④
---> | ==> | ============> | ==> | ==========> ----->
---> |     | ------------> | ==> | ----------------->
---> |     | ------------> | ==> | ----------------->
---> |     | ------------> | ==> | ----------------->
---> |     | ------------> | ==> | ----------------->
---> |     | ------------> | ==> | ----------------->
       STW                   STW

凡例
+--------------------+
| ==> GCスレッド     |
| --> アプリスレッド |
+--------------------+

図上示している通り、①と③の処理だけアプリケーションが停止する。

①	Initial Mark	STW	Rootを起点に利用されてるオブジェクトをマークする
②-1	Concurrent Mark		①でマークされたオブジェクトを起点に使用中のオブジェクトをマークする
②-2	Concurrent precleaning		②-1処理中アプリによる生じた変化部分をマークする、③の処理時間を短縮するため
③	Parallel Remark	STW	②処理中アプリによる生じた変化部分をマークする
④-1	Concurrent Sweeping		マーク処理によって判明した使用済みオブジェクトを削除する
④-2	Concurrent Reset		CMS処理自体のリセット

TODO: GCスレッドについて

Parallel GC Threads
Parallel CMS Threads
Concurrent Mark-Sweep GC Thread

2 実験するためのプログラム

メモリを大量に消費するWebサービス

package test.example;

import javax.jws.WebMethod;
import javax.jws.WebParam;
import javax.jws.WebService;
import javax.jws.soap.SOAPBinding;

@WebService
@SOAPBinding(style = SOAPBinding.Style.DOCUMENT, use = SOAPBinding.Use.LITERAL, parameterStyle = SOAPBinding.ParameterStyle.WRAPPED)
public class HelloWorld {

    @WebMethod(action = "sayHello")
    public String sayHello(@WebParam(name = "name" ) String name) throws CustomException {

        System.out.println("Hello: " + name);

        java.util.List l  =  new java.util.ArrayList<>();
        int x  = 0;
        while (x < 6300) {
            Thread t  =  new Thread();
            l.add(t);

            try {
                Thread.sleep(10);
            } catch (Exception e) {
            }
            x++;
            System.out.println(x);
        }
        return "Hello " + name + "!";
    }
}

Webサービスを載せるAPサーバの起動オプションにGC関係のパラメータを追加する。 Old領域のGCを発生しやすくため、ヒープサイズを小さめに割り当てる。

JAVA_OPTS="$JAVA_OPTS -Xms512m -Xmx512m -XX:MaxPermSize=256m"
JAVA_OPTS="$JAVA_OPTS -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled"
JAVA_OPTS="$JAVA_OPTS -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps"
JAVA_OPTS="$JAVA_OPTS -Xloggc:/tmp/gc-`date '+%Y-%m-%d'`.log"

以下のオプション、GC時に詳細なオブジェクト統計情報も出力する。ここでは略します。

JAVA_OPTS="$JAVA_OPTS -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution"

SoapUIから100多重で負荷を掛けて、テストアプリを実行させる。

SoapUIから負荷を掛けた後はしばらく、New領域のGCログが出続ける。Old領域が満タンな状態になる前にOld領域のGCログが出始める。以下はOld領域GC発生前後のログを示す。

2014-11-05T14:24:49.336+0900: 214.204: [GC2014-11-05T14:24:49.336+0900: 214.204: [DefNew: 76672K->8512K(76672K), 0.0978870 secs] 455251K->395770K(515776K), 0.0981100 secs] [Times: user=0.08 sys=0.00, real=0.10 secs] 
2014-11-05T14:24:51.971+0900: 216.840: [GC2014-11-05T14:24:51.971+0900: 216.840: [DefNew: 76672K->8412K(76672K), 0.0816580 secs] 463930K->404301K(515776K), 0.0818720 secs] [Times: user=0.06 sys=0.00, real=0.08 secs] 
2014-11-05T14:24:54.767+0900: 219.636: [GC2014-11-05T14:24:54.767+0900: 219.636: [DefNew: 76572K->8415K(76672K), 0.1165260 secs] 472461K->412833K(515776K), 0.1172920 secs] [Times: user=0.06 sys=0.01, real=0.12 secs] 
2014-11-05T14:24:54.899+0900: 219.768: [GC [1 CMS-initial-mark: 404417K(439104K)] 414152K(515776K), 0.0252080 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2014-11-05T14:24:55.043+0900: 219.912: [CMS-concurrent-mark-start]
2014-11-05T14:24:56.941+0900: 221.810: [GC2014-11-05T14:24:56.941+0900: 221.810: [DefNew: 76575K->8512K(76672K), 0.0933500 secs] 480993K->423185K(515776K), 0.0935560 secs] [Times: user=0.07 sys=0.00, real=0.10 secs] 
2014-11-05T14:24:58.119+0900: 222.988: [CMS-concurrent-mark: 2.773/3.076 secs] [Times: user=2.38 sys=0.46, real=3.07 secs] 
2014-11-05T14:24:58.119+0900: 222.988: [CMS-concurrent-preclean-start]
2014-11-05T14:24:58.127+0900: 222.996: [CMS-concurrent-preclean: 0.007/0.008 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2014-11-05T14:24:58.127+0900: 222.996: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2014-11-05T14:25:03.224+0900: 228.092: [CMS-concurrent-abortable-preclean: 2.683/5.096 secs] [Times: user=2.44 sys=0.08, real=5.10 secs] 
2014-11-05T14:25:03.224+0900: 228.093: [GC[YG occupancy: 48273 K (76672 K)]2014-11-05T14:25:03.224+0900: 228.093: [Rescan (non-parallel) 2014-11-05T14:25:03.224+0900: 228.093: [grey object rescan, 0.0011680 secs]2014-11-05T14:25:03.225+0900: 228.094: [root rescan, 0.2362360 secs], 0.2375020 secs]2014-11-05T14:25:03.462+0900: 228.331: [weak refs processing, 0.0044290 secs]2014-11-05T14:25:03.466+0900: 228.335: [class unloading, 0.0089260 secs]2014-11-05T14:25:03.475+0900: 228.344: [scrub symbol table, 0.0179240 secs]2014-11-05T14:25:03.493+0900: 228.362: [scrub string table, 0.0013030 secs] [1 CMS-remark: 414673K(439104K)] 462947K(515776K), 0.2714240 secs] [Times: user=0.26 sys=0.00, real=0.27 secs] 
2014-11-05T14:25:03.504+0900: 228.373: [CMS-concurrent-sweep-start]
2014-11-05T14:25:03.816+0900: 228.685: [CMS-concurrent-sweep: 0.310/0.312 secs] [Times: user=0.23 sys=0.00, real=0.31 secs] 
2014-11-05T14:25:03.817+0900: 228.686: [CMS-concurrent-reset-start]
2014-11-05T14:25:03.819+0900: 228.687: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2014-11-05T14:25:04.454+0900: 229.323: [GC [1 CMS-initial-mark: 394635K(439104K)] 443918K(515776K), 0.0809520 secs] [Times: user=0.08 sys=0.00, real=0.08 secs] 
2014-11-05T14:25:04.538+0900: 229.407: [CMS-concurrent-mark-start]
2014-11-05T14:25:05.602+0900: 230.471: [CMS-concurrent-mark: 1.064/1.064 secs] [Times: user=1.01 sys=0.00, real=1.07 secs] 
2014-11-05T14:25:05.603+0900: 230.471: [CMS-concurrent-preclean-start]
2014-11-05T14:25:05.605+0900: 230.474: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2014-11-05T14:25:05.605+0900: 230.474: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2014-11-05T14:25:10.648+0900: 235.516: [CMS-concurrent-abortable-preclean: 1.979/5.042 secs] [Times: user=1.89 sys=0.01, real=5.04 secs] 
2014-11-05T14:25:10.648+0900: 235.517: [GC[YG occupancy: 55959 K (76672 K)]2014-11-05T14:25:10.648+0900: 235.517: [Rescan (non-parallel) 2014-11-05T14:25:10.648+0900: 235.517: [grey object rescan, 0.0012890 secs]2014-11-05T14:25:10.649+0900: 235.518: [root rescan, 0.1016560 secs], 0.1030300 secs]2014-11-05T14:25:10.751+0900: 235.620: [weak refs processing, 0.0000500 secs]2014-11-05T14:25:10.751+0900: 235.620: [class unloading, 0.0078410 secs]2014-11-05T14:25:10.759+0900: 235.628: [scrub symbol table, 0.0162830 secs]2014-11-05T14:25:10.775+0900: 235.644: [scrub string table, 0.0010720 secs] [1 CMS-remark: 394635K(439104K)] 450595K(515776K), 0.1292870 secs] [Times: user=0.12 sys=0.01, real=0.13 secs] 
2014-11-05T14:25:10.777+0900: 235.646: [CMS-concurrent-sweep-start]
2014-11-05T14:25:10.981+0900: 235.850: [CMS-concurrent-sweep: 0.203/0.203 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 
2014-11-05T14:25:10.981+0900: 235.850: [CMS-concurrent-reset-start]
2014-11-05T14:25:10.983+0900: 235.852: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2014-11-05T14:25:32.473+0900: 257.342: [GC2014-11-05T14:25:32.474+0900: 257.342: [DefNew: 76664K->2361K(76672K), 0.0146410 secs] 463666K->389381K(515776K), 0.0148600 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2014-11-05T14:26:44.480+0900: 329.349: [GC2014-11-05T14:26:44.480+0900: 329.349: [DefNew: 70521K->1291K(76672K), 0.0214830 secs] 457541K->388311K(515776K), 0.0216760 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2014-11-05T14:27:56.504+0900: 401.373: [GC2014-11-05T14:27:56.504+0900: 401.373: [DefNew: 69451K->1214K(76672K), 0.0102000 secs] 456471K->388234K(515776K), 0.0103740 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

3 CMSログの見方

3.1 New領域GCログ

New領域のGCは minor GC と呼ばれる場合があります。

DefNew と PraNew 文字が含まれた行は New 領域のGC処理ログです。シングルコアの場合 DefNew=、マルチコアは =PraNew となります。

New領域のGCログは一行で完結する。ログ先頭の GC タグはSTWであることを示している。(つまりNew領域のGC処理はStop the worldです)続きの部分はGC前後New領域内メモリの変化を示している、その次の部分は、JVM全体のメモリ使用量の変化を示している。

2014-11-05T16:59:21.544+0900: 9486.413: [GC2014-11-05T16:59:21.544+0900: 9486.413: [DefNew: 68932K->1046K(76672K), 0.0122090 secs] 472847K->405094K(515776K), 0.0123880 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
                                          ★                                        ~~~~~~  ~~~~~   ~~~~  ~~~~                     ~~~~~~~  ~~~~~~
                                                                                      A       B       C     D                         E       F

A	New領域のGC	DefNew
B	GC前New領域の使用量	68932K
C	GC後New領域の使用量	1046K
D	New領域GCの閾値	76672K
E	GC前JVMメモリの使用量	472847K
F	GC後JVMメモリの使用量	405094K

New領域容量の変化とJMV全体のメモリ容量の変化からOLD領域の増加サイズを算出する。

New領域変化容量： 68932 K - 1046K   = 67886K
JVM全体変化容量： 472847K - 405094K = 67753K
★OLD領域の増加サイズ： New領域変化容量 - JVM全体変化容量 = 133K

最後の real 部分はSTW(アプリ停止時間)の時間となります、10ミリ秒ですね。

[Times: user=0.01 sys=0.00, real=0.01 secs]

3.2 Old領域GCログ

以下は通常なCMS処理のログです。

★CMS起きる前のNewGCログ
2014-11-05T16:59:21.544+0900: 9486.413: [GC2014-11-05T16:59:21.544+0900: 9486.413: [DefNew: 68932K->1046K(76672K), 0.0122090 secs] 472847K->405094K(515776K), 0.0123880 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

★①
2014-11-05T16:59:21.564+0900: 9486.433: [GC [1 CMS-initial-mark: 404047K(439104K)] 405358K(515776K), 0.0084940 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

★②-1
2014-11-05T16:59:21.573+0900: 9486.442: [CMS-concurrent-mark-start]
2014-11-05T16:59:21.727+0900: 9486.596: [CMS-concurrent-mark: 0.154/0.154 secs] [Times: user=0.14 sys=0.00, real=0.15 secs] 

★②-2
2014-11-05T16:59:21.727+0900: 9486.596: [CMS-concurrent-preclean-start]
2014-11-05T16:59:21.754+0900: 9486.623: [CMS-concurrent-preclean: 0.027/0.027 secs] [Times: user=0.00 sys=0.00, real=0.03 secs] 

★③
2014-11-05T16:59:21.754+0900: 9486.623: [GC[YG occupancy: 1535 K (76672 K)]2014-11-05T16:59:21.754+0900: 9486.623: [Rescan (non-parallel) 2014-11-05T16:59:21.754+0900: 9486.623: [grey object rescan, 0.0012560 secs]2014-11-05T16:59:21.755+0900: 9486.624: [root rescan, 0.0064000 secs], 0.0077470 secs]2014-11-05T16:59:21.762+0900: 9486.631: [weak refs processing, 0.0003290 secs]2014-11-05T16:59:21.762+0900: 9486.631: [class unloading, 0.0108870 secs]2014-11-05T16:59:21.773+0900: 9486.642: [scrub symbol table, 0.0156480 secs]2014-11-05T16:59:21.789+0900: 9486.658: [scrub string table, 0.0012200 secs] [1 CMS-remark: 404047K(439104K)] 405583K(515776K), 0.0371740 secs] [Times: user=0.04 sys=0.01, real=0.04 secs] 

★④-1
2014-11-05T16:59:21.792+0900: 9486.661: [CMS-concurrent-sweep-start]
2014-11-05T16:59:22.187+0900: 9487.056: [CMS-concurrent-sweep: 0.395/0.395 secs] [Times: user=0.38 sys=0.00, real=0.39 secs] 

★④-2
2014-11-05T16:59:22.189+0900: 9487.057: [CMS-concurrent-reset-start]

2014-11-05T16:59:22.190+0900: 9487.059: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

★CMS後のNewGCログ
2014-11-05T17:00:32.559+0900: 9557.428: [GC2014-11-05T17:00:32.559+0900: 9557.428: [DefNew: 69206K->1062K(76672K), 0.0103860 secs] 104633K->36628K(515776K), 0.0105880 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

CMS前後のNewGCログのJVMメモリ使用量からメモリが掃除されることをわかります。 405094K → 104633K、約293MBが掃除された。

Initial Markフェースログの先頭に GC 文字が現れるので、STWが発生することが分かります。

★①
2014-11-05T16:59:21.564+0900: 9486.433: [GC [1 CMS-initial-mark: 404047K(439104K)] 405358K(515776K), 0.0084940 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
                                                                 ~~~~~~  ~~~~~~    ~~~~~~  ~~~~~~                                                 ~~~~~~~~~~~~
                                                                   A        B        C       D                                                         E

Initial Markフェースログの内訳

A	CMS起動時のOLD領域使用量	404047K
B	CMSトリガーするOLD領域閾値	439104K
C	CMS起動時JVMのメモリの使用量	405358K
D
E	Initial Markフェースで消費した時間	10 ミリ秒

続いて、Concurrent MarkとConcurrent precleaning処理の時間を示している。この部分の処理はアプリケーションと平行で行われるため、停止時間生じない。

★②-1
2014-11-05T16:59:21.573+0900: 9486.442: [CMS-concurrent-mark-start]
2014-11-05T16:59:21.727+0900: 9486.596: [CMS-concurrent-mark: 0.154/0.154 secs] [Times: user=0.14 sys=0.00, real=0.15 secs] 
                                                                                                            ~~~~~~~~~~~~~~
                                                                                                                  F
★②-2
2014-11-05T16:59:21.727+0900: 9486.596: [CMS-concurrent-preclean-start]
2014-11-05T16:59:21.754+0900: 9486.623: [CMS-concurrent-preclean: 0.027/0.027 secs] [Times: user=0.00 sys=0.00, real=0.03 secs] 
                                                                                                                ~~~~~~~~~~~~~~
                                                                                                                      G

F	Concurrent Markフェースで消費した時間	150 ミリ秒
G	Concurrent Precleanフェースで消費した時間	30ミリ秒

Parallel Remarkフェーズのログは１行で完結する、折り返してインデントを付けると次の形になります。

★③
2014-11-05T16:59:21.754+0900: 9486.623:
[GC
    [YG occupancy: 1535 K (76672 K)]
                   ~~~~    ~~~~~
                    H        I
    2014-11-05T16:59:21.754+0900: 9486.623:
                                            [
                                              Rescan (non-parallel)
                                                2014-11-05T16:59:21.754+0900: 9486.623: [grey object rescan, 0.0012560 secs]
                                                2014-11-05T16:59:21.755+0900: 9486.624: [root rescan, 0.0064000 secs]
                                             , 0.0077470 secs
                                            ]
    2014-11-05T16:59:21.762+0900: 9486.631: [weak refs processing, 0.0003290 secs]
    2014-11-05T16:59:21.762+0900: 9486.631: [class unloading, 0.0108870 secs]
    2014-11-05T16:59:21.773+0900: 9486.642: [scrub symbol table, 0.0156480 secs]
    2014-11-05T16:59:21.789+0900: 9486.658: [scrub string table, 0.0012200 secs]

    [1 CMS-remark: 404047K(439104K)] 405583K(515776K), 0.0371740 secs
                   ~~~~~~  ~~~~~~    ~~~~~~  ~~~~~~
                     J       K         L       M
]
[Times: user=0.04 sys=0.01, real=0.04 secs]
                            ~~~~~~~~~~~~~~
                                 N

内訳

H	現時点New領域の使用量	1535K
I	New領域GCの閾値	76672K
J	現時点OLD領域使用量	404047K	変化なし
K	CMSトリガーするOLD領域閾値	439104K
L	現時点JVMのメモリの使用量	405583K	225K増加
M
N	Parallel Remarkフェーズで消費した時間	40 ミリ秒

処理時間からみるとParallel RemarkフェーズはInitial Markフフェーズより時間がかかることが分かりました。

続いて、Concurrent SweepとConcurrent Reset処理の時間を示している。この部分の処理はアプリケーションと平行で行われるため、停止時間生じない。

★④-1
2014-11-05T16:59:21.792+0900: 9486.661: [CMS-concurrent-sweep-start]
2014-11-05T16:59:22.187+0900: 9487.056: [CMS-concurrent-sweep: 0.395/0.395 secs] [Times: user=0.38 sys=0.00, real=0.39 secs]
                                                                                                             ~~~~~~~~~~~~~~
                                                                                                                   O
★④-2
2014-11-05T16:59:22.189+0900: 9487.057: [CMS-concurrent-reset-start]
2014-11-05T16:59:22.190+0900: 9487.059: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
                                                                                                             ~~~~~~~~~~~~~~~
                                                                                                                   P

O	Concurrent Sweepフェースで消費した時間	390 ミリ秒
P	Concurrent Resetフェースで消費した時間	10ミリ秒

フェース①〜④の処理時間とJVMメモリ容量変化は以下となります。

	フェーズ名	一時停止	処理時間(ミリ秒)	JVMメモリ(MB)
①	Initial Mark	◯	10	395.8
②-1	Concurrent Mark		150
②-2	Concurrent precleaning		30
③	Parallel Remark	◯	40	396.0
④-1	Concurrent Sweeping		390	102.0
④-2	Concurrent Reset		10
			630	-294

CMS全体処理で630ミリ秒かかる、そのうち50ミリ秒の停止時間が発生する。掃除されたメモリ容量約294MB。

3.3 concurrent mode failure

次の状況に置いて、コンカレントGCが縮退しFullGCを引き起こす可能性があります。

システムが高負荷時に、新しいオブジェクトの生成速度がGCのメモリ解放速度より早い
Java ヒープの断片化率が非常に高い時

また、縮退後のFullGCは Serial Old モードで行われるため、アプリ停止時間が長くなります。

Initial Mark 次の Concurrent Mark で縮退が起きて、 FullGC が起こった例。

2014-11-20T14:04:17.969+0900: 423.523: [GC [1 CMS-initial-mark: 439103K(439104K)] 451488K(515776K), 0.0209760 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2014-11-20T14:04:18.110+0900: 423.663: [CMS-concurrent-mark-start]
2014-11-20T14:04:19.105+0900: 424.659: [Full GC2014-11-20T14:04:19.105+0900: 424.659: [CMS2014-11-20T14:04:19.745+0900: 425.299: [CMS-concurrent-mark: 1.632/1.636 secs] [Times: user=1.41 sys=0.17, real=1.64 secs] 
 (concurrent mode failure): 439103K->439103K(439104K), 1.7507640 secs] 515775K->458321K(515776K), [CMS Perm : 57066K->57066K(95504K)], 1.7509190 secs] [Times: user=1.74 sys=0.00, real=1.75 secs]

FullGC を示すログに内容を分解すると次のようになります。

2014-11-20T14:04:19.105+0900: 424.659:
    [Full GC2014-11-20T14:04:19.105+0900: 424.659: 

          ★CMS失敗時の内容
          [CMS2014-11-20T14:04:19.745+0900: 425.299: 
               [CMS-concurrent-mark: 1.632/1.636 secs]
               [Times: user=1.41 sys=0.17, real=1.64 secs]  
               (concurrent mode failure): 439103K->439103K(439104K), 1.7507640 secs] 

          ★縮退後、FullGC実施後の結果
          515775K->458321K(515776K), [CMS Perm : 57066K->57066K(95504K)], 1.7509190 secs]

    [Times: user=1.74 sys=0.00, real=1.75 secs]

3.4 手動FullGC時のログ

CMS GCを利用した場合でも手動でFullGCを起こすことは可能です。以下は手動GC掛けられた時にのGCログとなります。

2014-11-20T15:03:39.462+0900: 2611.658: [Full GC2014-11-20T15:03:39.462+0900: 2611.658: [CMS: 365597K->33109K(439104K), 0.3923750 secs] 408803K->33109K(515776K), [CMS Perm : 57580K->57357K(95888K)], 0.3925240 secs] [Times: user=0.36 sys=0.00, real=0.39 secs] 

★分解
2014-11-20T15:03:39.462+0900: 2611.658: 
    [Full GC2014-11-20T15:03:39.462+0900: 2611.658: 
          [CMS: 365597K->33109K(439104K), 0.3923750 secs] 408803K->33109K(515776K), 
          [CMS Perm : 57580K->57357K(95888K)], 0.3925240 secs] 
    [Times: user=0.36 sys=0.00, real=0.39 secs]

Akira's Tech Notes

Java/JVM | GNU/Linux | Emacs/Lisp | 知的好奇心駆動

Table of Contents