18. GC가 어떻게 수행되고 있는지 보고 싶다

de_sj_awa·2021년 9월 10일

18. GC가 어떻게 수행되고 있는지 보고 싶다

GC가 어떻게 수행되는지 시스템을 분석하려면 관련된 툴을 사용해야 한다. 여러 방법이 있지만 jstat이라는 명령을 사용하여 실시간으로 보거나 verbosegc 옵션을 사용하여 로그로 남긴다. verbosegc 옵션을 자바 수행 옵션에 추가하고, JVM을 재시작해야 한다.

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

jps는 해당 머신에서 운영 중인 JVM의 목록을 보여준다. JDK의 bin 디렉터리에 있다. jps의 사용법은 매우 간단하다. 커맨드 프롬프트나 유닉스의 터미널에서 다음과 같은 옵션으로 수행하면 된다.

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

jps 명령의 각 옵션은 다음과 같다.

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

플래그 파일이란 .hotspotrc의 확장자를 가지거나 자바 옵션에 -XX:Flags=<file name>로 명시한 파일이다. 이 파일을 통해서 JAVA의 옵션을 지정할 수 있다.

커맨드 창에서 아무런 옵션없이 jps를 입력하면 현재 서버에서 수행되고 있는 자바 인스턴스들이 목록이 나타난다.

C:\jdk1.7\bin > jps
2464 Bootstrap
4224 Jps
3732 Bootstrap

위 결과는 두 개의 톰캣 서버 인스턴스를 띄워 놓은 상태에서 나온 것이다. 중간에 있는 JPS는 jps 명령 자체 인스턴스를 의미하는 프로세스로 이 명령 종료 후에 바로 사라진다. 프로세스 이름 좌측에 있는 수치는 프로세스 아이디이다.

그런데 이렇게 보면, 내가 모니터링하려는 톰캣이 어떤 것인지 알 수가 없다. 따라서, 이 명령을 사용할 때는 -v 옵션을 추가로 지정해 주면 자바 옵션까지 포함하여 출력해준다.

2. GC 상황을 확인하는 jstat

jstat는 GC가 수행되는 정보를 확인하기 위한 명령이다. jstat를 사용하면 유닉스 장비에서 vmstat이나 netstat와 같이 라인 단위로 결과를 보여 준다. 실행 예를 보면 다음과 같다.

C:\jdk1.7\bin>jstat -gcnew 2464 1000

명령 옵션이 복잡하지 않고, vmstat 명령어와 비슷하다는 느낌을 받을 수 있다. 그럼 옵션이 어떻게 되어 있는지 알아보자.

jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

-<option> 부분을 제외한 jstat 명령의 옵션을 살펴보자.

-t : 수행 시간을 표시한다.
-h:lines : 각 열의 설명을 지정된 라인 주기로 표시한다.
interval : 로그를 남기는 시간의 차이(밀리초 단위임)를 의미한다.
count : 로그 남기는 횟수를 의미한다.

참고로 -t 옵션을 주면 수행 시간을 표시한다고 되어 있는데, 여기서의 수행 시간은 해당 자바 인스턴스가 생성된 시점부터의 시간이다. 다시 말하면, 서버가 기동된 시점부터의 시간이다.

<option>의 종류는 다음과 같으며, <option>에 따라서 나타나는 결과의 내용이 많이 달라진다. 각 옵션에 따라서 나타나는 내용은 다음과 같다.

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

옵션 값들을 적용한 예를 보면서 어떻게 jstat를 사용해야 하는지 살펴보자.

jstat -gcnew -t h10 2624 1000 20 > jstat_WAS1.log

각 영역에 대한 통계를 보여주며,
수행 시간을 나타내고,
10줄에 한 번씩 각 열의 설명(타이틀)을 나타내고,
프로세스 번호는 2464이고,
1초(1,000)ms에 한 번씩 정보를 보여주고,
20회 반복 수행을 한다.
마지막으로 jstat_WAS1.log 파일에 결과를 저장한다.

jstat에서 프린트되는 결과를 사용하여 그래프를 그리면 GC가 처리되는 추이를 알아볼 수 있으므로 편리하다. 또한 결과를 파일로도 남길 수 잇어 나중에 분석할 때 사용할 수 있다. 단, 이 결과만으로는 어떻게 해석을 하면 좋을지 알기 어렵다는 단점이 있다. 하지만 JVM 파라미터 튜닝을 할 때나, GC를 수행하는데 소요된 모든 시간을 보고 싶을 때 유용하게 사용할 수 있다.

그런데, 이렇게 jstat을 로그로 남겨 분석하는 데는 한계가 있다. 왜냐하면, 로그를 남기는 주기에 GC가 한 번 발생할 수도 있고, 10번 발생할 수도 있기 때문이다. 따라서 정확한 분석을 하고자 할 때는 verbosegc 옵션 사용을 권장한다.

3. GC 튜닝을 할 때 가장 유용한 jstat 옵션은 두 개

jstat 명령에서 GC 튜닝을 위해서 가장 유용한 옵션은 -gcutil과 -gccapacity이다. 이 두개의 옵션에 대해서 자세히 알아보기 위해서 다음 코드를 살펴보자.

package com.perf.gc;

import java.util.ArrayList;

public class GCMaker {

    public static void main(String[] args) throws Exception{
        GCMaker maker=new GCMaker();
        for(int loop=0;loop<120;loop++) {
            maker.makeObject();
            Thread.sleep(1000);
            // System.out.print("."); 
        }
    }
    private void makeObject() {
        Integer[] intArr=new Integer[1024000];
        ArrayList<Integer> list=new ArrayList<Integer>(1024000);
        for(int loop=0;loop<1024;loop++) {
            intArr[loop]=loop;
            list.add(loop);
        }
    }
}

먼저 gccapacity 옵션을 살펴보자. 이 옵션은 현재 각 영역에 할당되어 있는 메모리의 크기를 KB 단위로 나타낸다.

$ jstat -gccapacity 3580

여기서 3580은 GCMaker 프로세스의 pid이다.

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

이 gccapacity 옵션을 사용하면 어떤 점이 좋을까? 바로 각 영역의 크기를 알 수 있기 때문에 어떤 영역의 크기를 좀 더 늘리고, 줄여야 할지를 확인할 수 있다는 장점이 있다.

이번에는 gcutil 옵션을 살펴보자. gcutil 옵션은 힙 영역의 사용량을 %로 보여준다.

$ jstat -gcutil 3580 1s

S0, S1 옵션은 Survivor 영역을 의미하며 E는 Eden 영역을 의미한다. 즉, 이 세개 영역이 Young 영역에 해당하고, YGC는 Young 영역의 GC 횟수, YGCT는 Young 영역의 GC그 수행된 누적 시간(초)이다. O는 Old, P는 Perm 영역을 의미하며, 이 두 개 영역 중 하나라도 GC가 발생하면 FCG의 횟수가 증가하고, FGCT 시간이 올라가게 된다. GCT는 Young GC가 수행된 시간인 YGCT와 Full GC가 수행된 시간인 FGCT의 합이다.

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

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

4. 원격으로 JVM 상황을 모니터링하기 위한 jstatd

앞서 살펴본 명령어들을 사용하면 로컬 시스템에서만 모니터링을 할 수 있다. 즉, 원격 모니터링이 불가능하다는 의미이다. 이러한 단점을 해결하기 위해서 jstatd라는 데몬이 만들어졌다. 이 명령어를 사용하면 원격 모니터링을 할 수 있지만, 중지하면 서버가 가동 중일 경우에도 원격 모니터링이 불가능하다. 먼저 jstatd의 사용법을 알아보자.

jstatd [-nr] [-p port] [-n rminame]

nr : RMI Registry가 존재하지 않을 경우 새로운 RMI 레지스트리를 jstatd 프로세스 내에서 시작하지 않는 것을 정의하기 위한 옵션이다.
p : RMI 레지스트리를 식별하기 위한 포트 번호.
n : RMI 객체의 이름을 지정한다. 기본 이름은 JStatRemoteHost이다.

아무 옵션 없이 jstad를 실행하면 에러가 발생한다. 그 이유는 자바에 기본적으로 지정되어 있는 보안 옵션이 jstad가 리모트 객체를 만드는 것을 억제하기 때문이다. 이 문제를 해결하려면 자바가 설치되어 잇는 서버 내의 디렉터리의 lib/security/java.policy 파일에 다음 허가 명령어를 추가해야 한다.

grant codebase "file:${java.home}/../lib/tools.jar" {
permission java.security.AllPermission;
};

만약 자바의 lib 디렉터리에 security 디렉터리가 없으면 jre 디렉터리의 lib/security 디렉터리를 확인해야 한다.

옵션을 추가햇으면 다음과 같이 jstatd를 수행하자.

jstatd -J-Djava.security.policy=all.policy -p 2020

-p 2020에 있는 2020이라는 숫자는 앞의 설명에 있는 것과 같이 포트 번호를 의미한다. 만약 이 포트를 다른 애플리케이션에서 사용하고 있으면 포트 번호를 다른 것으로 지정해야 한다. 옵션에 문제가 없다면, 정상적으로 프로세스가 수행될 것이다.

이제 jps에 다음과 같은 옵션을 지정하여 수행해보자.

c:\jdk1.7\bin> jps serverhostname:2020

serverhostname에는 모니터링할 서버의 호스트 이름을 지정하면 된다. 호스트 이름 뒤에는 콜론을 쓰고 아까 jstatd를 수행했을 때 -p 옵션에 지정했던 포트 번호와 동일한 번호를 지정한다.

jps를 통하여 프로세스 아이디를 확인하였으니 이제 jstat을 사용하여 서버의 GC 상황을 모니터링한다.

C:\jdk1.7\bin>jstat -gcutil 2904@serverhostname:2020 1000

이 명령어 중 앞에서 사용한 옵션과 다른 부분은 2904@serverhostname:2020이라고 되어 있는 부분이다. 설명하자면 2904는 프로세스 번호, minspc는 서버 명, 2020은 포트 번호다. 이와 같이 jstad를 통하여 '호스트명:포트 번호'를 지정하면 원격으로 jstat 명령을 수행하여 결과를 확인할 수 있다. 또한 원격지의 서버를 이 방식으로 사용하려면 해당 포트를 방화벽에서 열어주어야 한다.

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

jvmstat를 사용할 수 없는 상황이라면 어떻게 GC를 분석할 수 있을까? GC를 분석하기 위한 명령어로는 가장 쉬울, verbosegc라는 옵션이 있다. 자바 수행 시에 간단히 -verbosegc라는 옵션을 넣어주면 된다.

참고로 만일 HP 장비에서 HP JDK 1.3.1 이상 버전을 사용할 때는 -verbosegc가 아닌 -Xvervosegc라는 옵션을 주어야 한다. HP 장비에서 JDK 1.4.0 핫 스팟 VM을 사용할 경우에는 -Xloggc 옵션을 아숑할 수도 있다. JDK 1.4.X 이상의 버전에서는 -XX:+PrintTLE 옵션을 사용할 수도 있으나, JDK 5.0 이상의 버전에서는 이 PrintTLE 옵션을 사용할 수 없다.

옵션 사용 방법은 다음과 같다.

C:\was> java -verbosegc <기타 다른 옵션들> 자바 애플리케이션 이름

Sun JDK를 사용할 때 verbosegc 옵션을 쓰면 다음과 같은 결과가 출력된다. 이 결과가 출력되는 기본 위치는 System.out.println() 메서드를 호출했을 때 출력되는 위치와 동일하다.

[GC 8128K -> 848K(130112K), 0.0090257 secs]
[GC 8976K -> 1453K(130112K), 0.0090570 secs]
[GC 9581K -> 2242K(130112K), 0.0108919 secs]
...
[GC 120072K -> 112417K(130112K), 0.0019625 secs]
[GC 120543K -> 112988K(130112K), 0.0023279 secs]
[Full GC 121104K -> 9472K(130112K), 0.0647395 secs]
[GC 17562K -> 9935K(130112K), 0.0009996 secs]

각각의 항목이 어떤 의미가 있는지 확인해 보자.

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

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

PrintGCTimeStamps 옵션

그런데 이렇게 옵션을 주고 수행하면 언제 GC가 발생하였는지 알 수 없다. 이 경우를 대비해서 verbosegc 옵션과 함께 사용할 수 있는 -XX:+PrintGCTimeStamps 옵션이 있다. 먼저 옵션을 적용한 이후의 결과를 보자.

- verbosegc -XX:+PrintGCTimeStamps 옵션 적용 후
0.668 : [GC 8128K -> 848K(130112K), 0.0090257 secs]
1.073 : [GC 8976K -> 1453K(130112K), 0.0090570 secs]
1.496 : [GC 9581K -> 2242K(130112K), 0.0108919 secs]
1.857 : [GC 10370K -> 2993K(130112K), 0.0095970 secs]
2.136 : [GC 11121K -> 3699K(130112K), 0.0081142 secs]
5.911 : [GC 11827K -> 4387K(130112K), 0.0163130 secs]
6.070 : [GC 12511K -> 4594K(130112K), 0.0069344 secs]
6.085 : [GC 12722K -> 4604K(130112K), 0.0012633 secs]
6.095 : [GC 12727K -> 4592K(130112K), 0.0011932 secs]

verbosegc 옵션만 적용했을 때와 비교하면, 가장 좌측에 수행한 시간이 포함되는 것이 눈에 띈다. 서버가 가동되기 시작한 이후부터 해당 GC가 수행될 때까지의 시간을 로그에 포함하기 때문에 언제 GC가 발생되었는지 확인할 수 있다.

PrintHeapAtGC 옵션

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

-verbosegc -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC

이 명령어를 수행했을 때의 특징은 Before라고 되어 있는 블록에는 GC 전의 메모리 상황을, After라고 되어 있는 블록에는 GC 후의 메모리 상황을 제공한다는 것이다. 또한 이 결과는 JVM 벤더마다 다를 수 있다.

PrintGCDetails

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

-verbosegc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

이렇게 verbosegc 옵션에 다양한 추가 옵션을 사용하면 GC 현상에 대해 더 정밀하게 분석할 수 있다. 하지만 텍스트 기반으로 나온 결과를 직접 머리로 계산하면서 분석하고 싶은 사람은 한 명도 없을 것이다. 그래서 각 서버에 알맞은 분석 툴들이 존재한다. 그 목록은 다음과 같다.

GC Analyzer : Sun에서 제공하는 GC 분석 툴이다. 펄 스크립트 기반으로 분석 결과를 정리해 준다.
IBM GC 분석기(IBM Pattern Modeling and Analysis Tool for Java Garbage Collector, IBM PMAT) : IBM에서 제공하는 GC 분석 툴이다. Sun, IBM, HP 서버에서 작성된 GC 로그를 분석할 수 있다.
HPjtune : HP에서 제공하는 GC 분석 툴이다. 오직 HP JDK를 사용하여 작성된 GC 로그만 분석할 수 있다는 단점이 있지만, 매뉴얼이 잘 되어 있다. 하지만 HPJtune은 더 이상의 업그레이드나 버그 픽스가 제공되지 않는다고 명시되어 있다. 대신, HPjmeter를 사용하면 HP 기반의 서버에서 모니터링할 수 있다.

추가로 설명하자면 HPJmeter는 아파치 그룹에서 제공하는 JMeter와는 전혀 상관이 없는 모니터링 및 분석 툴이다. 이 툴의 단점은 HP 기반의 서버만 모니터링이 가능하다는 것이다. 모니터링 결과를 표시하는 콘솔은 윈도나 리눅스 버전도 제공한다.

6. 어설프게 아는 것이 제일 무섭다

메모리 릭이 발생하는지 확인하는 가장 확실한 방법은 verbosegc를 남겨서 보는 방법이다. 그리고, 간단하게 확인할 수 있는 또 한가지 방법은 Full GC가 일어난 후에 Old 영역의 메모리 사용량을 보는 것이다. 만약 사용량이 80% 이상이면 메모리 릭을 의심해야 한다. 그런데, Full GC를 한 번도 하지 않은 시스템에 메모리 릭이 있다고 생각할 수 있는가? 어떤 시스템도 Full GC가 한 번도 발생하지 않은 상황에서 메모리 릭이 있다고 이야기 할 수 없다.

참고