GC 모니터링

자바 인스턴스 확인을 위한 jps

jps 는 해당 머신에서 운영중인 JVM 의 목록을 보여준다.

• q : 클래스나 JAR 파일명, 인수 등을 생략하고 내용을 나타낸다. (단지 프로세스 ID 만 나타낸다)
• m : main 메서드에 지정한 인수들을 나타낸다.
• l : 애플리케이션의 main 클래스나 애플리케이션 JAR 파일의 전체 경로 이름을 나타낸다.
• v : JVM 에 전달된 자바 옵션 목록을 나태낸다.
• V : JVM 플래그 파일을 통해 전달된 인수를 나타낸다.
• Joption : 자바 옵션을 이 옵션 뒤에 지정할 수 있다.

$ jps [-q] [-mlvV] [-Joption] [<hostid>]

$ jps
66433 Jps
54965 

v 옵션을 추가하면 자바 옵션까지 포함해서 출력해준다.

$ jps -v
66434 Jps -Dapplication.home=/Library/Java/JavaVirtualMachines/jdk1.8.0_321.jdk/Contents/Home -Xms8m
54965  -XX:+IgnoreUnrecognizedVMOptions --add-modules=ALL-SYSTEM -Dosgi.requiredJavaVersion=11 -Xms64m -Xmx1024m -XstartOnFirstThread

GC 상황을 확인하는 jstat

• t : 수행 시간을 표시한다. (자바 인스턴스가 생성된 시점부터의 시간)
• h (lines) : 각 열의 설명을 지정된 라인 주기로 표시한다.
• interval : 로그를 남기는 시간의 차이(밀리초 단위임)을 의미한다.
• count : 로그 남기는 횟수를 의미한다.

1) 사용

$ jstat -gcnew 19743 1000

 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT  
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  38912.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  38912.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  38912.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468
   0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  39936.0     66    0.468

2) 옵션

옵션의 종류는 다음과 같다. option 에 따라서 나타나는 결과의 내용이 많이 달라진다.

• class : 클래스 로더에 대한 통계
• compiler : 핫스팟 JIT 컴파일러에 대한 통계
• gc : GC 힙 영역에 대한 통계
• gccapacity : 각 영역의 허용치와 연관된 영역에 대한 통계
• gccause : GC 의 요약 정보와, 마지막 GC와 현재 GC에 대한 통계
• gcnew : 각 영역에 대한 통계
• gcnewcapacity : Young 영역과 관련된 영역에 대한 통계
• gcold: Old 영역에 대한 통계
• gcoldcapacity : Old 영역의 크기에 대한 통계
• gcutil : GC에 대한 요약 정보
• printcomplication : 핫 스팟 컴파일 메서드에 대한 통계

사용

• 각 영역에 대한 통계를 보여주며,
• 수행시간을 나타내고,
• 10 줄에 한 번씩 각 열의 설명(타이틀) 을 나타내고,
• 프로세스 번호는 2464 이고,
• 1(1000ms) 에 한 번씩 정보를 보여주고
• 20 회 반복후 종료한다.

$ jstat -gcnew -t -h10 19743 20

Timestamp  S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT  
96788.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  96256.0     66    0.468
96789.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  96256.0     66    0.468
96790.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  96256.0     66    0.468
96791.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  96256.0     66    0.468
96792.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96793.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96794.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96795.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96796.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96797.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
Timestamp  S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT  
96798.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96799.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96800.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96801.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96802.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96803.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96804.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96805.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96806.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  97280.0     66    0.468
96807.7    0.0 1024.0    0.0 1024.0 15  15 10240.0 163840.0  98304.0     66    0.468

jstat 에서 프린트되는 결과를 사용하여 그래프를 그리면 GC가 처리되는 추이를 알아볼 수 있으므로 편리하다. 또한 결과를 파일로도 남길 수 있어 나중에 분석할 때 사용할 수 있다.

단, 이 결과만으로는 어떻게 해석을 하면 좋을지 알기 어렵다는 단점이 있다. 그러나 JVM 파라미터를 튜닝할 때나, GC 를 수행하는데 소요된 모든 시간을 보고 싶을 때 유용하게 사용할 수 있다.

GC 튜닝시 가장 유용한 옵션

jstat 명령에서 GC 튜닝을 위해서 가장 애용되는 옵션은 -gcutil 과 -gccapacity 이다.

1) gccapacity : 현재 각 영역에 할당되어 있는 메모리의 크기를 KB 단위로 보여준다.

• NGC 로 시작하는 것은 New (Young) 영역의 크기 관련, OGC 로 시작하는 것은 Old 영역 크기 관련 정보이다.
• 중간에는 S0C, S1C, EC, OC 는 각각 Survivor0, Survivor1, Eden, Old 영역의 현재 할당된 크기를 나타낸다.
• MN, MX, C 로 끝나는 항목들은 각각 Min, Max, Committed 를 의미한다.
• 가장 마지막 항목은 각각 Minor GC 획수와 Full GC 횟수를 의미한다.

jstat -gccapacity 19743

 NGCMN    NGCMX     NGC     S0C   S1C       EC      OGCMN      OGCMX       OGC         OC       MCMN     MCMX      MC     CCSMN    CCSMX     CCSC    YGC    FGC   CGC 
     0.0 262144.0 164864.0    0.0 1024.0 163840.0        0.0   262144.0    97280.0    97280.0      0.0 1128448.0  90572.0      0.0 1048576.0  11544.0     66     0     6

이 옵션의 장점은 바로 각 영역의 크기를 확인할 수 있다는 점이다. 본인이 운영하는 시스템이 아니더라도, 이 명령어만 수행해보면 누구에게 물어보지 않아도 해당 자바 프로세스의 메모리 점유 상황을 쉽게 확인할 수 있다.

2) gcutil : 힙 영역의 사용량을 %로 보여준다.

• 여기서 S0, S1 은 Survivor 영역을 의미하여 E는 Eden 영역을 의미한다. 즉, 이 3개의 영역이 Young 영역에 해당한다.
• YGC는 Young 영역의 GC 횟수, YGCYT는 Young 영역의 GC가 수행된 누적 시간(초) 이다.
• O는 Old 영역을 의미하며 GC 가 발생하면 FGC 의 횟수가 증가하고 FGCT 시간이 올라가게 된다.
• 가장 마지막에 있는 GCT는 Young GC가 수행된 시간인 YGCT아 FullGC가 수행된 시간인 FGCT의 합이다.

jstat -gcutil 19743 1s

S0     S1     E      O      M     CCS    YGC     YGCT    FGC   FGCT   CGC   CGCT     GCT   
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491
0.00 100.00   2.50  35.94  97.21  90.72    67   0.469    0   0.000    6   0.022    0.491

아주 간단하게 YoungGC가 한 번 수행될 때의 시간을 구하려면 어떻게 할까?
바로 YGCT / YGC 를 계산하면 된다. 실제로 정확하게 딱 떨어지지는 않지만 평균적인 값을 확인할 수 있다. 마찬가지로 Full GC 별 시간도 이렇게 구할 수 있다.

여기서 조심해야 할 것은 CMS GC를 사용할 경우에는 FullGC 의 단계에 따라서 수행되는 시간이 다르다는 점이다. 다시 말해서 평균 값이 낮다고 그냥 무시하면 안된다.

verbosegc 옵션을 이용하여 gc 로그 남기기

GC를 분석하기 위해서는 가장 간단한 verbosegc 라는 옵션이 있다. 자바 수행시 간단히 -verbosegc 라는 옵션을 넣어주면 된다.

• 결과가 출력되는 위치는 System.out.println() 메서드를 호출했을 때 출력되는 위치와 동일한다.

java -verbosegc

Young 영역에서 마이너 GC가 발생했으며 8,128kbyte 에서 848kbyte 로 축소되었다. 전체 할당된 크기는 130,112kbyte 이며, GC 수행 시간은 0.0090257초이다.
Full GC로 표시되어 있는 행은 수행이 다른 마이너 GC 에 비해 월등히 긴 것을 볼 수 있다.

[GC 8128K -> 848K(130112K), 0.0090257 secs]

1) PrintGCTimeStamps 옵션

위와 같이 옵션을 주고 수행하면 언제 GC가 발생했는지 알 수 없다. 이 경우를 대비해서 verbosegc 옵션과 함께 사용할 수 있는것이 -XX:+PrintGCTimeStamps 옵션이다.

• 옵션 적용후 : 서버가 기동되기 시작한 이후부터 GC가 수행될 때까지의 시간을 로그에 포함한다.

-verbosegc -XX:PrintGCTimeStamps 옵션 적용 후
0.681: [GC 8128K -> 848K(130112K), 0.0090257 secs]

2) PringHeapAtGC 옵션

또 다른 옵션으로 -XX:+PrintHeapAtGC 라는 것이 있다. 이 옵션을 지정하면 GC에 대한 더 많은 정보를 볼 수 있지만, 너무 많은 내용을 보여주기 때문에 분석하기가 그리 쉽지는 않다. 그러나 툴로 분석할 때는 아주 상세한 결과도 확인할 수 있다.

-verbosegc -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC  옵션 적용 후

3) PringGCDetails 옵션

더 간결하고 보기 쉬운 옵션이 하나 더 있다. 바로 -XX:+PrintGCDetails 옵션이다.

-verbosegc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails 옵션 적용 후

0.719: [GC: 0.719: [DefNew: 8128K -> 848K(9088K), 0.009086 secs] 8128K->848K(130112K), 0.0092344 secs]
...
63.616: [Tenured: 112634K->9923K(121024K), 0.0633237 secs] 121416K->9923K(130112K), 0.0634597 secs]

이렇게 verbosegc 옵션에 다양한 추가 옵션을 사용하면 GC 현상에 대해 더 정밀하게 분석할 수 있다. 그러나 다양한 툴이 있으므로 그 툴을 사용하는것을 고려해보자.