CMS GC日志解读

相关FLAG

-XX:+PrintGC

开启简单GC日志模式,例:

[GC 246656K->243120K(376320K), 0.0929090 secs] #堆空间从246656K减少到243120K,耗时0.0929090
[Full GC 243120K->241951K(629760K), 1.5589690 secs] #

-XX:PrintGCDetails

开启详细GC日志模式,日志格式根据使用的GC算法各不相同

-XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

打印GC发生的时间,一个是jvm启动时间,一个是真实的时间

  • PrintGCTimeStamps

10828.000: [GC (Allocation Failure) 2019-11-04T17:52:07.130+0800: 10828.000: [ParNew

  • PrintGCDateStamps

2019-11-04T17:52:07.130+0800: [GC (Allocation Failure)

-Xloggc:file -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1M

loggc:file将GC日志输出到文件中,后边的几个选项是开启滚动日志,也就是将日志按大小分割,实际上GC日志文件不是太大,不必要开启日志滚动。

-XX:+PrintGCCause

产生GC的原因,在JDK8已默认打开

-XX:+PrintPromotionFailure

如果有新生代对象晋升到老生代失败出现的FULL GC,打开这个日志可以看到更详细的信息

-XX:+PrintGCApplicationStoppedTime

GC日志格式

  • jstat -gcutil
  S0     S1     E      O      M     CCS     YGC      YGCT       FGC     FGCT      GCT
 10.40   0.00  47.03  72.53  98.19  95.76   251776   3272.123    14    0.698     3272.821
幸存区1 幸存区2  eden   老年代 元数据区 CCS使用率 YGC次数  YGC总时间  FGC次数  FGC总时间  总GC时间

CCS即 CompressedClassSpace 压缩类空间
java8移除了permanent generation,然后class metadata存储在native memory中,其大小默认是不受限的,可以通过-XX:MaxMetaspaceSize来限制;如果开启了-XX:+UseCompressedOops及-XX:+UseCompressedClassesPointers(默认是开启),则UseCompressedOops会使用32-bit的offset来代表java object的引用,而UseCompressedClassPointers则使用32-bit的offset来代表64-bit进程中的class pointer;可以使用CompressedClassSpaceSize来设置这块的空间大小
参考聊聊jvm的CompressedClassSpace

  • ParNew GC日志格式,flag为-Xloggc:filexx -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintPromotionFailure -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps时的日志格式示例:
{Heap before GC invocations=4 (full 0):#已发生GC次数,FULL GC次数0
#GC前年轻代堆内存使用情况,年轻代总大小1887488K,已使用1727926K
 par new generation   total 1887488K, used 1727926K [0x0000000660800000, 0x00000006e0800000, 0x00000006e0800000)
#年轻代三个区域的内存使用情况 
  eden space 1677824K, 100% used [0x0000000660800000, 0x00000006c6e80000, 0x00000006c6e80000)
  from space 209664K,  23% used [0x00000006c6e80000, 0x00000006c9f6d878, 0x00000006d3b40000)
  to   space 209664K,   0% used [0x00000006d3b40000, 0x00000006d3b40000, 0x00000006e0800000)
#老年代内存使用情况,总大小4194304K,已使用18438K
 concurrent mark-sweep generation total 4194304K, used 18438K [0x00000006e0800000, 0x00000007e0800000, 0x00000007e0800000)
#元数据区 参见 https://www.cnblogs.com/benwu/articles/8312699.html
 Metaspace       used 34624K, capacity 35104K, committed 35456K, reserved 1081344K
  class space    used 4253K, capacity 4365K, committed 4480K, reserved 1048576K
#GC发生时间,65493.227是GC发生时的jvm时间也就是nanotime GC发生的原因是Allocation Failure GC类型是ParNew
2019-12-24T09:46:35.442+0800: 65493.227: [GC (Allocation Failure) 2019-12-24T09:46:35.442+0800: 65493.227: [ParNew
#晋升阈值是3,也就是对象熬过的ygc次数,各个年龄(ygc次数)代的对象大小
#desired survivor size = (survivor区容量 * TargetSurvivorRatio)/100(TargetSurvivorRatio默认是50),是个固定值
Desired survivor size 107347968 bytes, new threshold 3 (max 3)
- age   1:   32349728 bytes,   32349728 total
- age   2:       9736 bytes,   32359464 total
- age   3:       9528 bytes,   32368992 total
#年轻代使用量从1727926K减少到了35459K,总大小是1887488K,堆使用量从1746364K减少到了55013K(总大小是6081792K),GC耗时0.0566931s
: 1727926K->35459K(1887488K), 0.0565661 secs] 1746364K->55013K(6081792K), 0.0566931 secs] [Times: user=0.31 sys=0.02, real=0.05 secs] 
# 这部分和开始处格式一样
Heap after GC invocations=5 (full 0):
 par new generation   total 1887488K, used 35459K [0x0000000660800000, 0x00000006e0800000, 0x00000006e0800000)
  eden space 1677824K,   0% used [0x0000000660800000, 0x0000000660800000, 0x00000006c6e80000)
  from space 209664K,  16% used [0x00000006d3b40000, 0x00000006d5de0cd0, 0x00000006e0800000)
  to   space 209664K,   0% used [0x00000006c6e80000, 0x00000006c6e80000, 0x00000006d3b40000)
 concurrent mark-sweep generation total 4194304K, used 19553K [0x00000006e0800000, 0x00000007e0800000, 0x00000007e0800000)
 Metaspace       used 34624K, capacity 35104K, committed 35456K, reserved 1081344K
  class space    used 4253K, capacity 4365K, committed 4480K, reserved 1048576K
}
  • CMS 日志格式
#初始标记阶段,会stop the world 老年代已使用3145728K(总4194304K),整个堆已使用3179746K(总堆6081792K)
2020-03-25T21:49:54.257+0800: 1142819.594: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3145728K(4194304K)] 3179746K(6081792K), 0.0058716 secs] [Times: user=0.02 sys=0.02, real=0.00 secs]
# 并发标记阶段,不会stw
2020-03-25T21:49:54.263+0800: 1142819.600: [CMS-concurrent-mark-start]
2020-03-25T21:49:55.002+0800: 1142820.339: [CMS-concurrent-mark: 0.739/0.739 secs] [Times: user=2.36 sys=1.91, real=0.74 secs]
# 并发预清理阶段,不会stw
2020-03-25T21:49:55.002+0800: 1142820.340: [CMS-concurrent-preclean-start]
2020-03-25T21:49:55.016+0800: 1142820.353: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 sys=0.02, real=0.02 secs]
2020-03-25T21:49:55.017+0800: 1142820.354: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2020-03-25T21:50:00.143+0800: 1142825.480: [CMS-concurrent-abortable-preclean: 5.121/5.126 secs] [Times: user=11.02 sys=0.00, real=5.12 secs]
# 重新标记阶段,会stw,也是最耗时的阶段,CMS导致的应用暂停基本都是这个阶段,可以看到耗时100ms
2020-03-25T21:50:00.149+0800: 1142825.486: [GC (CMS Final Remark) [YG occupancy: 652003 K (1887488 K)]2020-03-25T21:50:00.149+0800: 1142825.486: [Rescan (parallel) , 0.0716031 secs]2020-03-25T21:50:00.220+0800: 1142825.558: [weak refs processing, 0.0022247 secs]2020-03-25T21:50:00.223+0800: 1142825.560: [class unloading, 0.0164177 secs]2020-03-25T21:50:00.239+0800: 1142825.576: [scrub symbol table, 0.0070541 secs]2020-03-25T21:50:00.246+0800: 1142825.583: [scrub string table, 0.0009672 secs][1 CMS-remark: 3145728K(4194304K)] 3797731K(6081792K), 0.0992188 secs] [Times: user=0.00 sys=0.00, real=0.10 secs]
# 并发清除阶段,不会stw
2020-03-25T21:50:00.248+0800: 1142825.586: [CMS-concurrent-sweep-start]
2020-03-25T21:50:02.408+0800: 1142827.745: [CMS-concurrent-sweep: 2.159/2.159 secs] [Times: user=2.30 sys=0.39, real=2.16 secs]
# 并发重置阶段,不会stw
2020-03-25T21:50:02.408+0800: 1142827.745: [CMS-concurrent-reset-start]
2020-03-25T21:50:02.419+0800: 1142827.756: [CMS-concurrent-reset: 0.011/0.011 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]

安全点日志

-XX:+PrintSafepointStatistics 
-XX: PrintSafepointStatisticsCount=1 
-XX:+UnlockDiagnosticVMOptions 
-XX:- DisplayVMOutput 
-XX:+LogVMOutput 
-XX:LogFile=myapp.log

开启JMX

-Dcom.sun.management.jmxremote.port=7001 
-Dcom.sun.management.jmxremote 
-Dcom.sun.management.jmxremote.authenticate=false 
-Dcom.sun.management.jmxremote.ssl=false 
-Djava.rmi.server.hostname=127.0.0.1
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 214,504评论 6 496
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,434评论 3 389
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,089评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,378评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,472评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,506评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,519评论 3 413
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,292评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,738评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,022评论 2 329
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,194评论 1 342
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,873评论 5 338
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,536评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,162评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,413评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,075评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,080评论 2 352

推荐阅读更多精彩内容

  • 本系列的最后一部分是有关垃圾收集(GC)日志的JVM参数。GC日志是一个很重要的工具,它准确记录了每一次的GC的执...
    jerrik阅读 4,481评论 0 4
  • 声明:原创文章,转载请注明出处。http://www.jianshu.com/u/e02df63eaa87 1、J...
    唐影若凡阅读 1,203评论 0 6
  • 1.垃圾收集器 上图有连线的可以搭配使用如,选ParNew为年轻代收集器,则可选CMS和Serial Old 为老...
    香沙小熊阅读 1,295评论 1 17
  • AI乔治 关注 2018.07.29 21:49 字数 5273 阅读 878评论 1喜欢 55 一:虚拟机内存图...
    KwongRay阅读 179评论 0 0
  • 我在你的眼里 看见了一条河 看到了过去这里发生的 我像是个孩子一样,走在街上 天边那一抹令人心悸的美丽 儿时的秋千...
    岳海大大阅读 486评论 4 15