블로그 이미지
윤영식
Frontend Application Architecter, Full Stacker, KnowHow Dispenser and Bike Rider

Publication

Statistics Graph

Recent Comment

'JSTAT'에 해당되는 글 1

  1. 2013.05.21 [WAS] GC 모니터링 및 튜닝하기
2013.05.21 17:08 Middleware, Cloud/WAS

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

저작자 표시 비영리 변경 금지
신고
posted by peter yun 윤영식
TAG , , , , ,
prev 1 next