jstat コマンドで GC の様子を見てみる

何も特別なことはしていません。最近あまり使うことがなかったので。

サンプル用プログラム

一応、何らかのJavaプロセスを起動する必要があったので、単に1000万要素のList と Map を延々と作り続けるプログラムを用意。

public class GcTest {

  private static int numberOfData = 10000000;
  private static StopWatch stopWatch = new StopWatch();
  private static Integer counter = 1;

  public static void main(String[] args) {
	while (true) {
		System.out.println("----- attempt:" + counter + " -----");
		GcTest.createBigList();
		GcTest.createBigMap();
		counter++;
	}
  }

  private static void createBigList() {
	System.out.println("BigList");
	stopWatch.start();
	List<Integer> bigList = new ArrayList<>();
		
	// save
	IntStream.rangeClosed(0, numberOfData).forEach(i -> bigList.add(i));
		
	// load
	IntStream.rangeClosed(0, numberOfData).forEach(i -> bigList.get(i));
		
	System.out.println(stopWatch.getTime());
	stopWatch.reset();
  }
	
  private static void createBigMap() {
	System.out.println("BigMap");
	stopWatch.start();
		
	Map<Integer, Integer> bigMap = new HashMap<>();
	// save
	IntStream.rangeClosed(0, numberOfData).forEach(i -> bigMap.put(i, i));
		
	// load
	IntStream.rangeClosed(0, numberOfData).forEach(i -> bigMap.get(i));
		
	System.out.println(stopWatch.getTime());
	stopWatch.reset();
  }
}

jstat コマンド

Java プログラム開始後、プロセスIDを取得し、以下のコマンドを実行。

$ jstat -gcutil -h10 [プロセスID] 1000

gcutil : ガベージ・コレクション統計データのサマリー
h10 : 10行ごとにヘッダー表示
1000 : 1000ミリ秒ごとに更新

出力結果

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00  73.27   0.00 100.00  81.69  86.79     13    2.434     6    3.997    6.432
  0.00  73.18 100.00  69.69  81.69  86.79     14    2.434     6    7.437    9.871
 77.36   0.00   0.00  85.64  81.69  86.79     14    3.095     7    7.437   10.532
 77.36   0.00   0.00  85.64  81.69  86.79     14    3.095     7    7.437   10.532
 77.36   0.00   0.00  85.64  81.69  86.79     14    3.095     7    7.437   10.532
  0.00  22.87 100.00  73.65  81.69  86.79     15    3.095     7   10.685   13.781
 71.76   0.00   0.00  90.36  81.86  86.90     16    4.060     8   10.685   14.746
 71.76   0.00   0.00  90.36  81.86  86.90     16    4.060     8   10.685   14.746
 71.76   0.00   0.00  90.36  81.86  86.90     16    4.060     8   10.685   14.746
 71.76   0.00   0.00  90.36  81.86  86.90     16    4.060     8   10.685   14.746
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
 71.76   0.00   0.00  90.36  81.86  86.90     16    4.060     8   10.685   14.746
 14.00   0.00 100.00  99.93  81.86  86.90     16    4.060     9   15.546   19.606
 14.00   0.00 100.00  99.93  81.86  86.90     16    4.060     9   15.546   19.606
 14.00   0.00 100.00  99.93  81.86  86.90     16    4.060     9   15.546   19.606
 14.00   0.00  92.92  99.93  81.86  86.90     16    4.060    10   18.503   22.563
 99.12  78.71 100.00  17.41  81.86  86.90     18    4.193    10   19.029   23.222
 99.97   0.00   0.00  69.26  81.86  86.90     20    5.178    11   19.029   24.207
 99.97   0.00   0.00  69.26  81.86  86.90     20    5.178    11   19.029   24.207
  0.00  36.70 100.00  31.31  81.86  86.90     21    5.178    11   21.052   26.230
  0.00  99.97   5.99  64.73  81.86  86.90     23    6.104    11   21.052   27.156

これで１周分（List作成とMap作成をそれぞれ１回ずつ）くらい。
想像していたよりも、GCの回数（フルGC）を含めて多い。
それぞれのオブジェクト（List, Map）を生成するのに要した時間は以下のとおり。
BigList 2510ms
BigMap 16847ms

BigMap 生成に 17秒近く要している。
ただ、フルGCだけでトータル21秒近く要していることから、Map生成処理そのものよりも、フルGCが原因で待たされていた可能性がある。
あとで、ヒープサイズを増やして試してみる。