gc.log 분석하는 방법을 작성해보려한다.

 

JVM 기동옵션은 아래와 같다.

더보기

-XX:+DisableExplicitGC : system.gc() 메소드를 수행하지 않음.

※ 자바에서 RMI ( Remote Method Invocation ) 사용시, 60초마다 system.gc() 를 호출해 Full GC 발생 

 

-XX:-UseAdaptiveSizePolicy : New 영역의 크기가 동적으로 변하지 않음

-verbose:gc : GC 기록을 출력

-Xloggc:{gc_Path}.gclog : GC를 파일로 출력함

-XX:+PrintGCDetails : GC에 대한 상세정보 출력

-XX:+PrintGCTimeStamps : GC를 초단위로 기록함

-XX:+PrintHeapAtGC : GC시에 Heap 메모리 상태 기록

 

GC 로그파일은 아래와 같다.

 

- Minor GC

 

더보기

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 354304K, used 315392K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 315392K, 100% used [0x00000007a8000000,0x00000007bb400000,0x00000007bb400000)
  from space 38912K, 0% used [0x00000007bda00000,0x00000007bda00000,0x00000007c0000000)
  to   space 38912K, 0% used [0x00000007bb400000,0x00000007bb400000,0x00000007bda00000)
 ParOldGen       total 2228224K, used 0K [0x0000000720000000, 0x00000007a8000000, 0x00000007a8000000)
  object space 2228224K, 0% used [0x0000000720000000,0x0000000720000000,0x00000007a8000000)
 Metaspace       used 11772K, capacity 12066K, committed 12160K, reserved 1060864K
  class space    used 1284K, capacity 1401K, committed 1408K, reserved 1048576K
4.788: [GC (Allocation Failure) [PSYoungGen: 315392K->19963K(354304K)] 315392K->19979K(2582528K), 0.0095085 secs] [Times: user=0.14 sys=0.02, real=0.01 secs] 


Heap after GC invocations=1 (full 0):
 PSYoungGen      total 354304K, used 19963K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 315392K, 0% used [0x00000007a8000000,0x00000007a8000000,0x00000007bb400000)
  from space 38912K, 51% used [0x00000007bb400000,0x00000007bc77ede8,0x00000007bda00000)
  to   space 38912K, 0% used [0x00000007bda00000,0x00000007bda00000,0x00000007c0000000)
 ParOldGen       total 2228224K, used 16K [0x0000000720000000, 0x00000007a8000000, 0x00000007a8000000)
  object space 2228224K, 0% used [0x0000000720000000,0x0000000720004000,0x00000007a8000000)
 Metaspace       used 11772K, capacity 12066K, committed 12160K, reserved 1060864K
  class space    used 1284K, capacity 1401K, committed 1408K, reserved 1048576K
}

한줄씩 분석해보면,

 

{Heap before GC invocations=1 (full 0):

 

- invocations=1 : 프로세스가 구동되고, 발생한 GC의 횟수

- full 0 : 발생한 Full GC 횟수

 

 PSYoungGen      total 354304K, used 315392K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)
 PSYoungGen      total 354304K, used 19963K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)

 

- Young Generation이 354,304KB 중에 315,392KB 사용중 -> 19,963KB 사용

 

  eden space 315392K, 100% used [0x00000007a8000000,0x00000007bb400000,0x00000007bb400000)
  from space 38912K, 0% used [0x00000007bda00000,0x00000007bda00000,0x00000007c0000000)
  to   space 38912K, 0% used [0x00000007bb400000,0x00000007bb400000,0x00000007bda00000)
  
  eden space 315392K, 0% used [0x00000007a8000000,0x00000007a8000000,0x00000007bb400000)
  from space 38912K, 51% used [0x00000007bb400000,0x00000007bc77ede8,0x00000007bda00000)
  to   space 38912K, 0% used [0x00000007bda00000,0x00000007bda00000,0x00000007c0000000)

- Eden 영역 100% 사용으로 인한 GC 발생으로 보임.

- GC후에 Survivor From 영역으로 이동. Eden 0% 사용

 

 ParOldGen       total 2228224K, used 0K [0x0000000720000000, 0x00000007a8000000, 0x00000007a8000000)
  object space 2228224K, 0% used [0x0000000720000000,0x0000000720000000,0x00000007a8000000)
 Metaspace       used 11772K, capacity 12066K, committed 12160K, reserved 1060864K
  class space    used 1284K, capacity 1401K, committed 1408K, reserved 1048576K

- New 영역에 대한 Minor GC 였으므로, Old 영역은 변화가 없음

 

4.788: [GC (Allocation Failure) [PSYoungGen: 315392K->19963K(354304K)] 315392K->19979K(2582528K), 0.0095085 secs] [Times: user=0.14 sys=0.02, real=0.01 secs] 

GC 결과 요약

- GC ( Allocation Failure ) : GC 발생이유. 메모리 할당 실패로 인한 GC발생

- Young 영역 정리 ( 315,392KB -> 19,963KB , 354,304KB 정리 )

- 0.0095초 소요

 


- Full GC

 

더보기

{Heap before GC invocations=3 (full 1):
 PSYoungGen      total 354304K, used 38891K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 315392K, 0% used [0x00000007a8000000,0x00000007a8000000,0x00000007bb400000)
  from space 38912K, 99% used [0x00000007bda00000,0x00000007bfffafa8,0x00000007c0000000)
  to   space 38912K, 0% used [0x00000007bb400000,0x00000007bb400000,0x00000007bda00000)
 ParOldGen       total 2228224K, used 107K [0x0000000720000000, 0x00000007a8000000, 0x00000007a8000000)
  object space 2228224K, 0% used [0x0000000720000000,0x000000072001af50,0x00000007a8000000)
 Metaspace       used 20783K, capacity 21068K, committed 21248K, reserved 1069056K
  class space    used 2337K, capacity 2460K, committed 2560K, reserved 1048576K
5.461: [Full GC (Metadata GC Threshold) [PSYoungGen: 38891K->0K(354304K)] [ParOldGen: 107K->38122K(2228224K)] 38999K->38122K(2582528K), [Metaspace: 20783K->20783K(1069056K)], 0.0532366 secs] [Times: user=0.57 sys=0.03, real=0.05 secs] 


Heap after GC invocations=3 (full 1):
 PSYoungGen      total 354304K, used 0K [0x00000007a8000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 315392K, 0% used [0x00000007a8000000,0x00000007a8000000,0x00000007bb400000)
  from space 38912K, 0% used [0x00000007bda00000,0x00000007bda00000,0x00000007c0000000)
  to   space 38912K, 0% used [0x00000007bb400000,0x00000007bb400000,0x00000007bda00000)
 ParOldGen       total 2228224K, used 38122K [0x0000000720000000, 0x00000007a8000000, 0x00000007a8000000)
  object space 2228224K, 1% used [0x0000000720000000,0x000000072253a938,0x00000007a8000000)
 Metaspace       used 20783K, capacity 21068K, committed 21248K, reserved 1069056K
  class space    used 2337K, capacity 2460K, committed 2560K, reserved 1048576K
}

- from 영역의 Full로 인한 Full GC

- Old 영역이 107KB -> 38,122KB 로 증가

- GC 소요시간은 0.053초 정도. Minor GC 의 5배 정도 시간이다. ( 0.3초까지 걸리기도 함 )

'서버운영 > 자바 GC ( Garbage Collection )' 카테고리의 다른 글

GC 튜닝  (0) 2021.04.06
GC분석 - GUI를 통한 gc 추이분석  (0) 2021.04.05
GC 관리  (0) 2021.04.04
GC ( Garbage Collection )  (0) 2021.04.04

+ Recent posts