西安航天三沃:一次WebSphere性能问题诊断过程|IT168 技术开发

    赶到现场后，查看平台版本为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。