「Java」GC ログを出力する - プログラム日記

Java の GC ログを出力する方法についてメモ ( よく忘れるのですぐに引っ張ってこれる情報として残しておく )。

java コマンドのオプションに "-Xloggc:<ファイル名>" をつけてやるだけで出力される。

・java
http://docs.oracle.com/javase/7/docs/technotes/tools/windows/java.html

とりあえず、以下のようなプログラムを用意する。

import java.util.*;
import java.lang.*;

class Sample {
	public static void main(String[] args) {
		
		System.out.println("start");
		
		for(int i = 0; i < 100; i++) {
			List<String> list = new ArrayList<String>();
			for(int j = 0; j < 10000; j++) {
				list.add("test" + j);
				System.out.println(list.get(j));
			}
		}
		System.out.println("end");
	}
}

ヒープサイズを少なめに指定して実行する。

java -Xmx5m -Xms5m -Xloggc:gc.log Sample > output.txt

すると以下のような GC ログが得られる。

0.192: [GC 2048K->887K(6144K), 0.0014012 secs]
0.255: [GC 2935K->933K(6144K), 0.0023044 secs]
 - 略 -
0.849: [GC 4467K->3786K(5632K), 0.0008509 secs]
0.850: [Full GC 3786K->994K(7168K), 0.0114225 secs]
0.889: [GC 2018K->1442K(7168K), 0.0005910 secs]
 - 略 -

あと、オプションに "-XX:+PrintGCDetails"、"-XX:+PrintGCTimeStamps" あたりを指定してやると、もう少し詳細な情報が得られるみたいです。

java -Xmx5m -Xms5m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps Sample > output.txt

0.183: [GC [PSYoungGen: 2048K->495K(2560K)] 2048K->887K(6144K), 0.0011911 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.244: [GC [PSYoungGen: 2543K->510K(2560K)] 2935K->1118K(6144K), 0.0010508 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
 - 略 -
0.847: [Full GC [PSYoungGen: 438K->0K(2048K)] [ParOldGen: 3402K->994K(5120K)] 3841K->994K(7168K) [PSPermGen: 2526K->2525K(21504K)], 0.0110775 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
0.886: [GC [PSYoungGen: 1024K->448K(2048K)] 2018K->1442K(7168K), 0.0007287 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 - 略 -

ログの見方は以下のドキュメントに書いてありました。
・JVM Performance Tuning
- Diagnosing GC Issues ( P52 あたりから )
http://www.oracle.com/technetwork/cn/community/developer-day/2-jvm-tuning-1866448-zhs.pdf

コンカレント GC にすると、以下のような GC ログになる ( この場合の見方も上記のドキュメントにちょっと記載あり )。

0.144: [GC0.144: [ParNew: 1088K->128K(1216K), 0.0019545 secs] 1088K->576K(4992K), 0.0020734 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.247: [GC0.247: [ParNew: 1216K->128K(1216K), 0.0013556 secs] 1664K->866K(4992K), 0.0014187 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.312: [GC0.312: [ParNew: 1216K->127K(1216K), 0.0010474 secs] 1954K->1144K(4992K), 0.0011114 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.362: [GC0.362: [ParNew: 1189K->128K(1216K), 0.0009632 secs] 2207K->1422K(4992K), 0.0010302 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.425: [GC0.425: [ParNew: 1216K->126K(1216K), 0.0010969 secs] 2510K->1818K(4992K), 0.0011570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.489: [GC0.489: [ParNew: 1208K->128K(1216K), 0.0009436 secs] 2900K->2207K(4992K), 0.0009910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.490: [GC [1 CMS-initial-mark: 2079K(3776K)] 2282K(4992K), 0.0002152 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.491: [CMS-concurrent-mark-start]
0.492: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.03 sys=0.02, real=0.00 secs] 
0.492: [CMS-concurrent-preclean-start]
0.493: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.493: [GC[YG occupancy: 223 K (1216 K)]0.493: [Rescan (parallel) , 0.0002837 secs]0.493: [weak refs processing, 0.0000124 secs]0.493: [scrub string table, 0.0000957 secs] [1 CMS-remark: 2079K(3776K)] 2303K(4992K), 0.0004365 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 - 略 -

このあたりはまだまだ勉強が必要ですな・・・

以上です。