GCログを取得し、GCViewer で見てみる
0. GCViewer のインストール
// git clone でダウンロード
$ git clone https://github.com/chewiebug/GCViewer.git
// git clone した pom.xml と同じディレクトリで
$ mvn clean install
// target ディレクトリ内にある jar を実行
$ java -jar gcviewer-1.36-SNAPSHOT.jar
起動すると、GCViewer がGUIで起動するので、あとはGCログファイルをドラッグ＆ドロップしてあげるだけで、グラフが描画されます。
jstat コマンドで GC の様子を見てみる - 社内se × プログラマ × ビッグデータ
ここで使ったプログラムを VM 引数を変えつつ GC の様子を見てみます。
ケース1. -verbose:gc を指定してみる
VM引数に以下を指定します。
-verbose:gc -Xloggc:/tmp/gc.log
取得されたログ
Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 4048172k(1575784k free), swap 4187132k(4187132k free) CommandLine flags: -XX:InitialHeapSize=64770752 -XX:MaxHeapSize=1036332032 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 0.456: [GC (Allocation Failure) 15872K->9601K(60928K), 0.0264499 secs] 0.491: [GC (Allocation Failure) 25473K->20215K(76800K), 0.0352044 secs] 0.540: [GC (Allocation Failure) 51959K->44870K(76800K), 0.0568122 secs] 0.597: [Full GC (Ergonomics) 44870K->39980K(123904K), 0.4672640 secs] 1.076: [GC (Allocation Failure) 71724K->71757K(140288K), 0.0869480 secs] 1.163: [Full GC (Ergonomics) 71757K->61041K(185344K), 0.5344934 secs] 1.718: [GC (Allocation Failure) 109169K->109222K(200704K), 0.1078145 secs]
ケース2. -XX:+PrintGCDetails を指定してみる
VM引数に以下を指定します。GCログ取得オプションを変更しています。
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/tmp/gc2.log
取得されたログ
Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 4048172k(1446236k free), swap 4187132k(4187132k free) CommandLine flags: -XX:InitialHeapSize=64770752 -XX:MaxHeapSize=1036332032 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 2018-06-15T00:12:34.369+0900: 0.629: [GC (Allocation Failure) [PSYoungGen: 15872K->2531K(18432K)] 15872K->9585K(60928K), 0.0262355 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 2018-06-15T00:12:34.404+0900: 0.665: [GC (Allocation Failure) [PSYoungGen: 18403K->2560K(34304K)] 25457K->22305K(76800K), 0.0415842 secs] [Times: user=0.06 sys=0.01, real=0.04 secs] 2018-06-15T00:12:34.461+0900: 0.722: [GC (Allocation Failure) [PSYoungGen: 34304K->2560K(34304K)] 54049K->46964K(79360K), 0.0729155 secs] [Times: user=0.09 sys=0.01, real=0.08 secs] 2018-06-15T00:12:34.534+0900: 0.795: [Full GC (Ergonomics) [PSYoungGen: 2560K->0K(34304K)] [ParOldGen: 44404K->39959K(91648K)] 46964K->39959K(125952K), [Metaspace: 3991K->3991K(1056768K)], 0.7964764 secs] [Times: user=0.67 sys=0.18, real=0.79 secs] 2018-06-15T00:12:35.351+0900: 1.611: [GC (Allocation Failure) [PSYoungGen: 31744K->2560K(49664K)] 71703K->71735K(141312K), 0.1097980 secs] [Times: user=0.09 sys=0.02, real=0.11 secs] 2018-06-15T00:12:35.461+0900: 1.721: [Full GC (Ergonomics) [PSYoungGen: 2560K->0K(49664K)] [ParOldGen: 69175K->61019K(137728K)] 71735K->61019K(187392K), [Metaspace: 3991K->3991K(1056768K)], 0.5710107 secs] [Times: user=0.63 sys=0.20, real=0.58 secs] 2018-06-15T00:12:36.055+0900: 2.315: [GC (Allocation Failure) [PSYoungGen: 47104K->2560K(66048K)] 108123K->108176K(203776K), 0.1056789 secs] [Times: user=0.20 sys=0.01, real=0.10 secs]
GCViewerで見たグラフ
このオプションでは、より詳しい情報が取得できています。
黄色がYoung 領域で、ピンクがTenured 領域になっています。
サイズが頻繁に変わっていて、不安定な形状になっています。
ケース3. ヒープサイズを増やしてみる
VM引数に以下を指定します。
-Xms2048m -Xmx2048m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/tmp/gc3.log
取得されたログ
Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 4048172k(2316068k free), swap 4187132k(4178876k free) CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 2018-06-15T00:28:39.876+0900: 1.727: [GC (Allocation Failure) [PSYoungGen: 524800K->87011K(611840K)] 524800K->177939K(2010112K), 0.4045245 secs] [Times: user=0.72 sys=0.07, real=0.40 secs] 2018-06-15T00:28:40.551+0900: 2.403: [GC (Allocation Failure) [PSYoungGen: 611811K->87011K(611840K)] 702739K->720339K(2010112K), 1.4527595 secs] [Times: user=2.70 sys=0.15, real=1.45 secs] 2018-06-15T00:28:42.598+0900: 4.450: [GC (Allocation Failure) [PSYoungGen: 611811K->11747K(611840K)] 1245139K->645075K(2010112K), 0.0300888 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 2018-06-15T00:28:43.006+0900: 4.858: [GC (Allocation Failure) [PSYoungGen: 536547K->87011K(611840K)] 1169875K->1171891K(2010112K), 1.6728124 secs] [Times: user=2.67 sys=0.59, real=1.67 secs] 2018-06-15T00:28:44.679+0900: 6.531: [Full GC (Ergonomics) [PSYoungGen: 87011K->0K(611840K)] [ParOldGen: 1084880K->471985K(1398272K)] 1171891K->471985K(2010112K), [Metaspace: 3996K->3996K(1056768K)], 5.8750924 secs] [Times: user=8.38 sys=1.97, real=5.88 secs] 2018-06-15T00:28:50.897+0900: 12.749: [GC (Allocation Failure) [PSYoungGen: 524800K->87012K(611840K)] 996785K->792974K(2010112K), 0.8543719 secs] [Times: user=1.66 sys=0.01, real=0.86 secs] 2018-06-15T00:28:52.082+0900: 13.933: [GC (Allocation Failure) [PSYoungGen: 611812K->87008K(320000K)] 1317774K->1054921K(1718272K), 0.7219949 secs] [Times: user=1.40 sys=0.01, real=0.73 secs]
