故障分析报告

故障描述

       2007-3-6日上午，在系统监控时发现WebLogic实例的JAVA进程CPU使用率非常高，长期在60％以上，而内存消耗也较大。在11：30分，WebLogic其中一个实例内存溢出，很快另外一个实例访问也异常缓慢。经过重启，系统访问正常。

发生时间

       2007-3-6 11：30～2007-3-6 11：40

故障分析

       在故障发生时，WebLogic的被管服务器mserver2的gc日志出现连续FULL GC现象，如下所示：

68354.936: [Full GC 68354.936: [Tenured: 1441791K->1441791K(1441792K), 50.8704538 secs] 1823487K->1793402K(1823488K), [Perm : 122693K->122655K(131072K)], 50.8707784 secs]

68406.966: [Full GC 68406.966: [Tenured: 1441791K->1441791K(1441792K), 43.3959313 secs] 1823487K->1795107K(1823488K), [Perm : 122691K->122691K(131072K)], 43.3962451 secs]

68452.057: [Full GC 68452.057: [Tenured: 1441791K->1441791K(1441792K), 43.8102222 secs] 1823487K->1793985K(1823488K), [Perm : 122692K->122692K(131072K)], 43.8105214 secs]

68497.417: [Full GC 68497.417: [Tenured: 1441791K->1441791K(1441792K), 44.0541711 secs] 1823487K->1791516K(1823488K), [Perm : 122692K->122692K(131072K)], 44.0545032 secs]

68542.904: [Full GC 68542.904: [Tenured: 1441791K->1441791K(1441792K), 51.2142139 secs] 1823478K->1792950K(1823488K), [Perm : 122709K->122681K(131072K)], 51.2145271 secs]

由此，判断有大量对象占用了JVM的内存，并且在GC后没有释放。

同时，实例的输出日志中，发现有session复制现象，如下所示：

<Mar 6, 2007 11:36:35 AM CST> <Warning> <HTTP Session> <BEA-100074> <Primary session was removed during our attempt to retrieve secondary information from the session in the local server for the session: roid: 95421796383911755 , rsid: [ID: NdhhFsgX2JSpTzwqBWxFvllP5Qnj0wRphGJcLG23BQDLs5vT47X4 Primary: 847552361:192.168.80.17:8002:-1 Secondary: null] , primaryURL: t3://192.168.80.17:8002.>

这说明，WebLogic的被管服务器mserver2在向mserver1复制会话。

由于mserver1无法处理两个被管服务器的业务，很快也访问缓慢了。

之后，重启了WebLogic的2个实例，系统恢复正常。

       在接下来的系统监控中，发现WebLogic其中一个实例的JAVA进程的CPU使用率依然非常高，针对这一现象，我们dump出CPU的使用情况，发现有些JAVA线程使用CPU资源较高，且占用时间较长，如下所示：

PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/LWPID

 27662 cncbss   2225M 1631M cpu10    0   10   0:22.46  22% java/73

 27662 cncbss   2225M 1631M cpu9     0   10   0:20.31  22% java/72

 27662 cncbss   2225M 1631M run      0   10   0:22.12  22% java/75

经过多次dump CPU使用情况，这三个线程仍然存在。

此后dump WebLogic的线程，发现是如下线程导致高消耗CPU：

"ExecuteThread: '51' for queue: 'weblogic.kernel.Default'" daemon prio=5 tid=0x00ef7008 nid=0x4a runnable [0x79480000..0x79481998]

        at java.util.Vector.indexOf(Vector.java:363)

        - waiting to lock <0xa21b73f8> (a java.util.Vector)

        at java.util.Vector.contains(Vector.java:321)

        at cnc.util.FyCol.add(FyCol.java:204)

        at cnc.util.FyCol.add(FyCol.java:194)

        at cnc.util.RecordSet.<init>(RecordSet.java:199)

        at cnc.util.RecordSet.<init>(RecordSet.java:93)

        at cnc.util.FyDao.query(FyDao.java:264)

        at cnc.util.FyDao.query(FyDao.java:234)

        at listquery.ListQueryBean.getfreeList(ListQueryBean.java:404)

        at listquery.ListQuery_gq76y8_EOImpl.getfreeList(ListQuery_gq76y8_EOImpl.java:98)

        at listquery.ListQuery_gq76y8_EOImpl_WLSkel.invoke(Unknown Source)

        at weblogic.rmi.internal.ServerRequest.sendReceive(ServerRequest.java:166)

        at weblogic.rmi.cluster.ReplicaAwareRemoteRef.invoke(ReplicaAwareRemoteRef.java:290)

        at weblogic.rmi.cluster.ReplicaAwareRemoteRef.invoke(ReplicaAwareRemoteRef.java:248)

        at listquery.ListQuery_gq76y8_EOImpl_816_WLStub.getfreeList(Unknown Source)

        at cnc.query.list.QueryList.createExcel(QueryList.java:790)

        at cnc.query.list.ExportData.processRequest(ExportData.java:39)

        at cnc.query.list.ExportData.probe$0$doGet(ExportData.java:15)

        at cnc.query.list.ExportData.doGet(ExportData.java)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

        at weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run(ServletStubImpl.java:1077)

        at weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:465)

        at weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:348)

        at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:7047)

        at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)

        at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)

        at weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:3902)

        at weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2773)

        at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:224)

        at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:183)

经判断，这是清单查询的功能。

之后，转由开发人员对清单查询代码进行分析。

总结及改进措施

       此次故障是由于个别程序性能不佳消耗CPU过高导致，在3～5个这样查询的情况下就会使系统出现缓慢现象，而且清单查询对JVM内存消耗也较大，如果有大量清单查询会使JVM的内存出现溢出情况。

       由于在目前情况下，1台服务器的处理能力不足，特别是在业务高峰时，WebLogic的1个被管服务器并不足以支撑2个被管服务器的业务，因此其中一台服务器出现宕机、挂起等严重故障，往往另外一台也会出现相同故障。

       鉴于上述情况，我们提出下列改进意见：

1、  在第三台机器上增加一个WebLogic实例，加入到集群系统。这样在一台被管服务器出现故障时，另外两台依然可以实现负载均衡功能，宕机的可能性大大降低。

2、  将清单查询从BSS系统中移出去，目前这一项目正在进行。

3、  改良清单查询程序的性能。

附：

收集高 CPU 占用率的数据
对于有关收集高 CPU 占用率的数据的特定操作信息，请根据您的操作系统执行以下步骤。

重要说明：
这些操作系统的所有信息都基于 Sun JVM。 目前在 JRockit 中还没有办法将 PID 从说明 CPU 占用率的操作系统命令（prstat、top、pslist 等等）映射到 Thread Dump 中的正确线程。 从 Jrockit 的 70SP4RP2 和 81SP2RP1 以后的版本起，就可实现此映射。 例如，在 Linux 中，Thread Dump 在以后的版本中将采用如下形式（PID 显示在 Thread Dump 中）：