비정상적으로 높은 WLS의 CPU 사용량 패턴

http://kr.bea.com/support/customer_support/SupportPattern/05_04_High_CPU_Usage_Pattern.html

 
OS별로 정리되어있음

 
Solaris 부분만 카피해두겠음

 
비정상적으로 높은 WLS의 CPU 사용량 패턴

문제 설명
WebLogic Server 프로세스의 CPU 사용량이 과도하게 높기 때문에 시스템 관리자 또는 사용자는 CPU 사용량이 높은 원인을 파악하고자 합니다.

문제 해결
다음 항목을 모두 수행해야 하는 것은 아닙니다.  어떤 경우에는 다음 중 일부만 수행하여도 해결할 수 있습니다.
항목 바로가기

• 문제 발생 원인
• 높은 CPU 사용량에 대한 데이터 수집
  • Solaris
  • Linux
  • AIX
  • HP-UX
  • Windows
• 외부 리소스

문제 발생 원인
이 문제는 WebLogic Server 자체의 문제, 사용자가 만든 스레드, 잘못된 코딩 방식 또는 타사 소프트웨어 등 다양한 이유로 인해 발생할 수 있습니다.  따라서 문제 발생 원인을 파악하기가 쉽지 않습니다.  이 패턴은 운영 체제 고유의 명령을 사용하여 수집된 데이터를 활용하여 문제를 해결하는 데 도움을 줄 것입니다.

맨 위로
높은 CPU 사용량에 대한 데이터 수집
높은 CPU 사용량에 대한 데이터를 수집하려면 운영 체제별로 아래 단계를 따르십시오.
중요 참고 사항:
이러한 운영 체제에 대한 모든 정보는 Sun JVM을 기반으로 합니다.  현재 JRockit에서는 CPU 사용량을 나타내는 운영 체제 명령(prstat, top, pslist 등)에서 가져온 PID를 스레드 덤프의 올바른 스레드로 매핑할 수 없습니다.   이 매핑은 JRockit 70SP4RP2 버전과 81SP2RP1 버전부터 사용할 수 있습니다.  예를 들어, Linux에서 스레드 덤프는 이들 릴리스 이후에서는 다음과 같이 나타납니다. (PID는 스레드 덤프에 출력됩니다.)

"ExecuteThread: '20' for queue: 'default'"  id: 0x00000e80  prio: 5  ACTIVE, DAEMON, GCABLE
    thread: 0x469b0af0  lastj: 0xac0f19c
    pt_thr: 237596 pid: 23166
    at COM.jrockit.vm.Classes.defineClass0(Native Method)@0x8b4b798
    at COM.jrockit.vm.Classes.defineClass(Unknown Source)@0x8b4b8b1
    at java.lang.ClassLoader.defineClass(Unknown Source)@0x8b4b46f

위에서 PID는 23166으로, Linux 또는 사용 중인 운영 체제의 top(또는 운영 체제별 적절한 명령)에 보이는 PID와 직접 매핑되는 번호입니다.
16진수로 변환

참고:  이 패턴에 나오는 16진수 값을 보다 쉽게 계산하려면 셸 스크립트에서 다음 명령을 사용하여 10진수를 16진수로 변환할 수 있습니다.  Unix 기반 운영 체제에서는 편리할 것입니다.

dec2hex.sh:
    printf "dec -> hex:  %d = %x \n" ${1} ${1}

사용법:
$ sh dec2hex.sh 755

dec -> hex:  755 = 2f3

맨 위로

Solaris

1. Java 프로세스에 대해 prstat 명령을 실행합니다.  패턴을 파악할 수 있도록 이 명령을 여러 번 반복합니다. 예를 들면 다음과 같습니다. prstat -L -p <PID> 1 1

1. Java 프로세스에 대해 pstack 명령을 실행하여 LWP(Light Weight Process)를 PID(프로세스 ID)로 매핑합니다. 

예: pstack 9499 실행 후 출력을 파일로 리다이렉션합니다. 
Solaris에서 일반적인(/usr/lib) 스레드 라이브러리를 사용하는 경우 즉, LD_LIBRARY_PATH에 /usr/lib/lwp가 없는 경우, LWP는 OS 스레드로 직접 매핑되지 않으므로 프로세스에 대해 pstack을 실행해야 합니다. 따라서 대체(alternate, /usr/lib/lwp) 스레드 라이브러리를 사용하고 있는지 확인해야 합니다.

1. 실행 중인 스레드에 대한 올바른 정보를 얻기 위해 몇 번에 걸쳐 서버의 스레드 덤프를 작성합니다. 

이 작업을 수행하려면 Java 프로세스에 대해 kill -3 <PID>를 수행합니다.

1. LWP ID를 Java 스레드 ID에 매핑합니다. 

예를 들어, 문제의 LWP가 "8"이고 그것이 Java 스레드 "76"으로 매핑되었다고 가정합니다.  그러면 76의 16진수 값인 0x4c를 구합니다. 

1. 스레드 덤프에서 "nid= <스레드 식별자>"와 일치하는 스레드를 찾습니다.

이 예에서 "nid=0x4c"와 일치하는 스레드를 찾을 수 있으며, 이 스레드가 바로 CPU 사용량이 높은 스레드입니다.

1. 그런 후 다음을 수행해야 합니다.
   • 코드에서 이러한 문제가 발생한 이유를 파악합니다.
   • 또는 스택 트레이스의 내용에 WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의합니다.

다음은 위에 설명한 프로세스를 Solaris용으로 만든 예제입니다.

1. Java 프로세스에 대해 prstat 명령을 실행합니다.

$ prstat -L -p 9499 1 1
  PID  USERNAME   SIZE  RSS  STATE  PRI NICE   TIME    CPU  PROCESS/LWPID
  9499 usera      153M  100M sleep   58    0   0:00.22 0.6% java/8
  9499 usera      153M  100M sleep   58    0   0:00.10 0.2% java/10
  9499 usera      153M  100M sleep   58    0   0:00.11 0.1% java/9
  9499 usera      153M  100M sleep   58    0   0:00.03 0.0% java/5
  9499 usera      153M  100M sleep   58    0   0:01.01 0.0% java/1
  9499 usera      153M  100M sleep   58    0   0:00.00 0.0% java/12
  9499 usera      153M  100M sleep   58    0   0:00.00 0.0% java/11
  9499 usera      153M  100M sleep   58    0   0:00.00 0.0% java/14
  9499 usera      153M  100M sleep   58    0   0:00.00 0.0% java/13
  9499 usera      153M  100M sleep   59    0   0:00.07 0.0% java/7
  9499 usera      153M  100M sleep   59    0   0:00.00 0.0% java/6
  9499 usera      153M  100M sleep   59    0   0:00.00 0.0% java/4
  9499 usera      153M  100M sleep   58    0   0:00.11 0.0% java/3
  9499 usera      153M  100M sleep   58    0   0:00.00 0.0% java/2

1. pstack 명령을 실행합니다.

예: pstack 9499 실행 후 출력을 파일로 리다이렉션합니다. 
Solaris에서 일반적인 스레드(/usr/lib) 라이브러리를 사용하는 경우 즉, LD_LIBRARY_PATH에 /usr/lib/lwp가 없는 경우, LWP는 OS 스레드로 직접 매핑되지 않으므로 프로세스에 대해 pstack을 실행해야 합니다. 따라서 대체(alternate, /usr/lib/lwp) 스레드 라이브러리를 사용하고 있는지 확인해야 합니다.

위의 예제에서는 prstat 결과의 최상위에 "java/8" 프로세스가 표시되었습니다. 

1. "lwp# 8"에 대한 pstack 결과를 검토합니다. 

아래와 같이 이 값이 pstack 결과의 "thread# 76"에 매핑된다는 것을 알 수 있습니다.

----------------- lwp# 8 / thread# 76  --------------------
ff29d190 poll     (e2e81548, 0, bb8)
ff24d154 select   (0, 0, 0, e2e81548, ff2bf1b4, e2e81548) + 348
ff36b134 select   (0, bb8, 7fffffff, fe4c8000, 0, bb8) + 34
fe0f62e4 __1cCosFsleep6FpnGThread_xl_i_ (0, bb8, fe4c8000, 1, 0, 1e2fd8) + 234
fe23f050 JVM_Sleep (2, 0, bb8, fe4de978, fe4c8000, 1e2fd8) + 22c
0008f7ac ???????? (e2e818d4, bb8, 1e2fd8, 984a4, 0, 109a0)
0008c914 ???????? (e2e8194c, 1, fe4d6a80, 98564, 8, e2e81868)
fe5324e8 __1cMStubRoutinesG_code1_ (e2e819d8, e2e81c10, a, f6cb5000, 4, e2e818f0) + 3ec
fe0cbe94 __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (e2e81c08,fe4c8000, e2e81b54, 1e2fd8, 8e764, e2e81c10) +308
fe1f6dbc __1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandlee81c08, e2e81b54) + 150pnGThread__v_(f6cb64b8, e2e81b40, e2e81b44, fe4c8000, e2d8) + 60e_5pnGThread__v_ (e2e81c08, e2e81c04, e2e81c00,e2e81bf4, e2e81bec, 1e2f8000, e2e81d10, 1e, e) + 120FpnKJavaThread_pnGThread__v_ (f6817ff8, 1e2fd8, fe4c
7fd70) + 3d8cKJavaThreadDrun6M_v_ (e2e02000, fe4d3e34, fe4c8000, 7fd70, 1e2fd8,
fe213ec8 _start   (fe4c8000, fe625d10, 0, 5, 1, fe401000) + 20
ff36b728 _thread_start (1e2fd8, 0, 0, 0, 0, 0) + 40

1. Java 프로세스에 대해 다음을 수행하여 서버의 스레드 덤프를 가져옵니다.

kill -3 <PID>

1. lwp# 8은 스레드 #76에 매핑되어 있으므로 76의 16진수 값을 계산하여 4c를 구할 수 있습니다. 

이 값은 JVM 스레드 덤프의 nid=0x4c에 매핑됩니다.

"Thread-6" prio=5 tid=0x1e2fd8 nid=0x4c waiting on monitor [0xe2e81000..0xe2e819d8]
        at java.lang.Thread.sleep(Native Method)
        at weblogic.management.deploy.GenericAppPoller.run(GenericAppPoller.java:139)

이 예제에서 CPU 사용량이 가장 높은 스레드는 실제로 휴식 상태입니다.  서버를 개발 모드(Development Mode)로 시작하면 응용 프로그램 폴러가 실행됩니다.  응용 프로그램 폴러는 30초 간격으로 실행됩니다. 따라서 스레드 덤프가 이 스레드의 동작하는 시점에 만들어 지지 않았음을 알 수 있습니다. 
이론적으로는 세 단계를 모두 빠르게 연속적으로 수행하여 가능한 거의 동시에 데이터를 캡처할 수 있어야 합니다.  이러한 일련의 작업들은 아래와 같은 간단한 셸 스크립트를 이용하여 수행할 수 있습니다.

#
# Takes an argument (PID of the WLS process) and loops three times.  This will append the prstat information to a file called dump_high_cpu.txt.  The thread dump information will either be in file where stdout was redirected or printed on the screen.
#
for loopnum in 1 2 3
do
   prstat -L -p $1 1 1 >> dump_high_cpu.txt
   pstack $1  >> dump_high_cpu.txt
   kill -3  $1
   echo "prstat, pstack, and thread dump done. #" $loopnum
   sleep 1
   echo "Done sleeping."
done

1. 그런 후 해당 스레드를 검토하여 수행 중인 작업이나
   Tistory 태그: weblogic
2. 문제를 확인할 수 있습니다.