JAVA CPU 100 分析

某系统在 2016-01-06T14:52:36  时间开始，监控发现CPU  user time（us）一直保持在 60--100 ％区间。影响部分线上业务。

线程堆栈发现，GC线程排在消耗首位。

下面是GC日志部分截图：

2016-01-06T14:50:31.180+0800: 102400.862: [Full GC [PSYoungGen: 40061K->0K(617472K)] [ParOldGen: 1350223K->995472K(1398272K)] 1390284K->995472K(2015744K) [PSPermGen: 84257K->84257K(131072K)],
 1.2380320 secs] [Times: user=8.78 sys=0.01, real=1.24 secs] 
2016-01-06T14:50:43.344+0800: 102413.027: [GC [PSYoungGen: 531968K->46418K(613888K)] 1527440K->1041890K(2012160K), 0.0298220 secs] [Times: user=0.18 sys=0.00, real=0.03 secs] 
2016-01-06T14:50:53.238+0800: 102422.920: [GC [PSYoungGen: 578386K->42160K(621568K)] 1573858K->1081156K(2019840K), 0.0774150 secs] [Times: user=0.56 sys=0.00, real=0.08 secs] 
2016-01-06T14:51:04.430+0800: 102434.112: [GC [PSYoungGen: 582832K->45789K(618496K)] 1621828K->1123417K(2016768K), 0.0707380 secs] [Times: user=0.51 sys=0.00, real=0.07 secs] 
2016-01-06T14:51:14.757+0800: 102444.439: [GC [PSYoungGen: 586461K->44895K(624128K)] 1664089K->1165577K(2022400K), 0.0766230 secs] [Times: user=0.56 sys=0.00, real=0.08 secs] 
2016-01-06T14:51:26.678+0800: 102456.360: [GC [PSYoungGen: 592223K->50104K(622592K)] 1712905K->1211394K(2020864K), 0.0758200 secs] [Times: user=0.55 sys=0.01, real=0.08 secs] 
2016-01-06T14:51:36.415+0800: 102466.098: [GC [PSYoungGen: 597432K->41941K(627200K)] 1758721K->1250158K(2025472K), 0.0771890 secs] [Times: user=0.56 sys=0.00, real=0.08 secs] 
2016-01-06T14:51:47.601+0800: 102477.283: [GC [PSYoungGen: 593877K->49832K(624128K)] 1802094K->1296815K(2022400K), 0.0735560 secs] [Times: user=0.53 sys=0.00, real=0.07 secs] 
2016-01-06T14:52:05.081+0800: 102494.763: [GC [PSYoungGen: 601768K->37456K(629248K)] 1848751K->1330137K(2027520K), 0.0764990 secs] [Times: user=0.54 sys=0.01, real=0.08 secs] 
2016-01-06T14:52:22.095+0800: 102511.777: [GC [PSYoungGen: 594000K->28144K(626688K)] 1886681K->1354903K(2024960K), 0.0599890 secs] [Times: user=0.40 sys=0.01, real=0.06 secs] 
2016-01-06T14:52:36.851+0800: 102526.534: [GC [PSYoungGen: 584688K->39769K(632832K)] 1911447K->1390549K(2031104K), 0.0497950 secs] [Times: user=0.33 sys=0.00, real=0.05 secs] 
2016-01-06T14:52:36.902+0800: 102526.584: [Full GC [PSYoungGen: 39769K->0K(632832K)] [ParOldGen: 1350779K->1303190K(1398272K)] 1390549K->1303190K(2031104K) [PSPermGen: 84258K->84258K(131072K)
], 1.5552060 secs] [Times: user=11.23 sys=0.01, real=1.56 secs] 
2016-01-06T14:52:48.834+0800: 102538.516: [GC [PSYoungGen: 563200K->50397K(629760K)] 1866390K->1353587K(2028032K), 0.0352100 secs] [Times: user=0.20 sys=0.01, real=0.03 secs] 
2016-01-06T14:52:59.038+0800: 102548.720: [GC [PSYoungGen: 613597K->68081K(588288K)] 1916787K->1410168K(1986560K), 0.0874470 secs] [Times: user=0.64 sys=0.00, real=0.09 secs] 
2016-01-06T14:52:59.126+0800: 102548.808: [Full GC [PSYoungGen: 68081K->0K(588288K)] [ParOldGen: 1342086K->1388747K(1398272K)] 1410168K->1388747K(1986560K) [PSPermGen: 84258K->84190K(131072K)
], 2.0662720 secs] [Times: user=15.42 sys=0.02, real=2.06 secs] 
2016-01-06T14:53:10.514+0800: 102560.196: [Full GC [PSYoungGen: 520192K->37553K(588288K)] [ParOldGen: 1388747K->1398252K(1398272K)] 1908939K->1435806K(1986560K) [PSPermGen: 84190K->84190K(131
072K)], 3.8127140 secs] [Times: user=28.79 sys=0.07, real=3.81 secs] 
2016-01-06T14:53:23.536+0800: 102573.218: [Full GC [PSYoungGen: 520192K->81932K(588288K)] [ParOldGen: 1398252K->1397926K(1398272K)] 1918444K->1479858K(1986560K) [PSPermGen: 84190K->84190K(131
072K)], 3.7658820 secs] [Times: user=27.23 sys=0.06, real=3.77 secs] 
2016-01-06T14:53:35.142+0800: 102584.824: [Full GC [PSYoungGen: 520192K->123866K(588288K)] [ParOldGen: 1397926K->1398029K(1398272K)] 1918118K->1521895K(1986560K) [PSPermGen: 84190K->84190K(13
1072K)], 2.5700500 secs] [Times: user=19.33 sys=0.03, real=2.57 secs] 
2016-01-06T14:53:53.383+0800: 102603.065: [Full GC [PSYoungGen: 520192K->131016K(588288K)] [ParOldGen: 1398029K->1397860K(1398272K)] 1918221K->1528876K(1986560K) [PSPermGen: 84190K->84190K(13
1072K)], 3.5948370 secs] [Times: user=25.70 sys=0.04, real=3.60 secs] 

说明下述问题：

              1、系统开发频繁发生FullGC，并且一次FullGC时间过长。在这之前，MinorGC已经非常频繁。

            2、业务日志上看，多线程并发发送接收、MQ消息，new 对象一直不停发生。

再看:JVM运行参数：（部分）

               -server -Xms2048m -Xmx2048m -XX:PermSize=128m -XX:MaxPermSize=512m 

            

如将这个时段看做是我们的系统运行稳态。再结合，JVM内存分配以及回收策略。

建议改进如下：

        1、JVM参数改动下述配置

            -server -Xms3072m -Xmx3072m  -Xmn1024m -XX:SurvivorRatio=3  -XX:PermSize=128m -XX:MaxPermSize=512m

       2、 代码层面，可以合并多条MQ消息。比如，合并100--300条为一条处理。

持续监控，调优。