티스토리 뷰

728x90
반응형

 포스팅은 GC Log 수집 및 분석 가이드입니다.


GCLog는 다양한 플랫폼 JVM의 Working 상태를 분석하고, 메모리 사용패턴을 진단하여 효율적인 Gabage Collector를 수집할 수 있도록 도와주는 역할을 합니다. 


GC log 생성 및 log 정보[포맷]

GC log 생성

[SUN]

-verbosegc : 기본적인 GC Log를 출력하기 위한 옵션 -> default로 stdout log가 기록됨. 아래의 PrintGCDetails PrintGCTimeStamps 옵션을 조합하는 것이 일반적임.

-XX:PrintGCDetail : GC에 대한 추가적인 상세 정보를 출력하기 위한 옵션

-XX:PrintGCTimeStamps : GC가 수행된 내용에 대한 timestamp 정보를 출력하기 위한 옵션

 

[HP]

-Xverbosegc : HP JVM에서 GC Log를 출력하기 위한 옵션 -> default stdout에 로그가 기록됨

-Xverbosegc:file=[파일경로]를 통해 GC Log파일 저장위치 지정 가능함

 

[IBM]

-verbosegc : GC Log를 출력하기 위한 기본 옵션 -> default stdout에 로그가 기록됨

-Xverbosegclog : -Xverbosegclog:[파일경로]를 통해 GC Log 파일 저장위치 지정 가능함

GC log 정보

[포함 내용]

GC Log에는 Heap 메모리 사용률과 GC의 수행 패턴에 대한 정보가 포함되어 있습니다.  java 계열별로 GC Log의 포맷이 다르지만 GC Log가 제시하는 정보는 동일합니다.

- 메모리 사용패턴(Memory leak or Memory 사용량 급증), GC 수행 횟수, GC 수행 시간

 

[일반적인 GC 횟수 및 time Heap size 추이]

GC Time/Heap size 추이 그래프 참고하여 Heap size가 증가하게 되면 평균 Scavenge GC에 대한 시간도 같이 증가하는 것을 알 수 있습니다. GC 횟수/Heap size 추이 그래프를 보게 되면 Heap size가 증가하게 되면 GC의 횟수는 감소하는 것을 알 수 있습니다.

따라서 Heap 메모리 사용에 있어 문제점이 없는 시스템이라면 Heap size의 크기에 따라 GC Time GC 횟수가 달라 질것입니다.  Heap size에 대한 GC Count*GC 시간이 가장 효율적인 부분이 적정 Heap size라 할 수 있습니다.

 

JAVA 계열 별 GC Log 포맷

[Sun 계열]


Sun java minor GC 포맷입니다.

 부분에 대한 설명은 다음과 같습니다.

 1 : GC 발생 시간 정보입니다. GC 발생  다음 GC 발생할 때까지의 시간 GAP 확인할  있습니다.

 2 : GC 영역을 표시합니다. DefNew Young 영역 GC 표시합니다.

 3 : GC 수행  Young 영역 사용량입니다.

 4 : GC 수행  Young 영역 사용량입니다.

 5 : Young 영역 전체 크기입니다.

 6 : Minor GC 수행에 걸린 시간입니다.

 7 : GC  전체 Heap 사용량입니다.

 8 : GC  전체 Heap 사용량입니다.

 9 : Heap 영역 전체 크기입니다.

 10 : 전체 GC 수행에 걸린 시간입니다.

 


Sun java major GC 포맷 입니다.

 부분에 대한 설명은 다음과 같습니다.

 1 : GC 발생 시간 정보입니다. GC 발생  다음 GC 발생할 때까지의 시간 GAP 확인할  있습니다.

 2 : GC 유형을 표시합니다. Full GC 수행되었음을 표시합니다.

 3 : Tenured (Old) 영역의 GC 수행 전후의 사용량과 전체 Tenured 영역의 크기  GC 수행에 걸린 시간을 표시합니다.

 4 : GC 수행 전후의 전체 Heap 사용량  전체 Heap 크기를 표시합니다.

 5 : GC 수행 전후의 Perm 영역의 사용량 표시  전체 Perm 영역의 크기를 표시합니다.

 6 : 전체 GC 수행에 걸린 시간을 표시합니다.

 

[HP 계열]

HP Java Sun 계열의 JVM을 사용하지만 GC Log는 별도의 포맷으로 생성됩니다. HP Java GC Log도 기능을 추가하여 나름대로 분석에 용이한 상세한 정보를 출력합니다.

HP는 별도의 옵션(-Xverbosegc)를 이용하여 GC의 내용을 각 라인 별로 20개의 필드로 구분하여 출력합니다.

기본 구조는 다음과 같습니다.

<GC: %1 %2 %3 %4 %5 %6 %7 %8 %9 %10 %11 %12 %13 %14 %15 %16 %17 %18 %19 %20> 

<GC: 1 0  423197.329933 6664 1154144 1 357934864 1154144 358416384 7612568 44761088 44761088 552155024 598839048 894828544 825153920 825153920 1073741824 0.298067 0.298067 >

 

<GC: 1 0  423201.261613 6665 4280 1 358413880 4280 358416384 44761088 44761088 44761088 598839048 709467424 894828544 825154312 825154312 1073741824 0.655345 0.655345 >

Field 1: GC 유형에 대한 정보를 표시합니다.  숫자에 대한 GC 유형은 다음과 같습니다.

      1 : Scavenge (Young 영역에 대한 GC)

      2 : OLD 영역 GC 또는 Full GC

      3 : Background CMS GC (GC 완료 상태)

4 : Background CMS GC (GC 미완료 상태)

Field 2 : 1 필드의 값에 대한 추가 정보를 표시합니다.

      1 필드가 1 경우 (병렬 GC 여부 표시)

       - 0 : non-parallel scavenge

       - 1 : parallel scavenge, n parallel GC Thread 수를 나타냄

      1 필드가 2 경우 (GC 발생 사유 표시)

       - 1 : Allocation failure

       - 2 : System.gc 호출 

       - 3 : Tenured Generation full 상태

       - 4 : Permanent Generation full 상태

       - 5 : Train Generation full 상태

       - 6 : CMS Generation full 상태

       - 7 : Old Generation expanded on last scavenge

       - 8 : Old Generation too full to scavenge

       - 9 : FullGCAlot

       - 10 : Allocation profiler triggered

      1 필드가 3 경우 (GC 발생 사유 표시)

       - 1 : Occupancy > initiating Occupancy

       - 2 : Expended recently

       - 3 : Incremental collection will fail

       - 4 : Linear allocation will fail

       - 5 : Anticipated promotion

      1 필드가 4 경우

(GC 발생 사유 표시  양도[yielding] 상태의 CMS 상태 표시, n.m으로 표시)

       - n 1 : Occupancy > initiating Occupancy

       - n 2 : Expended recently

       - n 3 : Incremental collection will fail

       - n 4 : Linear allocation will fail

       - n 5 : Anticipated promotion

       - n 6 : incremental CMS

       - m 0 : Reseting

       - m 1 : Idling

       - m 2 : InitialMarking

       - m 3 : Marking

       - m 4 : FinalMarking

       - m 5 : Precleaning

       - m 6 : Sweeping

Field 3: GC 수행 시작 시간을 표시 합니다. ( 단위로 표시)

Field 4: GC 수행 누적 횟수를 표시 합니다.

Field 5: GC 일으킨 Object allocation 요청 크기를 표시합니다. (byte 단위)

Field 6: New 영역에 얼마나 오랫동안 object들이 남아 있었는지 표시합니다.

Tenuring threshold 값이 출력됩니다.

Field 7: GC 수행  Eden 영역의 사용량입니다. (byte 단위)

Field 8: GC 수행  Eden 영역의 사용량입니다. (byte 단위)

Field 9: New 영역내의 Eden 영역의 전체 용량을 표시합니다. (byte 단위)

Field 10: GC 수행  Survivor 영역의 사용량입니다. (byte 단위)

Field 11: GC 수행  Survivor 영역의 사용량입니다. (byte 단위)

Field 12: New 영역내의 Suvivor 영역의 전체 용량을 표시합니다. (byte 단위)

Field 13: GC 수행  Old 영역의 사용량입니다. (byte 단위)

Field 14: GC 수행  Old 영역의 사용량입니다. (byte 단위)

Field 15: Old 영역의 전체 용량을 표시합니다. (byte 단위)

Field 16: GC 수행  Perm 영역의 사용량입니다. (byte 단위)

Field 17: GC 수행  Perm 영역의 사용량입니다. (byte 단위)

Field 18: Perm 영역의 전체 용량을 표시합니다. (byte 단위)

Field 19: GC 인해 발생한 STW(Stop the world) 시간입니다. ( 단위)

Field 20: GC 사용된  시간입니다. ( 단위)

 

[IBM 계열]

IBM Java GC Log Java 1.4 1.5 이상 버전간에 Log 포맷이 다릅니다.

위 그림은 IBM Java 1.4 GC Log 입니다.

AF (Allocation Failure) : Heap Object 할당을 위한 메모리 allocation이 불가능 한 경우 발생

 

[AF Action Code : action=??]

0 : pinned free list로부터 메모리 할당을 시도하였으나 실패한 경우

1 : Large allocation 요청을 위한 영역인 wilderness 사용을 피하기 위해 (compaction 피하기 위해) GC 수행  경우

2 : wilderness 외의 영역에 메모리 할당을 시도하였으나 실패한 경우

3 : GC Heap 확장(expand) 시도하는 경우

4 : GC 남아 있는 soft reference들을 정리하는 경우 -> 최대 확장  Heap에서 사용 가능한 공간이 12%이하일 경우 발생 

5 : Resettable mode(z/OS only) 적용되며, transient heap 영역에 대한 확보를 시도하는 경우

6 : action 내용은 없음. Heap space 낮거나, 전체적으로 heap space 초과상태에 대한 메시지가 출력됨


Ex) GC 예제

<GC(3) : GC cycle started Tue Mar 19 08:24:34 2014>

<GC(3) : freed 58808 bytes, 27% free (1163016/4192768), in 14ms>

<GC(3) : Mark: 13ms, sweep: 1ms, compact 0ms>

<GC(3) : refs: soft 0 (age>=32), weak 0, final 0, phantom 0>

위 로그는 System.gc()로 인한 GC Log 입니다.

System.gc()로 인해 강제적으로 GC가 수행 될 경우, AF에 대한 로그는 남지 않고, GC에 대한 내용만 기록됩니다. 

<af type="tenured" id="15" timestamp=" Tue Mar 19 07:24:34 2014"

intervalms="15645.865">

- AF 유형 표시  발생 순번, 시간, INTERVAL 정보 표시

<minimum requested_bytes="24" />

- Allocation request bytes 

<time exclusiveaccessms="0.447">

<tenured freebytes="4294656" totalbytes="1073741824" percent="0">

<soa freebytes="0" totalbytes="1069447168" percent="0" />

<loa freebytes="4294656" totalbytes="4294656" percent="100" />

</tenured>

- GC 전의 tenured 영역 사용율 정보

<gc type="global" id="15" totalid="15" intervalms="15656.499">

<refs_cleared soft="192" weak="601" phantom="0" />

<finalization objectsqueued="5794" />

<timesms mark="182.440" sweep="24.124" compact="0.000" total="206.892" />

<tenured freebytes="996318152" totalbytes="1073741824" percent="92">

<soa freebytes="993097160" totalbytes="1070520832" percent="92" />

<oa freebytes="3220992" totalbytes="3220992" percent="100" />

</tenured>

<gc>

- GC 수행 관련 정보

<tenured freebytes="996317632" totalbytes="1073741824" percent="92">

<soa freebytes="993096640" totalbytes="1070520832" percent="92" />

<loa freebytes="3220992" totalbytes="3220992" percent="100" />

</tenured>

- GC  tenured 영역 사용율 정보

<time totalms="216.231" />

- 전체 GC 수행 시간

</af>

위 그림은 IBM Java 1.5 GC Log 입니다.

AF (Allocation Failure) : Heap Object 할당을 위한 메모리 allocation이 불가능 한 경우 발생

system.gc()의 경우 af 대신 sys로 출력 됩니다.

<sys id=”1” timestamp=" Tue Mar 19 07:24:34 2014" intervalms="15645.865">

..

..

..

 

[Heap Expansion이 발생할 수 있는 case]

순번 1 : GC 요청한 메모리를 안정적으로 할당할 충분한 여유 공간을 확보하지 못할 경우

순번 2 : Heap 여유 공간이 최소 여유 공간보다 작을 경우 -> 최소 여유 공간은 Xminf 파라미터를 통해 설정이 가능하며 기본값이 30%

순번 3 : Garbage Collection 걸린 시간이 전체 JVM 수행 시간의 13%(default)보다  경우

 

GC Log는 말 그대로 Gabage Collector 입니다. JVM의 쓰레기를 자동으로 치워주는 역할을 하는 것입니다. 이에 따라 때로는 성능 저하를 일으키거나, 심하게는 장애를 유발하기도 합니다. 이에 개발자나 운영자 또는 JVM을 사용하는 모든 벤더사에서는 구조와 동작방식을 정확히 이해하는 것이 필요합니다.

728x90
반응형