Java GC日志分析

1. 查看GC日志准备

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

2. 年轻代GC日志

2019-09-17T23:12:05.334+0800: 6950.220: [GC2019-09-17T23:12:05.334+0800: 6950.220: [ParNew: 1713371K->30726K(1887488K), 0.0325240 secs] 1910235K->227695K(6081792K), 0.0329710 secs] [Times: user=0.12 sys=0.01, real=0.04 secs

3. CMS GC日志

2019-09-17T21:19:48.213+0800: 213.099: [GC [1 CMS-initial-mark: 2136781K(4194304K)] 2378922K(6081792K), 0.0269660 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
2019-09-17T21:19:48.240+0800: 213.126: [CMS-concurrent-mark-start]
2019-09-17T21:19:48.499+0800: 213.385: [CMS-concurrent-mark: 0.259/0.259 secs] [Times: user=0.98 sys=0.08, real=0.26 secs]
2019-09-17T21:19:48.499+0800: 213.385: [CMS-concurrent-preclean-start]
2019-09-17T21:19:48.508+0800: 213.394: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
2019-09-17T21:19:48.509+0800: 213.395: [CMS-concurrent-abortable-preclean-start]
2019-09-17T21:19:50.125+0800: 215.011: [CMS-concurrent-abortable-preclean: 1.612/1.616 secs] [Times: user=3.28 sys=0.08, real=1.62 secs]
2019-09-17T21:19:50.125+0800: 215.011: [GC[YG occupancy: 1065145 K (1887488 K)]2019-09-17T21:19:50.125+0800: 215.011: [Rescan (parallel) , 0.1963400 secs]2019-09-17T21:19:50.321+0800: 215.207: [weak refs processing, 0.0003260 secs]2019-09-17T21:19:50.322+0800: 215.208: [class unloading, 0.0267880 secs]2019-09-17T21:19:50.349+0800: 215.235: [scrub symbol table, 0.0894820 secs]2019-09-17T21:19:50.438+0800: 215.324: [scrub string table, 0.0028500 secs] [1 CMS-remark: 2136781K(4194304K)] 3201926K(6081792K), 0.3199900 secs] [Times: user=0.87 sys=0.03, real=0.32 secs]
2019-09-17T21:19:50.445+0800: 215.331: [CMS-concurrent-sweep-start]
2019-09-17T21:19:51.334+0800: 216.220: [CMS-concurrent-sweep: 0.888/0.889 secs] [Times: user=1.81 sys=0.20, real=0.89 secs]
2019-09-17T21:19:51.334+0800: 216.220: [CMS-concurrent-reset-start]
2019-09-17T21:19:51.378+0800: 216.264: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.09 sys=0.04, real=0.04 secs]

4. CMS GC 7阶段解析

1.初始标记

这个是 CMS 两次 stop-the-wolrd 事件的其中一次,这个阶段的目标是:标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象,标记后示例如下所示:


file

2. 并发标记

在这个阶段 Garbage Collector 会遍历老年代,然后标记所有存活的对象,它会根据上个阶段找到的 GC Roots 遍历查找。并发标记阶段,它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记,因为在标记期间用户的程序可能会改变一些引用,如下图所示:


file

3.并发预清理

Concurrent Preclean:这也是一个并发阶段,与应用的线程并发运行,并不会 stop 应用的线程。在并发运行的过程中,一些对象的引用可能会发生变化,但是这种情况发生时,JVM 会将包含这个对象的区域(Card)标记为 Dirty,这也就是 Card Marking。如下图所示:


file

在pre-clean阶段,那些能够从 Dirty 对象到达的对象也会被标记,这个标记做完之后,dirty card 标记就会被清除了,如下:


file

4.并发可终止预清理

这也是一个并发阶段,但是同样不会影响影响用户的应用线程,这个阶段是为了尽量承担 STW(stop-the-world)中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素,由于这个阶段是在重复做很多相同的工作,直接满足一些条件(比如:重复迭代的次数、完成的工作量或者时钟时间等)

5.重新标记

这是第二个 STW 阶段,也是 CMS 中的最后一个,这个阶段的目标是标记所有老年代所有的存活对象,由于之前的阶段是并发执行的,gc 线程可能跟不上应用程序的变化,为了完成标记老年代所有存活对象的目标,STW 就非常有必要了。 通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行,目的是为了减少连续 STW 发生的可能性(年轻代存活对象过多的话,也会导致老年代涉及的存活对象会很多)。这个阶段会比前面的几个阶段更复杂一些

6.并发标记

这里不需要 STW,它是与用户的应用程序并发运行,这个阶段是:清除那些不再使用的对象,回收它们的占用空间为将来使用。如下图所示:


file

7.并发重置

这个阶段也是并发执行的,它会重设 CMS 内部的数据结构,为下次的 GC 做准备

本文由博客群发一文多发等运营工具平台 OpenWrite 发布

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

推荐阅读更多精彩内容