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'를 입력하면 현재 서버에서 실행 중인 자바 인스턴스들의 목록이 출력됩니다. 예를 들어, 두 개의 톰캣 서버 인스턴스를 실행한 상태에서 'jps'를 입력하면 다음과 같이 출력됩니다.

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

 

 위 결과에서 JPS는 'jps' 명령 자체의 인스턴스를 의미하는 프로세스입니다. 이 명령이 종료된 후에는 바로 사라집니다. 프로세스 이름 옆의 숫자는 프로세스 아이디를 의미합니다.

 

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

---

2) GC 상황을 확인하는 jstat

 `jstat`는 가비지 컬렉션(GC)의 상황을 확인하는 명령어입니다. 유닉스 장비에서 `vmstat`이나 `netstat`와 같이 라인 단위로 결과를 보여줍니다.

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

 

 위와 같이 `jstat` 명령어를 실행하면, 간단하고 `vmstat` 명령어와 유사한 결과를 확인할 수 있습니다. `jstat` 명령어의 기본 구조는 다음과 같습니다.

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

 

-<option>`을 제외한 옵션들은 아래와 같습니다.

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

 

`-t` 옵션을 사용하면 수행 시간이 표시되며, 이는 해당 자바 인스턴스가 생성된 시점부터의 시간입니다. 즉, 서버가 기동된 시점부터의 시간을 나타냅니다.

 

`<option>`의 종류는 많으며, 각 `<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초(,000)ms에 한 번씩 정보를 보여주며, 20회 반복 수행을 합니다. 그리고 `jstat_WAS1.log` 파일에 결과를 저장합니다.

 

`jstat`에서 출력되는 결과를 그래프로 표현하면 GC 처리 추이를 파악하는 데 편리하며, 결과를 파일로 저장해 나중에 분석할 때 사용할 수 있습니다. 하지만 결과 해석이 어려울 수 있으므로, JVM 파라미터 튜닝이 필요하거나 GC 수행 시간을 보고 싶을 때 주로 사용합니다.

 

그러나 `jstat`을 로그로 남기는 방식에는 한계가 있습니다. 로그를 남기는 주기에 GC가 한 번 또는 여러 번 발생할 수 있기 때문입니다. 따라서 정확한 분석을 위해선 `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, OGC, PGC는 각각 New (Young), Old, 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 옵션을 살펴봅시다. 이 옵션은 힙 영역의 사용량을 백분율로 표시합니다. 

$ jstat -gcutil 3580 1s

 

S0, S1은 Survivor 영역을, E는 Eden 영역을 의미합니다. 이 세 영역은 Young 영역에 해당하며, YGC는 Young 영역의 GC 횟수, YGCT는 Young 영역의 GC 수행 시간을 의미합니다. O는 Old, P는 Perm 영역을 의미하며, 이 두 영역 중 하나라도 GC가 발생하면 FGC 횟수가 증가하고, FGCT 시간이 증가합니다. GCT는 Young GC와 Full GC의 수행 시간 합계를 나타냅니다.

 

Young GC의 평균 수행 시간을 얻으려면 YGCT를 YGC로 나누면 됩니다. 이는 정확한 값은 아니지만 평균적인 값을 확인할 수 있습니다. 마찬가지로 Full GC의 평균 시간도 동일한 방식으로 구할 수 있습니다.

 

단, CMS GC를 사용하는 경우 Full GC의 단계에 따라 수행 시간이 다르므로, 평균 값이 낮다고 해서 무시해서는 안 됩니다. 이런 경우에는 verbosegc 옵션을 사용하는 것이 가장 확실한 방법입니다.

---

4) 원격 JVM 모니터링을 위한 jstatd 이용법

 앞서 로컬 시스템에서만 모니터링을 수행할 수 있는 방법들을 살펴보았습니다. 즉, 원격 모니터링을 원한다면 어떻게 해야 할까요? 이런 경우에는 jstatd라는 데몬을 사용하면 됩니다. 이 도구를 통해 원격 모니터링을 수행할 수 있지만, 단점으로는 jstatd가 중지되면 동작 중인 서버에서 원격 모니터링을 수행할 수 없습니다. 이제 jstatd의 사용법을 살펴봅시다. 

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

• -nr 옵션은 RMI 레지스트리가 없을 때 새로운 RMI 레지스트리를 jstatd 프로세스 내에서 시작하지 않도록 합니다.
• -p 옵션은 RMI 레지스트리를 식별하기 위한 포트 번호를 지정하고,
• -n 옵션은 RMI 객체의 이름을 지정합니다. 기본 이름은 JStatRemoteHost입니다.

 jstatd를 옵션 없이 실행하면 보안 문제로 인해 에러가 발생합니다. 자바의 보안 옵션이 jstatd가 리모트 객체를 생성하는 것을 방해하기 때문입니다. 이 문제를 해결하려면 자바가 설치된 서버 내의 lib/security/java.policy 파일에 아래 권한 명령어를 추가해야 합니다.

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

 

 위 권한 설정 후에는 아래와 같이 jstatd를 실행합니다.

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

여기서 2020은 RMI 레지스트리를 식별하기 위한 포트 번호를 의미합니다. 이 포트가 다른 애플리케이션에서 사용 중이라면 다른 번호로 변경해야 합니다. 옵션이 올바르게 지정되면, 프로세스가 정상적으로 실행됩니다.

 

이제 jps 명령어에 아래와 같은 옵션을 지정해서 수행해봅니다.

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

 

serverhostname은 모니터링하려는 서버의 호스트 이름입니다. 호스트 이름 뒤의 콜론 다음에는 jstatd를 실행할 때 지정한 포트 번호를 입력합니다. 프로세스 아이디를 확인한 후에는 jstat을 사용하여 서버의 GC 상황을 모니터링할 수 있습니다.

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

 여기서 2904는 프로세스 번호, serverhostname은 서버 이름, 2020은 포트 번호를 의미합니다. 이렇게 jstatd를 통해 '호스트명:포트 번호'를 지정하면 원격으로 jstat 명령을 수행하고 결과를 확인할 수 있습니다. 이를 위해서는 해당 포트가 방화벽에서 열려 있어야 합니다.

---

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

 JVMstat을 사용할 수 없는 상황에서 GC를 분석할 방법이 필요하다면, 가장 간단한 방법은 verbosegc라는 옵션을 사용하는 것입니다. 자바를 실행할 때 -verbosegc 옵션을 추가하면 됩니다.

 

HP 장비에서 HP JDK 1.3.1 이상의 버전을 사용할 경우에는 -verbosegc 대신 -Xverbosegc 옵션을 사용해야 합니다. 또한, HP 장비에서 JDK 1.4.0 핫스팟 VM을 사용할 경우에는 -Xloggc 옵션을 사용할 수 있습니다. JDK 1.4.X 이상 버전에서는 -XX:+PrintTLE 옵션을 사용할 수 있지만, JDK 5.0 이상 버전에서는 이 옵션을 사용할 수 없습니다.

 

옵션을 사용하여 자바를 실행하는 방법은 다음과 같습니다.

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가 발생하였고, 8128KB에서 848KB로 줄어들었습니다. 전체 할당된 크기는 130112KB이며, GC를 수행하는 데 걸린 시간은 0.0090257초입니다. Full GC 표시가 있는 행은 마이너 GC에 비해 수행 시간이 훨씬 긴 것을 알 수 있습니다.

 

 다만, 이 방식으로는 GC가 언제 발생했는지 확인할 수 없습니다. 이를 위해 -XX:+PrintGCTimeStamps 옵션을 verbosegc 옵션과 함께 사용할 수 있습니다. 더 많은 정보를 얻기 위해 -XX:+PrintHeapAtGC 옵션을 사용할 수 있습니다. 이 옵션은 많은 정보를 출력하므로 분석이 어렵지만, 툴을 사용하여 분석할 때에는 매우 상세한 정보를 제공합니다. 더 간결하게 정보를 얻기 위해 -XX:+PrintGCDetails 옵션을 사용할 수도 있습니다.

 

 이렇게 verbosegc 옵션에 다양한 추가 옵션을 사용하면 GC 현상에 대해 더욱 정확하게 분석할 수 있습니다. 하지만 이러한 정보를 직접적으로 분석하는 것은 어려우므로 다양한 분석 도구를 활용하는 것이 좋습니다. 이러한 도구로는 GC Analyzer, IBM GC 분석기(IBM PMAT), HPjtune 등이 있습니다. HPjtune은 HP JDK로 작성된 GC 로그만 분석 가능하며, 업데이트나 버그 픽스가 제공되지 않습니다. 대신에 HPjmeter를 사용하면 HP 기반 서버에서 모니터링이 가능합니다. HPjmeter는 아파치 그룹에서 제공하는 JMeter와는 다른 도구로, HP 기반 서버만 모니터링이 가능한 단점이 있습니다. 하지만 윈도우나 리눅스 버전의 콘솔을 제공하여 모니터링 결과를 표시합니다.

---

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

 메모리 릭 발생 여부를 가장 확실하게 확인하는 방법은 verbosegc를 사용하여 로그를 확인하는 것입니다. 또한, 간단하게 확인하는 다른 방법은 Full GC가 발생한 후에 Old 영역의 메모리 사용량을 살펴보는 것입니다. 이 사용량이 80% 이상인 경우에는 메모리 릭이 발생했을 가능성이 높으므로 주의해야 합니다. 그러나 Full GC가 한 번도 발생하지 않은 시스템에서 메모리 릭이 있다고 단정짓는 것은 어렵습니다. 실제로 어떤 시스템에서도 Full GC가 한 번도 발생하지 않은 상황에서 메모리 릭이 있다고 확실히 말할 수 없습니다.