一次接到用户电话,说某个应用在并发量稍大的情况下就会出现响应时间陡然增大,同时管理控制台的响应时间也很慢,几乎无法进行正常工作。
赶到现场后,查看平台版本为Webshpere6.0.2.29,操作系统为Windows 2003企业版sp2,于是首先分析systemout.log,发现有如下报错:
= com.ibm.websphere.ce.j2c.ConnectionWaitTimeoutException Max connections reached 869
Exception = com.ibm.websphere.ce.j2c.ConnectionWaitTimeoutException
Source = Max connections reached
probeid = 869
同时也发现有“Caused by: java.io.IOException: Async IO operation failed, reason: RC: 10053 您的主机中的软件放弃了一个已建立的连接。”
很明显是连接池无法分配一个新连接给请求,wait时间过长达到WaitTimeout时间,第一反应是数据库连接池大小开的不够,于是设成初始50,最大150,120S空闲则自动释放连接。
但是调整参数后没有改善,过了不到10分钟应用依旧变慢。再次查看System.out和FFDC里的错误信息,发现有许多关于IO的报错:
com.ibm.ws.webcontainer.channel.WCCByteBufferInputStream 102
Exception = java.net.SocketTimeoutException
Source = com.ibm.ws.webcontainer.channel.WCCByteBufferInputStream
probeid = 102
stack Dump = java.net.SocketTimeoutException: Async operation timed out
java.io.IOException com.ibm.ws.webcontainer.servlet.RequestUtils.parsePostData 398
Exception = java.io.IOException
Source = com.ibm.ws.webcontainer.servlet.RequestUtils.parsePostData
probeid = 398
Stack Dump = java.io.IOException: Async IO operation failed, reason: RC: 55 指定的网络资源或设备不再可用。probeid = 1184
事后才知道其实数据库和中间件之间的问题,但是一来没有报连接池大小不够的错,二来此时管理控制台也几乎无法使用,又结合此应用在操作中会上传许多文件并进行校验,怀疑是服务器的I/O瓶颈导致应用变慢。
于是在服务器上开启性能工具,添加%Disk time、%Disk Write、%Disk Read、Disk Queue Length、Fage Fault等计数器。发现%Disk Time平均维持在20~70之间,瞬时的Disk Time会达到90多,而且Disk Read值很小,基本是Disk Write。
继续观察了一段时间,发现当磁盘读写下来后,应用还是很慢,于是分析内存回收情况,查看是否有内存泄漏发生。
用IBM Monitoring and Diagnostic Tools for Java? – Garbage Collection and Memory Visualizer分析发现 Mean interval between collections只有0.46分钟,且内存使用量才250多M就开始GC,而内存参数设置为760~1260M,于是分析内存中的碎片太多,导致GC频繁,使服务的响应速度变慢。同时分析软件得出The mean heap unusable due to fragmentation is estimated at 34.685%,问了应用他们申请内存对象一般是短期的,于是更改GC Policy为Gencon(分代并发),再观察GC日志发现每次回收间隔都较长,而且是young区的回收,Global collections间隔为23分钟。
可惜做了如此的性能优化,情况一点都未改善,在控制台的性能实时检测中可以看到JDBC连接有40~60个繁忙状态,当时无法确定这是否正常,是否是确实需要用到如此多连接。后来应用开发的检测数据库,发现很多active的连接时间长达5到10分钟,内容为一查询语句。原来应用是在Hibernat下开发的,查询语句被它加了自己的函数,导致原先建的索引无法起作用(应用建立索引的时候犯了低级错误),后来重新建立索引后,查询很快完成,连接池繁忙数量降低到0~5,应用恢复正常。原来是数据库的查询时间过长,导致线程都在等待数据库的返回信息,100个线程很快被用完,无法响应新的服务,因为数据库连接池资源已经开大,所以没有这方面的报错。
回顾这一周的排错过程,走了很大的弯路,当时因为经验欠缺没有想到做thread dump,如果做了thread dump的话,应该很容易看到大量的线程在等待数据库的返回,从而定位到数据库问题。
从中我们也看到,最终的问题也许很低级,但是排查的过程会很复杂,因为中间件问题牵扯到主机、网络、数据库、应用等各方面。不过得到的经验就是,在应用响应慢的时候,应该做个thread dump观察线程运行情况,而并非要等到hang住,cpu 100%,OutOfMemory的时候才想起分析javacore。