一次诡异的调优

最近碰到的一个Java应用，费了半天劲还是没定位到是哪儿的问。发上来给大家看看，给点建议。

 

环境

• DB Server：32core HPUX DB2
• App Server * 2：8core HPUX WAS6.1 每个节点2个app

初次测试现象

• WAS，DB2CPU均上不去，CPU、内存、磁盘、网络等都正常。
• 从loadrunner报告来看，有两个用例很奇怪，在16/24/50用户下，呈线性增长。根据经验，这两个用例可能存在资源争用，造成串行的地方。
• 检查DB2，正常，语句执行都很快，部分用例有锁，但与造成问题的两个用例无关。

第一次尝试：初步定位是WAS的问题，针对WAS进行排查。

• 关闭WAS应用打印的日志（据观察有System.out），刚开始有往外打印东西，量不大，但是很频繁，一秒钟大概几十条，无效。
• 调整WAS监控日志为error，避免过多信息。无效。
• 后减少用户数，使用1个用户长时间跑，发现那两个用例依旧随时间线性增长。说明问题不是因为资源争用，更可能是程序问题。
• 检查WAS中的Apache，配置正常，返回页正常。

第二次尝试：定位应用程序哪块的问题

• 因为WAS跑在HPUX上，使用HPjmeter跟踪线程状态，发现线程在IO上等待事件非常高。而程序占用IO最多的地方就是数据库连接。
• 打印线程堆栈，发现大部分线程阻塞在SocketRead上。证明了HPjmeter IO占用高。
• SokcetRead阻塞，可能以下几个地方有问题：数据库（很值得怀疑，但从数据库监控看，没有问题），网络（内网环境，这个应该也不会有问题），操作系统IO部分。

第三次尝试：针对SocketRead定位问题

• 更新WAS所带JDK，无效。（JDK OK）
• 更新操作系统IO部分最新Patch，无效。（OS IO OK）
• 更新WAS的JDBC驱动，无效。（JDBC OK）
• 把WAS和DB放在同一台机器上，无效。（网络 OK）
• 通过WAS监控，其中JDBC Time很短（间接也说明了数据库正常），但是UseTime很高（是JDBC Time的100倍+）。
• 程序除了这两个用例外，其他用例均正常。

悬而未决：问题到这，进了死胡同了。也没有更好的想法。

• Use Time、JDBC Time、SocketRead的矛盾。
  • JDBC Time=JDBC处理时间+网络时间+数据库处理时间。JDBC Time应该包括了JDBC的SocketRead的时间。但是JDBC Time很小，而程序阻塞在SocketRead上。
  • Use Time=连接分配到连接归还的时间差=n*JDBC Time（在整个连接分配到归还之间的所有JDBC请求）+业务逻辑处理时间。
  • Use Time与JDBC Time差距很大，而且JDBC Time很小，能解释的话，第一种原因，就是在整个UseTime中有大量的JDBC请求，但是从这个业务看，不会有100倍那么多。
  • 第二种原因，是“业务逻辑程序处理时间”占用了很多。这个是有可能的，而且程序编写的bug也能说明为什么在1个用户的时候，用例执行时间也程序线性。但是，程序最耗时的地方出现在JDBC的SocketRead上，而JDBC Time又未反应出这部分的时间。
• 什么造成了SocketRead阻塞
  • 这个问题一直没有弄清楚，在数据、网络都正常的话，Socket不应该阻塞
• WAS的Java堆调整。这个问题是在调整WAS时碰到的。
  • WAS个人不是太熟，但是从一般JVM调整来说，基本是类似的，但是这次在WAS上碰到的问题也很诡异。
  • WAS堆之前配置是1560m，当调整为2048m后，用例的执行时间时间反而变长了。WAS堆之前配置是1560m，当调整为1024m后，用例的执行时间时间也变长了。很神奇的问题，程序执行速度一般取决于CPU和IO，内存影响很小，特别当内存足够的情况下。即便内存有影响，两个不同方向的调整居然能得出同样的结果，很令人费解。
  • 不知道是否有WAS方面的大牛给点提示：）

结论

• 应用应该是有问题的，但是更细的东西或许只有看到代码才知道
• WAS真不会用...

评论

3 楼 floating 2012-01-08  

我碰到过几次和楼主比较接近的情况，就是SocketRead成为性能的瓶颈。通过heapdump和coredump的分析，都是由于应用的处理方式与应用服务器与数据库服务器之间的防火墙的安全策略不匹配导致的。楼主能贴一段值得怀疑的headdump和coredump的片段出来分析分析吗？

2 楼 和你在一起 2010-10-25  

@kimmking
不是GC，执行用例都是在压力不大的情况下进行的。

kimmking 写道

WAS堆之前配置是1560m，当调整为1024m后，用例的执行时间时间也变长了。



GC??

1 楼 kimmking 2010-10-24  

WAS堆之前配置是1560m，当调整为1024m后，用例的执行时间时间也变长了。



GC??