제목: "Garbage Collection 모니터링 방법"
작성자: d2.naver.com(이상민)
작성자 수정일: 2012년 1월 13일
링크: https://d2.naver.com/helloworld/6043
작성일: 2022년7월31일
이 글에서 설명하는 도구나 JVM 옵션은 JVM 벤더에 상관없이 공통적으로 사용할 수 있는 방법은 아니다. GC 수행 정보를 보여 주는 것에 대한 '표준'은 필요 없기 때문이다. 이 글에서는 HotSpot JVM(Oracle JVM)을 기준으로 설명할 것이다.
jstat은 HotSpot JVM에 있는 모니터링 도구이다. jstat 이외에 HotSpot JVM 모니터링 도구로는 jps와 jstatd가 있다. Java 애플리케이션을 모니터링할 때에는 이 세 개의 도구를 모두 사용해야 할 경우도 있다.
jstat은 GC 수행 정보를 보는 기능만 제공하지는 않는다. 클래스로더 수행 정보나 Just-in-Time 컴파일러 수행 정보 등도 jstat으로 알 수 있다. 여러 정보를 얻을 수 있지만 이 글에서는 GC 수행 정보 모니터링에 대해서만 알아보겠다.
jstat은 $JDK_HOME/bin 디렉터리에 있다. 커맨드 라인에서 디렉터리를 지정하지 않고 바로 java 명령어나 javac 명령어를 실행할 수 있다면 jstat도 바로 실행할 수 있다.
커맨드 라인에서 다음과 같이 실행하면, S0C, S1C, S0U, S1U, EC, EU, OC, OU, PC 등의 칼럼과 함께 실수형의 데이터가 출력될 것이다.
vmid(Virtual Machine ID)는 말 그대로 VM을 가리키는 ID이다.
로컬 머신에서 동작하는 Java 애플리케이션뿐만 아니라 리모트 머신에서 동작하는 Java 애플리케이션도 vmid로 가리킬 수 있다. 로컬 머신에서 동작하는 Java 애플리케이션에 대한 vmid를 lvmid(Local vmid)라 하는데, 많은 경우 이 lvmid는 PID이다. 그래서 ps 명령어나 Windows 작업 관리자를 이용하여 확인한 PID 값을 lvmid로 쓸 수도 있지만, PID와 lvmid가 언제나 일치하는 것은 아니기 때문에 jps를 이용하는 것이 좋다.
jps는 그 이름이 말하듯 Java PS이다. jps를 실행하면 vmid와 main 메서드 정보를 보여 준다. 마치 ps가 PID와 프로세스 명을 알려 주듯이 말이다.
jps를 이용하여 모니터링하려는 Java 애플리케이션의 vmid를 알아낸 후 jstat의 인자로 사용한다. jps만 사용하면 WAS 인스턴스가 한 장비에서 여러 개 실행되고 있을 때 모두 부트스트랩(bootstrap) 정보만 나타내는 단점이 있기 때문에 ps -ef | grep java
명령을 함께 사용하는 것도 좋다.
GC 수행 정보는 지속적으로 관찰해야 하므로, 일정 시간마다 계속 GC 모니터링 정보를 출력하도록 jstat을 실행할 수 있다.
jstat -gc <vmid> 1000(또는 1s)
라고 실행하면 jstat은 1초마다 GC 모니터링 정보를 콘솔에 출력한다.jstat -gc <vmid> 1000 10
이라고 하면 1초마다 한 번씩 총 10회 GC 모니터링 정보를 출력할 것이다.-gc 옵션 이외에도 jstat에는 여러 옵션이 있는데 GC와 관련된 옵션만 소개하면 다음과 같다.
사용 빈도로만 본다면 -gcutil(또는 -gccause)
, -gc
, -gccapacity
의 순서로 많이 사용하게 될 것이다.
일단 -gcutil
옵션으로 힙 영역의 사용 정도와 GC 발생 횟수, 실행 누적 시간을 확인하고 -gccapacity 옵션 등을 이용하여 실제 할당 크기를 알 수 있기 때문이다.
-gc 옵션을 사용하면 다음과 같은 출력 정보를 볼 수 있다.
jstat의 옵션에 따라 나타나는 칼럼 종류가 다른데, 칼럼 정보를 정리하면 다음과 같다. jstat 옵션
의 옵션을 사용하면 해당 칼럼의 정보가 나타난다.
콘솔을 사용할 수만 있다면 언제든지 로컬/리모트에서 동작 중인 Java 애플리케이션의 GC 수행 정보를 모니터링할 수 있다는 것이 jstat의 장점이다.
위의 여러 항목 중에서 -gcutil 옵션을 사용하면 다음 예와 같은 결과가 출력된다.
GC 튜닝을 할 때 유념해서 봐야 하는 부분은 YGC, YGCT, FGC, FGCT, GCT이다.
이 항목들이 중요한 이유는 GC를 수행하는데 시간이 얼마나 소요되었는지 알 수 있기 때문이다.
위의 예에서 YGC는 217이고 YGCT가 0.928이므로, 산술평균을 내면 하나의 Young GC당 4ms(0.004초) 정도의 시간이 필요했다는 것을 알 수 있다. 마찬가지로 평균 Full GC 시간은 33ms임을 알 수 있다.
하지만 산술평균은 실제 GC 문제를 분석하는 데 도움이 되지 않는 경우가 많다. GC 수행 시간 편차가 심할 수 있기 때문이다(다시 말해서 0.067초의 Full GC 시간 중 한 번은 1ms, 다른 한 번은 57ms가 소요되었을 수도 있다).
산술평균이 아닌 개별적인 GC 시간을 파악하려면 -verbosegc
옵션을 이용하는 것이 더 유리하다.
-verbosegc
옵션은 Java 애플리케이션을 가동할 때 지정하는 JVM 옵션 가운데 하나이다. -verbosegc
옵션은 시작할 때 지정해야 하기 때문에 굳이 사용할 필요가 없는 옵션으로 이해할 수도 있다(jstat
을 사용하면 되므로). -verbosegc
옵션과 함께 사용할 수 있는 부가 옵션에는 다음과 같은 옵션이 있다.
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintGCDateStamps (from JDK 6 update 4)
만약 -verbosegc
옵션만 사용한다면 -XX:+PrintGCDetails
옵션이 기본으로 적용된다.
-verbosegc
옵션의 부가 옵션들은 배타적인 것이 아니라 함께 섞어서 사용할 수 있다.
-verbosegc
옵션을 사용하면 Minor GC가 발생할 때마다 다음과 같은 형식의 결과를 볼 수 있다.
[GC [<collector>: <starting occupancy1=""> -> <ending occupancy1="">, <pause time1=""> secs] <starting occupancy3=""> -> <ending occupancy3="">, <pause time3=""> secs]
</pause></ending></starting></pause></ending></starting></collector>
다음은 위의 결과 형식의 각 항목에 대한 설명이다.
다음은 Minor GC에 대한 -verbosegc
옵션 출력 결과의 예이다.
다음은 Full GC가 발생했을 때 출력 결과의 예이다.
[Full GC [Tenured: 3485K->4095K(4096K), 0.1745373 secs] 61244K->7418K(63104K), [Perm : 10756K->10756K(12288K)], 0.1762129 secs] [Times: user=0.19 sys=0.00, real=0.19 secs]
만약 CMS Collector를 사용한다면 다음과 같은 CMS 정보도 알 수 있다.
-verbosegc
옵션은 이렇게 GC 이벤트가 발생할 때마다 로그를 출력하기 때문에, GC 수행으로 인한 힙 사용률 변화를 알기 쉽다.
Java VisualVM은 Oracle JDK가 제공하는 GUI 프로파일링/모니터링 툴이다.
jstat
이나 -verbosegc
옵션만큼 자세한 정보는 알 수 없다. jstat 만큼의 자세한 정보를 원한다면 Visual GC 플러그인을 설치하는 것이 좋다. Visual GC를 이용하면 jstatd 실행을 통해 알 수 있는 정보를 좀 더 직관적으로 볼 수 있다.
원래 -verbosegc
옵션에 대한 GUI 분석 기능은 HPTune이라는 도구에서 제공했다. HPJMeter 3.0
부터는 HPTune을 기능을 통합하여 지원하기 때문에 별도로 HPTune을 설치하지 않아도 된다.
애플리케이션을 가동할 때 -verbosegc
옵션의 출력 결과를 별도의 파일로 리다이렉션하도록 하면, HPJMeter
에서 파일을 불러들여 GUI 환경에서 훨씬 더 편하고 빠르게 GC 수행 정보를 분석할 수 있다.