最近碰到的一个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真不会用...