-----------------------------------題外話-----------------------------------
最近一個(gè)weblogic的應(yīng)用總core，經(jīng)過觀察發(fā)現(xiàn)在做一個(gè)操作的時(shí)候會(huì)內(nèi)存猛飆，cpu占用率猛飆，然后core。
后來發(fā)現(xiàn)是載入了一個(gè)大表到內(nèi)存導(dǎo)致，調(diào)整后不再出現(xiàn)。
問題發(fā)現(xiàn)后覺得原來原因這么簡(jiǎn)單，但是一開始卻很迷茫。
這次的啟示就是，有時(shí)候問題啟示很簡(jiǎn)單，只是看你有沒有仔細(xì)分析過。
下面這篇文章，對(duì)本次幫助不大，但是看寫得這么詳細(xì)，留下為以后做個(gè)參考。
----------------------------------------------------------------------
問題描述
系統(tǒng)管理員或用戶注意到 WebLogic Server 進(jìn)程消耗大量的 CPU 資源，并想要了解是哪個(gè)方面消耗了大量 CPU
資源，以及導(dǎo)致出現(xiàn)這種現(xiàn)象的原因。
故障排除
請(qǐng)注意，并非下面所有任務(wù)都需要完成。有些問題僅通過執(zhí)行幾項(xiàng)任務(wù)就可以解決。
快速鏈接
為什么發(fā)生此問題？
收集高
CPU 占用率的數(shù)據(jù)
Solaris
Linux
AIX
HP-UX
Windows
外部資源
為什么發(fā)生此問題？
發(fā)生此問題有許多原因：WebLogic Server
本身、用戶創(chuàng)建的線程、不良編碼習(xí)慣或第三方軟件。遺憾的是，證明在什么地方發(fā)生此問題有時(shí)候非常困難。本模式嘗試通過利用特定操作命令和收集數(shù)據(jù)來幫助排除此問題。
收集高
CPU 占用率的數(shù)據(jù)
對(duì)于有關(guān)收集高 CPU
占用率的數(shù)據(jù)的特定操作信息，請(qǐng)根據(jù)您的操作系統(tǒng)執(zhí)行以下步驟。
重要說明：
這些操作系統(tǒng)的所有信息都基于 Sun JVM。 目前在
JRockit 中還沒有辦法將 PID 從說明 CPU 占用率的操作系統(tǒng)命令（prstat、top、pslist 等等）映射到 Thread Dump
中的正確線程。 從 Jrockit 的 70SP4RP2 和 81SP2RP1 以后的版本起，就可實(shí)現(xiàn)此映射。 例如，在 Linux 中，Thread Dump
在以后的版本中將采用如下形式（PID 顯示在 Thread Dump 中）：
"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 或任何所在系統(tǒng)上的 top（或任何您需要在操作系統(tǒng)上使用的特定命令）輸出直接關(guān)聯(lián)該
PID。
轉(zhuǎn)換為十六進(jìn)制號(hào)碼
備注：為協(xié)助您計(jì)算在本模式中討論的十六進(jìn)制值，您可以在 Shell 腳本中使用下列行將十進(jìn)制號(hào)碼轉(zhuǎn)換為十六進(jìn)制號(hào)碼。如果您使用 Unix
操作系統(tǒng)，那么轉(zhuǎn)換會(huì)很方便。
dec2hex.sh:
printf "dec -> hex: %d = %x \n" ${1}
${1}
用法：
$ sh dec2hex.sh 755
dec -> hex: 755 = 2f3
Solaris
在 Java 進(jìn)程中運(yùn)行
prstat命令。重復(fù)幾次這個(gè)操作，以便您能夠看到一種模式。例如：prstat -L -p <PID> 1 1
在 Java 進(jìn)程中運(yùn)行
pstack命令以獲得從輕量型進(jìn)程 (LWP) 到 PID（進(jìn)程 ID）的映射。
示例：pstack 9499
并將輸出結(jié)果重定向到一個(gè)文件。
如果您使用 Solaris 中的常規(guī)線程庫（即，在 LD_LIBRARY_PATH 中沒有
/usr/lib/lwp），LWP 就不會(huì)直接映射到操作系統(tǒng)線程，因此您必須從進(jìn)程中執(zhí)行
pstack（所以檢查看您是否正在使用替代線程庫）。
經(jīng)過一段時(shí)間后對(duì)服務(wù)器進(jìn)行若干 Thread Dump，確保您執(zhí)行正確的線程。
您可以通過在
Java 進(jìn)程中執(zhí)行 kill -3 <PID>來達(dá)到此目的。
將 LWP ID 映射到 Java 線程 ID。
例如，如果上述的
LWP 為“8”，它可以映射到 Java 線程“76”。然后將 76 換算為十六進(jìn)制值 0x4c。
檢查 Thread Dump，找到匹配“nid=
<上述標(biāo)識(shí)符/值>”的線程。
在本示例中，您找到匹配“nid=0x4c”的線程，而該線程就是正在消耗 CPU
資源的那個(gè)線程。
您將需要：
確定為什么在您的代碼中會(huì)發(fā)生這個(gè)問題
或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA
客戶支持部門聯(lián)系。
下面是 Solaris 系統(tǒng)中上述進(jìn)程的一個(gè)示例：
在 Java 進(jìn)程中運(yùn)行 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
運(yùn)行 pstack 命令。
示例：pstack 9499 并將輸出結(jié)果重定向到一個(gè)文件。
如果您使用
Solaris 中的常規(guī)線程庫（即，在 LD_LIBRARY_PATH 中沒有 /usr/lib/lwp），LWP
就不會(huì)直接映射到操作系統(tǒng)線程，因此您必須從進(jìn)程中執(zhí)行 pstack（所以檢查看您是否正在使用替代線程庫）。
上述示例顯示“java/8”進(jìn)程在
prstat 的頂端。
為“lwp# 8”檢驗(yàn) pstack輸出結(jié)果。
您會(huì)發(fā)現(xiàn)“lwp# 8”從 pstack
輸出結(jié)果映射到“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
進(jìn)程中執(zhí)行以下命令對(duì)服務(wù)器進(jìn)行 Thread Dump：
kill -3 <PID>。
由于 lwp# 8 映射到 thread
#76，您可以將 76 換算為十六進(jìn)制值 4c。
該值映射到 JVM Thread Dump 中的 nid=0x4c：
"Thread-6"
prio=5 tid=0x1e2fd8 nid=0x4c waiting on monitor
http://0xe2e81000..0xe2e819d8at
java.lang.Thread.sleep(Native Method)
at
weblogic.management.deploy.GenericAppPoller.run(GenericAppPoller.java:139)
在此示例中，占用最多
CPU 資源的線程實(shí)際上正處于休眠狀態(tài)。應(yīng)用程序輪詢程序在開發(fā)模式啟動(dòng)的服務(wù)器上運(yùn)行。由于它每隔 30 秒運(yùn)行一次，因此顯然無法及時(shí)捕捉 Thread Dump
以了解此線程中的活動(dòng)。
理想狀態(tài)下，應(yīng)當(dāng)迅速并且連續(xù)完成全部三個(gè)步驟，以便盡可能及時(shí)地捕捉數(shù)據(jù)。這可以通過類似下面的一個(gè)簡(jiǎn)單的 shell
腳本來完成。
#
# 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
然后，您可以檢查該線程以確定它正在執(zhí)行的任務(wù)以及是否出現(xiàn)問題。
Linux
獲得最頂端輸出并查找與之前啟動(dòng)了現(xiàn)占用
CPU 的 WLS 的那個(gè)用戶 ID 相關(guān)聯(lián)的 PID。
通過 kill -3 <PID> 對(duì) WebLogic Server 進(jìn)行若干
Thread Dump
將步驟 1 中的 PID 號(hào)轉(zhuǎn)換為一個(gè)十六進(jìn)制值。
（用于 Linux 的 JVM 將 Java
線程作為本地線程實(shí)現(xiàn)，這使每個(gè)線程成為一個(gè)獨(dú)立的 Linux 進(jìn)程。）
在 Thread Dump 中搜索 nid
的值等于上一步驟中所得到的十六進(jìn)制值的線程。
這將為您揭示造成高 CPU
占用率問題的線程。
確定為什么在您的代碼中會(huì)發(fā)生這個(gè)問題，或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA 客戶支持部門聯(lián)系。
下面是
Linux 系統(tǒng)中上述進(jìn)程的一個(gè)示例：
獲得 top輸出并查找與之前啟動(dòng)了現(xiàn)占用 CPU 的 WLS 的那個(gè)用戶 ID 相關(guān)聯(lián)的
PID。
將該號(hào)轉(zhuǎn)換為一個(gè)十六進(jìn)制值。
請(qǐng)參閱下面的 top 輸出示例（這只是一個(gè)代碼片斷，因?yàn)閷?duì)于單個(gè) WLS
進(jìn)程將啟動(dòng)更多的線程）。
在 Linux 中，每個(gè)線程映射到一個(gè)不同于其它 Unix 形式的進(jìn)程中。
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，則十六進(jìn)制值將是：0x59B2
使用此十六進(jìn)制值并在 Thread Dump 中查找哪個(gè) nid 等于該值，以便從 Thread Dump
中獲取正確的線程。
例如，如果 ExecuteThread 0 出現(xiàn)問題，則 0x59B2 將對(duì)應(yīng)于該線程：
"ExecuteThread:
'0' for queue: 'default'" daemon prio=1 tid=0x83da550 nid=0x59b2 waiting on
monitor http://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)
然后，您可以檢查該線程以確定它正在執(zhí)行的任務(wù)以及是否出現(xiàn)問題。
在上述示例中，由于該線程此時(shí)占用
0% 的 CPU，所以只顯示執(zhí)行此操作的進(jìn)程。理想狀態(tài)下，應(yīng)當(dāng)迅速并且連續(xù)完成全部三個(gè)步驟，以便盡可能及時(shí)地捕捉數(shù)據(jù)。這可以通過類似下面的一個(gè)簡(jiǎn)單的 shell
腳本來完成。
#
# 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
執(zhí)行： ps -mp
<WLS_PID> -o THREAD 以查找正在占用 CPU 的 tid。
您應(yīng)當(dāng)查看“CP”列（表示 CPU
占用率），看其中哪些線程的此項(xiàng)值比較高并從中挑選一個(gè)線程。
通過執(zhí)行以下命令對(duì)服務(wù)器進(jìn)行 Thread Dump：
kill -3
<WLS_PID>
運(yùn)行： dbx -a <WLS_PID>
在 dbx 中時(shí)，運(yùn)行 dbx
thread命令（以列出所有線程）。
查找與您通過 ps -mp <PID -o THREAD 命令獲取的 TID
匹配的行。
該行中的號(hào)碼應(yīng)當(dāng)采用“$t<NUM>”格式，其中“NUM”是一個(gè)號(hào)碼。
在 dbx 中時(shí)，運(yùn)行 dbx 命令 th info
<TID>（此 TID 來自上一步驟，該步驟在 $t<NUM>后面列出號(hào)碼）以獲取關(guān)于該線程的信息。
從第 3
步驟的輸出中，在“general”下查找“pthread_t”，并記錄該十六進(jìn)制號(hào)碼。
非常重要說明：在 dbx 提示符下，您需要在完成操作時(shí)在 dbx
命令行鍵入“detach”，否則，如果您在連接到進(jìn)程時(shí)只要一退出，dbx 將終止該進(jìn)程！
記下“p_thread_t”輸出中的十六進(jìn)制值，并在
Thread Dump 中搜索其中哪個(gè)線程的“native ID”等于該值。
這將為您揭示造成高 CPU
占用率問題的線程。
確定為什么在您的代碼中正在發(fā)生這個(gè)問題，或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA
客戶支持部門聯(lián)系。
下面是 AIX 系統(tǒng)中上述進(jìn)程的一個(gè)示例：
ps -mp 250076 -o THREAD 將顯示以下內(nèi)容：
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> 進(jìn)行該 WLS_PID 的
Thread Dump
檢查 ps -mp <WLS_PID> -o THREAD命令所輸出的信息。
注意，TID "667723" 在
CP 列中有一個(gè)高值（它達(dá)到“37”，而其它 TID 幾乎為 0）。
運(yùn)行 dbx -a 250076以連接到 WebLogic Server
進(jìn)程。
運(yùn)行 thread 命令以列出所有本地線程。
下面只顯示相關(guān)線程的一個(gè)代碼片斷：
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
.....
運(yùn)行 th
info 17 命令以獲取關(guān)于該本地線程的必要信息：
(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 提示符下運(yùn)行“detach”以從 WebLogic
進(jìn)程中分離。
記下上述“pthread_t”的數(shù)值，并用來查找 WebLogic Server 進(jìn)程的 Thread Dump
中的正確線程。
從早期進(jìn)行的 Thread Dump 中，您可以將十六進(jìn)制號(hào)碼“1011”與 Thread Dump 中在“native
ID”之后的號(hào)碼進(jìn)行匹配。
下面是匹配此十六進(jìn)制號(hào)碼并造成高 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
HP-UX
HP 目前沒有提供類似 prstat-
的命令來收集獨(dú)立的線程 ID，以將它們轉(zhuǎn)換回 Thread Dump，BEA 技術(shù)支持部門開發(fā)了一種簡(jiǎn)單的實(shí)用程序，可以顯示進(jìn)程 ID (PID)、與 PID
關(guān)聯(lián)的輕量型進(jìn)程 ID (LWPID)、用戶時(shí)間和所使用的系統(tǒng)時(shí)間。您可以使用該程序作為一個(gè)大致指南，因?yàn)樵诟?CPU 占用的情況中，LWPID 使用越來越多的
CPU，您會(huì)看到用戶時(shí)間在很短的時(shí)間之內(nèi)便增加了。您可以使用 BEA 的 hp_prstat 實(shí)用程序，并定期測(cè)量每個(gè) LWPID
的用戶時(shí)間以了解哪一個(gè)正在隨時(shí)間推移而增加。用戶時(shí)間只能顯示為一個(gè)整數(shù)，因?yàn)橛?HP 提供的 API 在這種情況下無法進(jìn)行更精細(xì)的測(cè)量。
若要收集
HP-UX 的數(shù)據(jù)：
單擊 hp_prstat 以下載 BEA 技術(shù)支持部門開發(fā)的 hp_prstat 實(shí)用程序。
在 Java 進(jìn)程中運(yùn)行
hp_prstat命令。
通過在 Java 進(jìn)程中執(zhí)行以下命令對(duì)服務(wù)器進(jìn)行若干 Thread Dump： kill -3
<PID>。
稍后，完成另一個(gè) hp_prstat <PID>快照。
檢查兩次
hp_prstat迭代的輸出結(jié)果以找到已經(jīng)迅速增加用戶時(shí)間的出現(xiàn)問題的 LWPID。
一旦您獲得該號(hào)碼 (LWPID)，請(qǐng)檢查 Thread
Dump，以查找您已經(jīng)完成的 Thread Dump 中哪一項(xiàng)的 lwp_id=<等于您所獲得的 LWPID>。
這將匹配將要占用完 CPU
的有問題的線程。
確定為什么在您的代碼中會(huì)發(fā)生這個(gè)問題，或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA
客戶支持部門聯(lián)系。
下面是 HP-UX 系統(tǒng)中上述進(jìn)程的一個(gè)示例：
在 Java 進(jìn)程中運(yùn)行 hp_prstat 命令。
示例：
hp_prstat <PID>
每隔幾分鐘執(zhí)行一次上述操作，執(zhí)行數(shù)次，同時(shí)觀察發(fā)生高 CPU
占用率的情況。
下面是輸出示例：
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
進(jìn)程中執(zhí)行以下命令對(duì)服務(wù)器進(jìn)行 Thread Dump： kill -3 <PID>。
稍后，完成另一個(gè) hp_prstat
<PID> 快照。
注意，與第一個(gè)快照對(duì)比，兩個(gè) LWPID（285475 和 285416）比較大。
您需要檢查這兩個(gè)
LWPID。
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
通過在 Java 進(jìn)程中執(zhí)行以下命令對(duì)服務(wù)器進(jìn)行另一個(gè) Thread Dump： kill
-3 <PID>，確保您捕捉到占用完 CPU 資源的正確線程。
從 hp_prstat 輸出中獲取
LWPID，該輸出在形式上與用戶時(shí)間相似，且不斷增大。一旦您獲得該號(hào)碼 (LWPID)，請(qǐng)檢查 Thread Dump，以查找您已經(jīng)完成的 Thread
Dump 中哪一項(xiàng)的 lwp_id 等于<您所獲得的 LWPID>。
可以檢查以下這兩個(gè) LWPID：
"Thread-6"
prio=8 tid=0x0004f620 nid=75 lwp_id=285475 waiting on monitor http://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 http://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)
顯然，實(shí)際造成問題的是
LWPID 285416。
您可以檢查該 Servlet 的服務(wù)方法，以查明圍繞此行號(hào)發(fā)生的情況（HelloWorldServlet.java第 28
行）并確定問題所在。
Windows
使用 pslist
您可以在
Windows 中使用 pslist 并獲取 java 進(jìn)程的線程詳細(xì)信息。 pslist可從以下網(wǎng)址得到：http://www.sysinternals.com/ntw2k/freeware/pslist.shtml
運(yùn)行
pslist -d <Java PID>
并將輸出結(jié)果重定向到一個(gè)文件。
重復(fù)幾次這個(gè)操作，以便您能夠看到一種模式。
您將看到“用戶時(shí)間”和“內(nèi)核時(shí)間”不斷增加。
在若干次迭代后對(duì)
WLS 服務(wù)器進(jìn)行 Thread Dump。
記下步驟 1 中看起來正在增加的線程 ID 號(hào)，將十進(jìn)制值改為十六進(jìn)制值（您可以使用 Windows
中的計(jì)算功能）。
根據(jù)“nid=0x<步驟 3 的十六進(jìn)制值>”檢查 Thread
Dump，直到您找到出現(xiàn)問題的線程。
確定為什么在您的代碼中會(huì)發(fā)生這個(gè)問題，或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA
客戶支持部門聯(lián)系。
使用 Process Explorer
您還可以使用 Systinternals 提供的 Process Explorer http://www.sysinternals.com/ntw2k/freeware/procexp.shtml。該工具直觀動(dòng)態(tài)顯示
CPU 占用率。 由于 Process Explorer 沒有記錄功能或歷史記錄，您必須監(jiān)視該程序并記錄占用幾乎全部 CPU 資源的 Java 進(jìn)程的線程
ID。 若要通過 Process Explorer 達(dá)到上述目的：
查找 java
進(jìn)程，然后右鍵單擊并選擇屬性。
單擊“Threads”選項(xiàng)卡以顯示與此 java
進(jìn)程關(guān)聯(lián)的所有線程。
您可以單擊以“MSVCRT.dll+<一些十六進(jìn)制偏移量>”形式列出的其中一個(gè)線程。
您可以看到在下面窗格中列出的“Thread
ID”。
觀察哪一個(gè)線程占用最多 CPU 資源。
進(jìn)行 WLS 服務(wù)器的 Thread Dump。
記下步驟 4 中看起來正在占用
CPU 的線程 ID 號(hào)，將十進(jìn)制值改為十六進(jìn)制值（您可以使用 Windows 中的計(jì)算功能）。
根據(jù)“nid=0x<十六進(jìn)制值>”檢查
Thread Dump，直到您找到出現(xiàn)問題的線程。
確定為什么在您的代碼中會(huì)發(fā)生這個(gè)問題，或者，如果堆棧的最頂端輸出來自 WebLogic，請(qǐng)與 BEA
客戶支持部門聯(lián)系。
下面是僅使用 pslist 和 Thread Dump 的步驟示例：
運(yùn)行 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
一段時(shí)間后再次進(jìn)行相同的輸出，以獲得線程的另一個(gè)快照，查明哪一個(gè)線程已經(jīng)顯著增大。
確定要進(jìn)一步檢查的線程 ID
(TID)。
再次運(yùn)行 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 正在使用最多的用戶/內(nèi)核時(shí)間，因此占用最多的 CPU
資源。顯然，該線程有問題。
記錄線程 ID 號(hào) 588，并將其轉(zhuǎn)換為十六進(jìn)制值 (0x24)。
查看您在出現(xiàn)問題時(shí)所記下的 Thread
Dump，并查找“nid=0x24”。
從以下輸出中可以看出，它對(duì)應(yīng)于 Thread Dump 中的 ExecuteThread 10：
"ExecuteThread: '10' for queue: 'default'" daemon prio=5 tid=0x20d75808
nid=0x24c runnable http://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)
顯然，問題出現(xiàn)在
socketWrite本地方法上，但表面看起來是 HelloWorld2.service()出錯(cuò)。
檢查行號(hào)（HelloWorld2.java的第
94 行）以確定發(fā)生的情況。
從 service()方法的 HelloWorld2.java 代碼片斷：
89 out.println(ExampleUtils.returnHtmlHeader("Hello World 2"));
90
out.println("
");
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("
");
98
out.println(ExampleUtils.returnHtmlFooter());
可以看出，由于某種原因，輸出流是用一個(gè)非常長(zhǎng)的“for
loop”語句編寫的。這是錯(cuò)誤所在，也是此示例中造成高 CPU 占用率的原因。
如果改正此代碼，則 CPU 就不會(huì)被完全占用.
外部資源
您可以在以下網(wǎng)址中獲得幫助檢查 CPU 占用率的實(shí)用程序/工具：
pslist： http://www.sysinternals.com/ntw2k/freeware/pslist.shtml
Process
Explorer： http://www.sysinternals.com/ntw2k/freeware/procexp.shtml
hp_prstat
實(shí)用程序：hp_prstat
以下是我的一些疑問，請(qǐng)教一下：
1.lwpid pid pri status UsrTime SysTime
285365 4426 154 1 29
3
285381 4426 154 1 0 7
這是運(yùn)行hp_prstat命令的一個(gè)示例截取，其中 UsrTime
,SysTime是不是就是文章一開頭提到的user態(tài)和kernel態(tài)呢？
另外這兩個(gè)time是具體指哪一段時(shí)間？
2.windows的pslist分析工具，說明文檔里提到是將顯示有關(guān)指定的 NT/Win2K
系統(tǒng)的信息，我在XP試了下也可以用啊？有功能上的局限性么？
文章里的下載鏈接有點(diǎn)問題，我另外找了一個(gè)：http://www.microsoft.com/china/technet/sysinternals/utilities/PsList.mspx。
回復(fù)：
UsrTime 就是user態(tài)，
SysTime就是kernel態(tài)，java虛擬機(jī)也要調(diào)用操作系統(tǒng)內(nèi)核的API，因此就有調(diào)用內(nèi)核的時(shí)間，其他只是在java虛擬機(jī)上跑沒有調(diào)用內(nèi)核的API就是用戶態(tài)了，winxp就是使用的NT技術(shù)所以plist可以用不奇怪。