一次Full GC 过程的日志分析

基础概念：
Full GC,新生代，旧生代和持久代都发生GC，说明这次GC是发生了Stop-The-World的
ParNew GC发生区域，和收集器有关，这里是ParNew收集器，如果为Serial收集器，则显示DefNew。如果Parallel Scavenge收集器，那它配套的新生代称为“PSYoungGen”
GC 332674.627 后面的数字为JVM启动后到现在的时间
4194304K->2097152K(4194304K),GC前大小－>GC后大小（总量）后面是时间
12708916K->11511721K(18874368K), 方括号外的为JAVA堆的大小
CMS Perm : 62737K->62170K(262144K)，持久带GC前后大小（总量）-XX:PermSize -XX:MaxPermSize
[Times: user=16.08 sys=0.67, real=2.01 secs] 这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间（Wall Clock Time），由于多核等情况前者时间会大雨real时间
[1 CMS-initial-mark: 9414569K(14680064K) 旧生代的使用量（总量），由JVM参数 -Xmx 减去 －Xmn的值决定

当时的log：

2016-03-07T16:19:41.876+0800: 332665.291: [GC 332665.291: [ParNew: 4194304K->2097152K(4194304K), 2.0051080 secs] 12708916K->11511721K(18874368K), 2.0059970 secs] [Times: user=16.08 sys=0.67, real=2.01 secs]
2016-03-07T16:19:43.886+0800: 332667.301: [GC [1 CMS-initial-mark: 9414569K(14680064K)] 11550068K(18874368K), 3.3386230 secs] [Times: user=3.33 sys=0.00, real=3.34 secs]
2016-03-07T16:19:47.226+0800: 332670.640: [CMS-concurrent-mark-start]
2016-03-07T16:19:51.212+0800: 332674.626: [GC 332674.627: [ParNew: 4194304K->2097152K(4194304K), 2.1854100 secs] 13608873K->12438922K(18874368K), 2.1863460 secs] [Times: user=17.75 sys=0.73, real=2.18 secs]
2016-03-07T16:19:57.435+0800: 332680.849: [GC 332680.850: [ParNew: 4194304K->2097152K(4194304K), 2.2184010 secs] 14536074K->13394507K(18874368K), 2.2193090 secs] [Times: user=17.90 sys=0.73, real=2.22 secs]
2016-03-07T16:20:03.112+0800: 332686.526: [GC 332686.527: [ParNew: 4194304K->1828266K(4194304K), 1.9129620 secs] 15491659K->14026818K(18874368K), 1.9138510 secs] [Times: user=15.57 sys=0.64, real=1.91 secs]
2016-03-07T16:20:09.003+0800: 332692.418: [GC 332692.418: [ParNew: 3925418K->2097152K(4194304K), 2.0599170 secs] 16123970K->15235066K(18874368K),