본문 바로가기

알아두면 좋은 IT 지식/Java

GC 로그 분석 툴 - jstat 사용법

GC(Garbage Collection) 란?

메모리 관리 기법 중의 하나로, 프로그램이 동적으로 할당했던 메모리 영역 중에서 필요없게 된 영역을 해제하는 기능이다.

(출처 : 위키백과)

GC 로그 분석이 필요한 이유?

프로그램의 성능 문제나 메모리 관련 이슈(OOM 등) 발생 시 GC 로그 분석을 통해서 원인 파악 및 해결책(GC 튜닝 등)을 찾을 수 있다.

왜 jstat를 사용하는가?

Java HotSpot VM에 내장된 API를 사용하므로 추가 설치나 jvm옵션이 필요없고 동작 중인 서비스에 영향을 주지 않는다.

 

 

 

사용예제

jdk 설치 시 $JAVA_HOME/bin/jstat 유틸리티를 아래와 같이 여러 옵션을 추가하여 사용할 수 있다.

 

1. jstat -gcutil

PID가 29597인 프로세스에 연결하여 250ms간격으로 10번 반복해서 gc 요약 통계 샘플 수집 명령어 실행 결과

 

user@hostname:~/jdk1.8.0_333/bin$ jstat -gcutil 29597 250 10

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  
 99.97   0.00  77.41  21.93  96.71  92.99    174   18.056     3    0.593   18.649
  0.00  48.94  15.43  21.93  96.71  92.99    175   18.075     3    0.593   18.667
  0.00  48.94  49.92  21.93  96.71  92.99    175   18.075     3    0.593   18.667  --3행
 51.14   0.00   0.00  21.94  96.72  92.99    176   18.090     3    0.593   18.683  --4행
 51.14   0.00  29.71  21.94  96.72  92.99    176   18.090     3    0.593   18.683
 51.14   0.00  87.86  21.94  96.72  92.99    176   18.090     3    0.593   18.683
  0.00  99.63  36.60  21.94  96.72  92.99    177   18.115     3    0.593   18.708
  0.00  99.63  93.45  21.94  96.72  92.99    177   18.115     3    0.593   18.708
 70.00   0.00  58.40  21.94  96.72  92.99    178   18.148     3    0.593   18.741
  0.00  99.72  20.03  21.94  96.72  92.99    179   18.170     3    0.593   18.763

 

분류(영역,GC 등)별 3행 → 4행 수치 변화 상세 분석

분류(영역, GC 등) 수치(3행 → 4행) 설명
S0(Survivor0) 0.00 → 51.14 Survivor0 영역을 사용 (YGC 발생으로 Survivor 영역 변경)
S1(Survivor1) 48.94 → 0.00 Survivor1 영역을 비움 (YGC 발생으로 Survivor 영역 변경)
E(Eden) 49.92 → 0.00 Eden 영역이 가득 차서 Young GC 발생 시 Survivor영역으로 이동 후 Eden영역은 비움
O(Old) 21.93 → 21.94 Young GC 발생 후 Survivor에서 Old로 승격된 객체가 존재하여 Old 영역 사용률 증가
M(Metaspace) 96.71 → 96.72 Metaspace 사용률 증가
CCS(Compressed Class Space) 92.99 → 92.99 92.99 → 92.99 // Compressed Class Space 사용률 변경 없음
YGC(Young GC) 175 → 176 Young GC 발생 횟수 (+1)
FGC(Full GC) 3 → 3 FullGC 발생 횟수 (+0)
FGCT(Full GC Time) 0.593 → 0.593 Full GC 발생시간 변경 없음
GCT(total GC Time) 18.667 → 18.683 Young GC 발생으로 인해 총 GC 발생시간 증가

 

 

 

2. jstat -gcnew

PID가 29597인 프로세스에 연결하여 250ms간격으로 gc new 영역 통계 샘플 수집 (5행마다 열 머리글 표시) 명령어 실행 결과

user@hostname:~/jdk1.8.0_333/bin$ jstat -gcnew -h5 29597 250

S0C     S1C     S0U    S1U    TT MTT  DSS      EC       EU        YGC     YGCT

87552.0 85504.0 4762.4    0.0  5  15 85504.0 525824.0 348183.9    262   20.875
87552.0 85504.0 4762.4    0.0  5  15 85504.0 525824.0 524614.6    262   20.875  --2행
83968.0 85504.0    0.0 3792.4  4  15 83968.0 525824.0 318255.2    263   20.902  --3행
83968.0 85504.0    0.0 3792.4  4  15 83968.0 525824.0 525824.0    264   20.902
83968.0 81408.0 3709.5    0.0  3  15 81408.0 533504.0 194235.4    264   20.989

 S0C    S1C     S0U    S1U    TT MTT  DSS      EC       EU        YGC     YGCT
 
78848.0 81408.0    0.0 2461.5  2  15 78848.0 533504.0 129195.4    265   21.009
78848.0 81408.0    0.0 2461.5  2  15 78848.0 533504.0 318248.2    265   21.009
78848.0 81408.0    0.0 2461.5  2  15 78848.0 533504.0 527328.8    265   21.009
78848.0 75264.0 7120.3    0.0  1  15 75264.0 544768.0 178944.2    266   21.021
78848.0 75264.0 7120.3    0.0  1  15 75264.0 544768.0 504089.7    266   21.021

 

분류(영역,GC 등)별 2행 → 3행 수치 변화 상세 분석

분류(영역, GC 등) 수치(2행 → 3행) 설명
S0C(S0 Capacity(KB))  87552.0 → 83968.0 DSS를 기준으로 S0용량 조절(감소)
S1C(S1 Capacity(KB)) 85504.0 → 85504.0 DSS를 기준으로 S0용량 조절(동일)
S0U(S0 Utilization(KB)) 4762.4 → 0.0 YGC발생으로 S0영역을 비움
S1U(S1 Utilization(KB)) 0.0 → 3792.4 YGC발생으로 S0영역 → S1영역으로 이동
TT(Tenuring Threshold) 5 → 4 임계값이 감소
MTT(Maximum Tenuring Treshold) 15 → 15 15 → 15 // 최대임계값은 15 고정
DSS(Desired Survivor Size) 85504.0 → 83968.0 YGC 후 생존한 객체가 사용하는 공간을 기준으로 희망 생존자 크기를 조절(감소)
EC(current Eden space Capacity) 525824.0 → 525824.0 Eden용량 변경 없음
EU(current Eden space Utilization) 524614.6 → 318255.2 YGC 발생으로 Eden영역을 비우고 다시 0부터 318255.2까지 증가
YGC(number of Young generation GC events) 262 → 263 YGC 발생 횟수 (+1)
YGCT(Young generation Garbage Collection Time) 20.875 → 20.902 총 YGC 발생 시간 (+0.027)

 

 

 

3. jstat -gcoldcapacity

pid가 29597인 프로세스에 연결하여 250ms간격으로 gc old 영역 크기 통계 샘플 3번 수집 명령어 실행 결과

user@hostname:~/jdk1.8.0_333/bin$ jstat -gcoldcapacity -t 21891 250 3

Timestamp    OGCMN     OGCMX       OGC        OC   YGC   FGC     FGCT     GCT

    150.1   1408.0   60544.0   11696.0   11696.0   194    80    2.874   3.799  --1행
    150.4   1408.0   60544.0   13820.0   13820.0   194    81    2.938   3.863  --2행
    150.7   1408.0   60544.0   13820.0   13820.0   194    81    2.938   3.863

 

분류(영역,GC 등)별 1행 → 2행 수치 변화 상세 분석

 

분류(영역, GC 등) 수치(1행 → 2행) 설명
Timestamp 150.1 → 150.4 Jvm 시작 이후 경과 시간(초)
OGCMN(Old Generation Capacity Minimum) 1408.0 Old 영역 최소 용량(kB)
OGCMX(Old Generation Capacity Maximum) 60544.0 Old 영역 최대 용량(kB)
OGC(current Old Generation Capacity) 11696.0 → 13820.0 Full GC 발생으로 현재 Old Generation 용량(kB) 증가
OC(current Old space Capacity) 11696.0 → 13820.0 Full GC 발생으로 Old space 용량(kB) 증가
YGC(Young Generation Collection) 194 → 194 Young GC 발생 횟수 변경 없음
FGC(Full Generation Collection) 80 → 81 Full GC 발생 횟수 증가 (+1)
FGCT(Full Garbage Collection Time) 2.874 → 2.938 Full GC 발생 시간(초) 증가 (+0.064)
GCT(total Garbage Collection Time) 3.799 → 3.863 총 GC 발생 시간(초) 증가 (+0.064)

 

 


위 글은 제가 직접 사용 및 분석 후 한땀한땀 작성한 글 입니다. 요즘 블로그를 보면 내용을 이해하지 못한 채 짜깁기 된 글이나 출처도 명시하지 않은 채 불법으로 퍼온 글들이 너무 많아서 정보 획득에 주의가 필요할 것 같습니다.