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초까지 걸리기도 함 )
