Was故障分析及优化整改方案

IT那活儿 2022-08-26

4426

点击上方“IT那活儿”公众号，关注后了解更多内容，不管IT什么活儿，干就完了！！！

7月28日15点50分左右，某管理平台一台应用服务器主机出现前端应用请求反应严重超慢的现象，17点48分重启应用服务后，应用访问暂时恢复正常。

问题故障原因定位

从错误日志分析，错误原因的数据库连接池的连接达到最大设定值，导致系统无法获取新的数据库连接导致。

数据库连接池连接最大值设置为200，如没有特殊情况发生，系统不会出现连接数不足的现象。按以往的经验造成连接数不足现象的原因有以下几个：

系统发生数据库死锁导致大量连接被锁定；
数据库系统超负荷运转导致反应变慢；
网络连接问题导致无法连接数据库；
系统有大数据量操作导致；
系统程序有未释放连接的程序bug，导致连接被使用光；
数据库其他问题导致无法获取连接。

通过排查该应用系统各个层面的影响因素，最终将故障原因定位在连接池上。

问题分析过程

1. 首先检查数据库是否有死锁

从前端发送到2节点的请求可以立马得到响应，请求的页面立马显示出来。从以上现象可以判断，数据库的访问是肯定没有问题的，不会存在死锁或者数据库宕机的可能；另外通过后台查看数据库没有死锁对象。

2. 检查数据库系统的负载情况

检查数据库主机的日志，发现CPU、内存占用率都很低，数据库主机允许的最大连接数为1500，远超2台应用服务器连接池配置的共400的数据库连接数，足以满足应用的数据库连接需求。

3. 检查网络连接情况

这台服务器的WAS服务重启后，请求立即得到快速响应，页面很快就展现出来，说明网络没有任何问题。

4. 应用服务器的资源使用情况

通过重新启动1节点中的WAS应用服务器之后，前端的请求发送到1节点之后，前端的请求可以立马得到反应，而且请求的页面也很快展现显示出来，可以认为是WAS应用服务器释放了相应的资源，可以满足前端的请求响应了。同时，从websphere的层面来看，没有生成相应的JavaCore和HeapDump文件，可以判断机器的CPU和MEMORY资源也很正常，没有发生内存泄漏等严重问题存在。

平台使用的连接池是DBCP(DataBase connection pool)数据库连接池。是 apache 上的一个 java 连接池项目，也是 tomcat 使用的连接池组件，也就是根本没用到WAS的连接池。

5. WAS日志信息分析

继续检查1节点上WAS的应用日志信息，发现WAS的应用服务器重启之前有大量如下报错：

APP-1:

[7/27/14 15:51:54:938 GMT+08:00] 000000db AcfCoreServle E com.ursa.acf.plugins.todomessage.impl.DealReadToDoMsgMgr list error.plugin.user.error_sqlerror
com.ursa.acf.plugins.user.UserPluginException: error.plugin.user.error_sqlerror
at com.ursa.acf.plugins.user.ursaimpl.UrsaUser.j(UrsaUser.java:646)
at com.ursa.acf.plugins.user.ursaimpl.UrsaUser.<init>(UrsaUser.java:53)
at com.ursa.acf.plugins.user.ursaimpl.UrsaUserManager.getUser(UrsaUserManager.java:178)
at com.ursa.acf.plugins.user.UserHelper.getUser(UserHelper.java:52)
at com.ursa.acf.plugins.todomessage.impl.DealReadToDoMsgMgr.list(DealReadToDoMsgMgr.java:132)
at com.itss.xz.test.login.AcfPanel_DBSY.setPanel(AcfPanel_DBSY.java:265)
at com.ursa.acf.plugins.acfpage.acfpanel.AcfPanelShow.acfShow(AcfPanelShow.java:65)
at com.ursa.acf.plugins.acfshow.AcfShow.acfExecute(AcfShow.java:38)
at com.ursa.acf.core.servlet.AcfCoreAction.execute(AcfCoreAction.java:62)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:419)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:224)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1194)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:414)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:575)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1147)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:722)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:449)
at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:178)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:125)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:92)
at com.ursa.acf.core.EncodingFilter.doFilter(EncodingFilter.java:46)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:919)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1016)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:87)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:883)
at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1659)
at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:195)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:452)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:511)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:305)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:276)
at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)
at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)
at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
at com.ibm.io.async.AsyncChannelFuture$1.run(AsyncChannelFuture.java:205)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1648)
Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at com.ursa.acf.component.datasource.impl.StrutsDSManager.getConnection(StrutsDSManager.java:107)
at com.ursa.acf.component.datasource.DatabaseHelper.getConnection(DatabaseHelper.java:42)
at com.ursa.acf.plugins.user.ursaimpl.UrsaUser.j(UrsaUser.java:629)
... 39 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1144)
at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:79)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
... 43 more

其中红色字体部分：

Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object

Caused by: java.util.NoSuchElementException: Timeout waiting for idle object

指出了产生问题的原因：

抛出此异常的原因为连接池泄漏，也就是再也无法从连接池中获取有效的数据库连接。

可能由于频繁的刷新页面导致上一次获取的connection还没有得到有效释放，下一次的connection请求已经到达，如是刷新多次后导致池资源耗尽，即所谓的连接池泄漏。

而且，在此种情况下，最糟糕的是异常发生后导致整个服务向连接池发起connection请求都将一直抛出如上异常，无法恢复到正常状态。向服务器发送请求，服务器没有响应，最简单的办法是重新启动释放连接池的资源，才能使连接池的连接数恢复到一个正常状态。前端的应用程序访问才能正常。

查看WAS重启后的日志信息，发现大量的如下错误信息：

2节点:

[7/28/14 10:41:32:109 GMT+08:00] 00004676 filter        E com.ibm.ws.webcontainer.filter.FilterInstanceWrapper service SRVE8109W: Uncaught exception thrown by filter EncodingFilter: java.io.FileNotFoundException: SRVE0190E: File not found: xzpage/bjyc/fs/resources/styles/ursadefault.css
at com.ibm.ws.webcontainer.extension.DefaultExtensionProcessor.handleRequest(DefaultExtensionProcessor.java:443)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:125)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:92)
at com.ursa.acf.core.EncodingFilter.doFilter(EncodingFilter.java:46)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:919)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1016)
at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:3639)
at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:304)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:950)
at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1659)
at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:195)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:452)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:511)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:305)
at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:83)
at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)
at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)
at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1648)

1节点:

[7/28/14 8:47:21:557 GMT+08:00] 00000036 filter        E com.ibm.ws.webcontainer.filter.FilterInstanceWrapper service SRVE8109W: Uncaught exception thrown by filter EncodingFilter: java.io.FileNotFoundException: SRVE0190E: File not found: xzdefault.css
at com.ibm.ws.webcontainer.extension.DefaultExtensionProcessor.handleRequest(DefaultExtensionProcessor.java:443)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:125)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:92)
at com.ursa.acf.core.EncodingFilter.doFilter(EncodingFilter.java:46)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:919)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1016)
at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:3639)
at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:304)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:950)
at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1659)
at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:195)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:452)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:511)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:305)
at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:83)
at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)
at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)
at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1648)

6. 对大数据量操作的分析

因为没有针对用户的归档和查询操作进行记录，因此无法获悉问题发生前的客户操作情况，而大量的归档、查询操作会导致应用的负载急剧增加，数据库连接数量瞬间爆发，导致连接池满，后续需要对客户的这类操作进行详细记录，同时通过应用层面做些适当的限制措施避免大量重复点击操作等。

7. 应用代码的分析

由于时间关系，没来得及检查系统的所有源代码，以及是否有未关闭数据库连接的程序，所以针对如何导致连接池泄露的根本原因还无法查明，需要后续排查应用代码。

9. 应用调用数据库的模式

应用调用数据库使用的常连接，意味着即使用户没有在做业务的情况下，也一直不释放而占用着数据库连接的资源，也会影响别的用户访问数据库。

系统优化整改要求

根据连接池问题，系统优化整改要求如下：

1. 增加Apache上的最大连接数

由于应用调用数据库采用的常连接，确实很消耗连接数资源，因此本操作需要优先执行。

加大最大连接数到300，同时对连接池进行监控，设置报警阀值，当连接总数达到阀值后进行紧急处理，进行日志数据抓取，详见“5. 应急预案”。

阀值：Aqsiq 180 Xzblob 140

2. 大数据量操作的优化建议

由于无法获悉客户操作情况，因此不好判断一定就是客户对大数据量误操作导致的连接数急剧增加撑满了连接池，因此后续也需要针对这块进行优化整改，本操作需要优先执行。

对大数据量操作增加操作日志，以及对可能发生大数据量操作的程序进行以下优化。

收文查询打印功能限制最大打印数量（小于1000条），超过数量会在打印的文档最后输出“打印数量超过1000条请优化查询后再进行打印”；
收文查询记录查询日志，记录查询人、查询时间、查询sql等信息；
归档操作记录日志，记录归档人、归档时间、归档条数等日志；
对收文查询、归档操作实现屏蔽重复操作的功能（屏蔽双击或多次快速点击操作）。

3. 建议查看如下方法中的代码问题

检查系统的所有源代码，检查是否有未关闭数据库连接的程序。

可重点检查以下代码：

A) at com.ursa.acf.core.EncodingFilter.doFilter(EncodingFilter.java:46)
中doFilter(EncodingFilter.java:46)方法中的46行代码

B) com.ursa.acf.component.datasource.impl.StrutsDSManager.getConnection
(StrutsDSManager.java:107)
中getConnection（）方法中的107行代码

C) com.ursa.acf.component.datasource.DatabaseHelper.getConnection
(DatabaseHelper.java:42)
中getConnection(DatabaseHelper.java:42) 方法中的42行代码

4. 依据用户的应用使用习惯进行适当调整

鉴于应用调用数据库使用的“常连接”，意味着即使用户没有在做OA业务的情况下，也一直不释放而占用着数据库连接的资源，也会影响别的用户访问数据库。

因此建议应用开发方强制取消用户常连接，比如：每24小时，常连接中断。

5. Websphere应用服务器的优化

由于是32位的WAS平台，对于32位的操作系统，最多只能使用4G的内存，而且又由于JVM的特殊性，对于32的JAVA 虚拟机，它只用到2G内存，考虑到JVM本身的原因，最多又只能使用2G内存的75%，所以，对于32位的JVM的堆最大大小的设置，不要超过1.5G(1536M)，对于，上面的最大堆大小，建议改为1536 MB。

对于垃圾回收机制问题，一般在生产环境建议不要开启，因为开启这个功能，会进行垃圾的回收功能，会损耗JVM的资源，也会影响性能。所以建议最好【详细垃圾回收】不要开启，除非是需要进行GC问题的故障诊断功能，才需要开启该功能。

6. 升级WAS主机的操作系统及中间件

现网WAS主机部署的操作系统是32位，WAS中间件的位数也是32位。

建议如有可能，最好是安装64位的操作系统，同时也安装64位的websphere应用服务器中间件。尤其在应用访问数据库是基于常连接的调用模式的情况下，更耗系统资源。

7. 升级前端Apache分发机制的负载均衡功能

另外我们也认为前端Apache分发机制的负载均衡功能确实不尽如人意，2节点主机的连接数都达到200的极限值了，可故障发生当时另外一台主机1节点的连接数还不到120；很显然。基于Apache软件分发负载均衡的功能还是大大弱于类似F5等硬件负载均衡机制的。

主要有两个原因：

硬件负载均衡设备可根据连接数、后台服务器的负载压力判断实现真正的负载均衡；而Apache基本上是采用轮询的方式。
另外用apache、tomcat这种部署方式导致主分发节点成为了单点，一旦这个节点出现故障，整个系统就会瘫痪；而硬件负载均衡设备可以实现每个节点均可充当主节点，大大提升系统可靠性和高可用性。

如果系统采用了硬件负载均衡设备，两台应用服务器的连接数会保持均衡，比如都是160~170左右，应该可以规避10月27日下午发生的故障。

强烈建议：如系统后续有升级改造，在资金宽裕的情况下，采用硬件负载均衡设备。

应急预案

以后针对应用的类似问题，我方建议采用以下应急预案。

当主机的应用出现瘫痪的情况下，首先重启服务优先保证应用的持续运行，再进行故障诊断、排错及后续的优化。

因此需要建立相应的应急数据抓取机制，以便问题发生后可以对当时的运行情况进行分析找出问题根本原因，抓取的内容由各家联合统一进行分析。

数据抓取内容如下：

连接数抓取，用于分析数据库连接使用情况。
执行sql如下：
select username,machine,count(username) from v$session where username is not null and username <> 'SYS' group by machine,username order by machine
分别在数据库服务器1和2上执行。
应用服务器日志抓取，分析程序错误。当前日志保存5个历史文件，如有问题发生很有可能会大量产生日志，导致前面的日志被冲掉，所以需要加大日志保存的数量和时间。
数据库锁情况抓取。
应用服务器内存快照抓取，用于分析问题发生时系统正在运行的程序。
应用服务器内存、cpu使用情况抓取。

本文作者：李松桦（上海新炬王翦团队）

本文来源：“IT那活儿”公众号

数据库系统系统日志连接池 apache 连接数

文章转载自IT那活儿，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。