【标题】：WEBLOGIC Server 的异常高 CPU 占用率
【关键字】：WEBLOGIC,Server,CPU
【来源】：http://www.cublog.cn/u/17749/showart.php?id=104801

WEBLOGIC Server 的异常高 CPU 占用率

WEBLOGIC Server 的异常高 CPU 占用率

问题描述
系统管理员或用户注意到 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

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         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，并将其转换为十六进制值 (0x24)。

查看您在出现问题时所记下的 Thread Dump，并查找“nid=0x24”。
从以下输出中可以看出，它对应于 Thread Dump 中的 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本地方法上，但表面看起来是 HelloWorld2.service()出错。

检查行号（HelloWorld2.java的第 94 行）以确定发生的情况。
从 service()方法的 HelloWorld2.java 代码片断：

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());