EXEM Knowledge Base

[편집] 개요

GC Dump는 JVM의 Heap 사용 현황을 파악하는 가장 기본적인 도구이다. GC Dump를 이용하면 다음과 같은 정보를 얻을 수 있다.

• GC 발생 시간
• GC 수행 소요 시간
• GC 발생 당시 Heap Usage

GC Dump는 시스템에 부하는 부하가 작기 때문에 운영 시스템에서 GC Dump를 남기는 옵션을 켜둘 것을 권장한다. 만일 메모리 문제가 발생했을 경우 GC Dump만으로 정보가 부족할 경우에는 Heap Dump를 이용해서 추가적인 분석을 수행할 수 있다. 단, Heap Dump는 시스템에 상당한 부하를 줄 수 있기 때문에 꼭 필요한 경우에만 사용해야 한다.

[편집] Sun Hotspot JVM

Sun Hotspot JVM에서는 다음과 같은 옵션들을 이용해서 GC Dump를 제어한다.

• PrintGCDetails : GC 수행 상세 정보를 출력한다.
• PrintGCTimeStamps : GC 발생 시간 정보를 출력한다.
• PrintHeapAtGC : GC 발생시 Heap 상세 정보를 출력한다.
• -Xloggc:<file>: GC Dump를 저장할 파일명을 지정한다. 따로 지정하지 않으면 Console에 바로 출력된다.

[편집] 기본 포맷

GC Dump의 출력 결과는 기본적으로 다음과 같은 포맷을 지닌다.

• 시간(JVM 시작이후의 시간)
• Generation이름(DefNew+Tenured, PSYoungGen+PSOldGen, ParNew+CMS-concurrent-mark)
• Heap Usage 변동: {GC전 Usage} -> {GC후 Usage}({Total Size})
  • 예를 들어 896K->64K(960K) 이면 GC 전에는 896K를 사용했으며, GC 후 64K로 사용량이 줄었으며, 전체 크기는 960K라는 의미이다.
• GC 소요 시간: GC를 수행하는데 걸린 시간

아래 간단한 예제가 있다.

0.186: [GC 0.186: [DefNew: 896K->64K(960K), 0.0022028 secs] 896K->434K(5056K), 0.0023143 secs]

위의 예제가 의미하는 바는 다음과 같다.

• JVM 구동후 0.186 초에 수행된 GC 작업이다.
• DefNew는 Default Serial Collector에서의 Young Generation을 의미한다. 즉 Minor GC가 수행되었다.
• Young Generation의 크기는 960K이며, 896K를 사용 중이었고, GC 작업에 의해 64K만을 사용하게 되었다. 즉, GC에 의해 832K(896-64)가 Collection 되었다.
• Minor GC 작업에 0.0022028 초가 소요되었다.
• 전체 Heap 크기는 5056K이며, Minor GC에 의해 사용량이 896K에서 434K로 줄어들었다.
• Minor GC를 포함해 GC를 수행하는데 총 소요된 시간은 0.0023143 초이다.

[편집] Collector 종류별 포맷

[편집] Serial Collector

Serial Collector는 UseSerialGC 옵션을 이용해 활성화된다. Serial Collector는 Young Generation과 Old Generation 정리 작업에 모두 Serial 방식, 즉 하나의 Thread(Single Thread)를 사용해서 GC 작업을 수행한다. Serial Collector에 의한 GC Dump에는 다음과 같은 세 가지 종류의 로그가 기록된다.

-- Minor GC
0.186: [GC 0.186: [DefNew: 896K->64K(960K), 0.0022028 secs] 896K->434K(5056K), 0.0023143 secs]

-- Major GC (Promotion Failure 발생)
1.388: [GC 1.388: [DefNew: 3839K->383K(3840K), 0.0064941 secs]
 1.394: [Tenured: 50563K->49784K(50592K), 0.1538941 secs] 53367K->49784K(54432K), 0.1605942 secs]

-- Full GC
2.425: [Full GC 2.425: [Tenured: 60543K->60543K(60544K), 0.1595010 secs] 65087K->64787K(65088K), 
 [Perm : 391K->391K(12288K)], 0.1596044 secs]

Serial Collector에서의 GC Dump의 전체 샘플은 Serial Collector GC Log Sample을 참조한다.

[편집] Parallel Collector

Parallel Collector는 UseParallelGC 옵션을 이용해 활성화된다. Parallel Collector는 Young Generation 정리 작업에 Parallel 방식, 즉 여러 개의 Thread를 사용한다. Enterprise 급의 대형 Application에서는 매우 큰 크기의 Young Generation을 사용하게 된다. 이 경우 Minor GC에 많은 시간이 걸릴 수 있다. Parallel Collector는 Minor GC 작업에 Multi Thread를 사용함으로써 Minor GC에 의한 Pause Time을 최소화한다. UseParallelOldGC 옵션을 이용하면 Old Generation에 대해서도 Parallel 방식을 사용할 수 있다.
Parallel Collector에 의한 GC Dump에는 다음과 같은 종류의 로그가 기록된다.

-- Minor GC
0.893: [GC [PSYoungGen: 28023K->10311K(25728K)] 49157K->38181K(56000K), 0.0556451 secs]

-- Full GC
1.460: [Full GC [PSYoungGen: 4032K->0K(26880K)] [PSOldGen: 49402K->51007K(66752K)] 53434K->51007K(93632K) 
 [PSPermGen: 2003K->2003K(12288K)], 0.1678135 secs]

Parallel Collector에서의 GC Dump의 전체 샘플은 Parallel Collector GC Log Sample을 참조한다.

[편집] CMS Collector

CMS Collector는 UseConcMarkSweepGC 옵션에 의해 활성화된다. CMS Collector는 Full GC에 의한 Pause Time을 최소화하기 위해 Old Generation에 대한 정리 작업을 Concurrent 방식으로 진행한다. CMS Collector에 의한 GC Dump에는 다음과 같은 종류의 로그가 기록된다.

-- Minor GC
0.138: [GC 0.138: [ParNew: 26240K->3264K(29504K), 0.0503947 secs] 26240K->8241K(521024K), 0.0505461 secs]

-- Concurrent GC
2.593: [GC [1 CMS-initial-mark: 259838K(491520K)] 263365K(521024K), 0.0023419 secs]
2.596: [CMS-concurrent-mark-start]
4.357: [CMS-concurrent-mark: 0.655/1.761 secs]
4.357: [CMS-concurrent-preclean-start]
4.419: [CMS-concurrent-preclean: 0.040/0.062 secs]
4.419: [CMS-concurrent-abortable-preclean-start]
4.428: [CMS-concurrent-abortable-preclean: 0.007/0.010 secs
4.588: [GC[YG occupancy: 3619 K (29504 K)]4.588: [Rescan (parallel) , 0.0148329 secs]4.603: [weak refs processing, 0.0000291 secs] [1 CMS-remark: 422939K(491520K)] 426559K(521024K), 0.0149645 secs]
4.688: [CMS-concurrent-sweep-start]
5.425: [CMS-concurrent-sweep: 0.302/0.737 secs]
5.425: [CMS-concurrent-reset-start]
5.489: [CMS-concurrent-reset: 0.014/0.064 secs]

CMS Collector에서의 GC Dump의 전체 샘플은 CMS Collector GC Log Sample을 참조한다.

[편집] Memory Leak과 GC Dump

Memory Leak이 발생한 경우 GC Dump은 다음과 같은 전형적인 패턴을 보인다.

1.564: [GC 1.564: [DefNew: 4543K->447K(4544K), 0.0074507 secs] 55108K->52239K(65088K), 0.0075322 secs]
1.576: [GC 1.576: [DefNew: 4543K->447K(4544K), 0.0084435 secs] 56335K->54675K(65088K), 0.0085257 secs]
1.589: [GC 1.589: [DefNew: 4543K->447K(4544K), 0.0072420 secs] 58771K->55902K(65088K), 0.0073378 secs]
1.600: [GC 1.600: [DefNew: 4543K->447K(4544K), 0.0073699 secs] 59998K->57130K(65088K), 0.0074590 secs]
1.610: [GC 1.610: [DefNew: 4543K->447K(4544K), 0.0075529 secs] 61226K->58357K(65088K), 0.0076395 secs]
1.621: [GC 1.621: [DefNew: 4543K->447K(4544K), 0.0074387 secs] 62453K->59585K(65088K), 0.0075247 secs]
1.632: [GC 1.632: [DefNew: 4543K->4543K(4544K), 0.0000433 secs] 63681K->63681K(65088K), 0.0001028 secs]
1.632: [Full GC 1.632: [Tenured: 59137K->57835K(60544K), 0.2154176 secs] 63681K->57835K(65088K), [Perm : 392K->391K(12288K)], 0.2155249 secs]
1.851: [GC 1.851: [DefNew: 4096K->447K(4544K), 0.0057781 secs] 61931K->59063K(65088K), 0.0058661 secs]
1.860: [GC 1.860: [DefNew: 4543K->447K(4544K), 0.0071495 secs] 63159K->60291K(65088K), 0.0072347 secs]
1.870: [GC 1.871: [DefNew: 4543K->4543K(4544K), 0.0000335 secs]1.871: [Tenured: 59843K->60543K(60544K), 0.1666050 secs] 64387K->61519K(65088K), 0.1667678 secs]
2.038: [Full GC 2.038: [Tenured: 60543K->60543K(60544K), 0.1665533 secs] 62712K->61855K(65088K), [Perm : 391K->391K(12288K)], 0.1666667 secs]
2.234: [Full GC 2.234: [Tenured: 60543K->60543K(60544K), 0.1607975 secs] 65087K->64658K(65088K), [Perm : 391K->391K(12288K)], 0.1609087 secs]
2.425: [Full GC 2.425: [Tenured: 60543K->60543K(60544K), 0.1595010 secs] 65087K->64787K(65088K), [Perm : 391K->391K(12288K)], 0.1596044 secs]

위의 패턴은 다음과 같이 해석할 수 있다.

• Minor GC가 계속해서 일어남에도 불구하고 Heap 사용량이 계속해서 증가하기만 한다.
• Young Generation과 Old Generation이 모두 꽉찬 시점이 되면 계속해서 Full GC만이 발생한다.
• 최종적으로 Out Of Memory Error가 발생하게 된다.

[편집] IBM JVM

IBM JVM에서는 다음 옵션들을 이용해서 GC Dump를 제어한다.

• verbosegc : GC Dump를 남길 것을 지정한다. (예: -verbosegc)
• verbosegclog : GC Dump를 남길 File 이름을 지정한다. (예: -Xverbosegclog:gc.log)

IBM JVM은 Sun Hotspot JVM과는 달리 XML 포맷의 로그를 남긴다. 일반적인 포맷(Generational Collection을 사용하지 않는 경우)은 다음과 같다.

<af type="tenured" id="1" timestamp="Tue Oct 23 00:33:18 2007" intervalms="0.000">
  <minimum requested_bytes="32" />
  <time exclusiveaccessms="0.037" />
  <tenured freebytes="209408" totalbytes="4194304" percent="4" >
    <soa freebytes="0" totalbytes="3984896" percent="0" />
    <loa freebytes="209408" totalbytes="209408" percent="100" />
  </tenured>
  <gc type="global" id="1" totalid="1" intervalms="0.000">
    <expansion type="tenured" amount="1048576" newsize="5242880" timetaken="0.010" reason="insufficient free space following gc" />
    <refs_cleared soft="6" weak="8" phantom="0" />
    <finalization objectsqueued="9" />
    <timesms mark="5.154" sweep="0.138" compact="0.000" total="5.405" />
    <tenured freebytes="1696464" totalbytes="5242880" percent="32" >
      <soa freebytes="1520336" totalbytes="5066752" percent="30" />
      <loa freebytes="176128" totalbytes="176128" percent="100" />
    </tenured>
  </gc>
  <tenured freebytes="1695728" totalbytes="5242880" percent="32" >
    <soa freebytes="1519600" totalbytes="5066752" percent="29" />
    <loa freebytes="176128" totalbytes="176128" percent="100" />
  </tenured>
  <time totalms="5.590" />
</af>

용어의 의미는 다음과 같다.

• af는 Allocation Failure의 약자로 새로운 Object를 위한 메모리를 할당받는데 실패했다는 것을 의미한다.
• gc는 Garbage Collection의 약자로 Allocation Failure에 의해 GC가 발생했다는 것을 의미한다.
• soa는 Small Object Area의 약자로 크기가 작은 Object들이 거주하는 공간을 의미한다.
• loa는 Large Object Area의 약자로 크기가 큰 Object들이 거주하는 공간을 의미한다.
• 'expansion은 Free Memory 부족으로 인해 Heap Expansion이 발생했다는 것을 의미한다.
• intervalms, timetaken, timems, totalms 등의 값을 통해 GC 수행 시간 정보를 알 수 있다.

이 용어를 이용해서 위의 GC Log를 분석하면 다음과 같은 사실들을 알 수 있다.

• GC 작업 이전의 Total Heap은 4M(4194304)이며, Free Heap은 200K(209408)였다.
• GC 과정에서 Expansion이 발생했으며 1M(1048576)만큼 Heap 크기가 증가했다.
• Mark에 5.154ms, Sweep에 0.138ms가 소요되었으며 Compaction은 일어나지 않았다.
• GC 작업 후 Free Heap은 1.6M(1695728), Total Heap은 5M(5242880)로 증가했다.

[편집] Throughput Collector

Throughput Collector는 gcpolicy(-Xgcpolicy:optthruput) 옵션에 의해 활성화된다. Throughput, 즉 일량을 최대화하게끔 작동한다. Throughput Collector에 의한 GC Dump에는 다음과 같은 정보가 기록된다.

...            
<af type="tenured" id="21" timestamp="Tue Oct 23 00:33:27 2007" intervalms="1441.639">
  <minimum requested_bytes="32" />
  <time exclusiveaccessms="0.055" />
  <tenured freebytes="0" totalbytes="764988928" percent="0" >
    <soa freebytes="0" totalbytes="764988928" percent="0" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>   
  <gc type="global" id="21" totalid="21" intervalms="1441.756">
    <compaction movecount="1913517" movebytes="123114336" reason="compact to aid heap contraction" />
    <contraction type="tenured" amount="38248960" newsize="726739968" timetaken="0.949" reason="excess free space following gc" />
    <refs_cleared soft="0" weak="0" phantom="0" />
    <finalization objectsqueued="0" />
    <timesms mark="315.329" sweep="5.649" compact="443.578" total="767.525" />
    <tenured freebytes="603616120" totalbytes="726739968" percent="83" >
      <soa freebytes="603616120" totalbytes="726739968" percent="83" />
      <loa freebytes="0" totalbytes="0" percent="0" />
    </tenured> 
  </gc>        
  <tenured freebytes="603550584" totalbytes="726739968" percent="83" >
    <soa freebytes="603550584" totalbytes="726739968" percent="83" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>   
  <time totalms="767.678" />
</af>   
...

IBM JVM은 기본적으로 Generation을 사용하지 않기 때문에 Minor GC와 Major GC의 구분이 없다. Generation을 사용하지 않기 때문에 항상 모든 Heap 영역이 GC 대상이 된다. gc type="global"이 의미하는 바가 이것이다.

[편집] Response Time Collector

Response Time Collector는 gcpolicy(-Xgcpolicy:optavgpause) 옵션에 의해 활성화된다. Response Time, 즉 응답 시간을 최적화하게끔 작동한다. Response Time Collector에 의한 GC Dump에는 다음과 같은 정보가 기록된다.

...
<af type="tenured" id="9" timestamp="Tue Oct 23 00:34:10 2007" intervalms="8099.846">
  <minimum requested_bytes="88" />
  <time exclusiveaccessms="0.036" />
  <tenured freebytes="0" totalbytes="1072750592" percent="0" >
    <soa freebytes="0" totalbytes="1072750592" percent="0" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>
  <con event="completed full sweep" timestamp="Tue Oct 23 00:34:10 2007">
    <stats sweepbytes="0" sweeptime="0.088" connectbytes="0" connecttime="0.003" />
  </con>
  <gc type="global" id="20" totalid="20" intervalms="1752.723">
    <refs_cleared soft="0" weak="0" phantom="0" />
    <finalization objectsqueued="0" />
    <timesms mark="320.279" sweep="218.930" compact="0.000" total="539.259" />
    <tenured freebytes="261405180" totalbytes="1072750592" percent="24" >
      <soa freebytes="261405180" totalbytes="1072750592" percent="24" />
      <loa freebytes="0" totalbytes="0" percent="0" />
    </tenured>
  </gc>
  <tenured freebytes="261404428" totalbytes="1072750592" percent="24" >
    <soa freebytes="261404428" totalbytes="1072750592" percent="24" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>
  <time totalms="539.514" />
</af>
...

Response Time Collector 또한 Generation을 사용하지 않는다. 따라서 Throughput Collector와 같이 gc type="global"로 표현된다.

[편집] Concurrent Generational Collector

Concurrent Generational Collector는 gcpolicy(-Xgcpolicy:gencon) 옵션에 의해 활성화된다. IBM JDK 1.5에서 새롭게 추가되었으며 Sun Hotspot JVM의 CMS Collector와 매우 유사한 기법을 사용한다. Concurrent Generational Collector에 의한 GC Dump에는 다음과 같은 로그가 기록된다.

...
<af type="nursery" id="91" timestamp="Tue Oct 23 00:34:50 2007" intervalms="27.674">
  <minimum requested_bytes="32" />
  <time exclusiveaccessms="0.053" />
  <nursery freebytes="0" totalbytes="38255104" percent="0" />
  <tenured freebytes="92785912" totalbytes="372438528" percent="24" >
    <soa freebytes="92785912" totalbytes="372438528" percent="24" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>
  <gc type="scavenger" id="91" totalid="101" intervalms="27.755">
    <flipped objectcount="161001" bytes="9015948" />
    <tenured objectcount="300702" bytes="16428048" />
    <refs_cleared soft="0" weak="0" phantom="0" />
    <finalization objectsqueued="0" />
    <scavenger tiltratio="60" />
    <nursery freebytes="30438400" totalbytes="40268800" percent="75" tenureage="1" />
    <tenured freebytes="74960120" totalbytes="372438528" percent="20" >
      <soa freebytes="74960120" totalbytes="372438528" percent="20" />
      <loa freebytes="0" totalbytes="0" percent="0" />
    </tenured>
    <time totalms="86.476" />
  </gc>
  <nursery freebytes="30436352" totalbytes="40268800" percent="75" />
  <tenured freebytes="74960120" totalbytes="372438528" percent="20" >
    <soa freebytes="74960120" totalbytes="372438528" percent="20" />
    <loa freebytes="0" totalbytes="0" percent="0" />
  </tenured>
  <time totalms="86.610" />
</af>
...

Concurrent Generational Collector는 Generation에 기반한다. 따라서 Minor GC와 Major GC와 같은 구분이 존재한다. IBM JVM에서는 Scavenger GC와 Global GC라는 용어가 사용된다. 위의 예에서 af type="nursery", gc type="scavenger"가 의미하는 것은 Nursery, 즉 Young Generation에서 GC가 발생했으며, Scavenger GC, 즉 Minor GC가 발생했다는 것을 의미한다.

[편집] 관련 정보

1. Garbage Collector

[편집] 외부 참조