记一次生产环境axis2服务特别慢的问题。

时间:2022-10-11 20:02:12

情况如下:

某服务,在测试环境测试的时候整个响应过程也就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.

一个Tomcat高CPU占用问题的定位

生产环境下JAVA进程高CPU占用故障排查

的确查找到某个线程占用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 修饰的方法 是线程安全的,一次只能被一个线程使用,所以 相对其他方法 就慢!

关于synchronized锁和Spring事务

Java多线程总结之由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的服务。