【IT168 评论】1.起因

　　前段时间在做一个消息平台的二期开发工作，该平台支持着某领域的不少重要应用，要求要有比较高的性能，但是在二期开发完成后的性能测试中出现比较严重的性能问题，其表现为响应速度时快时慢，TPS(每秒事物数)和请求响应时间成波动性，并且波动较大，低谷处TPS甚至降到10以下，高峰时可以达到60以上，因此决定查找性能问题，进行性能调优。本文将我调优的过程记录下来，分享给大家。

　　2.过程

　　2.1观察日志

　　首先观察日志，查看在波动点上程序发生了什么。在日志中发现TPS低谷的那段时间处每秒的相应个数明显少了很多，再仔细看日志的打印并不是持续的，而是大概每隔1到2秒的时间系统就会卡住0.6秒左右的时间，排除这部分时间，系统处理速度还是比较快的，检查这段空闲时间的日志周围并没有太多的规律，执行的代码逻辑并不是非常固定，甚至在相邻两个get方法中间都会停止0.6秒，因此排除是这附近代码的问题，怀疑是内存的原因，在这段时间内进行了频繁的GC，从而影响了系统的处理速度。

　　2.2本机内存情况监控

　　我的环境是linux java1.6u16 tomcat6，而服务器的环境是win server jdk1.4 resin,有一些不同，但还是要在本机调试比较方便，而且java1.6提供了比较好的内存监控工具jvisualvm可以方便的查看内存情况，其位置是在jdk的bin目录下面，双击运行。

　　经过一番监控，发现并发测试开始后，堆内存不停的上涨，涨到接近堆内存最大值也基本不释放，保持一个超负荷状态，因此调高tomcat的内存分配为JAVA_OPTS='-Xms512m -Xmx1024m'‘默认好像是双128)，但情况依旧，在内存堆积的时间段内系统响应速度变慢，不少时间都被用来执行GC，也就导致了LR测试所形成的波谷图形，此时如果执行jvisualvm的GC功能，内存立刻被大量回收，响应速度也立刻变快，TPS恢复到最大值，可以确认是有内存泄露无法正常回收，此时查看系统对象使用情况，发现系统的日志缓存对象LogObjectBean的个数不断增加，达到几百万个，从不被回收，因此可以确定是此类的内存泄露导致的。

　　2.3使用池技术减少大量日志对象生成的消耗

　　日志模块为了减轻数据库的压力会缓存一部分LogObjectBean之后每隔一段时间一次性将日志写入数据库，因此有一部分日志对象未被回收是正常的，但是经过一番程序的调整后LogObjectBean的增加速度减慢但还是不停的涨，而日志模块的代码较繁琐，不好改。因此我决定使用池技术，将LogObjectBean使用后状态初始化，扔回到池中，后来的需要的日志对象也不需要new，而是直接从池中取得，如果不够的话池会自动新建，这里使用了apache commons pool，很容易的完成了这个逻辑，最终效果在100个并发下LogObjectBean稳定在6000个左右，不停的从池中借出，用完后再放回，这块就算稳定下来了，再经过一些JVM参数调整，在我的电脑上的短时间测试中，堆内存虽然会涨到95%左右，但大部分内存会在GC时立即回收，因此将程序移到服务器上做长期测试，但是很遗憾的是，服务器上效果依旧不好，只比调整前稍微好一点。

　　2.4JDK更换

　　这时由于在我的电脑上效果还可以，而在服务器上效果比较差，因此怀疑是服务器上的低版本JDK可能GC的效果比较差导致的，所以将服务器的JDK版本改为1.6,这样也可以进行内存监控，但是启动时缺发现resin不支持jdk1.6，无法启动……换回jdk1.4后也可以用jdk1.6的jvisualvm监控，但是只能看到堆内存使用情况的图形，无法看到具体类的实例个数等信息。最终我决定更换更快的Jrockit JDK1.4.2，他提供更快的性能，并且有很好用的内存监控工具JMC。替换之后测试效果良好，TPS甚至提高到了90以上，图形虽然有个别低谷状态，但是波动很小。然而，并没有这样结束，失败的请求个数确大大增加了，而且都是在那一点低谷中批量失败的，这种情况每小时大约出现4到5次，经检查日志，发现这段时间resin自动重启了……