JVM. GARBAGE COLLECTION 모니터링

NHN 생산성혁신랩 이상민, NHN Business Platform 웹플랫폼개발랩 송기선

이전 글인 "Java Garbage Collection"에서는 여러 GC(Garbage Collection) 알고리즘의 동작 과정을 알아보았습니다. 이번 글에서는 JVM에서 어떻게 GC가 수행되고 있는지 실시간으로 알 수 있는 방법을 소개하려 합니다.

GC 모니터링이란

GC 모니터링이란 JVM이 어떻게 GC를 수행하고 있는지 알아내는 과정을 말한다. 가령 Young 영역에 있던 객체를 Old 영역으로 언제 얼마나 이동했는지, stop-the-world가 언제 일어나고 얼마동안 일어났는지 등의 정보를 알 수 있다. GC를 모니터링하는 이유는 JVM이 효율적으로 GC를 수행하는지 파악하고 추가적인 GC 튜닝 작업이 필요한지 확인하기 위해서다. GC 모니터링으로 파악한 정보를 바탕으로 애플리케이션을 수정하거나 GC 방법을 변경(GC 튜닝)할 수 있다.

GC를 모니터링하는 방법은?

GC를 모니터링하는 방법에는 여러 가지 방법이 있지만, GC 수행 정보를 사용자에게 보여 주는 방법만 다르다. GC는 JVM이 수행하는 것이고 GC 모니터링 도구는 JVM이 제공하는 GC 정보를 받아 사용자에게 보여 주는 것이기 때문에, 어떤 방법을 사용하든 동일한 결과를 얻을 수 있다. 그렇기 때문에 여러 GC 모니터링 방법을 모두 익혀야 할 필요는 없지만 GC 모니터링 방법을 익히는 데에는 아주 약간의 시간만 투자하면 되므로, 여러 GC 모니터링 방법을 익혀 둔다면 환경과 상황에 따라 적합한 GC 모니터링 방식을 빠르게 쓸 수 있어 도움이 될 것이다.

이 글에서 설명하는 도구나 JVM 옵션은 JVM 벤더에 상관없이 공통적으로 사용할 수 있는 방법은 아니다. GC 수행 정보를 보여 주는 것에 대한 '표준'은 필요 없기 때문이다. 이 글에서는 HotSpot JVM(Oracle JVM)을 기준으로 설명할 것이다.

GC 모니터링 방법은 접근 인터페이스에 따라 CUI와 GUI로 구분할 수 있다.

대표적인 CUI GC 모니터링 방법에는 'jstat'이라는 CUI 애플리케이션을 이용하는 방법과 JVM을 가동할 때 '-verbosegc'라는 JVM 옵션을 이용하는 방법이 있다.

GUI GC 모니터링 방법은 별도의 GUI 애플리케이션을 이용한다. 대표적인 GUI 애플리케이션 세 가지를 꼽으라면 'jconsole', 'jvisualvm', 'Visual GC'를 들 수 있다.

다음에서 각각의 방법에 대하여 알아보겠다.

jstat

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 등의 칼럼과 함께 실수형의 데이터가 출력될 것이다.

?

1 2 3 4 5 6

> jstat stat , S1C, S0U S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT 3008.0 3072.0 0.0 1511.1 343360.0 46383.0 699072.0 283690.2 75392.0 41064.3 2540 18.454 4 1.133 19.588 3008.0 3072.0 0.0 1511.1 343360.0 47530.9 699072.0 283690.2 75392.0 41064.3 2540 18.454 4 1.133 19.588 3008.0 3072.0 0.0 1511.1 343360.0 47793.0 699072.0 283690.2 75392.0 41064.3 2540 18.454 4 1.133 19.588 >

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와 관련된 옵션만 소개하면 다음과 같다.

표 1 GC 관련 jstat 옵션

옵션	기능
gc	각 힙(heap) 영역의 현재 크기와 현재 사용량(Eden 영역, Survivor 영역, Old 영역등), 총 GC 수행 횟수, 누적 GC 소요 시간을 보여 준다.
gccapactiy	각 힙 영역의 최소 크기(ms), 최대 크기(mx), 현재 크기, 각 영역별 GC 수행 횟수를 알 수 있는 정보를 보여 준다. 단, 현재 사용량과 누적 GC 소요 시간은 알 수 없다.
gccause	-gcutil 옵션이 제공하는 정보와 함께 마지막 GC 원인과 현재 발생하고 있는 GC의 원인을 알 수 있는 정보를 보여 준다.
gcnew	New 영역에 대한 GC 수행 정보를 보여 준다.
gcnewcapacity	New 영역의 크기에 대한 통계 정보를 보여 준다.
gcold	Old 영역에 대한 GC 수행 정보를 보여 준다.
gcoldcapacity	Old 영역의 크기에 대한 통계 정보를 보여 준다.
gcpermcapacity	Permanent 영역에 대한 통계 정보를 보여 준다.
gcutil	각 힙 영역에 대한 사용 정도를 백분율로 보여 준다. 아울러 총 GC 수행 횟수와 누적 GC 시간을 알 수 있다.

사용 빈도로만 본다면 -gcutil(또는 -gccause), -gc, -gccapacity의순서로 많이 사용하게 될 것이다. 일단 -gcutil 옵션으로 힙 영역의 사용 정도와 GC 발생 횟수, 실행 누적 시간을 확인하고 -gccapacity 옵션 등을 이용하여 실제 할당 크기를 알 수 있기 때문이다.

-gc 옵션을 사용하면 다음과 같은 출력 정보를 볼 수 있다.

?

1 2 3 4

S0C S1C … GCT 1248.0 896.0 … 1.246 1248.0 896.0 … 1.246 … … … …

jstat의 옵션에 따라 나타나는 칼럼 종류가 다른데, 칼럼 정보를 정리하면 다음과 같다. 'jstat 옵션'의 옵션을 사용하면 해당 칼럼의 정보가 나타난다.

표 2 jstat의 옵션에 따른 칼럼 정보

칼럼	설명	jstat 옵션
S0C	Survivor 0 영역의 현재 크기를 KB 단위로 표시	-gc -gccapacity -gcnew -gcnewcapacity
S1C	Survivor 1 영역의 현재 크기를 KB 단위로 표시	-gc -gccapacity -gcnew -gcnewcapacity
S0U	Survivor 0 영역의 현재 사용량을 KB 단위로 표시	-gc -gcnew
S1U	Survivor 1 영역의 현재 사용량을 KB 단위로 표시	-gc -gcnew
EC	Eden 영역의 현재 크기를 KB 단위로 표시	-gc -gccapacity -gcnew -gcnewcapacity
EU	Eden 영역의 현재 사용량을KB 단위로 표시	-gc -gcnew
OC	Old 영역의 현재 크기를 KB 단위로 표시	-gc -gccapacity -gcold -gcoldcapacity
OU	Old 영역의 현재 사용량을KB 단위로 표시	-gc -gcold
PC	Permanent영역의 현재 크기를 KB 단위로 표시	-gc -gccapacity -gcold -gcoldcapacity -gcpermcapacity
PU	Permanent영역의 현재 사용량을KB 단위로 표시	-gc -gcold
YGC	Young Generation의 GC 이벤트 발생 횟수	-gc -gccapacity -gcnew -gcnewcapacity -gcold -gcoldcapacity -gcpermcapacity -gcutil -gccause
YGCT	Yong Generation의 GC 수행 누적 시간	-gc -gcnew -gcutil -gccause
FGC	Full GC 이벤트가 발생한 횟수	-gc -gccapacity -gcnew -gcnewcapacity -gcold -gcoldcapacity -gcpermcapacity -gcutil -gccause
FGCT	Full GC 수행 누적 시간	-gc -gcold -gcoldcapacity -gcpermcapacity -gcutil -gccause
GCT	전체 GC 수행 누적 시간	-gc -gcold -gcoldcapacity -gcpermcapacity -gcutil -gccause
NGCMN	New Generation의 최소 크기를 KB단위로 표시	-gccapacity -gcnewcapacity
NGCMX	New Generation의 최대 크기를 KB단위로 표시	-gccapacity -gcnewcapacity
NGC	New Generation의 현재 크기를 KB단위로 표시	-gccapacity -gcnewcapacity
OGCMN	Old Generation의 최소 크기를 KB단위로 표시	-gccapacity -gcoldcapacity
OGCMX	Old Generation의 최대 크기를 KB단위로 표시	-gccapacity -gcoldcapacity
OGC	Old Generation의 현재 크기를 KB단위로 표시	-gccapacity -gcoldcapacity
PGCMN	Permanent Generation의 최소 크기를 KB단위로 표시	-gccapacity -gcpermcapacity
PGCMX	Permanent Generation의 최대 크기를 KB단위로 표시	-gccapacity -gcpermcapacity
PGC	현재 Permanent Generation의 크기를 KB단위로 표시	-gccapacity -gcpermcapacity
PC	Permanent 영역의 현재 크기를 KB단위로 표시	-gccapacity -gcpermcapacity
PU	Permanent 영역의 현재 사용량을 KB단위로 표시	-gc -gcold
LGCC	지난 GC의 발생 이유	-gccause
GCC	현재 GC의 발생 이유	-gccause
TT	Tenuring threshold. Young 영역 내에서 이 횟수만큼 복사되었을 경우(S0 ->S1, S1->S0) Old 영역으로 이동	-gcnew
MTT	최대 Tenuring threshold. Yong 영역 내에서 이 횟수만큼 복사되었을 경우 Old 영역으로 이동	-gcnew
DSS	적절한 Survivor 영역의 크기를 KB단위로 표시	-gcnew

콘솔을 사용할 수만 있다면 언제든지 로컬/리모트에서 동작 중인 Java 애플리케이션의 GC 수행 정보를 모니터링할 수 있다는 것이 jstat의 장점이다. 위의 여러 항목 중에서 -gcutil 옵션을 사용하면 다음 예와 같은 결과가 출력된다. GC 튜닝을 할 때 유념해서 봐야 하는 부분은 YGC, YGCT, FGC, FGCT, GCT이다.

?

1 2 3 4

S0 S1 E O P YGC YGCT FGC FGCT GCT 0.00 66.44 54.12 10.58 86.63 217 0.928 2 0.067 0.995 0.00 66.44 54.12 10.58 86.63 217 0.928 2 0.067 0.995 0.00 66.44 54.12 10.58 86.63 217 0.928 2 0.067 0.995

이 항목들이 중요한 이유는 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 옵션

-verbosegc 옵션은 Java 애플리케이션을 가동할 때 지정하는 JVM 옵션 가운데 하나이다. jstat은 특별한 옵션을 지정하지 않은 어떤 Java 애플리케이션도 모니터링할 수 있는 반면, -verbosegc 옵션은 시작할 때 지정해야 하기 때문에 굳이 사용할 필요가 없는 옵션으로 이해할 수도 있다(jstat을 사용하면 되므로). 그러나 직관적으로 이해하기 쉬운 출력 결과를 GC가 발생할 때마다 보여 주기 때문에 개략적인 GC 정보를 모니터링할 때에는 아주 좋다.

표 3 jstat과 -verbosegc 옵션 비교

	jstat	-verbosegc 옵션
모니터링 대상	터미널에 로그인할 수 있는 머신에서 가동 중인 Java 애플리케이션이거나 jstatd를 통하여 네트워크로 연결할 수 있는 리모트 Java 애플리케이션	JVM 시작 옵션으로 -verbosegc를 지정한 Java 애플리케이션에 대해서만
출력 정보	힙 상태(사용량, 최대 크기, GC 횟수/시간 등)	New 영역과 Old 영역에 대한 GC 이전/이후 크기와 수행 시간
출력 시기	지정한 시간 간격마다	GC가 발생할 때마다
유용할 때	힙 영역의 크기 변화를 관찰할 때	한 번의 GC에 대한 효과

-verbosegc 옵션과 함께 사용할 수 있는 부가 옵션에는 다음과 같은 옵션이 있다.

 

• -XX:+PrintGCDetails
• -XX:+PrintGCTimeStamps
• -XX:+PrintHeapAtGC
• -XX:+PrintGCDateStamps (from JDK 6 update 4)

만약 -verbosegc 옵션만 사용한다면 -XX:+PrintGCDetails 옵션이 기본으로 적용된다. -verbosegc 옵션의 부가 옵션들은 배타적인 것이 아니라 함께 섞어서 사용할 수 있다.

-verbosegc 옵션을 사용하면 Minor GC가 발생할 때마다 다음과 같은 형식의 결과를 볼 수 있다.

?

1 2	[GC [<collector>: <starting occupancy1=""> -> <ending occupancy1="">, <pause time1=""> secs] <starting occupancy3=""> -> <ending occupancy3="">, <pause time3=""> secs]  </pause></ending></starting></pause></ending></starting></collector>

다음은 위의 결과 형식의 각 항목에 대한 설명이다.

표 4 -verbosegc 옵션 사용 결과 형식의 항목

항목	설명
Collector	Minor GC를 위해 사용하는 컬렉터의 이름
starting occupancy1	GC 전 Young 영역의 크기
ending occupancy1	GC 후 Young 영역의 크기
pause time1	Minor GC를 위해 Java 애플리케이션이 수행을 멈춘 시간
starting occupancy3	GC 전 전체 힙 크기
ending occupancy3	GC 후 전체 힙 크기
pause time3	Major GC를 포함하여 전체 힙 GC를 위해 Java 애플리케이션 수행을 멈춘 시간

다음은 Minor GC에 대한 -verbosegc 옵션 출력 결과의 예이다.

?

1 2 3

[GC [DefNew: 4032K->64K(4032K), 0.0429742 secs] 9350K->7748K(32704K), 0.0431096 secs]    [GC [DefNew: 4032K->64K(4032K), 0.0403446 secs] 11716K->10121K(32704K), 0.0404867 secs]

다음은 Full GC가 발생했을 때 출력 결과의 예이다.

?

1	[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 정보도 알 수 있다.

?

1 2 3 4 5

[CMS-concurrent-mark: 0.129/0.129 secs] [CMS-concurrent-preclean: 0.007/0.007 secs] … [CMS-concurrent-sweep: 1.208/1.208 secs] [CMS-concurrent-reset: 0.036/0.036 secs]

-verbosegc 옵션은 이렇게 GC 이벤트가 발생할 때마다 로그를 출력하기 때문에, GC 수행으로 인한 힙 사용률 변화를 알기 쉽다.

(Java) VisualVM + Visual GC

Java VisualVM은 Oracle JDK가 제공하는 GUI 프로파일링/모니터링 툴이다.

JDK 포함 버전이 아니라 홈 페이지에서 Visual VM을 내려 받을 수도 있다. 편의상 이 둘을 구분하기 위해 JDK 포함 버전은 Java VisualVM(jvisualvm)이라고 부르고, 홈 페이지에서 내려 받는 버전을 Visual VM(visualvm)이라고 부른다. 둘의 기능이 완벽히 동일한 것은 아니고, 플러그인 설치 등에서 약간의 기능 차이가 있다. 필자는 개인적으로는 별도로 내려 받는 Visual VM을 선호하는 편이다.

Visual VM을 가동한 후 왼쪽의 패널에서 모니터링하려는 애플리케이션을 선택하면, 다음과 같은 Monitoring 탭을 찾을 수 있다. 이 Monitoring 탭에서 GC와 힙에 대한 개략적인 정보를 볼 수 있다.

그림 1 VisualVM 실행 화면

Visual VM의 기본 기능만으로도 개략적인 GC 상황을 알 수는 있지만 jstat이나 -verbosegc 옵션만큼 자세한 정보는 알 수 없다. jstat 만큼의 자세한 정보를 원한다면 Visual GC 플러그인을 설치하는 것이 좋다. Visual GC는 Tools 메뉴에서 실시간으로 설치할 수 있다.

그림 2 Visual GC 설치 화면

Visual GC를 이용하면 jstatd 실행을 통해 알 수 있는 정보를 좀 더 직관적으로 볼 수 있다.

그림 3 Visual GC 실행 화면

HPJMeter

HPJMeter는 -verbosegc 옵션의 출력 결과 분석을 쉽게 해 준다. jstat에 대응하는 GUI 애플리케이션이 Visual GC라면 HPJMeter는 -verbosegc 옵션에 대응하는 GUI 애플리케이션이라고 할 수 있다. 물론 GC 분석 기능은 HPJMeter가 제공하는 기능 중 일부일 뿐이다. HPJmeter는 HP에서 제작한 퍼포먼스 모니터링 도구로, HP-UX뿐만 아니라, Linux나 Microsoft Windows에서도 사용할 수 있다.

그림 4 HPJMeter를 이용한 GC 분석

원래 -verbosegc 옵션에 대한 GUI 분석 기능은 HPTune이라는 도구에서 제공했다. HPJMeter 3.0부터는 HPTune을 기능을 통합하여 지원하기 때문에 별도로 HPTune을 설치하지 않아도 된다.

애플리케이션을 가동할 때 -verbosegc 옵션의 출력 결과를 별도의 파일로 리다이렉션하도록 하면, HPJMeter에서 파일을 불러들여 GUI 환경에서 훨씬 더 편하고 빠르게 GC 수행 정보를 분석할 수 있다.

마치며

이 글에서는 GC 튜닝을 위한 준비 단계로 GC 수행 정보를 모니터링하는 방법을 알아보았다. 개인적인 경험으로는 jstat으로 모니터링하고 GC 시간이 오래 걸린다고 생각한다면 -verbosegc 옵션으로 GC를 분석하는 방법을 추천한다. 분석한 내용을 토대로 -verbosegc 옵션을 적용한 상태에서 변경한 GC 옵션을 적용한 결과를 분석하는 것이 일반적인 GC 튜닝 과정이다. 다음 글에서는 실제 사례를 보며 GC 튜닝을 어떻게 진행하면 좋을지 알아보겠다.

출처 : http://helloworld.naver.com/helloworld/6043