GC日志中times表示什么含义？

Question

最近系统出现了运行一段时间后就无法响应的问题，表现就是浏览器的圈圈一直在转，页面没有加载出来。
查看GC的日志，有一些疑问是关于日志中的时间，如下面部分日志：

1182.030: [GC[YG occupancy: 8729512 K (9216000 K)]1182.030: [Rescan (parallel) , 7.6001940 secs]1189.630: [weak refs processing, 0.0000190 secs] [1 CMS-remark: 262120K(436904K)] 8991632K(9652904K), 7.6004580 secs] [Times: user=86.06 sys=0.42, real=7.60 secs]

13901.282: [GC 13901.283: [ParNew: 8766574K->400883K(9216000K), 1.9300940 secs] 10239467K->1917256K(11578944K), 1.9309390 secs] [Times: user=13.68 sys=0.07, real=1.93 secs]

我有两个问题：

1. 这两段日志中后面Times的3个时间分别是什么含义？
2. 因为看到第一个user有86秒多，不知道这个有没有什么影响？

我是刚进新公司，系统最近老是出现无响应，自己就看了日志。我看了下jvm的参数配置，觉得有问题，各位看看这些参数有问题么：

-server -Xms10200m -Xmx13200m -Xmn10000m -XX:MaxPermSize=4040m -XX:+UseConcMarkSweepGC -XX:+DisableExplicitGC -Dsun.reflect.inflationThreshold=2147483647 -XX:PermSize=3000m -XX:+PrintGCDetails -Xloggc:/data/resin/gc_detail.log  -verbose:class -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/resin/heapdump.bin

再贴一段CMS的GC日志：

800.344: [CMS-concurrent-mark-start]
800.733: [CMS-concurrent-mark: 0.312/0.389 secs] [Times: user=1.82 sys=0.03, real=0.39 secs]
800.734: [CMS-concurrent-preclean-start]
800.750: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
800.750: [CMS-concurrent-abortable-preclean-start]
  CMS: abort preclean due to time 809.299: [CMS-concurrent-abortable-preclean: 8.527/8.549 secs] [Times: user=10.60 sys=0.09, real=8.55 secs]
809.299: [GC[YG occupancy: 1120816 K (9216000 K)]809.300: [Rescan (parallel) , 0.2415390 secs]809.541: [weak refs processing, 0.0000210 secs] [1 CMS-remark: 185629K(204800K)] 1306445K(9420800K), 0.2416930 secs] [Times: user=2.91 sys=0.01, real=0.24 secs]
809.542: [CMS-concurrent-sweep-start]
809.674: [CMS-concurrent-sweep: 0.132/0.132 secs] [Times: user=0.15 sys=0.00, real=0.13 secs]
809.674: [CMS-concurrent-reset-start]
809.879: [CMS-concurrent-reset: 0.205/0.205 secs] [Times: user=0.12 sys=0.20, real=0.21 secs]
810.546: [GC [1 CMS-initial-mark: 185571K(309288K)] 1309669K(9525288K), 1.1555440 secs] [Times: user=1.15 sys=0.00, real=1.16 secs]
811.702: [CMS-concurrent-mark-start]
811.951: [CMS-concurrent-mark: 0.245/0.249 secs] [Times: user=1.02 sys=0.01, real=0.25 secs]
811.951: [CMS-concurrent-preclean-start]
811.961: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
811.961: [CMS-concurrent-abortable-preclean-start]
  CMS: abort preclean due to time 820.526: [CMS-concurrent-abortable-preclean: 8.556/8.565 secs] [Times: user=9.18 sys=0.09, real=8.56 secs]
820.528: [GC[YG occupancy: 1169864 K (9216000 K)]820.528: [Rescan (parallel) , 0.7405100 secs]821.269: [weak refs processing, 0.0000120 secs] [1 CMS-remark: 185571K(309288K)] 1355435K(9525288K), 0.7406440 secs] [Times: user=8.58 sys=0.03, real=0.74 secs]
821.270: [CMS-concurrent-sweep-start]
821.401: [CMS-concurrent-sweep: 0.131/0.131 secs] [Times: user=0.16 sys=0.00, real=0.14 secs]
821.401: [CMS-concurrent-reset-start]

Answer 1

这些时间是GC花费的时间，user是用户态耗费的时间，sys是内核态耗费的时间，real是整个过程实际花费的时间。user+sys是CPU时间，每个CPU core单独计算，所以这个时间可能会是real的好几倍。
从你的日志看，一次ParNew居然回收掉了8G多的内存，程序真得要好好优化一下了。
几点优化的建议：

1. Xms可以和Xmx设成一样大小，这样可以避免GC之后重新分配内存
2. Xmn太大，这其实是你遇到的问题的根本原因，官方推荐配置为整个堆的3/8，对于你的情况，可以试试-Xmn=4G

Answer 2

86秒的意思是指一个CPU需要的用户态时间, 楼主应该关注的是 real 的 7.6 秒时间.
因为有多核的关系, 所以 real 时间肯定比 user + sys 少的.

楼主给的 CMS GC 的日志并不全, 在此之前应该还有 GC 的日志.

单看这个 GC 日志, 就需要 7 秒多, 而且基本上都是发生在 CMS 的 remark 阶段, 而且这时候 Young 区已经使用了 90% 的内存, 可能是内存涨的太快, 中断了 CMS 前面的工作, 导致 remark 时间过长.

影响肯定很大的, 因为 remark 是 stop the world 的(既然选择了CMS, 说明应用还是很重视响应时间的), 建议楼主查找原因.

Answer 3

1. 减小xmn

2. 加上参数-XX:+CMSScavengeBeforeRemark，remark之前做一次minor gc，减小remark时间