问题描述
系统管理员或用户注意到 WebSphere Application Server 进程消耗大量的 CPU 资源,并想要了解是哪个方面消耗了大量 CPU 资源,以及导致出现这种现象的原因。
故障排除
请注意,并非下面所有任务都需要完成。有些问题仅通过执行几项任务就可以解决。
为什么发生此问题?
发生此问题有许多原因:WebSphere Application Server 本身、用户创建的线程、不良编码习惯或第三方软件。遗憾的是,证明在什么地方发生此问题有时候非常困难。本模式尝试通过利用特定操作命令和收集数据来帮助排除此问题。
收集高 CPU 占用率的数据
对于有关收集高 CPU 占用率的数据的特定操作信息,请根据您的操作系统执行以下步骤。
备注:为协助您计算在本模式中讨论的十六进制值,您可以在 Shell 脚本中使用下列行将十进制号码转换为十六进制号码。如果您使用 Unix 操作系统,那么转换会很方便。
dec2hex.sh:
printf "dec -> hex: %d = %x /n" ${1} ${1}
用法:
$ sh dec2hex.sh 755
dec -> hex: 755 = 2f3
AIX
- 执行: ps -mp <WAS_JAVA_PID> -o THREAD 以查找正在占用 CPU 的 tid。
您应当查看“CP”列(表示 CPU 占用率),看其中哪些线程的此项值比较高并从中挑选一个线程。
- 通过执行以下命令对服务器进行 Thread Dump:
kill -3 <WAS_JAVA_PID>
- 运行: dbx -a <WAS_JAVA_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 占用率问题的线程。
1、ps -mp 250076 -o THREAD 将显示以下内容:
USER PID PPID TID ST CP PRI SC WCHAN F TT BND COMMAND |
- 通过 kill -3 <WAS_JAVA_PID>产生该 WAS_JAVA_PID 的 Thread Dump
- 检查 ps -mp <WAS_JAVA_PID> -o THREAD命令所输出的信息。
注意,TID "667723" 在 CP 列中有一个高值(它达到“37”,而其它 TID 几乎为 0)。
- 运行 dbx -a 250076以连接到 WebSphere Application Server 进程。
- 运行 thread 命令以列出所有本地线程。
下面只显示相关线程的一个代码片断:
thread state-k wchan state-u k-tid mode held scope function |
- 运行 th info 17 命令以获取关于该本地线程的必要信息:
(dbx) th info 17 |
- 非常重要说明:在 dbx 提示符下运行“detach”以从 WebSphere Application Server Java 进程中分离。 警告:☆☆☆☆☆!
- 记下上述“pthread_t”的数值,并用来查找 WebSphere Application Server 进程Thread Dump 中的正确线程。
- 从早期进行的 Thread Dump 中,您可以将十六进制号码“1011”与 Thread Dump 中在“native ID”之后的号码进行匹配。
下面是匹配此十六进制号码并造成高 CPU 占用率问题的线程示例:
3XMTHREADINFO "Servlet.Engine.Transports:915" (TID:0x34B82C78, sys_thread_t:0x778F7670, state:MW, native ID:0x1011) prio=5 4XESTACKTRACE at com.henry.util.JSONWriter.putValue(JSONWriter.java(Compiled Code)) 4XESTACKTRACE at com.henry.util.JSONWriter.putNextValue(JSONWriter.java(Inlined Compiled Code)) 4XESTACKTRACE at person._FPT_5F_I_5F_0002_5F_1Pay_jsp_0.toAccountList2JsonArray(_FPT_5F_I_5F_0002_5F_1Pay_jsp_0.java(Compiled Code)) 4XESTACKTRACE at person._FPT_5F_I_5F_0002_5F_1Pay_jsp_0._jspService(_FPT_5F_I_5F_0002_5F_1Pay_jsp_0.java:392) 4XESTACKTRACE at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java(Compiled Code)) 4XESTACKTRACE at javax.servlet.http.HttpServlet.service(HttpServlet.java(Compiled Code)) 4XESTACKTRACE at org.apache.jasper.runtime.JspServlet$JspServletWrapper.service(JspServlet.java(Compiled Code)) 4XESTACKTRACE at org.apache.jasper.runtime.JspServlet.serviceJspFile(JspServlet.java(Compiled Code)) 4XESTACKTRACE at org.apache.jasper.runtime.JspServlet.service(JspServlet.java(Compiled Code)) 4XESTACKTRACE at javax.servlet.http.HttpServlet.service(HttpServlet.java(Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.StrictServletInstance.doService(ServletManager.java(Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.StrictLifecycleServlet._service(StrictLifecycleServlet.java(Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.ServicingServletState.service(StrictLifecycleServlet.java(Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.StrictLifecycleServlet.service(StrictLifecycleServlet.java(Inlined Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.ServletInstance.service(ServletManager.java(Compiled Code)) 4XESTACKTRACE at com.ibm.servlet.engine.webapp.ValidServletReferenceState.dispatch(ServletManager.java(Compiled Code)) |
Windows
使用 pslist
您可以在 Windows 中使用 pslist 并获取 java 进程的线程详细信息。 pslist可从以下网址得到:http://www.microsoft.com/technet/sysinternals/ProcessesAndThreads/PsList.mspx
- 运行 pslist -d <WAS Java PID> 并将输出结果重定向到一个文件。
- 重复几次这个操作,以便您能够看到一种模式。
您将看到“用户时间”和“内核时间”不断增加。
- 在若干次迭代后对 WAS 服务器进行 Thread Dump。
- 记下步骤 1 中看起来正在增加的线程 ID 号,将十进制值改为十六进制值(您可以使用 Windows 中的计算功能)。
- 根据“nid=0x<步骤 3 的十六进制值>”检查 Thread Dump,直到您找到出现问题的线程。
使用 Process Explorer
您还可以使用 Systinternals 提供的 Process Explorer http://www.microsoft.com/technet/sysinternals/ProcessesAndThreads/ProcessExplorer.mspx。
该工具直观动态显示 CPU 占用率。 由于 Process Explorer 没有记录功能或历史记录,您必须监视该程序并记录占用几乎全部 CPU 资源的 Java 进程的线程 ID。 若要通过 Process Explorer 达到上述目的:
- 查找 java 进程,然后右键单击并选择属性。
- 单击“Threads”选项卡以显示与此 java 进程关联的所有线程。
- 您可以单击以“MSVCRT.dll+<一些十六进制偏移量>”形式列出的其中一个线程。
您可以看到在下面窗格中列出的“Thread ID”。
- 观察哪一个线程占用最多 CPU 资源。
- 进行 WAS 服务器的 Thread Dump。
- 记下步骤 4 中看起来正在占用 CPU 的线程 ID 号,将十进制值改为十六进制值(您可以使用 Windows 中的计算功能)。
- 根据“native ID=0x<十六进制值>”检查 Thread Dump,直到您找到出现问题的线程。
下面是仅使用 pslist 和 Thread Dump 的步骤示例:
1. 运行 pslist -d 172
java 1720: |
- 一段时间后再次进行相同的输出,以获得线程的另一个快照,查明哪一个线程已经显著增大。
- 确定要进一步检查的线程 ID (TID)。
- 再次运行 pslist: pslist -d 1720
java 1720: |
注意,线程 ID 588 正在使用最多的用户/内核时间,因此占用最多的 CPU 资源。显然,该线程有问题。
- 记录线程 ID 号 588,并将其转换为十六进制值 (0x24c)。
- 查看您在出现问题时所记下的 Thread Dump,并查找“native ID=0x24c”。
从以下输出中可以看出,它对应于 Thread Dump 中的线程:
3XMTHREADINFO "Servlet.Engine.Transports:915" (TID:0x34B82C78, sys_thread_t:0x778F7670, state:MW, native ID: 0x24c) prio=5 |
显然,问题出现在 socketWrite本地方法上,但表面看起来是 HelloWorld2.service()出错。
- 检查行号(HelloWorld2.java的第 94 行)以确定发生的情况。 从 service()方法的 HelloWorld2.java 代码片断:
89 out.println(ExampleUtils.returnHtmlHeader("Hello World 2")); |
可以看出,由于某种原因,输出流是用一个非常长的“for loop”语句编写的。这是错误所在,也是此示例中造成高 CPU 占用率的原因。
如果改正此代码,则 CPU 就不会被完全占用。
Linux
- 获得最顶端输出并查找与之前启动了现占用 CPU 的 WAS 的那个用户 ID 相关联的 PID。
- 通过 kill -3 <PID> 对 WebSphere Application Server 进行若干 Thread Dump
- 将步骤 1 中的 PID 号转换为一个十六进制值。
(用于 Linux 的 JVM 将 Java 线程作为本地线程实现,这使每个线程成为一个独立的 Linux 进程。)
- 在 Thread Dump 中搜索native ID 的值等于上一步骤中所得到的十六进制值的线程。 这将为您揭示造成高 CPU 占用率问题的线程。
- 获得 top输出并查找与之前启动了现占用 CPU 的 WAS 的那个用户 ID 相关联的 PID。
- 将该号转换为一个十六进制值。
请参阅下面的 top 输出示例(这只是一个代码片断,因为对于单个 WAS 进程将启动更多的线程)。
在 Linux 中,每个线程映射到一个不同于其它 Unix 形式的进程中。
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND |
如果 PID 为 22962,则十六进制值将是:0x59B2
- 使用此十六进制值并在 Thread Dump 中查找哪个 native ID 等于该值,以便从 Thread Dump 中获取正确的线程。
例如,如果某个线程出现问题,则 0x59B2 将对应于该线程:
|
3XMTHREADINFO "Servlet.Engine.Transports:915" (TID:0x34B82C78, sys_thread_t:0x778F7670, state:MW, native ID: 0x59B2) prio=5 |
- 然后,您可以检查该线程以确定它正在执行的任务以及是否出现问题。
在上述示例中,由于该线程此时占用 0% 的 CPU,所以只显示执行此操作的进程。理想状态下,应当迅速并且连续完成全部三个步骤,以便尽可能及时地捕捉数据。这可以通过类似下面的一个简单的 shell 脚本来完成。
# |