java jvm内存管理/gc策略/参数设置(二)

1.GC的类型以及对应日志的解释

http://www.iteye.com/topic/603347

在大型的java运用中，要进行程序调优，指定一个合适的垃圾回收机制是必不可少的，那如何可确定某gc是否使得程序最优化呢？我们可以查看jvm打印出的gc日志来分析，并做出进一步优化，而目前并没有一篇文章明确的指明java中各种gc算法打印出日志的格式，以及如何阅读。所以接下来本文将试着边介绍各种垃圾回收机制边解释该回收机制下log的格式。
1，垃圾收集算法
 1.1 引用计数法（Reference Counting Collector）
   系统记录对象被应用的次数，当应用次数为0时，就可以将该对象所占内存回收。该算法可以不用暂停运用，但缺点是无法解决重复运用的问题。所以java并没有提供此类垃圾回收器。
  1.2 tracing算法(Tracing Collector)
       tracing算法的垃圾收集器从根集开始扫描，识别出哪些对象可达，哪 些对象不可达，并用某种方式标记可达对象。
  1.2.1 复制（ Copying ）算法
    复制算法将堆等分成2个区域，一个区域含有现在的数据对象(ToSpace)，而另一个区域包含废弃的数据(FromSpace)。复制算法将存活的对象从FromSpace复制到ToSpace，然后切换Fromspace和ToSpace的指针，以前的FromSpace变为现在的ToSpace区域。
  1.2.2 标记－整理（ Mark-Compact ）算法
       
 1.2.3 标记-清除（Mark-Sweep）
Using the -XX flags for our collectors for jdk6,

• UseSerialGC is "Serial" + "Serial Old"
• UseParNewGC is "ParNew" + "Serial Old"
• UseConcMarkSweepGC is "ParNew" + "CMS" + "Serial Old". "CMS" is used most of the time to collect the tenured generation. "Serial Old" is used when a concurrent mode failure occurs.
• UseParallelGC is "Parallel Scavenge" + "Serial Old"
• UseParallelOldGC is "Parallel Scavenge" + "Parallel Old" 

SerailGC

1，Serial Young GC 
0.246: [GC 0.246: [DefNew: 1403K->105K(1984K), 0.0109275 secs] 1403K->1277K(6080K), 0.0110143 secs] 
2, Serial Olg Gc

1.133: [GC 1.133: [DefNew: 960K->64K(960K), 0.0012208 secs]1.135: [Tenured: 7334K->7142K(7424K), 0.0213756 secs] 7884K->7142K(8384K), [Perm : 364K->364K(12288K)], 0.0226997 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

Parrallel GCserailGC的适应muti Core的加强版，就是在minorGC时候采用并行的进行收集，而fullGC并没有改变

CMS将老生代的回收分为4个阶段 其中只有2个阶段是要stop-the-world的,而其余阶段是不需要的，因此降低了系统暂停时间，缺点是在其余的2个阶段会更应用抢jvm资源。

 

  

从上图可以看出，CMS的运行过程。

Concurrent Mark-Sweep GC log format：



Full GC 被调用的出现情况 

promotion failed(mark-sweep-compact stop-the-world)ParNew (promotion failed):  当老生代空闲空间存在碎片，导致没有足够大的连续空间开存放新生代对象的升级时，机会触发promotion failed。此时调用一个Mark-Compact 垃圾收集器是很有必要的。（默认采用 Serial Old GC）

full promotion guarantee failure(concurrent mode failure):当垃圾回收算法预测在下一次Conc-Mark-Sweep算法调用之前，老生代的空余空间将会被系统占用光。为了解决这一问题，垃圾回收算法进入conccurent mode failure状态，调用一个 stop-the-world（serail Old GC）来清理系统Heap。

eg:为了触发这种情况 我们先分配64m内存给jvm，然后新生代和老年代的占用比例为7，即老年代用了7*8=58 触发concurrent mode failure的情况:

public class FullPromotionGuaranteeFailure
{
    public static void main(String[] args)
    {
    List<byte[]> bytesList = new ArrayList<byte[]>();
    for (int i = 0; i < 7 * 8 * 1024; i++)
    {
        bytesList.add(new byte[1024]);
    }
    
    //bytesList = null; 没有必要的 gc会知道函数里面变量是否还会被引用
    byte[] bytes = new byte[16 * 1024 * 1024];
    String.valueOf(bytes[0]);
    }
}

运行时JVM参数：
-Xmx64m -Xms64m -XX:NewRatio=7 -XX:MaxTenuringThreshold=0 -verbose:gc  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+UseConcMarkSweepGC
-Xloggc:full-promotion-guarantee-failure.log
full-promotion-guarantee-failure.log 内容

调用Serial Old GC 是费时并且暂停了整个应用，这显然不是我们想看到的。为了 避免办法出现（concurrent mode failure）这种情况,可以参考bluedavy的该篇blogGC 策略的调优

Stop-the-world GC happens when a JNI critical section is released. Here again the young generation collection failed due to "full promotion guarantee failure" and then the Full GC was invoked.

2. CMS gc实践总结

http://www.iteye.com/topic/473874

首先感谢阿宝同学的帮助，我才对这个gc算法的调整有了一定的认识，而不是停留在过去仅仅了解的阶段。在读过sun的文档和跟阿宝讨论之后，做个小小的总结，如果有谬误，敬请指正。
    CMS，全称Concurrent Low Pause Collector，是jdk1.4后期版本开始引入的新gc算法，在jdk5和jdk6中得到了进一步改进，它的主要适合场景是对响应时间的重要性需求大于对吞吐量的要求，能够承受垃圾回收线程和应用线程共享处理器资源，并且应用中存在比较多的长生命周期的对象的应用。CMS是用于对tenured generation的回收，也就是年老代的回收，目标是尽量减少应用的暂停时间，减少full gc发生的几率，利用和应用程序线程并发的垃圾回收线程来标记清除年老代。在我们的应用中，因为有缓存的存在，并且对于响应时间也有比较高的要求，因此希望能尝试使用CMS来替代默认的server型JVM使用的并行收集器，以便获得更短的垃圾回收的暂停时间，提高程序的响应性。
    CMS并非没有暂停，而是用两次短暂停来替代串行标记整理算法的长暂停，它的收集周期是这样：
   初始标记(CMS-initial-mark) -> 并发标记(CMS-concurrent-mark) -> 重新标记(CMS-remark) -> 并发清除(CMS-concurrent-sweep) ->并发重设状态等待下次CMS的触发(CMS-concurrent-reset)。
    其中的1，3两个步骤需要暂停所有的应用程序线程的。第一次暂停从root对象开始标记存活的对象，这个阶段称为初始标记；第二次暂停是在并发标记之后，暂停所有应用程序线程，重新标记并发标记阶段遗漏的对象（在并发标记阶段结束后对象状态的更新导致）。第一次暂停会比较短，第二次暂停通常会比较长，并且 remark这个阶段可以并行标记。

    而并发标记、并发清除、并发重设阶段的所谓并发，是指一个或者多个垃圾回收线程和应用程序线程并发地运行，垃圾回收线程不会暂停应用程序的执行，如果你有多于一个处理器，那么并发收集线程将与应用线程在不同的处理器上运行，显然，这样的开销就是会降低应用的吞吐量。Remark阶段的并行，是指暂停了所有应用程序后，启动一定数目的垃圾回收进程进行并行标记，此时的应用线程是暂停的。

    CMS的young generation的回收采用的仍然是并行复制收集器，这个跟Paralle gc算法是一致的。

    下面是参数介绍和遇到的问题总结，

1、启用CMS：-XX:+UseConcMarkSweepGC。 咳咳，这里犯过一个低级错误，竟然将+号写成了-号

2。CMS默认启动的回收线程数目是  (ParallelGCThreads + 3)/4)，如果你需要明确设定，可以通过-XX:ParallelCMSThreads=20来设定,其中ParallelGCThreads是年轻代的并行收集线程数

3、CMS是不会整理堆碎片的，因此为了防止堆碎片引起full gc，通过会开启CMS阶段进行合并碎片选项：-XX:+UseCMSCompactAtFullCollection，开启这个选项一定程度上会影响性能，阿宝的blog里说也许可以通过配置适当的CMSFullGCsBeforeCompaction来调整性能，未实践。

4.为了减少第二次暂停的时间，开启并行remark:-XX:+CMSParallelRemarkEnabled。如果remark还是过长的话，可以开启-XX:+CMSScavengeBeforeRemark选项，强制remark之前开始一次minor gc，减少remark的暂停时间，但是在remark之后也将立即开始又一次minor gc。

5.为了避免Perm区满引起的full gc，建议开启CMS回收Perm区选项：

+CMSPermGenSweepingEnabled -XX:+CMSClassUnloadingEnabled

6.默认CMS是在tenured generation沾满68%的时候开始进行CMS收集，如果你的年老代增长不是那么快，并且希望降低CMS次数的话，可以适当调高此值：
-XX:CMSInitiatingOccupancyFraction=80

这里修改成80%沾满的时候才开始CMS回收。

7.年轻代的并行收集线程数默认是(cpu <= 8) ? cpu : 3 + ((cpu * 5) / 8)，如果你希望降低这个线程数，可以通过-XX:ParallelGCThreads=N 来调整。

8.进入重点，在初步设置了一些参数后，例如：

Java代码 

1. -server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m -XX:PermSize=64m   
2. -XX:MaxPermSize=64m -XX:-UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection   
3. -XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSParallelRemarkEnabled   
4. -XX:SoftRefLRUPolicyMSPerMB=0  

-server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m -XX:PermSize=64m
-XX:MaxPermSize=64m -XX:-UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection
-XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSParallelRemarkEnabled
-XX:SoftRefLRUPolicyMSPerMB=0

需要在生产环境或者压测环境中测量这些参数下系统的表现，这时候需要打开GC日志查看具体的信息，因此加上参数：

-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/test/logs/gc.log

在运行相当长一段时间内查看CMS的表现情况，CMS的日志输出类似这样：

Java代码 

1. 4391.322: [GC [1 CMS-initial-mark: 655374K(1310720K)] 662197K(1546688K), 0.0303050 secs] [Times: user=0.02 sys=0.02, real=0.03 secs]   
2. 4391.352: [CMS-concurrent-mark-start]   
3. 4391.779: [CMS-concurrent-mark: 0.427/0.427 secs] [Times: user=1.24 sys=0.31, real=0.42 secs]   
4. 4391.779: [CMS-concurrent-preclean-start]   
5. 4391.821: [CMS-concurrent-preclean: 0.040/0.042 secs] [Times: user=0.13 sys=0.03, real=0.05 secs]   
6. 4391.821: [CMS-concurrent-abortable-preclean-start]   
7. 4392.511: [CMS-concurrent-abortable-preclean: 0.349/0.690 secs] [Times: user=2.02 sys=0.51, real=0.69 secs]   
8. 4392.516: [GC[YG occupancy: 111001 K (235968 K)]4392.516: [Rescan (parallel) , 0.0309960 secs]4392.547: [weak refs processing, 0.0417710 secs] [1 CMS-remark: 655734K(1310720K)] 766736K(1546688K), 0.0932010 secs] [Times: user=0.17 sys=0.00, real=0.09 secs]   
9. 4392.609: [CMS-concurrent-sweep-start]   
10. 4394.310: [CMS-concurrent-sweep: 1.595/1.701 secs] [Times: user=4.78 sys=1.05, real=1.70 secs]   
11. 4394.310: [CMS-concurrent-reset-start]   
12. 4394.364: [CMS-concurrent-reset: 0.054/0.054 secs] [Times: user=0.14 sys=0.06, real=0.06 secs]  

4391.322: [GC [1 CMS-initial-mark: 655374K(1310720K)] 662197K(1546688K), 0.0303050 secs] [Times: user=0.02 sys=0.02, real=0.03 secs]
4391.352: [CMS-concurrent-mark-start]
4391.779: [CMS-concurrent-mark: 0.427/0.427 secs] [Times: user=1.24 sys=0.31, real=0.42 secs]
4391.779: [CMS-concurrent-preclean-start]
4391.821: [CMS-concurrent-preclean: 0.040/0.042 secs] [Times: user=0.13 sys=0.03, real=0.05 secs]
4391.821: [CMS-concurrent-abortable-preclean-start]
4392.511: [CMS-concurrent-abortable-preclean: 0.349/0.690 secs] [Times: user=2.02 sys=0.51, real=0.69 secs]
4392.516: [GC[YG occupancy: 111001 K (235968 K)]4392.516: [Rescan (parallel) , 0.0309960 secs]4392.547: [weak refs processing, 0.0417710 secs] [1 CMS-remark: 655734K(1310720K)] 766736K(1546688K), 0.0932010 secs] [Times: user=0.17 sys=0.00, real=0.09 secs]
4392.609: [CMS-concurrent-sweep-start]
4394.310: [CMS-concurrent-sweep: 1.595/1.701 secs] [Times: user=4.78 sys=1.05, real=1.70 secs]
4394.310: [CMS-concurrent-reset-start]
4394.364: [CMS-concurrent-reset: 0.054/0.054 secs] [Times: user=0.14 sys=0.06, real=0.06 secs]

其中可以看到CMS-initial-mark阶段暂停了0.0303050秒，而CMS-remark阶段暂停了0.0932010秒，因此两次暂停的总共时间是0.123506秒，也就是123毫秒左右。两次短暂停的时间之和在200以下可以称为正常现象。

但是你很可能遇到两种fail引起full gc：Prommotion failed和Concurrent mode failed。

Prommotion failed的日志输出大概是这样：

Java代码 

1. [ParNew (promotion failed): 320138K->320138K(353920K), 0.2365970 secs]42576.951: [CMS: 1139969K->1120688K(   
2. 166784K), 9.2214860 secs] 1458785K->1120688K(2520704K), 9.4584090 secs]  

[ParNew (promotion failed): 320138K->320138K(353920K), 0.2365970 secs]42576.951: [CMS: 1139969K->1120688K(
2166784K), 9.2214860 secs] 1458785K->1120688K(2520704K), 9.4584090 secs]

这个问题的产生是由于救助空间不够，从而向年老代转移对象，年老代没有足够的空间来容纳这些对象，导致一次full gc的产生。解决这个问题的办法有两种完全相反的倾向：增大救助空间、增大年老代或者去掉救助空间。增大救助空间就是调整-XX:SurvivorRatio参数，这个参数是Eden区和Survivor区的大小比值，默认是32，也就是说Eden区是 Survivor区的32倍大小，要注意Survivo是有两个区的，因此Surivivor其实占整个young genertation的1/34。调小这个参数将增大survivor区，让对象尽量在survitor区呆长一点，减少进入年老代的对象。去掉救助空间的想法是让大部分不能马上回收的数据尽快进入年老代，加快年老代的回收频率，减少年老代暴涨的可能性，这个是通过将-XX:SurvivorRatio 设置成比较大的值（比如65536)来做到。在我们的应用中，将young generation设置成256M，这个值相对来说比较大了，而救助空间设置成默认大小(1/34)，从压测情况来看，没有出现prommotion failed的现象，年轻代比较大，从GC日志来看，minor gc的时间也在5-20毫秒内，还可以接受，因此暂不调整。

Concurrent mode failed的产生是由于CMS回收年老代的速度太慢，导致年老代在CMS完成前就被沾满，引起full gc，避免这个现象的产生就是调小-XX:CMSInitiatingOccupancyFraction参数的值，让CMS更早更频繁的触发，降低年老代被沾满的可能。我们的应用暂时负载比较低，在生产环境上年老代的增长非常缓慢，因此暂时设置此参数为80。在压测环境下，这个参数的表现还可以，没有出现过Concurrent mode failed。


参考资料：
《JDK5.0垃圾收集优化之--Don't Pause》 by 江南白衣
《记一次Java GC调整经历》1,2by Arbow
Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning
Tuning Garbage Collection with the 5.0 JavaTM Virtual Machine

3.  通过GC输出分析内存泄露问题
http://www.iteye.com/topic/256701

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