1 概述
<?xml:namespace prefix = o ns = "urn:schemas-microsoft-com:office:office" />
1.1 基本情况
应XX银行局方要求，自
7月26日起，对[413]故障进行排查。由于在故障发生时段没有保留线程快照，不能直观的反映当时现场状况，从而加大了故障排查的难度。局方提供的资料有：WLS日志，WLS配置文件等。
2 故障排查
2.1 集群Cluster_1稳定性考察
mserver1（188.188.64.9）日志摘要如下：
####<2012-4-13 下午01时38分56秒 CST> <Info> <Cluster> <esb1.bocd.com.cn> <mserver1> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334295536137> <BEA-000112> <
Removing mserver3 jvmid:-8371879284094377789S:188.188.64.11:[7023,7023,-1,-1,-1,-1,-1]:
EsbJms:mserver3from cluster view due to timeout.>
####<2012-4-13 下午01时39分43秒 CST> <Info> <Cluster> <esb1.bocd.com.cn> <mserver1> <[STANDBY] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334295583811> <BEA-000111> <
Adding mserver3 with ID -8371879284094377789S:188.188.64.11:[7023,7023,-1,-1,-1,-1,-1]:
EsbJms:mserver3 to cluster: Cluster_1 view.>
####<2012-4-13 下午01时39分55秒 CST> <Info> <Cluster> <esb1.bocd.com.cn> <mserver1> <[STANDBY] ExecuteThread: '25' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334295595079> <BEA-000128> <
Updating -8371879284094377789S:188.188.64.11:[7023,7023,-1,-1,-1,-1,-1]:
EsbJms:mserver3 in the cluster.>
从下午01时38分56秒将mserver3移出集群，到下午01时39分55秒将mserver3重新加入集群，时间间隔约1分钟，之后再没有出现将Cluster_1中成员移出集群的日志记录。
mserver2（188.188.64.10）日志表明从下午01时38分52秒将mserver3移出集群，到下午01时39分49秒将mserver3重新加入集群，时间间隔约1分钟，之后再没有出现将Cluster_1中成员移出集群的日志记录。
mserver3（188.188.64.11）日志表明从下午01时39分43秒将mserver2、mserver4、mserver5移出集群，到下午01时41分15秒将mserver2、mserver4、mserver5重新加入集群，时间间隔约1.5分钟，之后再没有出现将Cluster_1中成员移出集群的日志记录。
mserver4（188.188.64.12）日志表明从下午01时38分58秒将mserver3移出集群，到下午01时39分55秒将mserver3重新加入集群，时间间隔不足1分钟，之后再没有出现将Cluster_1中成员移出集群的日志记录。
mserver5（188.188.64.13）日志表明从下午01时38分58秒将mserver3移出集群，到下午01时39分53秒将mserver3重新加入集群，时间间隔不足1分钟，之后再没有出现将Cluster_1中成员移出集群的日志记录。
下午01时55分09秒，系统管理员对mserver3实施关闭操作，日志摘要如下：
####<2012-4-13 下午01时55分
09秒 CST> <Alert> <WebLogicServer> <esb3.bocd.com.cn> <
mserver3> <[STANDBY] ExecuteThread: '267' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1334296509291> <BEA-000396> <Server shutdown has been requested by weblogic>
约3秒之后，mserver1、mserver4、mserver5取得mserver3关闭的信息，约13秒之后，mserver2取得mserver3关闭的信息，从而表明集群Cluster_1成员之间通信状况良好，日志摘要如下：
####<2012-4-13 下午01时55分
12秒 CST> <Info> <Cluster> <esb1.bocd.com.cn> <
mserver1> <[ACTIVE] ExecuteThread: '165' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334296512810> <BEA-000144> <Managed server mserver3 has been suspended or shutdown.>
####<2012-4-13 下午01时55分
22秒 CST> <Info> <Cluster> <esb2.bocd.com.cn> <
mserver2> <[ACTIVE] ExecuteThread: '180' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334296522795> <BEA-000144> <Managed server mserver3 has been suspended or shutdown.>
####<2012-4-13 下午01时55分
12秒 CST> <Info> <Cluster> <esb4.bocd.com.cn> <
mserver4> <[ACTIVE] ExecuteThread: '311' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334296512785> <BEA-000144> <Managed server mserver3 has been suspended or shutdown.>
####<2012-4-13 下午01时55分
12秒 CST> <Info> <Cluster> <esb5.bocd.com.cn> <
mserver5> <[ACTIVE] ExecuteThread: '237' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334296512812> <BEA-000144> <Managed server mserver3 has been suspended or shutdown.>
3 [413]故障推测
3.1 SmartEsb域NPE异常的关注
故障发生时段，SmartEsb01-05抛出大量NPE异常，堆栈内容如下：
<The following exception has occurred:java.lang.NullPointerException
java.lang.NullPointerException
at com.dcfs.impls.esb.MXSDMessage.<init>(MXSDMessage.java:36)
at com.dcfs.impls.esb.MXSDMessage.<init>(MXSDMessage.java:49)
at com.dcfs.impls.esb.communication.NormalMessageReceiverImpl.onMessage
(NormalMessageReceiverImpl.java:119)
at weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4121)
at weblogic.jms.client.JMSSession.execute(JMSSession.java:4011)
at weblogic.jms.client.JMSSession.invoke(JMSSession.java:4506)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:759)
at weblogic.messaging.dispatcher.DispatcherServerRef.invoke(DispatcherServerRef.java:276)
at weblogic.messaging.dispatcher.DispatcherServerRef$2.run(DispatcherServerRef.java:112)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)
>
系统中提供MXSDMessage.java源代码，红色高亮部分，即抛出异常的第36行：
public MXSDMessage(Message msg) throws JMSException {
this.msg = msg;
String sErr = msg.getStringProperty(MSG_TYPE);
bError = sErr != null && sErr.equals(TYPE_ERROR);
corID = msg.getJMSCorrelationID();
from = msg.getStringProperty(FROM);
String to = msg.getStringProperty(TO);
int idx = to.indexOf("/");
firstTo = to;
if (idx != -1) {
firstTo = to.substring(0, idx);
lastTo = to.substring(idx + 1);
}
replyName = msg.getStringProperty(MSG_REPLYNAME);
replyUrl = msg.getStringProperty(MSG_REPLYURL);
replyQueue = msg.getStringProperty(MSG_REPLYQUEUE);
replyConectionFactory = msg.getStringProperty(MSG_REPLYCONNFACTYNAME);
}
从代码可以看到，to.indexOf()报告NullPointerException，是因为msg.getStringProperty(TO)返回的是Null。这就是说，ESB3收到的报文中缺少路由的关键信息，服务名称。
即SmartEsb01-05中抛出的大量NPE异常是由异常报文引起。由于异常报文不能被SmartEsb应用处理，导致异常报文无法离开消息队列，于是应用不断重复“读取异常报文、抛出NPE异常、再读取异常报文”的过程，直到异常报文超时被JMS服务器清除。报文设定存活时间为10分钟。
下表列出[413]故障当日NPE异常持续时间：
SmartEsb01
SmartEsb02
SmartEsb03
SmartEsb04
SmartEsb05
首次出现时间
01时39分34秒
01时48分15秒
01时40分57秒
01时41分11秒
01时39分27秒
最后出现时间
03时27分28秒
03时27分23秒
03时25分49秒
03时28分18秒
03时27分23秒
由异常报文引起的NPE异常，可以在[413]故障之前的日志中找到，但是[413]故障之后到现在这段时间，却还没有再次出现NPE异常。作为[413]故障的一个分界点，可考虑对NPE异常进行重点排查。深入排查需要了解报文的完整结构，以及报文拼接、传递等流程，尝试找出异常报文产生的根源。例如：需要解释msg.getStringProperty(TO)中变量TO对应报文的字段。在27日上午与应用方的交流中，应用方未给出明确的说法。
3.2 分布式队列“堵塞”的推测
NPE异常持续时间表明，SmartEsb01-05中抛出大量NPE异常的行为一直持续到下午03时28分18秒。局方系统管理员向SmartEsb03发出结束指令是在下午03时25分29秒，在SmartEsb03的进程结束后，系统恢复正常。
假设在SmartEsb03结束前，分布式队列中只有异常报文被SmartEsb01-05读取，正常报文不被处理，那么执行线程将重复“读取异常报文、抛出NPE异常、再读取异常报文”的过程，则系统无法处理正常的业务逻辑；SmartEsb03结束后，可以看作是缓解了队列堵塞的状况；之后没有新的异常报文发送到队列，旧的异常报文超时舍弃，于是系统恢复正常。
4 WLS与JDK版本
WLS需要运行于JDK之上，JDK本身的稳定性和性能对系统运行存在直接影响。当前生产环境并未使用通过Oracle官方认证的JDK版本，Oracle官方不对由此引起的任何问题提供支持，建议尽快将JDK升级到官方支持的版本。下表中列出适用于WLS 9.2 MP4的JDK提供商及其版本要求：
JDK 提供商
生产环境运行版本
WLS 9.2 MP4 要求版本
BEA
R27.6.3
R27.6.6+
Sun
1.5.0_19
1.5.0_22+
WLS 9.2发布于2005年7月，经历4次维护包升级，已于去年11月结束标准支持（PS），并停止销售。如果希望继续得到Oracle官方支持，需要额外购买扩展支持（ES），Oracle将于明年11月结束扩展支持。基于产品运行的稳定性、性能表现和可维护性，建议统一更新至当前最新发行版本，建议目标版本为 10.3 MP6。
5 排查结论
大量RMI调用触发的WLS核心组件BUG（编号13717183），该BUG导致消息队列集群 Cluster_1中所有结点“挂起”。由于消息队列集群 Cluster_1不能正常处理客户端发出的请求，致使局方核心系统业务全部中断，即：[413]故障。Oracle官方已对BUG 13717183进行修复，并且为WLS 10.0 MP1及其后续版本提供补丁支持。
注： BUG 13717183
* 详细可参考MOS（My Oracle Support）知识库：STUCK Threads When Sending Too Many RMI Calls [ID 1469746.1]
The issue is due to an Integer overflow. RJVMImpl maintains a running counter in order to map requests with their respective responses. This is maintained with the integer variable, and every time a request is sent and expects a response, the variable is increased and sent along with the request (in JVMMessage) to the other end. If this variable gets increased over Integer.MAX_VALUE it will overflow and wrap acquiring negative values. This will produce the messages to be silently dropped.
RJVMImpl利用整型计数器维护请求及其应答的映射关系，大量RMI调用导致计数值变为负值，从而破坏了映射关系。
下表中列出Oracle官方支持的WLS版本号及其对应的补丁ID：
WLS版本号
补丁ID
10.0.1
12VI
10.3.0
MKTL
10.3.3
LRSU
10.3.4
TZNK
10.3.5
7A15
10.3.6
JZED
6 【413】故障分析
通过WLS日志记录，考察在故障发生时段，消息队列集群Cluster_1各结点的执行线程编号。由于域EsbJms没有约束执行线程的数量，WLS的执行线程将采用自调优策略。因此，通过日志记录的执行线程编号最大值，可推知当前结点中执行线程的数量在这个值附近。
能够看到结点mserver1、mserver2、mserver4、mserver5的执行线程编号均大于400，结点mserver3的编号大于250。日志摘要如下：
####<2012-4-13 下午02时12分41秒 CST> <Info> <Cluster> <esb1.bocd.com.cn> <mserver1> <[STANDBY] ExecuteThread: '403' for queue: 'weblogic.kernel.Default (self-tuning)'>
####<2012-4-13 下午01时52分17秒 CST> <Info> <JMS> <esb2.bocd.com.cn> <mserver2> <[STANDBY] ExecuteThread: '407' for queue: 'weblogic.kernel.Default (self-tuning)'>
####<2012-4-13 下午01时55分09秒 CST> <Info> <Server> <esb3.bocd.com.cn> <mserver3> <[STANDBY] ExecuteThread: '268' for queue: 'weblogic.kernel.Default (self-tuning)'>
####<2012-4-13 下午01时52分03秒 CST> <Info> <JMS> <esb4.bocd.com.cn> <mserver4> <[STANDBY] ExecuteThread: '404' for queue: 'weblogic.kernel.Default (self-tuning)'>
####<2012-4-13 下午02时11分39秒 CST> <Info> <Server> <esb5.bocd.com.cn> <mserver5> <[STANDBY] ExecuteThread: '401' for queue: 'weblogic.kernel.Default (self-tuning)'>
结合集群Cluster_1 稳定性考察进行合理推测，即：在结点mserver3离开集群的短暂时间，集群中其他结点由于需要处理RMI请求，增加了执行线程的数量。但是，由于维护请求及其应答映射关系的整型计数器在早先某个时间已经出现整型溢出，新产生的执行线程只能“挂起”，对应客户端的执行线程由于得不到应答消息同样只能“挂起”。对于集群结点执行线程“挂起”的推测，可从《XX报告》中4月23日重现场景，集群结点产生大量守护线程（大于400）的现象得到支持。通过结点mserver3离开集群的短暂时间，其他四个结点的执行线程增量大于130，可以得到：在结点mserver3离开集群前的某个时间，整型计数器的计数值已经变为负值的推测。
通过整理核心系统全部WLS域服务器日志中标记为 STUCK 的等待中执行线程，在域Cbsd04中找到最早满足条件的执行线程。日志摘要如下：
####<Apr 13, 2012
2:06:33 PM CST> <Error> <WebLogicServer> <app4.bocd.com.cn> <AdminServer>
<[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1334297193705> <BEA-000337> <[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "1,808" seconds working on the request "weblogic.work.ServerWorkManagerImpl$WorkAdapterImpl@1feea581",
which is more than the configured time (StuckThreadMaxTime) of "1,800" seconds. Stack trace:
Thread-18 "[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, waiting, priority=1, DAEMON> {
-- Waiting for notification on: weblogic.rjvm.ResponseImpl@2053f3ff[fat lock]
java.lang.Object.wait(Object.java:???)
weblogic.rjvm.ResponseImpl.waitForData(ResponseImpl.java:80)
weblogic.rjvm.ResponseImpl.retrieveThreadLocalContext(ResponseImpl.java:134)
可尝试进行如下推测，即：整型计数器出现整型溢出的时段在下午1时36分25秒左右。在此之后，由于集群各个结点“挂起”的执行线程逐渐增多，以致集群对外请求响应能力的逐渐降低，累加的结果导致核心系统业务全部中断。
下表列出[413]故障发生时段，值得关注的NPE 异常连续抛出时间点：
出现时间点1
出现时间点2
出现时间点3
出现时间点4
出现时间点5
SmartEsb01
01时39分34秒
01时39分43秒
01时39分44秒
01时41分16秒
01时44分17秒
SmartEsb02
01时48分15秒
N/A
N/A
N/A
N/A
SmartEsb03
01时40分57秒
01时40分58秒
01时41分39秒
01时41分39秒
01时45分09秒
SmartEsb04
01时41分11秒
01时41分17秒
01时41分49秒
01时42分05秒
01时42分11秒
SmartEsb05
01时39分27秒
01时39分27秒
01时39分34秒
01时39分34秒
01时39分34秒
比较SmartEsb01-05在下午3时之后的NPE日志记录频度，不难得到推测，即：在故障发生时段，SmartEsb01-05先是无法及时从集群取得异常报文，后是无法从集群取得异常报文，从而证明集群对外请求响应能力逐渐降低过程的存在。
以下指出并修正存在的两个问题：
故障发生时段及其后续的一段时间，SmartEsb01-05抛出大量NPE 异常。其中不准确的地方在于，在故障发生时段，NPE异常抛出的频度并不高，大量抛出NPE异常是在下午3时之后的一段时间。因而，由于异常报文导致分布式队列“堵塞”的推测不正确。
对于集群 Cluster_1稳定性相对良好的分析不够准确，集群结点之间的多播传递是交由指定线程weblogic.cluster.MessageReceiver完成，因而不能推出集群结点的执行队列weblogic.kernel.Default中线程的执行情况。
7 解决方案
对于产品自身存在的BUG，最优方案是应用Oracle官方提供的补丁进行修正。
如果沿用老版本的WLS 9.2 MP4，可考虑下一章给出的其他建议。
8 其他建议
首先，从应用框架角度，对InitialContext、连接工厂、分布式队列等资源进行缓存，减少源代码中的RMI调用。此外，建议源代码中加入报文格式的检查机制，避免异常报文发送到分布式队列。
其次，从系统构架角度，对分布式队列进行合理分组。此外，建议JMS生产者采用RMI调用，JMS消费者采用本地调用。对于JMS消息发送的可靠性和稳定性，可考虑配置存储转发代理（SAF）。
再次，从集群配置角度，通过在WLS启动命令行中添加相应参数，控制集群结点的并发线程数量；可根据系统资源和实际运行情况酌情修改，以下示例将结点的并发线程设置为25：
-Dweblogic.threadpool.MinPoolSize=25
-Dweblogic.threadpool.MaxPoolSize=25
当前位置：
论坛首页 »
自由讨论区 »
Tomcat, WebLogic及J2EE讨论区
»
发起投票
技术讨论
加好友
发消息
2014-3-19 17:38:37 |
赞(
操作
