情况如下:
某服务,在测试环境测试的时候整个响应过程也就0.5s左右,测试环境和生产环境axis2版本一致,tomcat版本一致,但是生产环境需要差不多20S。
后来,越来越慢,导致服务一起来,整个生产环境的CPU负载长期超过200%,响应超时2分钟,生产环境OSB大面积报错。并且由于CPU负载过高,导致此axis2容器下的其他服务均不能正常执行。
开始着手解决问题:
第一步当然是重启大法,重启tomcat服务,仍然不行,此服务响应刚开始能做到20S,但是慢慢的就开始变慢,半小时后,响应超过两分钟,超时。
并且奇怪的是服务一启动,CPU负载立马超过100%。(真是心都凉了!!!!!!)
开始思考:
1.由于业务逻辑是交由数据库处理的,java代码部分只负责数据的传递,考虑业务处理部分的代码逻辑问题。
2.考虑网络传输时间问题。
3.考虑环境差异问题。
针对问题1,查看了数据库的死锁情况,的确发现该部分逻辑对应的某张表发生了死锁现象,于是先kill该部分进程,并在update之后都加入commit动作。(当时想的是如果commit还不能解决,就把这个存储过程设为自治事务处理。)幸运的是,做了commit,之后,情况暂时好了很多,至少在kill进程之后,开始响应OSB了。
问题2,数据反馈封装的包也就1Kb左右,生产环境之间都是用的光纤,且该axis2容器其他部分的对接OSB服务的响应少于100MS,故排除。
问题3,tomcat版本和测试环境一致,axis2版本与测试环境一致。jdk都是1.6版本,生产环境系统32位,测试环境64位,但是我觉得即使系统性能应该没有问题,毕竟其他服务都是OK的。
。。。。。。
于是加入时间戳,开始判断是否由于程序处理过慢导致的问题。
通过时间分析发现,业务逻辑处理部分其实也就花了不到1s的时间,并且业务处理的开始时间就是OSB系统的触发时间。
也就是说,20S的总时长,除去程序处理的1s,剩下的19s都花在了return之后的部分,排除网络传输的时间问题,那么到底这19s的时间axis2在干嘛?
。。。。。。
陷入僵局,开始谷歌找资料。
。。。。。。
思路1.
的确查找到某个线程占用CPU过高的现象,但是没找到具体原因,大概是跟GC有关系,遂放弃。
思路2。axis2响应超时的路子,经过查证,排除。相关资料自行谷歌。
思路3。查看tomcat的catalina.out文件,发现大量内存泄露的异常
参考:Tomcat6.0的Thisisverylikelytocreateamemoryleak异常
但是,文档提到的方案1和方案2上头不允许采取,方案3无实际意义,和大神讨论之后放弃此思路。
思路4.本地用soapui调用了生产环境的wsdl,响应时间18000ms。确定不是tomcat到OSB系统的数据传输问题。
思路5.要不,重构一遍?
开玩笑,刚上线的代码,太打脸了。
功能人员和我的内心都是拒绝的,并且时间不允许,但是测试环境又没有任何问题,我拒绝是代码的问题。
。。。。。。。
不过也只能从代码层去思考问题了,既然花在了return上面,那么就从rerurn返回的数据结构开始查找吧。
(return部分的数据结构是遗留代码,并且询问遗留此代码的人员之后,得到的建议是此段代码尽量不要动,是当初客户端的系统直接提供的封装好的代码,改出过问题。)
不过查找代码也不是没有收获,里面看到了大量的synchronized
public synchronized boolean equals(java.lang.Object obj) {
//。。。
}
一看这就是通过工具生成的代码嘛。
并且老实说,synchronized这个东西我不熟,没用过,于是查资料。
找到以下一些资料
为什么用synchronized修饰的代码块里的代码执行的比普通代码慢?
应该 被synchronized 修饰的方法 是线程安全的,一次只能被一个线程使用,所以 相对其他方法 就慢!
关于程序加锁自己的一点见解: 建议程序中尽量不要加锁;
尽量在业务和代码层,解决线程安全的问题,实现无锁的线程安全;
如果以上两点都做不到,一定要加锁,尽量使用java.util.concurrent包下的锁(因为是非阻塞锁,基于CAS算法实现,具体可以查看AQS类的实现);
如果以上三点仍然都做不到,一定要加阻塞锁:synchronized锁,两个原则:(1)尽量减小锁粒度;(2)尽量减小锁的代码范围;
synchronized可能造成死锁。
Java Web 服务,第 3 部分: Axis2 数据绑定
不过,验证对性能具有很大的影响(正如您在下一篇文章中将看到的,即使不对每个文档调用 validate(),XMLBeans 也已经非常慢了)
内心一喜,删除所有的冗余代码,重新打包丢生产开始测试。
然并卵,仍然20S。
绝望。。。
我是成功的分割线
大神打开生产环境的wsdl服务地址,浏览器响应特别慢,我开始认为是因为生产环境cpu负载过高的问题,然而他打开其他的wsdl服务地址都特别快,于是决定从这里下手。
但是测试环境又特别快。
打开wsdl服务地址需要差不多6S,刷新一次也需要差不多6S。(我猜测是不是三次握手18秒再加程序处理1S这不刚好就凑齐了20S),于是确定是程序本身的问题。
最后,大神看了一眼axis2下的其他aar包都只有几十KB,而问题服务的包却高达5M,问我为啥这么大?
我说里面导入了很多jar包啊,并且有个叫axis的包。
大神看了一眼,说,会不会是jar包冲突啊?容器是axis2的。要不,干掉他?
我说,不要啊,我以前干掉这些jar包直接扔测试环境,过不去啊,报各种axis相关的错误啊。
大神说,试一试嘛。
于是就把纯class生成的aar,不包含任何jar包的aar扔到了测试环境。
我觉得要崩,服务起不来。
麻溜儿的重启进入tomcat,打开axis2服务列表,该服务好好的躺在那里。点开,正常。
我当场就懵逼了。
大神淡定的说了一句,他删除的冗余代码里面有很多类似这样的东西
public static org.apache.axis.description.TypeDesc getTypeDesc() {
return typeDesc;
}
我嘞个大X。
于是把这个aar直接丢生产,用soapui测试,第一次反馈仍然是17000ms,我对大神呵呵一笑。
大神不服,说,你再试一下。
第二次反馈,300ms。
WTF???
ok,确定了问题,就是那些冗余代码中的锁和axis包共同引起的。
结论:
1.代码中大量的synchronized导致某个线程锁,于是jstack看到某个线程占用CPU高达50%找到原因。
2.代码中的xmlbean和synchronized验证导致return之后的过程变慢。
3.怀疑axis和axis2同时存在的情况下有一定的阻塞或者冲突。
4.为什么在测试环境里面能保证1S以内,因为测试环境的axis2没有负载那么多active的服务。