一次性能调优实战记录

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自动重启了……
2.5使用JMC寻找内存泄露
    resin中没有显示出有内存溢出的日志，但是出现自动重启的原因应该是resin检测到内存使用达到一定限度的自我保护机制，而TPS的提高只能归功于JRocket出色的性能了,在接近堆内存最大值的情况下频繁GC依然保持系统的高速运转，确实是厉害。但是我们的程序还是有内存泄露的问题，要彻底解决才行。
    Jrocket安装好后会附带JMC，它是我见过的最好的内存监控工具，比jvisualvm以及JProfile都要好，而且BEA被Oracle收购后JMC的功能似乎已经没有使用限制了，而且许可也公开了出来，我这里是3.0版。

    使用JMC进行内存实例监控如上图。这是系统刚跑不久的实例情况，随着系统跑的越来越久前面几项都会不停的涨，GC掉的实例数非常少，也是内存泄露的原因所在，而LogObjectBean经过优化后偶尔会超过1W，大多数时候都保持在6100，不是内存泄露的原因。
    首先最前面的char[],byte[],String是jdk中的基本类，其中char和String实例个数是涨的最快的也是最多的，resin重启前char占了将近300M的内存空间，而且基本上实例个数差不多，涨幅也基本一致，也就是说char的增长大都由String泄露引起，虽然char占到了内存使用的40％，但是String才是char使用的根本原因，这个时候追踪String的使用情况，JMC可以轻易的监控一个对象被别的类引用的情况，以及被方法调用的情况。
    监控String的使用：

    从上图看出，开发人员自己写的一个BeanUtil的CopyBeanToBean方法生成了大量的String，达到了200多W个，检查这个方法，该方法是利用反射遍历SubMessage类里所有属性的get 方法，再invoke 遍历LogObjectBean的所有set方法给他赋值，生成新的日志对象，而SubMessage的属性有20个左右，每次都要执行subString方法截取方法名，加起来每次调用要生成将近40个String，每个String就是一个char[]，执行该方法非常的消耗，而bean的拷贝已经有非常多成熟的工具，因此直接替换为apache commons-bean的PropertyUtils.copyProperties(logObj,subMessage);
    替换后的效果：

生成的String和char[]明显少了，然而，经过长时间的测试，内存还是有泄露现象，并没有解决根本问题。
    这时候注意到系统中最常用的SubMessage类，该类是对请求报文和结果报文的封装，如果该类没有被释放，自然会导致其内部大量的string和其他相关对象都不会被GC掉。
    彻底检查代码中SubMessage的使用，仔细检查过几遍后还是没有发现SubMessage有没释放掉的地方，只改掉一个多余的SubMessage的clone后再测试，问题依旧。
    这样，最不大可能不释放资源的类MessageDispatchThread，也就是业务逻辑主线程类，成了唯一的可能。
2.6问题锁定线程池
    照常理说，一个线程跑完后资源自然会释放，如果使用线程池的话，线程回到池中时也会释放掉之前使用的所有资源，因为他的run方法已经跑完了，而且我们使用的线程池是JDK5.0的并发包的前身也就是Doug Lea教授的并发包jdk1.4编译的版本，有着广泛的应用，应该不会有这么明显的线程执行完毕还资源不释放的bug。
    我在MessageDispatchThread的finally最后打印出“第N条线程执行完毕“的日志，日志里显示确实所有的线程都执行完毕了，再仔细检查线程池使用的代码，似乎也没有什么特别的，试着更改setKeepAlive方法，更改活动线程的存活时间似乎也没有用……
    然而将线程池的执行线程的方法去掉，直接让线程start，所有的问题都解决了，程序非常良好的运行，完全没有内存泄露情况出现，String和char[]也很好的被GC回收了。

    系统终于稳定了下来，但是不使用线程池还是会增加系统的开销，降低性能，因此还是要找出根本原因，这时候想到以前学习concurrent并发包的线程池的时候记得一句话：他的线程池可以执行实现了Runnable接口的线程，以前看他的源代码，入参是Runnable接口。确实，目前系统的线程池的使用与我之前的用法唯一不同就是MessageDispatchThread是继承自Thread实现的线程，而我以前写过的都是implements Runnable。虽然说继承Thread和实现Runnable得到的线程只是Thread提供了更多的功能，按理说运行机制应该没什么不同，但是我将MessageDispatchThread改为implements Runnable后，问题居然就解决了，也就是说继承Thread的线程，在交给jdk1.4并发包的线程池执行完毕后并没有被释放资源，而且也没被再利用，而是白白占着内存，导致内存泄露。导致这样的具体原因可以看下面的讨论http://www.iteye.com/topic/263928?page=1。简单的说就是JDK1.5之前的Thread初始话的时候就会将自己添加到thread group中，在执行完start后再释放自己的资源，如果是执行他的run方法，那么就不会从thread group中拿掉，导致内存泄露，而Doug Lea的并发包里的线程池就是执行的线程的run方法。也难怪我本机的JDK1.6不会出现泄露。
3.总结：
    从JMC的第一张监控图上其实就可以看出MessageDispatchThread可能会有问题，但是一个线程在一个成熟的线程池管理下会出现泄露情况确实有些出乎意料，虽然走了些弯路，但是还是优化了其他相关模块的代码。
    最后调优的效果是在单台普通服务器上(或者说配置好一点的电脑)LR的100并发下TPS从60波动提高到了90以上稳定，300并发仍然可以290的TPS，500并发最高也能到450的TPS，极大的提高了系统性能。

评论

16 楼 strawbingo 2010-09-13  

很棒的文章，谢谢共享这么好的调优经验

15 楼 gqlzhw 2009-11-12  

我还没来及平精华就变成良好贴了，来晚了。
真好，希望多点这种实战贴。

14 楼 sesame 2009-10-21  

不错~  提个建议，测试环境和开发环境最好一样，这样可以少走很多弯路！ linux 和windows jdk的就不同，更不用说windows和linux不一样~.

13 楼 sunrie 2009-10-10  

学到东西了，线程方面确实容易出问题啊！

12 楼 Max_1106 2009-10-08  

你太幸福了啊
还有测试MM帮你跑性能测试呀
我们这里开发测试都是开发人员一条龙搞顶的哟，当然也包括性能测试

11 楼 gjhohj 2009-10-07  

不错.很专业啊

10 楼 beckrabbit 2009-10-03  

香克斯 写道

新版JDK跑旧代码会不兼容?

不同JDK个别地方实现的方式不一样，你可以把JDK1.4的src.zip里面的Thread和JDK1.6里的代码比较一下

9 楼 beckrabbit 2009-10-03  

deeplives 写道

beckrabbit 写道

1.起因
   其表现为响应速度时快时慢，TPS（每秒事物数）和请求响应时间成波动性，并且波动较大，低谷处TPS甚至降到10以下，高峰时可以达到60以上，

你好，我比较菜，想请教一下你是如何从第一张图得出这些数据？ 你又是用什么工具来监控tps 数量呢？
谢谢！

测试MM的Load Runner跑出来的:)

8 楼 deeplives 2009-10-03  

beckrabbit 写道

1.起因
   其表现为响应速度时快时慢，TPS（每秒事物数）和请求响应时间成波动性，并且波动较大，低谷处TPS甚至降到10以下，高峰时可以达到60以上，

你好，我比较菜，想请教一下你是如何从第一张图得出这些数据？ 你又是用什么工具来监控tps 数量呢？
谢谢！

7 楼 香克斯 2009-10-03  

新版JDK跑旧代码会不兼容?

6 楼 seele 2009-10-02  

codeutil 写道

你用的什么版本不支持jdk1.6？

Linux+jdk1.6 update18 +Resin3.0.x在生产环境跑的很快很好。

二期开发...

代码不一定兼容.

5 楼 beckrabbit 2009-10-02  

codeutil 写道

你用的什么版本不支持jdk1.6？

Linux+jdk1.6 update18 +Resin3.0.x在生产环境跑的很快很好。

resin吗 好像也是3点几的，我记得启动时候日志里说什么required java version 1.6之类的无法启动，就没有多研究，直接考虑别的方案了

4 楼 codeutil 2009-10-02  

你用的什么版本不支持jdk1.6？

Linux+jdk1.6 update18 +Resin3.0.x在生产环境跑的很快很好。

3 楼 beckrabbit 2009-10-02  

ximenpiaohua 写道

为什么不用JMS处理日志呢？这样不是更简单，还能达到你要的效果
我觉得比较怪，当然和你探讨的问题没关系。

因为二期系统是在一期的基础上做的，直接记录数据库已经可以满足要求了，就没有做太大的改动：）

2 楼 ximenpiaohua 2009-10-02  

为什么不用JMS处理日志呢？这样不是更简单，还能达到你要的效果
我觉得比较怪，当然和你探讨的问题没关系。

1 楼 dennis_zane 2009-10-01  

doug lea的并发包直接调用的是run方法，哪怕你传的是Thread。而默认的Thread本身初始化在1.4是将自己加入了一个ThreadGroup，如果你没有调用它的start方法，JVM不会在该线程结束后将这个thread从TreadGroup中移除，这就是造成内存泄露的原因所在。不过在JDK6上，将加入ThreadGroup这个操作从构造函数转移到了start方法，避免了这个问题。这个也提醒我们，实现接口总比继承好:D