[WAS] GC 모니터링 및 튜닝하기

OOM(OutOfMemory) 에러가 발생하거나 Heap Dump 로그를 떨구고서 WAS가 죽을 경우 메모리설정에 대한 이슈를 어떻게 해결할지 알아보자 

1) JVM 메모리 운영

  - Heap = Young Generation + Old Generation + Permanent Generation(PermSize=MethodArea)

    + Young 에서 신규 생성되어 오래된 객체가 Old로 넘어감

    + Young 에서 바로 사용되지 않으면 Minor GC

    + Old로 넘어간 후 Old에서 더 이상 사용되지 않으면 Full GC

    + Perm 영역은 상수영역으로 GC 대상은 아니나 간혹 일어남

  - Young Generation = Eden + Survivor (2개)  로 구성

    + Eden 에서 사용되어진 것은 Survivor로 넘어가고 다시 Old 영역으로 넘겨진다  

2) jstat 명령을 통한 GC 모니터링

  - $JDK_HOME/bin/jstat 명령어 이용 

  - jstat 옵션들 : 출처 (http://helloworld.naver.com/helloworld/helloworld/6043)

옵션	기능
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 / gccapcity 사용 예

    + gcutil : WAS 기동후 FGC(Full GC 건수)는  230회 발생하였고, FGCT(Full GC 수행시간)은 2302초로 거의 10초가 소요되었다

                 Full GC 수행마다 10초의 시간

    + gccapacity : New 영역 사용크기(NGCMN) 이 2,097,152 (즉 2Gbytes)이고 Old 영역 사용크기(OGCMN)가 3,145,728 (즉 3GBytes) 가량이 된다 

[jboss@dowon ~]$ ps -ef |grep java

jboss    13090 13053  8 Mar27 ?        04:28:28 /usr/java/jdk1.6.0_31/bin/java -Dprogram.name=run.sh -server .. 중략..

[jboss@dowon ~]$ jstat -gcutil 13090

  S0     S1     E        O       P     YGC   YGCT    FGC   FGCT      GCT   

  0.76   0.00  85.57  86.24  26.88   1260  644.013   230   2302.259   2946.273

[jboss@dowon ~]$ jstat -gccapacity 13090

 NGCMN    NGCMX     NGC     S0C   S1C       EC      OGCMN      OGCMX       OGC         OC      PGCMN    PGCMX     PGC       PC     YGC    FGC 

2097152.0 2097152.0 2097152.0 430656.0 412096.0 1254400.0  3145728.0  3145728.0  3145728.0  3145728.0 524288.0 524288.0 524288.0 524288.0   1260   230

  - 간단한  GC Check Shell Script 작성해 보았다 

    + weblogic.Server (jboss: org.jboss.Main) 부분을 WAS나 JAVA Process 환경에 맞게 변경하여 사용한다

    + WAS가 기동된 이후 Full GC 평균 시간 = FGCT/FGC  : 만일 3초이상이면 점검 대상으로 지정

#!/bin/sh

# [GC Statistics after WAS started]

# config

#   interval : 3 sec

#   count : 2

echo ""

echo "[GC statistics after WAS is started]"

echo "----------------------------------------"

echo " S0/S1: Survivor 0/1 (KB)"

echo " E    : Eden (KB)"

echo " O    : Old area size (KB)"

echo " P    : Permanent area size (KB)"

echo " YGC  : Young Generation GC Count"

echo " YGCT : Young Generation GC Total Time"

echo " FGC  : Full GC Count"

echo " FGCT : Full GC Total Time"

echo " GCT  : GC Total Time"

echo "----------------------------------------"

echo ""

echo " HostName : " $(hostname)

echo ""

for PID in  `ps -ef | grep java | egrep -v grep | grep weblogic.Server | awk -F" " '{print $2}'`

do

echo " WAS PID  : " $PID

echo "----------------------------------------------------------------------------"

jstat -gcutil $PID 3000 2

echo "----------------------------------------------------------------------------"

echo ""

done

echo ""

결과

===========================================

 HostName :  jupitorDowon

 WAS PID  :  355343

----------------------------------------------------------------------------

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   

  0.00   0.00  52.68  13.52  31.58   3764   30.408  1878 1148.863 1179.271

  0.00   0.00  52.69  13.52  31.58   3764   30.408  1878 1148.863 1179.271

----------------------------------------------------------------------------

  - 컬럼 출력 내용 : 출처 (http://helloworld.naver.com/helloworld/helloworld/6043)

칼럼	설명	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

3) verbose:gc 옵션을 통한 GC 모니터링

  - WAS 기동 Shell에 verbose:gc 옵션을 준다

    + GC에 대해 자세히 시간을 찍도록 한다

    + 로그위치와 명칭을 지정한다

-verbose:gc 

-Xloggc:/applog/cmsmDomain/gclog/gc.log 

-XX:+PrintGCDetails 

-XX:+PrintGCTimeStamps 

-XX:+PrintHeapAtGC 

-XX:+HeapDumpOnOutOfMemoryError 

-XX:HeapDumpPath=/applog/cmsmDomain/gclog/java_pid.hprof 

  - 로그 출력 예

// Full GC

7210.826: [Full GC (System) [PSYoungGen: 23616K->0K(1947520K)] [PSOldGen: 886563K->856929K(3145728K)] 910179K->856929K(5093248K) [PSPermGen: 138064K->138064K(524288K)], 2.9391980 secs] [Times: user=2.98 sys=0.00, real=2.94 secs]

Heap after GC invocations=52 (full 3):

 PSYoungGen      total 1947520K, used 0K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)

  eden space 1801536K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007edf50000)

  from space 145984K, 0% used [0x00000007edf50000,0x00000007edf50000,0x00000007f6de0000)

  to   space 141376K, 0% used [0x00000007f75f0000,0x00000007f75f0000,0x0000000800000000)

 PSOldGen        total 3145728K, used 856929K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)

  object space 3145728K, 27% used [0x00000006c0000000,0x00000006f44d8428,0x0000000780000000)

 PSPermGen       total 524288K, used 138064K [0x00000006a0000000, 0x00000006c0000000, 0x00000006c0000000)

  object space 524288K, 26% used [0x00000006a0000000,0x00000006a86d41d8,0x00000006c0000000)

}

// Minor GC

10500.769: [GC [PSYoungGen: 1769535K->35007K(1928320K)] 2645761K->912640K(5074048K), 0.0958040 secs] [Times: user=0.17 sys=0.00, real=0.09 secs]

Heap after GC invocations=67 (full 3):

 PSYoungGen      total 1928320K, used 35007K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)

  eden space 1754816K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007eb1b0000)

  from space 173504K, 20% used [0x00000007f5690000,0x00000007f78bff00,0x0000000800000000)

  to   space 168832K, 0% used [0x00000007eb1b0000,0x00000007eb1b0000,0x00000007f5690000)

 PSOldGen        total 3145728K, used 877632K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)

  object space 3145728K, 27% used [0x00000006c0000000,0x00000006f59101d8,0x0000000780000000)

 PSPermGen       total 524288K, used 138386K [0x00000006a0000000, 0x00000006c0000000, 0x00000006c0000000)

  object space 524288K, 26% used [0x00000006a0000000,0x00000006a8724880,0x00000006c0000000)

}

4) 튜닝하기 

  - WAS 기동 Shell의 기본옵션

    + -Xms -Xmx 힙사이즈 지정

    + -server 옵션 지정

    GC 튜닝 시 기본적으로 학인해야 하는 JVM 옵션 (출처: http://helloworld.naver.com/helloworld/37111)

구분	옵션	설명
힙(heap) 영역 크기	-Xms	JVM 시작 시 힙 영역 크기
	-Xmx	최대 힙 영역 크기
New 영역의 크기	-XX:NewRatio	New영역과 Old 영역의 비율
	-XX:NewSize	New영역의 크기
	-XX:SurvivorRatio	Eden 영역과 Survivor 영역의 비율

  - 설정 예 

/usr/java/jdk1.6.0_31/bin/java 

-server 

-Xms5120m -Xmx5120m 

-XX:NewSize=2048m 

-XX:MaxNewSize=2048m 

-XX:PermSize=512m 

-XX:MaxPermSize=512m 

-Xss5m 

-verbose:gc 

-Xloggc:/applog/cmsmDomain/gclog/gc.log 

-XX:+PrintGCDetails 

-XX:+PrintGCTimeStamps 

-XX:+PrintHeapAtGC 

-XX:+HeapDumpOnOutOfMemoryError 

-XX:HeapDumpPath=/applog/cmsmDomain/gclog/java_pid.hprof 

  - 다음의 경우 튜닝이 필요없다. 단 이것은 서비스의 특성에 따라 틀리다. 해당 시간 이상이면 튜닝 대상

• Minor GC의 처리 시간이 빠르다(50ms내외).
• Minor GC 주기가 빈번하지 않다(10초 내외).
• Full GC의 처리 시간이 빠르다(보통1초 이내).
• Full GC 주기가 빈번하지 않다(10분에 1회).

  - Full GC 수행 시간과 수행 간격 조사 => Minor GC 수행 시간과 수행 간격 조사 => 전체 평균값 및 수행 횟수등을 조사하여 튠이 필요성을 판단한다 

  - 메모리 설정 옵션을 조정하면서 결정한다

    + 힙사이즈가 크면 GC 시간도 올래 걸린다 : 그만큼 많은 객체가 쌓여 있을 것이므로 

    + 따라서 무조건 크게 잡는다고 해서 좋은 것은 아니므로 적정사이즈를 찾아가는 것이 중요하다 

    + NewRatio=2 는 New Generation:Old Generation = 1:2 비율 사이즈로 사용크기를 지정하는 것임 (-Xmx 사이즈에 대해서)

      즉, NewRatio=4 이면 New:Old=1:4 비율의 크기임

  - 튜닝 예 1)

    + jstat -gccapacity의 New영역 사용크기(NGCMN)과 Old영역 사용크기(OGCMN) 값의 비율을 체크한다 

      NGCMN:OGCMN = 2:3 (Gbytes)

    + NewRatio=2 => 3 => 4 로 바꾸어 가면서 Full/Minor GC 평균응답시간을 구한다 (jstat -gctuil로 구함)

  - 튜닝 예 2)

    + verbose:gc 로그가 남으면 HP JMeter를 통하여 분석한다

    + JMeter를 통하여 Duration 발생 간격을 측정하거나 GC 소요 시간을 그래프 형태로 볼 수 있다. 

    + 여러 옵션을 차례로 처음 몇개에만 적용해 보고 jstat -gcutil 을 통하여 통계값을 얻고 최적치를 측정해 나간다 

• Case1 : -XX:+UseParallelGC -Xms1536m -Xmx1536m -XX:NewRatio=2
• Case2 : -XX:+UseParallelGC -Xms1536m -Xmx1536m -XX:NewRatio=3
• Case3 : -XX:+UseParallelGC -Xms1g -Xmx1g -XX:NewRatio=3
• Case4 : -XX:+UseParallelOldGC -Xms1536m -Xmx1536m -XX:NewRatio=2
• Case5 : -XX:+UseParallelOldGC -Xms1536m -Xmx1536m -XX:NewRatio=3
• Case6 : -XX:+UseParallelOldGC -Xms1g -Xmx1g -XX:NewRatio=3

 

위의 모든 내용은 HelloWorld의 연재글을 통하여 현재 운영하고 있는 JBoss의 GC 분석을 수행할 예정이다. 이자리를 빌어 이상민님에게 감사를 드린다. 또한 사전 허락없이 옵션 테이블을 인용하였고 만일 문제가 된다면 바로 삭제토록 할 예정이다. 

<참조>

  - GC 에 대한 이해 

    + Young:Old 영역에 대한 이해 : http://helloworld.naver.com/helloworld/1329

    + GC 모니터링 방법 -verbose:gc : http://helloworld.naver.com/helloworld/helloworld/6043

  - GC 튜닝 가이드 : http://helloworld.naver.com/helloworld/37111

  - jstat 사용예제 : https://community.jboss.org/thread/159052