java GC调优

原帖地址：http://arbow.javaeye.com/blog/362861

由于Boss看了某JVM GC调整的文章，兴致大发叫嚷要对我们的服务进行调优，于是开始了一次调优经历。

由于服务是属于非后台计算类型，因此抛弃了并行回收策略，而使用并发回收，对年轻代做并行回收，年老代做并发回收，参数

引用

-Xms2048m -Xmx2048m -Xmn512m -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -Xloggc:/home/resin/logs/gc.log

这个配置，年轻代设置比较大，有512M，但问题不在于此。使用jstat做统计，发现几乎所有的Full GC都是在100ms以下完成，但是查看gc.log，却发现里面的Full GC都在几秒，数量不多。这个gc log跟jstat中的数据对不上。更糟糕的是，在高峰期，由于堆被大量占用（疑似有内存泄漏），OU到了90%以上，FullGC相当频繁，期间也出现 了几次高达7s的停顿。Boss心慌慌，听到有7s之后特着急，想着要是每次都7s，每分钟来一次FullGC，那系统就有10%以上的时间得停止了~~

好了，碰到这种问题，有人第一时间想Java 的性能真烂，有人打算换JVM，估计还有人想着用C++重写。

Stop！这属于抓瞎行为，让我们来分析下问题所在。
1.缺乏详细日志，这对调优来说，太重要了
2.数据样本太少，服务仅仅运行了几天，也没有详细的记录，需要记录数据。
3.使用CMS回收器，但是却有几条停顿时间超长的记录，Why？

处理：

首先加入了更详尽的日志输出

引用

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

数据采样，将jstat -gcutil的结果记录到日志，以2000ms为间隔，记录一个星期。

Concurrent mode failure：当cms并发回收期间，如果需要分配的内存不足，就会导致Stop All World，进行一次大的回收，当年老代快暴满的时候，很有可能发生。另外使用CMS回收会导致内存碎片，也有可能导致运行一段时间之后由于碎片问题而不 得不进行一次完整的GC。参数加入

引用

-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80

设置每次回收时，压缩内存碎片，并且在年老代达到80%使用率时马上进行回收。

最终将参数设置为

引用

-Xms2048m -Xmx2048m -Xmn384m -Xss256k -XX:PermSize=128M -XX:NewSize=384m -XX:MaxNewSize=384m -XX:MaxPermSize=256m -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/resin/logs/gc.log

经过一周的观察，有几点值得注意。

1.在系统空闲时，会有时间较长的FullGC发生，而且此时年老代的占用并没有上80%，而且间隔时间很接近1个小时整。日志输出为类似

引用

9654.793: [Full GC (System) 9654.793: [CMS: 1285124K->512456K(1703936K), 2.9613390 secs] 1340458K->512456K(2057856K), [C
MS Perm : 98053K->81932K(155480K)], 2.9617070 secs] [Times: user=2.94 sys=0.01, real=2.96 secs]

2.当系统有一定负载后，年老代占用到80%会马上进行cms gc，时间一般都很短，分2次停顿完成。日志输出类似

引用

6047.709: [GC [1 CMS-initial-mark: 869803K(1703936K)] 909529K(2057856K), 0.0352070 secs] [Times: user=0.04 sys=0.00, rea
l=0.03 secs]
6047.745: [CMS-concurrent-mark-start]
6048.475: [CMS-concurrent-mark: 0.713/0.730 secs] [Times: user=1.64 sys=0.02, real=0.73 secs]
6048.475: [CMS-concurrent-preclean-start]
6048.486: [CMS-concurrent-preclean: 0.010/0.011 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
6048.486: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 6053.533: [CMS-concurrent-abortable-preclean: 2.835/5.047 secs] [Times: user=3.52 sys=0
.05, real=5.05 secs]
6053.533: [GC[YG occupancy: 205354 K (353920 K)]6053.533: [Rescan (parallel) , 0.1636670 secs]6053.697: [weak refs proce
ssing, 0.2716410 secs] [1 CMS-remark: 869803K(1703936K)] 1075158K(2057856K), 0.4361030 secs] [Times: user=0.57 sys=0.28,
real=0.44 secs]
6053.970: [CMS-concurrent-sweep-start]
6054.791: [CMS-concurrent-sweep: 0.810/0.821 secs] [Times: user=0.99 sys=0.01, real=0.82 secs]
6054.791: [CMS-concurrent-reset-start]
6054.802: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

3.使用jmap -histo做输出，很可能会造成一次FullGC，停顿可能超过8s！不要在高峰期做这种操作，只使用jstat。

4.样本数据分析。对jstat输出的fgc时间进行分析，按小时段归类，结果如下：

引用

时刻 总时间 总次数 平均停顿时间
0 3248.0ms 59 55.0508474576ms
1 2103.0ms 36 58.4166666667ms
2 11239.0ms 20 561.95ms
3 20596.0ms 16 1287.25ms
4 31261.0ms 14 2232.92857143ms
5 36141.0ms 14 2581.5ms
6 34614.0ms 14 2472.42857143ms
7 23626.0ms 19 1243.47368421ms
8 14499.0ms 31 467.709677419ms
9 10341.0ms 59 175.271186441ms
10 11063.0ms 95 116.452631579ms
11 8086.0ms 113 71.5575221239ms
12 16305.0ms 145 112.448275862ms
13 6952.0ms 164 42.3902439024ms
14 7079.0ms 171 41.3976608187ms
15 8023.0ms 193 41.5699481865ms
16 26697.0ms 221 120.800904977ms
17 15841.0ms 186 85.1666666667ms
18 7092.0ms 198 35.8181818182ms
19 8373.0ms 211 39.682464455ms
20 8718.0ms 228 38.2368421053ms
21 8184.0ms 212 38.6037735849ms
22 6001.0ms 158 37.9810126582ms
23 5884.0ms 98 60.0408163265ms

要注意这里的次数包含了每一次cms回收时的2次停顿，而且包含了由于少量jmap操作导致的误差。

结论：
1.CMS回收器已经比较理想，能够将1.5G的堆FullGC时间降到平均每次50ms左右。对于VOIP这些实时性要求更高的应用，可以期待 G1回收器。对应用来说，在吞吐量和延迟之间，需要找到一个平衡点，CMS回收器这种延迟低的算法，会导致吞吐量下降。此外由于使用了 UseCMSCompactAtFullCollection参数，会导致性能有所下降。配置适当的 CMSFullGCsBeforeCompaction参数，可能有助于提高性能。
2.JVM会在服务器空闲时定时进行非CMS的FullGC，时间平均在2s以上，通常发生于半夜。而且回收时，年老代尚未到 CMSInitiatingOccupancyFraction设置的值。但这种现象很少会发生，在服务器繁忙时基本不会出现，对服务不会造成较大影响。
3.对Java 这种共享堆的GC而言，2G已经比较吃力。一般1G是较为理想的大小。尽可能使用多JVM进程集群的方式来充分使用服务器资源才是正道。（无法想象开8G的堆会发生什么事情）

下一步再对jvm参数做调整，观察效果。