问题描述
系统管理员或用户注意到 WebLogic Server 进程消耗大量的 CPU 资源,并想要了解是哪个方面消耗了大量 CPU 资源,以及导致出现这种现象的原因。 |
故障排除
请注意,并非下面所有任务都需要完成。有些问题仅通过执行几项任务就可以解决。
快速链接
|
|
为什么发生此问题?
发生此问题有许多原因:WebLogic Server 本身、用户创建的线程、不良编码习惯或第三方软件。遗憾的是,证明在什么地方发生此问题有时候非常困难。本模式尝试通过利用特定操作命令和收集数据来帮助排除此问题。
返回页首
收集高
CPU 占用率的数据
对于有关收集高 CPU 占用率的数据的特定操作信息,请根据您的操作系统执行以下步骤。
重要说明:
这些操作系统的所有信息都基于 Sun JVM。 目前在 JRockit 中还没有办法将 PID 从说明 CPU 占用率的操作系统命令(prstat、top、pslist
等等)映射到 Thread Dump 中的正确线程。 从 Jrockit 的 70SP4RP2 和 81SP2RP1
以后的版本起,就可实现此映射。 例如,在 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 或任何所在系统上的 top(或任何您需要在操作系统上使用的特定命令)输出直接关联该
PID。
转换为十六进制号码
备注:为协助您计算在本模式中讨论的十六进制值,您可以在 Shell 脚本中使用下列行将十进制号码转换为十六进制号码。如果您使用
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) 到 PID(进程 ID)的映射。
示例:pstack
9499 并将输出结果重定向到一个文件。
如果您使用 Solaris 中的常规线程库(即,在 LD_LIBRARY_PATH
中没有 /usr/lib/lwp),LWP
就不会直接映射到操作系统线程,因此您必须从进程中执行 pstack(所以检查看您是否正在使用替代线程库)。
- 经过一段时间后对服务器进行若干 Thread Dump,确保您执行正确的线程。
您可以通过在 Java 进程中执行 kill
-3 <PID>来达到此目的。
- 将 LWP ID 映射到 Java 线程 ID。
例如,如果上述的 LWP 为“8”,它可以映射到 Java 线程“76”。然后将
76 换算为十六进制值 0x4c。
- 检查 Thread Dump,找到匹配“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 中的常规线程库(即,在 LD_LIBRARY_PATH
中没有 /usr/lib/lwp),LWP
就不会直接映射到操作系统线程,因此您必须从进程中执行 pstack(所以检查看您是否正在使用替代线程库)。
上述示例显示“java/8”进程在 prstat
的顶端。
- 为“lwp# 8”检验 pstack输出结果。
您会发现“lwp# 8”从 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 进程中执行以下命令对服务器进行 Thread Dump:
kill
-3 <PID>。
- 由于 lwp# 8 映射到 thread #76,您可以将 76 换算为十六进制值 4c。
该值映射到 JVM Thread Dump 中的 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 资源的线程实际上正处于休眠状态。应用程序轮询程序在开发模式启动的服务器上运行。由于它每隔
30 秒运行一次,因此显然无法及时捕捉 Thread Dump 以了解此线程中的活动。
理想状态下,应当迅速并且连续完成全部三个步骤,以便尽可能及时地捕捉数据。这可以通过类似下面的一个简单的 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 |
- 然后,您可以检查该线程以确定它正在执行的任务以及是否出现问题。
返回页首
|
Linux
- 获得最顶端输出并查找与之前启动了现占用 CPU 的 WLS 的那个用户 ID 相关联的 PID。
- 通过 kill
-3 <PID> 对 WebLogic Server 进行若干 Thread Dump
- 将步骤 1 中的 PID 号转换为一个十六进制值。
(用于 Linux 的 JVM 将 Java 线程作为本地线程实现,这使每个线程成为一个独立的
Linux 进程。)
- 在 Thread Dump 中搜索 nid 的值等于上一步骤中所得到的十六进制值的线程。
这将为您揭示造成高 CPU 占用率问题的线程。
- 确定为什么在您的代码中会发生这个问题,或者,如果堆栈的最顶端输出来自 WebLogic,请与 BEA 客户支持部门联系。
下面是 Linux 系统中上述进程的一个示例:
- 获得 top输出并查找与之前启动了现占用
CPU 的 WLS 的那个用户 ID 相关联的 PID。
- 将该号转换为一个十六进制值。
请参阅下面的 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,则十六进制值将是:0x59B2
- 使用此十六进制值并在 Thread Dump 中查找哪个 nid 等于该值,以便从 Thread Dump 中获取正确的线程。
例如,如果 ExecuteThread 0 出现问题,则 0x59B2
将对应于该线程:
|
"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,所以只显示执行此操作的进程。理想状态下,应当迅速并且连续完成全部三个步骤,以便尽可能及时地捕捉数据。这可以通过类似下面的一个简单的
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
- 执行: ps
-mp <WLS_PID> -o THREAD 以查找正在占用 CPU 的 tid。
您应当查看“CP”列(表示 CPU 占用率),看其中哪些线程的此项值比较高并从中挑选一个线程。
- 通过执行以下命令对服务器进行 Thread Dump:
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>后面列出号码)以获取关于该线程的信息。
- 从第 3 步骤的输出中,在“general”下查找“pthread_t”,并记录该十六进制号码。
- 非常重要说明:在 dbx 提示符下,您需要在完成操作时在 dbx 命令行键入“detach”,否则,如果您在连接到进程时只要一退出,dbx
将终止该进程!
- 记下“p_thread_t”输出中的十六进制值,并在 Thread Dump 中搜索其中哪个线程的“native ID”等于该值。
这将为您揭示造成高 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 的 Thread Dump
- 检查 ps -mp <WLS_PID>
-o THREAD命令所输出的信息。
注意,TID "667723" 在 CP 列中有一个高值(它达到“37”,而其它
TID 几乎为 0)。
- 运行 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 命令以获取关于该本地线程的必要信息:
|
(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 进程的 Thread Dump 中的正确线程。
- 从早期进行的 Thread Dump 中,您可以将十六进制号码“1011”与 Thread Dump 中在“native
ID”之后的号码进行匹配。
下面是匹配此十六进制号码并造成高 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 目前没有提供类似 prstat-
的命令来收集独立的线程 ID,以将它们转换回 Thread Dump,BEA 技术支持部门开发了一种简单的实用程序,可以显示进程
ID (PID)、与 PID 关联的轻量型进程 ID (LWPID)、用户时间和所使用的系统时间。您可以使用该程序作为一个大致指南,因为在高
CPU 占用的情况中,LWPID 使用越来越多的 CPU,您会看到用户时间在很短的时间之内便增加了。您可以使用 BEA 的 hp_prstat
实用程序,并定期测量每个 LWPID 的用户时间以了解哪一个正在随时间推移而增加。用户时间只能显示为一个整数,因为由 HP 提供的
API 在这种情况下无法进行更精细的测量。
若要收集 HP-UX 的数据:
- 单击 hp_prstat
以下载 BEA 技术支持部门开发的 hp_prstat
实用程序。
- 在 Java 进程中运行 hp_prstat命令。
- 通过在 Java 进程中执行以下命令对服务器进行若干 Thread Dump: kill
-3 <PID>。
- 稍后,完成另一个 hp_prstat
<PID>快照。
- 检查两次 hp_prstat迭代的输出结果以找到已经迅速增加用户时间的出现问题的
LWPID。
- 一旦您获得该号码 (LWPID),请检查 Thread Dump,以查找您已经完成的 Thread Dump 中哪一项的
lwp_id=<等于您所获得的 LWPID>。
这将匹配将要占用完 CPU 的有问题的线程。
- 确定为什么在您的代码中会发生这个问题,或者,如果堆栈的最顶端输出来自 WebLogic,请与 BEA 客户支持部门联系。
- 在 Java 进程中运行 hp_prstat
命令。
示例: hp_prstat
<PID>
- 每隔几分钟执行一次上述操作,执行数次,同时观察发生高 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 进程中执行以下命令对服务器进行 Thread Dump: kill
-3 <PID>。
- 稍后,完成另一个 hp_prstat
<PID> 快照。
注意,与第一个快照对比,两个 LWPID(285475 和 285416)比较大。
您需要检查这两个 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 进程中执行以下命令对服务器进行另一个 Thread Dump: kill
-3 <PID>,确保您捕捉到占用完 CPU 资源的正确线程。
- 从 hp_prstat
输出中获取 LWPID,该输出在形式上与用户时间相似,且不断增大。一旦您获得该号码 (LWPID),请检查 Thread
Dump,以查找您已经完成的 Thread Dump 中哪一项的 lwp_id 等于<您所获得的 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。
- 您可以检查该 Servlet 的服务方法,以查明围绕此行号发生的情况(HelloWorldServlet.java第
28 行)并确定问题所在。
返回页首
|
|
Windows
使用
pslist
您可以在 Windows 中使用 pslist
并获取 java 进程的线程详细信息。 pslist可从以下网址得到:http://www.sysinternals.com/ntw2k/freeware/pslist.shtml
- 运行 pslist
-d <Java PID> 并将输出结果重定向到一个文件。
- 重复几次这个操作,以便您能够看到一种模式。
您将看到“用户时间”和“内核时间”不断增加。
- 在若干次迭代后对 WLS 服务器进行 Thread Dump。
- 记下步骤 1 中看起来正在增加的线程 ID 号,将十进制值改为十六进制值(您可以使用 Windows 中的计算功能)。
- 根据“nid=0x<步骤 3 的十六进制值>”检查 Thread Dump,直到您找到出现问题的线程。
- 确定为什么在您的代码中会发生这个问题,或者,如果堆栈的最顶端输出来自 WebLogic,请与 BEA 客户支持部门联系。
使用 Process Explorer
您还可以使用 Systinternals 提供的 Process Explorer
http://www.sysinternals.com/ntw2k/freeware/procexp.shtml。 该工具直观动态显示
CPU 占用率。 由于 Process Explorer 没有记录功能或历史记录,您必须监视该程序并记录占用几乎全部
CPU 资源的 Java 进程的线程 ID。 若要通过 Process Explorer 达到上述目的:
- 查找 java 进程,然后右键单击并选择属性。
- 单击“Threads”选项卡以显示与此 java 进程关联的所有线程。
- 您可以单击以“MSVCRT.dll+<一些十六进制偏移量>”形式列出的其中一个线程。
您可以看到在下面窗格中列出的“Thread ID”。
- 观察哪一个线程占用最多 CPU 资源。
- 进行 WLS 服务器的 Thread Dump。
- 记下步骤 4 中看起来正在占用 CPU 的线程 ID 号,将十进制值改为十六进制值(您可以使用 Windows 中的计算功能)。
- 根据“nid=0x<十六进制值>”检查 Thread Dump,直到您找到出现问题的线程。
- 确定为什么在您的代码中会发生这个问题,或者,如果堆栈的最顶端输出来自 WebLogic,请与 BEA 客户支持部门联系。
下面是仅使用
pslist 和 Thread Dump 的步骤示例:
- 运行 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&nb | |