一次诡异的调优

最新推荐文章于 2022-11-26 14:09:15 发布

最新推荐文章于 2022-11-26 14:09:15 发布 · 177 阅读

文章标签：

#JDBC #网络应用 #DB2 #Loadrunner #多线程

java路上专栏收录该内容

24 篇文章

订阅专栏

最近碰到的一个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方面的大牛给点提示：）

结论