OS별로 Thread별 CPU사용량 알아내는 방법
+++++++++++++++++++++++++++++++++++++++
+++++++++
문제 설명
++++++++++
WebLogic Server 프로세스의 CPU 사용량이 과도하게 높기 때문에 시스템 관리자 또는
사용자는 CPU 사용량이 높은 원인을 파악하고자 합니다.
문제 해결
다음 항목을 모두 수행해야 하는 것은 아닙니다. 어떤 경우에는 다음 중 일부만 수행
하여도 해결할 수 있습니다.
항목 바로가기
문제 발생 원인
이 문제는 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
Java 프로세스에 대해 prstat 명령을 실행합니다. 패턴을 파악할 수 있도록 이 명령
을 여러 번 반복합니다. 예를 들면 다음과 같습니다. prstat -L -p <PID> 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 <PID>를 수행합니다.
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_pn
GThread__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 <PID>
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 <PID>를 실행하여 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
맨 위로
AIX
ps -mp <WLS_PID> -o THREAD를 수행하여 CPU를 사용 중인 TID를 찾습니다.
스레드 중에서 "CP" 열(CPU 사용량)의 값이 높은 것을 확인합니다.
다음을 수행하여 서버의 스레드 덤프를 생성합니다.
kill -3 <WLS_PID>
dbx -a <WLS_PID>를 실행합니다.
dbx에서 dbx thread 명령을 실행하여 모든 스레드를 나열합니다.
ps -mp <PID> -o THREAD 명령을 실행하여 위에서 얻은 TID와 일치하는 줄을 찾습니
다.
해당 줄의 숫자는 "$t<NUM>" 형식으로 표시됩니다. 여기에서 "NUM"은 숫자를 나타냅니
다.
dbx에서 dbx 명령 th info <TID>(TID는 이전 단계의 $t<NUM> 번호에서 구함)를 실행하
여 해당 스레드에 대한 정보를 가져옵니다.
위의 결과에서 "general" 아래의 "pthread_t"를 확인하고 해당 16진수를 기록해 둡니
다.
매우 중요: 작업이 끝나면 dbx 프롬프트에서 dbx 명령에 "detach"를 입력해야 하며
그렇지 않고 프로세스에 연결된 상태로 그냥 종료하면 dbx는 해당 프로세스를 종료합
니다.
스레드 덤프에서 "native ID" 가 "p_thread_t"에 나타난 16진수 값과 일치하는 경우
를 검색합니다.
이렇게 하면 높은 CPU 사용량 문제를 발생시키는 스레드를 알 수 있습니다.
사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스의 내용에
WebLogic 라이브러리가 최상위에 있는 경우 BEA 지원부에 문의하십시오.
다음은 위에 설명한 프로세스를 AIX용으로 만든 예제입니다.
ps -mp 250076 -o THREAD를 실행하면 다음과 같은 결과가 표시됩니다.
USER PID PPID TID ST CP PRI SC WCHAN F TT BND COMMAND
usera 250076 217266 - A 38 60 72 * 242011 pts/0 -
/wwsl/sharedInstalls/aix/jdk130/...
- - - 315593 Z 0 97 1 - c00007 - - -
- - - 344305 S 0 60 1 f1000089c020e200 400400 -
- -
- - - 499769 S 0 60 1 f1000089c0213a00 400400 -
- -
- - - 540699 S 0 60 1 f100008790008440 8410400 -
- -
- - - 544789 S 0 60 1 f100008790008540 8410400 -
- -
- - - 548883 S 0 60 1 f100008790008640 8410400 -
- -
- - - 552979 S 0 60 1 f100008790008740 8410400 -
- -
- - - 565283 Z 0 60 1 - c00007 - - -
- - - 585783 S 0 60 1 f100008790008f40 8410400 -
- -
- - - 589865 Z 0 80 1 - c00007 - - -
- - - 593959 S 1 60 1 f100008790009140 8410400 -
- -
- - - 610365 S 0 60 1 f100008790009540 8410400 -
- -
- - - 614453 S 0 60 1 f100008790009640 8410400 -
- -
- - - 618547 S 0 60 1 f100008790009740 8410400 -
- -
- - - 622645 S 0 60 1 f100008790009840 8410400 -
- -
- - - 626743 S 0 60 1 f100008790009940 8410400 -
- -
- - - 630841 S 0 60 1 f100008790009a40 8410400 -
- -
- - - 634941 S 0 60 1 f100008790009b40 8410400 -
- -
- - - 639037 S 0 60 1 f100008790009c40 8410400 -
- -
- - - 643135 S 0 60 1 f100008790009d40 8410400 -
- -
- - - 647233 S 0 60 1 f100008790009e40 8410400 -
- -
- - - 651331 S 0 60 1 f100008790009f40 8410400 -
- -
- - - 655429 S 0 60 1 f10000879000a040 8410400 -
- -
- - - 659527 S 0 60 1 f10000879000a140 8410400 -
- -
- - - 663625 S 0 60 1 f10000879000a240 8410400 -
- -
- - - 667723 S 37 78 1 f1000089c020f150 400400 -
- -
- - - 671821 S 0 60 1 f10000879000a440 8410400 -
- -
- - - 675919 S 0 60 1 - 418400 - - -
- - - 680017 S 0 60 1 f10000879000a640 8410400 -
- -
- - - 684115 S 0 60 1 f10000879000a740 8410400 -
- -
- - - 688213 S 0 60 1 f10000879000a840 8410400 -
- -
- - - 692311 S 0 60 1 f10000879000a940 8410400 -
- -
- - - 696409 S 0 60 1 f10000879000aa40 8410400 -
- -
- - - 712801 S 0 60 1 f10000879000ae40 8410400 -
- -
- - - 716899 S 0 60 1 f10000879000af40 8410400 -
- -
- - - 721011 S 0 60 1 f10000879000b040 8410400 -
- -
- - - 725095 S 0 60 1 f10000879000b140 8410400 -
- -
- - - 729193 S 0 60 1 f10000879000b240 8410400 -
- -
- - - 733291 S 0 60 1 f10000879000b340 8410400 -
- -
- - - 737389 S 0 60 1 f10000879000b440 8410400 -
- -
- - - 741487 S 0 60 1 f10000879000b540 8410400 -
- -
- - - 745585 S 0 60 1 f10000879000b640 8410400 -
- -
- - - 749683 S 0 60 1 f10000879000b740 8410400 -
- -
- - - 753781 S 0 60 1 f10000879000b840 8410400 -
- -
- - - 757879 S 0 60 1 f10000879000b940 8410400 -
- -
- - - 761977 S 0 60 1 f10000879000ba40 8410400 -
- -
- - - 766075 S 0 60 1 f10000879000bb40 8410400 -
- -
- - - 770173 S 0 60 1 f10000879000bc40 8410400 -
- -
- - - 774271 Z 0 60 1 - c00007 - - -
- - - 778373 S 0 60 1 f10000879000be40 8410400 -
- -
- - - 782467 S 0 60 1 f10000879000bf40 8410400 -
- -
- - - 786565 S 0 60 1 f10000879000c040 8410400 -
- -
- - - 790663 S 0 60 1 f10000879000c140 8410400 -
- -
- - - 794761 S 0 60 1 f10000879000c240 8410400 -
- -
- - - 798859 S 0 60 1 f10000879000c340 8410400 -
- -
- - - 802957 S 0 60 1 f10000879000c440 8410400 -
- -
- - - 807055 S 0 60 1 f10000879000c540 8410400 -
- -
- - - 811153 S 0 60 1 f10000879000c640 8410400 -
- -
- - - 815253 S 0 60 1 f10000879000c740 8410400 -
- -
- - - 819357 S 0 60 1 f10000879000c840 8410400 -
- -
- - - 823447 S 0 60 1 f10000879000c940 8410400 -
- -
- - - 827545 S 0 60 1 f10000879000ca40 8410400 -
- -
- - - 831643 S 0 60 1 f10000879000cb40 8410400 -
- -
- - - 835741 S 0 60 1 f10000879000cc40 8410400 -
- -
- - - 839839 S 0 60 1 f10000879000cd40 8410400 -
- -
- - - 843937 S 0 60 1 f10000879000ce40 8410400 -
- -
- - - 848037 S 0 60 1 f10000879000cf40 8410400 -
- -
- - - 852135 S 0 60 1 f10000879000d040 8410400 -
- -
- - - 856257 S 0 60 1 f10000879000d140 8410400 -
- -
- - - 868527 S 0 60 1 f10000879000d440 8410400 -
- -
- - - 872623 S 0 60 1 f10000879000d540 8410400 -
- -
- - - 876725 S 0 60 1 f10000879000d640 8410400 -
- -
kill -3 <WLS_PID>를 실행하여 해당 WLS_PID의 스레드 덤프를 구합니다.
ps -mp <WLS_PID> -o THREAD 명령으로 표시된 정보를 검토합니다.
TID "667723"은 CP 열의 값이 높게 표시되어 있습니다. 즉, 다른 모든 열은 0에 가까
운 값을 나타내지만 이 열은 "37"을 나타냅니다.
dbx -a 250076을 실행하여 WebLogic Server 프로세스에 연결합니다.
thread 명령을 실행하여 모든 원시 스레드를 나열합니다.
다음은 관련된 스레드 부분만 나타낸 것입니다.
thread state-k wchan state-u k-tid mode held scope function
.....
$t15 wait 0xf10000879000a140 blocked 659527 k no sys
_event_sleep
$t16 wait 0xf10000879000a240 blocked 663625 k no sys
_event_sleep
$t17 run running 667723 k no sys
JVM_Send
$t18 wait 0xf10000879000a440 blocked 671821 k no sys
_event_sleep
$t19 wait running 675919 k no sys
poll
$t20 wait 0xf10000879000a640 blocked 680017 k no sys
_event_sleep
.....
th info 17 명령을 실행하여 해당 native 스레드에 대해 필요한 정보를 가져옵니다.
(dbx) th info 17
thread state-k wchan state-u k-tid mode held scope function
$t17 run running 667723 k no sys
JVM_Send
general:
pthread addr = 0x3ea55c68 size = 0x244
vp addr = 0x3e69e5e0 size = 0x2a8
thread errno = 2
start pc = 0x300408b0
joinable = no
pthread_t = 1011
scheduler:
kernel =
user = 1 (other)
event :
event = 0x0
cancel = enabled, deferred, not pending
stack storage:
base = 0x3ea15000 size = 0x40000
limit = 0x3ea55c68
sp = 0x3ea55054
매우 중요: dbx 프롬프트에서 "detach"를 실행하여 WebLogic 프로세스에서 연결을 끊
습니다.
위에서 "pthread_t"로 찾은 번호를 사용하여 WebLogic Server 프로세스의 스레드 덤프
에서 일치하는 스레드를 찾습니다.
앞에서 구한 스레드 덤프에서 "native ID" 다음에 나오는 숫자 중 "1011"의 16진수에
해당하는 숫자를 찾을 수 있습니다.
다음은 이 16진수와 일치하며 높은 CPU 사용량을 유발하는 스레드의 예입니다.
"ExecuteThread: '11' for queue: 'default'" (TID:0x31cf86d8,
sys_thread_t:0x3e5ea108, state:R, native ID:0x1011) prio=5
at java.net.SocketOutputStream.socketWrite(Native Method)
at java.net.SocketOutputStream.write(SocketOutputStream.java(Compiled
Code))
at weblogic.servlet.internal.ChunkUtils.writeChunkTransfer
(ChunkUtils.java(Compiled Code))
at weblogic.servlet.internal.ChunkUtils.writeChunks(ChunkUtils.java
(Compiled Code))
at weblogic.servlet.internal.ChunkOutput.flush(ChunkOutput.java
(Compiled Code))
at weblogic.servlet.internal.ChunkOutput.checkForFlush(ChunkOutput.java
(Compiled Code))
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java
(Compiled Code))
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java
(Compiled Code))
at weblogic.servlet.internal.ChunkOutputWrapper.write
(ChunkOutputWrapper.java(Compiled Code))
at weblogic.servlet.internal.ChunkWriter.write(ChunkWriter.java
(Compiled Code))
at java.io.Writer.write(Writer.java(Compiled Code))
at java.io.PrintWriter.write(PrintWriter.java(Compiled Code))
at java.io.PrintWriter.write(PrintWriter.java(Compiled Code))
at java.io.PrintWriter.print(PrintWriter.java(Compiled Code))
at java.io.PrintWriter.println(PrintWriter.java(Compiled Code))
at examples.servlets.HelloWorldServlet.service(HelloWorldServlet.java
(Compiled Code))
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run
(ServletStubImpl.java:1058)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:401)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:306)
at
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run
(WebAppServletContext.java:5445)
at weblogic.security.service.SecurityServiceManager.runAs
(SecurityServiceManager.java(Compiled Code))
at weblogic.servlet.internal.WebAppServletContext.invokeServlet
(WebAppServletContext.java:3105)
at weblogic.servlet.internal.ServletRequestImpl.execute
(ServletRequestImpl.java:2588)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java(Compiled
Code))
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:189)
----- Native Stack -----
sysSend
JVM_Send
Java_java_net_SocketOutputStream_socketWrite
사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스의 내용에
WebLogic 라이브러리가 최상위에 있는 경우 BEA 지원부에 문의하십시오.
맨 위로
HP-UX
현재 HP에는 별도의 스레드 ID를 수집하여 다시 스레드 덤프로 변환하기 위한 prstat
유사 명령이 없습니다. BEA Support에서는 PID(프로세스 ID), 해당 PID와 관련된
LWPID(Light Weight Process ID) 및 사용된 사용자 시간과 시스템 시간을 보여 주는
간단한 유틸리티를 개발했습니다. 사용자 시간(user time)은 LWPID가 CPU를 사용할수
록 증가하는 값이라 이 유틸리티를 사용하면 짧은 시간 동안의 증가치만 확인할 수 있
습니다. 따라서 이것은 대략적인 참조로만 사용하는 것이 좋습니다. BEA의
hp_prstat 유틸리티를 사용하면 각 LWPID의 사용자 시간을 주기적으로 측정하여 시간
에 따라 사용량이 증가하는 PID를 확인할 수 있습니다. HP에서 제공하는 API는 이보
다 세밀한 측정 방법을 제공하지 않기 때문에 사용자 시간은 정수로만 표시될 수 있습
니다.
HP-UX에 대한 데이터를 수집하려면 다음과 같이 하십시오.
hp_prstat를 클릭하여 BEA Support에서 개발한 hp_prstat 유틸리티를 다운로드합니
다.
Java 프로세스에 대해 hp_prstat 명령을 실행합니다.
Java 프로세스에 대해 kill -3 <PID>를 여러 번 실행하여 서버의 스레드 덤프를 몇
개 생성합니다.
잠시 후에 또 다른 hp_prstat <PID> 스냅샷을 만듭니다.
두 차례에 걸친 hp_prstat의 반복 작업에서 얻은 결과를 검토하여 사용자 시간이 빠르
게 증가하는 잘못된 LWPID가 있는지 확인합니다.
스레드 덤프를 검토하여 이 LWPID와 일치하는 "lwp_id=<Your LWPID>"가 있는지 확인합
니다.
이 LWPID는 CPU 사용량이 높은 스레드와 일치할 것입니다.
사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스의 내용에
WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의하십시오.
다음은 위에 설명한 프로세스를 HP-UX용으로 만든 예제입니다.
Java 프로세스에 대해 hp_prstat 명령을 실행합니다.
예: hp_prstat <PID>
높은 CPU 사용량 결과를 확인하면서 2-3분 간격으로 여러 번 이 작업을 수행합니다.
다음은 샘플 출력입니다.
lwpid pid pri status UsrTime SysTime
285365 4426 154 1 29 3
285381 4426 154 1 0 7
285382 4426 154 1 2 7
285383 4426 154 1 0 7
285384 4426 154 1 0 7
285385 4426 168 1 0 7
285386 4426 154 1 0 7
285387 4426 154 1 0 7
285388 4426 154 1 0 7
285389 4426 154 1 30 7
285404 4426 168 1 0 7
285405 4426 154 1 0 7
285406 4426 154 1 0 7
285407 4426 154 1 0 7
285408 4426 154 1 0 7
285409 4426 154 1 0 7
285410 4426 154 1 0 7
285411 4426 154 1 0 7
285412 4426 154 1 0 7
285413 4426 154 1 0 7
285414 4426 154 1 0 7
285415 4426 154 1 0 7
285416 4426 154 1 0 7
285417 4426 154 1 0 7
285418 4426 154 1 0 7
285419 4426 154 1 0 7
285420 4426 154 1 0 7
285421 4426 154 1 0 7
285422 4426 154 1 0 7
285423 4426 154 1 0 7
285424 4426 154 1 0 7
285425 4426 154 1 0 7
285426 4426 154 1 0 7
285427 4426 154 1 0 7
285428 4426 154 1 0 7
285429 4426 154 1 0 7
285430 4426 154 1 0 7
285431 4426 154 1 0 7
285432 4426 154 1 0 7
285433 4426 154 1 0 7
285434 4426 154 1 0 7
285435 4426 154 1 0 7
285436 4426 154 1 0 7
285439 4426 154 1 0 7
285441 4426 154 1 0 7
285442 4426 154 1 0 7
285443 4426 154 1 0 7
285444 4426 154 1 0 7
285445 4426 154 1 0 7
285446 4426 154 1 0 7
285449 4426 154 1 0 7
285450 4426 154 1 0 7
285451 4426 154 1 0 7
285452 4426 154 1 0 7
285453 4426 154 1 0 7
285454 4426 154 1 0 7
285455 4426 154 1 0 7
285456 4426 154 1 0 7
285457 4426 154 1 0 7
285458 4426 154 1 0 7
285459 4426 154 1 0 7
285460 4426 154 1 0 7
285461 4426 154 1 0 7
285462 4426 154 1 0 7
285463 4426 154 1 0 7
285464 4426 168 1 0 7
285468 4426 178 4 0 7
285469 4426 154 1 0 7
285470 4426 154 1 0 7
285471 4426 154 1 0 7
285472 4426 154 1 0 7
285473 4426 154 1 0 7
285475 4426 168 1 1 7
285477 4426 154 1 0 7
285478 4426 154 1 0 7
Java 프로세스에 대해 kill -3 <PID>를 실행하여 서버의 스레드 덤프를 생성합니다.
잠시 후에 또 다른 hp_prstat <PID> 스냅샷을 만듭니다.
2개의 LWPID(285475 및 285416)가 첫 번째 스냅샷에 비해 상당히 크다는 것을 알 수
있습니다.
두 PID를 검토해야 합니다.
lwpid pid pri status UsrTime SysTime
285365 4426 154 1 29 3
285381 4426 154 1 0 7
285382 4426 154 1 2 7
285383 4426 154 1 0 7
285384 4426 154 1 0 7
285385 4426 168 1 0 7
285386 4426 154 1 0 7
285387 4426 154 1 0 7
285388 4426 154 1 0 7
285389 4426 154 1 32 7
285404 4426 168 1 0 7
285405 4426 154 1 0 7
285406 4426 154 1 0 7
285407 4426 154 1 0 7
285408 4426 154 1 0 7
285409 4426 154 1 0 7
285410 4426 154 1 0 7
285411 4426 154 1 0 7
285412 4426 154 1 0 7
285413 4426 154 1 0 7
285414 4426 154 1 0 7
285415 4426 154 1 0 7
285416 4426 154 1 13 7
285417 4426 154 1 0 7
285418 4426 154 1 0 7
285419 4426 154 1 0 7
285420 4426 154 1 0 7
285421 4426 154 1 0 7
285422 4426 154 1 0 7
285423 4426 154 1 0 7
285424 4426 154 1 0 7
285425 4426 154 1 0 7
285426 4426 154 1 0 7
285427 4426 154 1 0 7
285428 4426 154 1 0 7
285429 4426 154 1 0 7
285430 4426 154 1 0 7
285431 4426 154 1 0 7
285432 4426 154 1 0 7
285433 4426 154 1 0 7
285434 4426 154 1 0 7
285435 4426 154 1 0 7
285436 4426 154 1 0 7
285439 4426 154 1 0 7
285441 4426 154 1 0 7
285442 4426 154 1 0 7
285443 4426 154 1 0 7
285444 4426 154 1 0 7
285445 4426 154 1 0 7
285446 4426 154 1 0 7
285449 4426 154 1 0 7
285450 4426 154 1 0 7
285451 4426 154 1 0 7
285452 4426 154 1 0 7
285453 4426 154 1 0 7
285454 4426 154 1 0 7
285455 4426 154 1 0 7
285456 4426 154 1 0 7
285457 4426 154 1 0 7
285458 4426 154 1 0 7
285459 4426 154 1 0 7
285460 4426 154 1 0 7
285461 4426 154 1 0 7
285462 4426 154 1 0 7
285463 4426 154 1 0 7
285464 4426 168 1 0 7
285468 4426 178 4 0 7
285469 4426 154 1 0 7
285470 4426 154 1 0 7
285471 4426 154 1 0 7
285472 4426 154 1 0 7
285473 4426 154 1 0 7
285475 4426 168 1 5 7
285477 4426 154 1 0 7
285478 4426 154 1 0 7
CPU 사용량이 높은 스레드를 올바르게 캡처할 수 있도록 Java 프로세스에 대해 kill -
3 <PID>를 수행하여 또 다른 스레드 덤프를 생성합니다.
UserTime이 증가하는 것으로 나타나는 hp_prstat 결과에서 LWPID를 구합니다. 스레
드 덤프를 검토하여 이 LWPID와 일치하는 "lwp_id=<Your LWPID>"가 있는지 확인합니
다.
다음과 같이 문제의 두 LWPID를 찾을 수 있습니다.
"Thread-6" prio=8 tid=0x0004f620 nid=75 lwp_id=285475 waiting on monitor
[0x66d5e000..0x66d5e500]
at java.lang.Thread.sleep(Native Method)
at weblogic.management.deploy.GenericAppPoller.run
(GenericAppPoller.java:139)
"ExecuteThread: '11' for queue: 'default'" daemon prio=10 tid=0x0004ad00 nid=23
lwp_id=285416 runnable [0x67874000..0x67874500]
at java.net.SocketOutputStream.socketWrite(Native Method)
at java.net.SocketOutputStream.write(Unknown Source)
at weblogic.servlet.internal.ChunkUtils.writeChunkTransfer
(ChunkUtils.java:222)
at weblogic.servlet.internal.ChunkUtils.writeChunks(ChunkUtils.java:198)
at weblogic.servlet.internal.ChunkOutput.flush(ChunkOutput.java:285)
at weblogic.servlet.internal.ChunkOutput.checkForFlush
(ChunkOutput.java:345)
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java:222)
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java:237)
at weblogic.servlet.internal.ChunkOutputWrapper.write
(ChunkOutputWrapper.java:86)
at weblogic.servlet.internal.ChunkWriter.write(ChunkWriter.java:37)
at java.io.Writer.write(Unknown Source)
- locked <0x753408e8> (a weblogic.servlet.internal.ChunkWriter)
at java.io.PrintWriter.write(Unknown Source)
- locked <0x753408e8> (a weblogic.servlet.internal.ChunkWriter)
at java.io.PrintWriter.write(Unknown Source)
at java.io.PrintWriter.print(Unknown Source)
at java.io.PrintWriter.println(Unknown Source)
- locked <0x753408e8> (a weblogic.servlet.internal.ChunkWriter)
at examples.servlets.HelloWorldServlet.service
(HelloWorldServlet.java:28)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run
(ServletStubImpl.java:1058)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:401)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:306)
at
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run
(WebAppServletContext.java:5445)
at weblogic.security.service.SecurityServiceManager.runAs
(SecurityServiceManager.java:780)
at weblogic.servlet.internal.WebAppServletContext.invokeServlet
(WebAppServletContext.java:3105)
at weblogic.servlet.internal.ServletRequestImpl.execute
(ServletRequestImpl.java:2588)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:213)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:189)
위 예제를 보면 실제로 문제가 되는 LWPID는 285416인 것을 알 수 있습니다.
해당 서블릿의 service() 메쏘드를 조사하여 해당 행 번호(HelloWorldServlet.java의
28번 행)에서 어떤 작업이 수행 중인지 확인할 수 있습니다.
맨 위로
Windows
pslist 사용
pslist를 사용하여 Windows상의 Java 프로세스에 대한 스레드 세부 사항을 가져올 수
있습니다. pslist는 다음 사이트에서 구할 수 있습니다.
http://www.sysinternals.com/ntw2k/freeware/pslist.shtml
pslist -d <Java PID>를 실행하고 출력을 파일로 리다이렉션합니다.
패턴을 파악할 수 있도록 이 명령을 여러 번 반복합니다.
"User Time"과 "Kernel Time" 값이 증가하는 것을 볼 수 있습니다.
WLS 서버의 스레드 덤프를 여러 번 가져옵니다.
1단계에서 값이 증가하는 것으로 나타나는 스레드 ID 번호를 가져온 후 10진수 값을
16진수 값으로 변경합니다. 이 작업을 수행하려면 Windows의 계산기를 사용하십시오.
스레드 덤프에서 "nid=0x<3번 단계에서 구한 16진수>"를 찾습니다.
사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스 의 내용에
WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의하십시오.
Process Explorer 사용
http://www.sysinternals.com/ntw2k/freeware/procexp.shtml에서 제공되는
Systinternals의 Process Explorer를 사용할 수도 있습니다. 이 도구는 시각적인 방
식으로 CPU 사용량을 동적으로 나타냅니다. Process Explorer에는 로그 또는 기록 기
능이 없으므로 이 도구를 모니터링하면서 CPU 사용량이 높은 Java 프로세스의 스레드
ID를 적어 두어야 합니다. Process Explorer를 통해 이 작업을 수행하려면 다음과 같
이 하십시오.
Java 프로세스를 찾아서 마우스 오른쪽 단추를 누르고 properties를 선택합니다.
@@Threads@@ 탭을 눌러 이 Java 프로세스와 관련된 모든 스레드를 불러옵니다.
"MSVCRT.dll+<Some hex offset>"으로 나열된 스레드 중 하나를 누를 수 있습니다.
아래의 창에 "Thread ID"가 나열됩니다.
CPU 사용량이 높은 스레드를 확인합니다.
WLS 서버의 스레드 덤프를 생성합니다.
4단계에서 CPU 사용량이 높은 것으로 나타나는 스레드 ID 번호를 가져온 후 10진수 값
을 16진수 값으로 변경합니다. 이 작업을 수행하려면 Windows의 계산기를 사용하십시
오.
스레드 덤프에서 "nid=0x<Your Hex Value>"가 일치하는 문제의 스레드를 찾습니다.
사용자의 코드에서 이러한 문제가 발생한 이유를 파악하고, 스택 트레이스 의 내용에
WebLogic 라이브러리가 최상위에 있는 경우 BEA 고객 지원부에 문의하십시오.
다음은 pslist 및 스레드 덤프만 사용하는 이러한 단계의 예입니다.
pslist -d 172를 실행합니다.
java 1720:
Tid Pri Cswtch State User Time Kernel Time Elapsed Time
1520 8 9705 Wait:UserReq 0:00:23.734 0:00:01.772 0:04:55.264
1968 9 2233 Wait:UserReq 0:00:04.606 0:00:00.040 0:04:54.874
1748 15 146 Wait:UserReq 0:00:00.010 0:00:00.010 0:04:54.863
1744 11 62 Wait:UserReq 0:00:00.010 0:00:00.000 0:04:54.853
1420 15 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:54.563
1856 15 7 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:54.563
1860 9 3157 Wait:UserReq 0:00:03.314 0:00:00.160 0:04:54.563
412 15 5888 Wait:DelayExec 0:00:00.000 0:00:00.000 0:04:54.553
1864 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:50.567
1660 15 61 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:42.125
2020 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:42.025
1532 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:42.015
1332 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:42.005
1696 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.995
2060 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.995
1552 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.985
2072 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.985
2068 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.975
2044 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.975
2000 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.965
588 9 4744 Wait:UserReq 0:00:02.814 0:00:00.110 0:04:41.965
1784 9 132 Wait:UserReq 0:00:00.080 0:00:00.000 0:04:41.955
1756 9 196 Wait:UserReq 0:00:00.931 0:00:00.000 0:04:41.955
1716 8 6 Wait:Queue 0:00:00.000 0:00:00.000 0:04:41.945
1800 9 1457 Wait:Queue 0:00:00.761 0:00:00.210 0:04:41.945
1996 8 47 Wait:UserReq 0:00:00.170 0:00:00.000 0:04:41.835
1992 11 18 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.434
1988 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.424
1984 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.414
1976 8 231 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.274
1956 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.234
1740 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.224
1944 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.214
1964 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.204
1972 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.204
1280 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.194
1960 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.194
1872 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.184
1884 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.184
1952 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.174
1940 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.174
1936 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:41.164
1932 6 4 Wait:UserReq 0:00:00.010 0:00:00.000 0:04:39.291
1928 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.880
1916 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.870
1912 8 4 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.860
1908 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.860
1904 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.850
1900 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:31.840
1896 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.889
2064 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.879
1828 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.869
1892 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.859
1888 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.859
1852 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.849
1848 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.849
1844 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.839
1412 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.839
332 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.829
1840 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.829
1440 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.819
1796 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.819
1240 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.809
568 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:30.809
1732 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:29.797
2056 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:15.006
1688 8 4 Wait:UserReq 0:00:00.000 0:00:00.010 0:04:14.996
1776 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:14.986
1648 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:14.976
1768 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:04:14.976
284 8 188 Wait:UserReq 0:00:00.190 0:00:00.040 0:04:08.887
576 9 123 Wait:UserReq 0:00:00.070 0:00:00.020 0:04:07.515
큰 폭으로 증가한 부분이 있는지 확인하기 위해 또 다른 스냅샷을 잠시 후에 생성합니
다.
좀 더 자세히 검토할 스레드 ID(TID)를 결정합니다.
pslist를 다시 실행합니다. pslist -d 1720
java 1720:
Tid Pri Cswtch State User Time Kernel Time Elapsed Time
1520 8 9705 Wait:UserReq 0:00:23.734 0:00:01.772 0:08:14.511
1968 8 6527 Wait:UserReq 0:00:06.309 0:00:00.070 0:08:14.120
1748 15 157 Wait:UserReq 0:00:00.010 0:00:00.010 0:08:14.110
1744 10 68 Wait:UserReq 0:00:00.010 0:00:00.000 0:08:14.100
1420 15 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:13.810
1856 15 18 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:13.810
1860 8 3169 Wait:UserReq 0:00:03.314 0:00:00.160 0:08:13.810
412 15 9890 Wait:DelayExec 0:00:00.000 0:00:00.000 0:08:13.800
1864 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:09.814
1660 15 188 Wait:UserReq 0:00:00.010 0:00:00.010 0:08:01.372
2020 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.272
1532 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.262
1332 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.252
1696 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.241
2060 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.241
1552 9 40 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.231
2072 8 13 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.231
2068 8 20 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.221
2044 8 15 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:01.221
2000 8 657 Wait:UserReq 0:00:00.090 0:00:00.010 0:08:01.211
588 10 59123 Wait:UserReq 0:00:48.830 0:00:02.633 0:08:01.211
1784 8 150 Wait:UserReq 0:00:00.090 0:00:00.000 0:08:01.201
1756 8 251 Wait:UserReq 0:00:00.941 0:00:00.000 0:08:01.201
1716 8 6 Wait:Queue 0:00:00.000 0:00:00.000 0:08:01.191
1800 8 1457 Wait:Queue 0:00:00.761 0:00:00.210 0:08:01.191
1996 8 47 Wait:UserReq 0:00:00.170 0:00:00.000 0:08:01.081
1992 10 29 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.681
1988 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.671
1984 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.661
1976 9 400 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.520
1956 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.480
1740 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.470
1944 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.460
1964 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.450
1972 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.450
1280 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.440
1960 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.440
1872 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.430
1884 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.430
1952 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.420
1940 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.420
1936 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:08:00.410
1932 6 4 Wait:UserReq 0:00:00.010 0:00:00.000 0:07:58.538
1928 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.127
1916 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.117
1912 8 5 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.107
1908 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.107
1904 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.097
1900 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:51.087
1896 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.136
2064 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.126
1828 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.115
1892 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.105
1888 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.105
1852 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.095
1848 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.095
1844 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.085
1412 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.085
332 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.075
1840 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.075
1440 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.065
1796 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.065
1240 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.055
568 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:50.055
1732 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:49.044
2056 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:34.253
1688 8 4 Wait:UserReq 0:00:00.000 0:00:00.010 0:07:34.243
1776 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:34.233
1648 8 2 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:34.223
1768 8 3 Wait:UserReq 0:00:00.000 0:00:00.000 0:07:34.223
284 9 416 Ready 0:00:00.420 0:00:00.100 0:07:28.134
576 8 123 Wait:UserReq 0:00:00.070 0:00:00.020 0:07:26.762
스레드 ID 588이 대부분의 사용자/커널 시간을 사용하고 있으며 결과적으로는 CPU 사
용량이 매우 높음을 알 수 있습니다. 확실히 이 스레드에 문제가 있습니다.
스레드 ID 번호 588을 가져와서 16진수(0x24)로 변환합니다.
문제가 발생할 때 만든 스레드 덤프에서 "nid=0x24"를 찾습니다.
아래 내용을 보면 이는 스레드 덤프에서 ExecuteThread 10에 해당한다는 것을 알 수
있습니다.
"ExecuteThread: '10' for queue: 'default'" daemon prio=5 tid=0x20d75808
nid=0x24c runnable [219ff000..219ffd90]
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at weblogic.servlet.internal.ChunkUtils.writeChunkTransfer
(ChunkUtils.java:222)
at weblogic.servlet.internal.ChunkUtils.writeChunks
(ChunkUtils.java:198)
at weblogic.servlet.internal.ChunkOutput.flush(ChunkOutput.java:284)
at weblogic.servlet.internal.ChunkOutput.checkForFlush
(ChunkOutput.java:344)
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java:221)
at weblogic.servlet.internal.ChunkOutput.write(ChunkOutput.java:236)
at weblogic.servlet.internal.ChunkOutputWrapper.write
(ChunkOutputWrapper.java:95)
at weblogic.servlet.internal.ChunkWriter.write(ChunkWriter.java:37)
at java.io.Writer.write(Writer.java:150)
- locked <0x11d0d1c0> (a weblogic.servlet.internal.ChunkWriter)
at java.io.PrintWriter.write(PrintWriter.java:230)
- locked <0x11d0d1c0> (a weblogic.servlet.internal.ChunkWriter)
at java.io.PrintWriter.write(PrintWriter.java:247)
at java.io.PrintWriter.print(PrintWriter.java:378)
at java.io.PrintWriter.println(PrintWriter.java:515)
- locked <0x11d0d1c0> (a weblogic.servlet.internal.ChunkWriter)
at examples.servlets.HelloWorld2.service(HelloWorld2.java:94)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at
weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run
(ServletStubImpl.java:1058)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:401)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:306)
at
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run
(WebAppServletContext.java:5412)
at weblogic.security.service.SecurityServiceManager.runAs
(SecurityServiceManager.java:744)
at weblogic.servlet.internal.WebAppServletContext.invokeServlet
(WebAppServletContext.java:3086)
at weblogic.servlet.internal.ServletRequestImpl.execute
(ServletRequestImpl.java:2544)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:153)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:134)
socketWrite native 메서드에 문제가 있는 것처럼 보이지만 아마도
HelloWorld2.service()가 잘못된 동작을 수행하고 있을 것입니다.
행 번호(HelloWorld2.java의 94)를 검토하여 어떤 작업이 수행 중인지 확인합니다.
HelloWorld2.java의 service() 메서드 코드를 살펴 보십시오.
89 out.println(ExampleUtils.returnHtmlHeader("Hello World 2"));
90 out.println("<h4>");
91 for (int i=0;i<100000000;i++) {
92 int j = 0;
93 j = j +i;
94 out.println(defaultGreeting + " " + defaultName + "!");
95 }
96
97 out.println("</h4>");
98 out.println(ExampleUtils.returnHtmlFooter());
어떤 이유인지는 몰라도 긴 "for loop" 내에서 스트림 출력을 하도록 작성되었습니
다. 이 예제에서 CPU 사용량이 높게 나타난 이유는 바로 이 것 때문입니다.
이 코드를 수정하면 CPU 사용량이 최대치로 증가하지 않을 것입니다.
맨 위로
외부 리소스
다음에서 CPU 사용량을 검사하는 데 도움이 되는 유틸리티 및 도구를 구할 수 있습니
다.
pslist: http://www.sysinternals.com/ntw2k/freeware/pslist.shtml
Process Explorer: http://www.sysinternals.com/ntw2k/freeware/procexp.shtml
hp_prstat 유틸리티: hp_prstat
맨 위로
추가 도움말이 필요하십니까?
패턴대로 작업했지만 추가 도움말이 필요한 경우 다음과 같이 할 수 있습니다.
http://support.bea.com의 AskBEA에서 "high CPU usage"로 문제점을 조회하여 게시된
다른 해결 방법을 찾아봅니다.
http://newsgroups.bea.com 사이트에서 BEA 뉴스그룹에 보다 자세한 내용을 질문합니
다.
이렇게 해도 문제를 해결할 수 없는 경우 유효한 유지보수 계약이 되어 있다면
http://support.bea.com/에 로그인하여 Support Case를 신청할 수 있습니다.
댓글
댓글 쓰기