求助>GC日志中times表示什么含义?>
1回复

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



最近系统出现了运行一段时间后就无法响应的问题,表现就是浏览器的圈圈一直在转,页面没有加载出来。
查看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]

我有两个问题:

这两段日志中后面Times的3个时间分别是什么含义?
因为看到第一个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]
100 阅读
请先登录,再评论

回复列表

可乐把1周前

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

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