通过GC输出分析内存泄露问题

SIP5.0以后服务的请求量爆发性增长，因此也暴露了原来没有暴露出来的问题。由于过去一般一个新版本发布周期在一个月左右，因此如果是小的内存泄露，在一个月之内重新发布以后也就看不出任何问题。

因此这阵子除了优化Memcache客户端和SIP框架逻辑以外其他依赖部分以外，对于内存泄露的压力测试也开始实实在在的做起来。经过这次问题的定位和解决以后，大致觉得对于一个大用户量应用要放心的话，那么需要做这么几步。

1.       在GC输出的环境下，大压力下做多天的测试。（可以在 JAVA_OPTS增加-verbose:gc -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError）

2.       检查GC输出日志来判断是否有内存泄露。（这部分后面有详细的实例说明）

3.       如果出现内存泄露问题，则使用jprofiler等工具来排查内存泄露点（之所以不一开始使用，因为jprofiler等工具对于压力测试有影响，使得大压力无法上去，也使问题不那么容易暴露）

4.       解决问题，并在重复2步骤。

这里对SIP在jdk1.5和jdk1.6下做压力测试的GC 日志来做一个实际的分析对比，通过对比来大致描述一下如何根据输出情况能够了解应用是否存在内存泄露问题。（这里的内存泄露问题就是在以前blog写过的jdk的concurrent包内LinkedBlockingQueue的poll方法存在比较严重的内存泄露，调用频率越高，内存泄露的越厉害）

两次压力测试都差不多都是两天，测试方案如下：

开始50个并发，每个并发每次请求完毕后休息0.1秒，10分钟后增长50个并发，按此规律增长到500并发。

旧版本SIP是在JDK1.5环境下完成的压力测试，

新版本SIP的JDK版本是1.6，

压力机和以前一样，是10.2.226.40，DELL1950，8CPU，8G内存。

压力机模拟发出对一个需要签名的API不断的调用请求。

看看两个Log的具体内容（内容很多截取部分做分析）

先说一下日志输出的结构：(1.6和1.5略微有一些不同，只是1.6对于时间统计更加细致)

[GC [<collector>: <starting occupancy1> -> <ending occupancy1>, <pause time1> secs] <starting occupancy3> -> <ending occupancy3>, <pause time3> secs]

<collector>GC收集器的名称

<starting occupancy1> 新生代在GC前占用的内存

<ending occupancy1> 新生代在GC后占用的内存

<pause time1> 新生代局部收集时jvm暂停处理的时间

<starting occupancy3> JVM Heap 在GC前占用的内存

<ending occupancy3> JVM Heap 在GC后占用的内存

<pause time3> GC过程中jvm暂停处理的总时间

Jdk1.5 log：

启动时GC输出：

[GC [DefNew: 209792K->4417K(235968K), 0.0201630 secs] 246722K->41347K(498112K), 0.0204050 secs]

[GC [DefNew: 214209K->4381K(235968K), 0.0139200 secs] 251139K->41312K(498112K), 0.0141190 secs]

一句输出：

新生代回收前209792K，回收后4417K，回收数量205375K，Heap总量回收前246722K回收后41347K，回收总量205375K。这就表示100%的收回，没有任何新生代的对象被提升到中生代或者永久区（名字说的不一定准确，只是表达意思）。

第二句输出：

按照分析也就只是有1K内容被提升到中生代。

运行一段时间后：

[GC [DefNew: 210686K->979K(235968K), 0.0257140 secs] 278070K->68379K(498244K), 0.0261820 secs]

[GC [DefNew: 210771K->1129K(235968K), 0.0275160 secs] 278171K->68544K(498244K), 0.0280050 secs]

第一句输出：

         新生代回收前210686K，回收后979K，回收数量209707K，Heap总量回收前278070K回收后68379K，回收总量209691K。这就表示有16k没有被回收。

第二句输出：

         新生代回收前210771K，回收后1129K，回收数量209642K，Heap总量回收前278171K回收后68544K，回收总量209627K。这就表示有15k没有被回收。

比较一下启动时与现在的新生代占用内存情况和Heap使用情况发现Heap的使用增长很明显，新生代没有增长，而Heap使用总量增长了27M，这就表明可能存在内存泄露，虽然每一次泄露的字节数很少，但是频率很高，大部分泄露的对象都被升级到了中生代或者持久代。

又一段时间后：

[GC [DefNew: 211554K->1913K(235968K), 0.0461130 secs] 350102K->140481K(648160K), 0.0469790 secs]

[GC [DefNew: 211707K->2327K(235968K), 0.0546170 secs] 350275K->140921K(648160K), 0.0555070 secs]

第一句输出：

         新生代回收前211554K，回收后1913K，回收数量209641K，Heap总量回收前350102K回收后140481K，回收总量209621K。这就表示有20k没有被回收。



         分析到这里就可以看出每一次泄露的内存只有10几K，但是在大压力长时间的测试下，内存泄露还是很明显的，此时Heap已经增长到了140M，较启动时已经增长了100M。同时GC占用的时间越来越长。

后续的现象：

         后续观察日志会发现，Full GC的频率越来越高，收集所花费时间也是越来越长。（Full GC定期会执行，同时局部回收不能满足分配需求的情况下也会执行）。



[Full GC [Tenured: 786431K->786431K(786432K), 3.4882390 secs] 1022399K->1022399K(1022400K), [Perm : 36711K->36711K(98304K)], 3.4887920 secs]

java.lang.OutOfMemoryError: Java heap space

Dumping heap to java_pid7720.hprof ...



         出现这个语句表示内存真的被消耗完了。

Jdk1.6 log：



启动时GC的输出：

[GC [PSYoungGen: 221697K->31960K(229376K)] 225788K->36051K(491520K), 0.0521830 secs] [Times: user=0.26 sys=0.05, real=0.05 secs]

[GC [PSYoungGen: 228568K->32752K(229376K)] 232659K->37036K(491520K), 0.0408620 secs] [Times: user=0.21 sys=0.02, real=0.04 secs]



第一句输出：

         新生代回收前221697K，回收后31960K，回收数量189737K，Heap总量回收前225788K回收后36051K，回收总量189737K。100%被回收。



运行一段时间后输出：

[GC [PSYoungGen: 258944K->2536K(259328K)] 853863K->598135K(997888K), 0.0471620 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]

[GC [PSYoungGen: 259048K->2624K(259328K)] 854647K->598907K(997888K), 0.0462980 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]



第一句输出：

         新生代回收前258944K，回收后2536K，回收数量256408K，Heap总量回收前853863K回收后598135K，回收总量255728K。680K没有被回收，但这并不意味着就会产生内存泄露。同时可以看出GC回收时间并没有增加。



在运行一段时间后输出：

[GC [PSYoungGen: 258904K->2488K(259264K)] 969663K->713923K(1045696K), 0.0485140 secs] [Times: user=0.16 sys=0.01, real=0.04 secs]

[GC [PSYoungGen: 258872K->2448K(259328K)] 970307K->714563K(1045760K), 0.0473770 secs] [Times: user=0.16 sys=0.01, real=0.05 secs]



第一句输出：

         新生代回收前258904K，回收后2488K，回收数量256416K，Heap总量回收前969663K回收后713923K，回收总量255740K。676K没有被回收，同时总的Heap也有所增加。

         此时看起来好像和1.5的状况一样。但是查看了一下Full GC的执行还是400-500次GC执行一次，因此继续观察。



运行一天多以后输出：

[GC [PSYoungGen: 257016K->3304K(257984K)] 1019358K->766310K(1044416K), 0.0567120 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]

[GC [PSYoungGen: 257128K->2920K(258112K)] 1020134K->766622K(1044544K), 0.0549570 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]



可以发现Heap增长趋缓。



运行两天以后输出：

[GC [PSYoungGen: 256936K->3584K(257792K)] 859561K->606969K(1044224K), 0.0565910 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]

[GC [PSYoungGen: 256960K->3368K(257728K)] 860345K->607445K(1044160K), 0.0553780 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]



发现Heap反而减少了，此时可以对内存泄露问题作初步排除了。（其实在jdk1.6环境下用jprofiler来观察，对于concurrent那个内存泄露点的跟踪发现，内存的确还是会不断增长的，不过在一段时间后还是有回收，因此也就可以部分解释前面出现的情况）



总结：

         对于GC输出的观察需要分两个维度来看。一个是纵向比较，也就是一次回收对于内存变化的观察。一个是横向比较，对于长时间内存分配占用情况的比较，这部分比较需要较长时间的观察，不能仅仅凭短时间的几个抽样比较，因为对于抽样来说，Full GC前后的区别，运行时长的区别，资源瞬时占用的区别都会影响判断。同时要结合Full GC发生的时间周期，每一次GC收集所耗费的时间作为辅助判断标准。

         顺便说一下，Heap的 YoungGen,OldGen,PermGen的设置也是需要注意的，并不是越大越好，越大执行收集的时间越久，但是可能执行Full GC的频率会比较低，因此需要权衡。这些仔细的去了解一下GC的基础设计思想会更有帮助，不过一般用默认的也不错。还有就是可以配置一些特殊的GC，并行，同步等等，充分利用多CPU的资源。

         对于GC的优化可以通过现在很多图形工具来做，也可以类似于我这样采用最原始的分析方式，好处就是任何时间任何地点只要知道原理就可以分析无需借助外部工具。原始的总是最好的^_^。

评论

14 楼 fantaxy025025 2009-04-21  

楼上能否详细介绍一下：
在Tocat启动加入-XX:...的位置

当系统崩溃时，记录的文件在哪个目录，文件名字是什么

13 楼 willpower 2008-10-29  

disorder 写道

我最近也在找一个项目的内存泄漏问题，毫无头绪，哪位能否介绍一下如何才能发现是程序的哪里出现了内存泄漏？

如果真是内存泄漏，系统最终会抛OutOfMemory, 加这个-XX:+HeapDumpOnOutOfMemoryError (jdk1.5以上)可以得到heap dump. 这个dump纪录了所有在OutOfMemory时存在于内存中的对象。用普通的jhat之类的工具分析dump文件不够好。推荐使用SAP Memory Analyzer。用这个工具你可以比较快的定位原因。

不要说dump没用，dump里面提供了足够的信息。只是看你怎么利用它，分析它。

12 楼 disorder 2008-10-28  

我最近也在找一个项目的内存泄漏问题，毫无头绪，哪位能否介绍一下如何才能发现是程序的哪里出现了内存泄漏？

11 楼 willpower 2008-10-28  

既然有dump文件了，应该就可以找到原因了。

dump当然不会很直接的告诉你root cause,
但是通过分析dump文件应该可以把问题缩小，然后看相应的代码，问题就能解决。

我不知道你们用不用一个叫做SAP Memory Analyer的工具。非常好用（至少比jhat好太多）。
如果没用过，强烈推荐。

10 楼 biubiu 2008-10-28  

GC log只能告诉你有没有内存泄漏，不能告诉你哪儿有内存泄漏。

生产环境中加入GC log还是不错的选择，对性能没有影响，又可以快速知道有没有内存泄漏。

9 楼 WhisperXD 2008-10-27  

zeelong2 写道

这个方法太理想化了，实际环境下不很实用。

PS:目前我也正在找一个项目的OUT of Memory,基本上分析Dump文件没什么用，抓狂中......各位有啥其他好方法可以晒晒

netbeans or jprofiler 吧 

楼主这个是用来判断有没有OOM的 ，使用gc看输出主要是为了模拟高并发下的情况，查找是否有微量内存泄露，具体排查还是得一点一点的来啊。。

8 楼 zeelong2 2008-10-27  

这个方法太理想化了，实际环境下不很实用。

PS:目前我也正在找一个项目的OUT of Memory,基本上分析Dump文件没什么用，抓狂中......各位有啥其他好方法可以晒晒

7 楼 ddbird 2008-10-26  

引用

        
对于GC的优化可以通过现在很多图形工具来做，也可以类似于我这样采用最原始的分析方式，好处就是任何时间任何地点只要知道原理就可以分析无需借助外部工具。原始的总是最好的^_^。

你现在贴的这个日志只是非常笼统的统计了几个内存区域的情况，只能看个大概的，如果真有内存泄漏，你能用这个日志找出来？ 另外，图表也是基于原始数据的，表现形式不同，还可以加上一些分析判断逻辑，方便很多，效率更高。“原始总是最好的”--绝对不敢苟同。

6 楼 hallywang 2008-10-24  

g9394 写道

你遇到的是最理想的情况,但有时候,这种方法不能找到原因,只找到造成崩溃的点.就好比,一个HTTP 请求,没有设置超时(对不起,默认是不超时,不知道为什么SUN要这样设定),然后这条线程就卡在这里了,然后,这条线程里的一个堆栈被另一条线程放入内容,本来这些内容就是要这条闲线程去处理的,但是现在,这条线程卡住了,但是用你说的这种方法,绝对找不到造成内存泄露的原因是因为http不超时,一直卡在那里.

http默认不超时吗？试试看

5 楼 robbin 2008-10-24  

我还有一个笨办法做精细的内存分配比较：就是定期用pmap命令dump出来JVM进程的内存映射表，然后diff。

4 楼 becool 2008-10-24  

可以试一下jmap和jhat

3 楼 zhaobohao 2008-10-24  

学习了.......

2 楼 nihongye 2008-10-24  

cenwenchu 写道

又一段时间后：

[GC [DefNew: 211554K->1913K(235968K), 0.0461130 secs] 350102K->140481K(648160K), 0.0469790 secs]

[GC [DefNew: 211707K->2327K(235968K), 0.0546170 secs] 350275K->140921K(648160K), 0.0555070 secs]



第一句输出：

         新生代回收前211554K，回收后1913K，回收数量209641K，Heap总量回收前350102K回收后140481K，回收总量209621K。这就表示有20k没有被回收。



         分析到这里就可以看出每一次泄露的内存只有10几K，但是在大压力长时间的测试下，内存泄露还是很明显的，此时Heap已经增长到了140M，较启动时已经增长了100M。同时GC占用的时间越来越长。

只能推断这20k的内存从新生代迁移到老(tenured)代，可以打开tenured的回收日志。

1 楼 cenwenchu 2008-10-24  

g9394 写道

你遇到的是最理想的情况,但有时候,这种方法不能找到原因,只找到造成崩溃的点.就好比,一个HTTP 请求,没有设置超时(对不起,默认是不超时,不知道为什么SUN要这样设定),然后这条线程就卡在这里了,然后,这条线程里的一个堆栈被另一条线程放入内容,本来这些内容就是要这条闲线程去处理的,但是现在,这条线程卡住了,但是用你说的这种方法,绝对找不到造成内存泄露的原因是因为http不超时,一直卡在那里.

我上面提到的仅仅是检查内存泄露的一种方式，至于资源死锁，或者hold，那么就需要其他方式来看，包括top , kill -3等等各种方式，没有任何一种方式是万能药，要不然就不会有那么让人抓狂的问题了。^_^，也欢迎将你遇到的问题以及解决的方法说一下，这样起码会让很多人少走弯路，少浪费宝贵的时间，在我看来时间是用来学习的，抓虫虽然也是一种学习，不过成本可能比较高。