무난하게

Java 프로세스에 대해 prstat 명령을 실행합니다. 패턴을 파악할 수 있도록 이 명령을 여러 번 반복합니다. 예를 들면 다음과 같습니다. prstat -L -p 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) 스레드 라이브러리를 사용하고 있는지 확인해야 합니다.
실행 중인 스레드에 대한 올바른 정보를 얻기 위해 몇 번에 걸쳐 서버의 스레드 덤프를 작성합니다.
이 작업을 수행하려면 Java 프로세스에 대해 kill -3 를 수행합니다.

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

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

그런 후 다음을 수행해야 합니다.
코드에서 이러한 문제가 발생한 이유를 파악합니다.

또는 스택 트레이스의 내용에 WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의합니다.
다음은 위에 설명한 프로세스를 Solaris용으로 만든 예제입니다.

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

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

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

"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

Java 프로세스에 대해 다음을 수행하여 서버의 스레드 덤프를 가져옵니다.
kill -3
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

그런 후 해당 스레드를 검토하여 수행 중인 작업이나 문제를 확인할 수 있습니다.
맨 위로



Linux


top 실행 결과에서 WLS를 시작한 유저의 것 중 CPU 사용량이 높은 PID를 찾습니다.
kill -3 를 실행하여 WebLogic Server의 스레드 덤프를 여러 번 생성합니다.
첫 번째 단계에서 얻은 PID 번호를 16진수 값으로 변환합니다.
Linux용 JVM은 Java 스레드를 native 스레드로 구현하였으므로 각 스레드는 별도의 Linux 프로세스가 됩니다.

스레드 덤프에서 "nid=" 다음에 나오는 값이 이전 단계에서 가져온 16진수와 일치하는 스레드를 찾습니다.
이렇게 하면 높은 CPU 사용량 문제를 발생시키는 스레드를 알 수 있습니다.

사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스의 내용에 WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의하십시오.
다음은 위에 설명한 프로세스를 Linux용으로 만든 예제입니다.
top 실행 결과에서 WLS를 시작한 유저의 것 중 CPU 사용량이 높은 PID를 찾습니다.
해당 숫자를 16진수 값으로 변환합니다.
아래의 top 결과 예제를 참조하십시오 (WLS 프로세스에는 더 많은 스레드가 있지만 이 예제에서는 일부만 나타낸 것입니다.)


Linux에서 각 스레드는 Unix의 스레드와 달리 프로세스에 매핑됩니다.


PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
...........
22962 usera 9 0 86616 84M 26780 S 0.0 4.2 0:00 java
...........

PID가 22962이면 16진수 값은 0x59B2가 됩니다.

이 16진수 값을 사용하고 스레드 덤프에서 "nid=" 다음에 해당 값이 나오는 올바른 스레드를 찾아 가져옵니다.
예를 들어, 해당 스레드에 문제가 있을 경우 0x59B2는 ExecuteThread "0"이 됩니다.


"ExecuteThread: '0' for queue: 'default'" daemon prio=1 tid=0x83da550 nid=0x59b2 waiting on monitor [0x56138000..0x56138870]
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:415)
at weblogic.kernel.ExecuteThread.waitForRequest(ExecuteThread.java:146)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:172)

그런 후 해당 스레드를 검토하여 수행 중인 작업이나 문제를 확인할 수 있습니다.
위의 예제에서는 문제의 스레드가 현재 0%의 CPU를 사용하고 있으므로 이 작업의 프로세스만 표시됩니다. 이론적으로는 세 단계 모두 빠르게 연속적으로 수행하여 가능한 거의 동시에 데이터를 캡처할 수 있어야 합니다. 이러한 일련의 작업들은 아래와 같은 간단한 셸 스크립트를 이용하여 수행할 수 있습니다.


#
# 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
top -b -n1 >> dump_high_cpu.txt
kill -3 $1
echo "cpu snapshot and thread dump done. #" $loopnum
sleep 1
echo "Done sleeping."
done