자바에서 GC 로그를 남길 수 있다.

다음은 GC 테스트를 위한 프로그램이다.

import java.util.Map;
import java.util.WeakHashMap;

import org.junit.Test;

public class GcTest {

 @Test
 public void testGcLog() {
  Map<Double, Double> map = new WeakHashMap<Double, Double>();
  while (true) {
   map.put(Math.random(), Math.random());
  }
 }

}

간단하게는 다음 옵션을 사용할 수 있다.

-verbose:gc

결과는 다음과 같다.

[GC 32704K->25359K(125056K), 0.0266314 secs]
[GC 58063K->50831K(157760K), 0.0389435 secs]
[GC 116239K->110463K(176384K), 0.0773596 secs]
[Full GC 110463K->85796K(270912K), 0.3572675 secs]
[GC 151204K->149420K(296896K), 0.2064152 secs]

GC는 minor GC를, Full GC는 major GC를 의미한다.

'->' 전의 값은 GC 전의 힙 (Heap) 크기이고 후의 값은 GC 후의 힙 크기이다.

괄호 안의 값은 Committed 힙 크기로 OS (Operating System)로부터 확보한 힙 크기이다.

더 자세한 정보를 보고 싶다면 다음 옵션을 사용한다.

-XX:+PrintGCDetails

결과는 다음과 같다.

[GC [PSYoungGen: 32704K->5369K(38080K)] 32704K->25317K(125056K), 0.0246504 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
[GC [PSYoungGen: 38073K->5369K(70784K)] 58021K->50853K(157760K), 0.0345281 secs] [Times: user=0.17 sys=0.02, real=0.03 secs]
[GC [PSYoungGen: 70777K->5353K(70784K)] 116261K->110461K(176192K), 0.0658082 secs] [Times: user=0.41 sys=0.02, real=0.07 secs]
[Full GC [PSYoungGen: 5353K->0K(70784K)] [PSOldGen: 105107K->85759K(201216K)] 110461K->85759K(272000K) [PSPermGen: 4349K->4349K(21248K)], 0.3772447 secs] [Times: user=0.37 sys=0.00, real=0.38 secs]
[GC [PSYoungGen: 65408K->5376K(94784K)] 151167K->149391K(296000K), 0.2028507 secs] [Times: user=0.79 sys=0.01, real=0.20 secs]

Generation 별로 보여주고, 소요 시간도 user, sys, real로 구분해서 보여준다.

하지만 시간 정보가 빠져있다.

타임스탬프 (Timestamp)를 같이 기록하기 위해 다음과 같이 한다.

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps

결과는 다음과 같다.

0.274: [GC [PSYoungGen: 32704K->5369K(38080K)] 32704K->25360K(125056K), 0.0251832 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
0.381: [GC [PSYoungGen: 38073K->5353K(70784K)] 58064K->50848K(157760K), 0.0348441 secs] [Times: user=0.19 sys=0.00, real=0.03 secs]
0.588: [GC [PSYoungGen: 70761K->5353K(70784K)] 116256K->110480K(176000K), 0.0660660 secs] [Times: user=0.39 sys=0.02, real=0.07 secs]
0.654: [Full GC [PSYoungGen: 5353K->0K(70784K)] [PSOldGen: 105126K->85768K(201024K)] 110480K->85768K(271808K) [PSPermGen: 4349K->4349K(21248K)], 0.3657664 secs] [Times: user=0.37 sys=0.00, real=0.37 secs]
1.454: [GC [PSYoungGen: 65408K->5376K(94656K)] 151176K->149384K(295680K), 0.1594115 secs] [Times: user=0.81 sys=0.00, real=0.16 secs]

각 GC 간에 얼마의 시간이 소요되었는지 한눈에 볼 수 있지만,

언제였는지 알기 위해서는 처리가 필요하다.

날짜와 시간을 같이 기록하기 위해 다음과 같이 한다.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

결과는 다음과 같다.

2012-08-04T17:43:56.609+0900: [GC [PSYoungGen: 32704K->5369K(38080K)] 32704K->25223K(125056K), 0.0281648 secs] [Times: user=0.11 sys=0.02, real=0.03 secs]
2012-08-04T17:43:56.720+0900: [GC [PSYoungGen: 38073K->5353K(70784K)] 57927K->50263K(157760K), 0.0503802 secs] [Times: user=0.22 sys=0.00, real=0.05 secs]
2012-08-04T17:43:56.942+0900: [GC [PSYoungGen: 70761K->5353K(70784K)] 115671K->109415K(174848K), 0.0612401 secs] [Times: user=0.44 sys=0.03, real=0.06 secs]
2012-08-04T17:43:57.003+0900: [Full GC [PSYoungGen: 5353K->0K(70784K)] [PSOldGen: 104062K->85019K(198656K)] 109415K->85019K(269440K) [PSPermGen: 4349K->4349K(21248K)], 0.3622474 secs] [Times: user=0.36 sys=0.02, real=0.36 secs]
2012-08-04T17:43:57.807+0900: [GC [PSYoungGen: 65408K->5376K(96448K)] 150427K->148643K(295104K), 0.1734960 secs] [Times: user=0.72 sys=0.03, real=0.17 secs]

필요에 따라 날짜와 시간 그리고 타임스탬프를 기록하기 위해 다음과 같이 할 수 있다.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

결과는 다음과 같다.

2012-08-04T18:07:41.646+0900: 0.275: [GC [PSYoungGen: 32704K->5353K(38080K)] 32704K->25320K(125056K), 0.0242501 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
2012-08-04T18:07:41.756+0900: 0.385: [GC [PSYoungGen: 38057K->5353K(70784K)] 58024K->50840K(157760K), 0.0331700 secs] [Times: user=0.19 sys=0.00, real=0.03 secs]
2012-08-04T18:07:41.956+0900: 0.585: [GC [PSYoungGen: 70761K->5369K(70784K)] 116248K->110456K(176000K), 0.0633566 secs] [Times: user=0.39 sys=0.05, real=0.06 secs]
2012-08-04T18:07:42.019+0900: 0.648: [Full GC [PSYoungGen: 5369K->0K(70784K)] [PSOldGen: 105086K->85751K(201408K)] 110456K->85751K(272192K) [PSPermGen: 4349K->4349K(21248K)], 0.3739181 secs] [Times: user=0.37 sys=0.00, real=0.37 secs]
2012-08-04T18:07:42.843+0900: 1.472: [GC [PSYoungGen: 65408K->5376K(94336K)] 151159K->149375K(295744K), 0.1934554 secs] [Times: user=1.06 sys=0.00, real=0.19 secs]

로그 파일 지정은 다음과 같이 할 수 있다.

-Xloggc:gc.log

레퍼런스에 따르면 -XX:+PrintGCDateStamp는 1.6u4부터 지원되는 것으로 보인다.

References:
http://cleanjava.wordpress.com/2011/07/05/how-to-print-gcgarbage-collector-log-in-jvm/
http://www.williamhathaway.com/wordpress/2009/09/01/printing-java-garbage-collection-time-stamps/
http://stackoverflow.com/questions/895444/java-garbage-collection-log-messages

Posted by izeye