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

 nnamyp_826 发布于 2022-11-05 16:28

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

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

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

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

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

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

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

    1. Xms可以和Xmx设成一样大小,这样可以避免GC之后重新分配内存
    2. Xmn太大,这其实是你遇到的问题的根本原因,官方推荐配置为整个堆的3/8,对于你的情况,可以试试-Xmn=4G
    2022-11-10 08:58 回答
撰写答案
今天,你开发时遇到什么问题呢?
立即提问
热门标签
PHP1.CN | 中国最专业的PHP中文社区 | PNG素材下载 | DevBox开发工具箱 | json解析格式化 |PHP资讯 | PHP教程 | 数据库技术 | 服务器技术 | 前端开发技术 | PHP框架 | 开发工具 | 在线工具
Copyright © 1998 - 2020 PHP1.CN. All Rights Reserved 京公网安备 11010802041100号 | 京ICP备19059560号-4 | PHP1.CN 第一PHP社区 版权所有