G1从入门到放弃(二)

G1从入门到放弃(二)

上一篇文章主要讲了G1的理论知识,本篇文章会讲解在实际生产中如何读懂G1日志,以及介绍G1的参数配置。

Young GC日志

通过使用-XX:+PrintGCDetails参数查看的Young GC日志如下:

image.png

① 四个关键信息

  • 2016-12-12T10:40:18.811-0500:GC发生的时间(通过设置-XX:+PrintGCDateStamps打印)
  • 29.959:相对JVM启动的时间
  • G1 Evacuation Pause (young):GC类型,表示这是evacuation停顿,并且是Young GC。
  • 0.0305171 sec:本次GC耗时。

② 所有并行任务

  • Parallel Time:26.6 。并行任务花费的STW的时间,从收集开始到最后一个GC线程结束。
  • GC Workers:4 。并行收集的线程数量。通过 -XX:ParallelGCThreads。当CPU数量小于8时,该值为CPU个数,最大设置成8,对于多于8个的CPU,将默认取CPU个数的5/8。
  • GC Worker start:最小|最大时间戳表示第一个线程和最后一个线程的启动时间。理想情况下希望同时启动。
  • **Ext Root Scanning **:扫描外部根节点的时间。外部节点包括JNI、全局变量、线程栈等。
  • **Update RS (Remembered Set or RSet) **:每个线程更新RSet的时间。
  • **Scan RS **: 扫描每个CSet中Region的RSet,避免了扫描整个老年代。
  • Code Root Scanning:扫描code root耗时。Code Root是JIT编译后的代码里引用了heap中的对象。
  • Object Copy:拷贝存活对象到新的Region.
  • Termination: 当GC线程完成任务之后尝试结束到真正结束耗时。因为在结束前他会检查其他线程是否有未完成的任务,帮助完成之后再结束。
  • GC Worker Other:线程花费在其他工作上的时间
  • GC Worker Total:每个线程花费的时间总和。
  • GC Worker End: 每个线程的结束时间。最小|最大时间戳表示第一个线程和最后一个线程的结束时间。理想情况下希望同时结束。

③ 串行任务

  • Code Root Fixup:修复GC期间code root指针改变的耗时
  • Code Root Purge:清除code root耗时
  • Clear CT:清除card tables 中的dirty card的耗时

④其他事项
其他事项共耗时3.7ms,其他事项包括选择CSet,处理已用对象,引用入ReferenceQueues,释放CSet中的region。

⑤各代变化

  • Eden: 1097.0M(1097.0M)->0.0B(967.0M):表明了Young GC被触发,因为Eden区已经满了(分配了1097M 已经使用了1097.0M),并且Eden区都被清空了(0B),下次垃圾回收Eden区大小降到967M。
  • Survivors: 13.0M->139.0M:Young GC之后,Survivor从13M增加到了139M
  • Heap: 1694.4M(2048.0M)->736.3M(2048.0M):开始前整个堆占用了1694.4M,最大可分配2048M,在收集之后,整个堆占用736M,最大可分配没有变还是2048M。

⑥ 这次回收耗时

  • user=0.08:在垃圾回收时,花费在用户代码上的CPU时间。这个时间包含了所有线程运行的CPU时间,所以比real-time大很多
  • sys=0.00: 花费在系统内核上的时间。
  • real=0.03: 垃圾回收的实际时间。这里包括了其他进程的时间和等待时间。

并发日志

image.png

①标明标记阶段开始

  • GC pause (G1 Evacuation Pause) (young) (initial-mark):利用STW停顿期间,跟踪所有可达对象,该阶段和Young GC一起执行。同时该阶段也设置两个指针TAMS来标识已经存在的对象以及在并发标记阶段新生成的对象,这两个指针在上一篇文章中介绍过。
    ② 第一个并发事件
  • GC concurrent-root-region-scan-start: 扫描初始化标记阶段Survivor区的root Region并标记出来。

③并发标记

  • GC concurrent-mark-start:该阶段和应用线程一起执行,并发线程数默认是并行线程数的四分之一。可以通过-XX:ConcGCThreads显示指定。

④ STW阶段

  • GC remark / Finalize Marking / GC ref-proc / Unloading: 这个阶段

⑤ 这也是STW阶段
-GC cleanup: 这个阶段没有存活对象的Old Region和Humongous Region将被释放和清空。为了准备下次GC,在CSets中的Old Regions会根据他们的回收收益的大小排序。为了准备下一次标记,previous bitmaps 和 next bitmaps会被交换。同时并行线程会标记那些inital mark阶段生成的对象,以及至少存在一个存活对象的region的bitmap。
⑥这也是一个并发阶段

  • GC concurrent-cleanup-start:处理第5阶段所有空的Region。每个Region中的RSet被清空,当所有的Region都被清理完成,他们会被加入到一个临时表中,最终会被合并到master free list。

Mixed GC

当并发标记完成后,在Young GC日志后面紧随着Mixed GC,下面是Mixed GC日志。可以看到Mixed GC日志和前面介绍的Young GC很相似,只有两个不同点:
1、第一行会表示这是一个Mixed GC
2、收集的集合里包含了老年代(Old Region),由并发标记阶段确定的。


image.png

Full GC

Full GC的日志结果如下。


image.png

需要注意的是如果是几天一次Full GC,则是正常现象,但是每小时频繁GC就需要调优了。

其他

建议大家开启-XX:+PrintAdaptiveSizePolicy-XX:+PrintTenuringDistribution两个标签,可以帮助大家更好的分析日志。

  • -XX:+PrintAdaptiveSizePolicy: 显示收集器工效(Collector ergonomics)
  • -XX:+PrintTenuringDistribution: Survivor区的使用和分布

Young GC开启-XX:+PrintAdaptiveSizePolicy之后的日志如下:

image.png

① 告诉我们有多少在dirty card队列里的cards等待被处理。并且展示了预计处理时间(包括了更新RSet和扫描RSet的时间);
② 有多少Region将被加入到这次GC中
③ 选择出CSets并且估算这次收集时间
④ 该行并不一定在Young GC日志中出现,如果花费在GC上的时间比应用线程大到一个阈值的时候,G1可以动态扩大堆大小。如果你设置了最大堆和最小堆的大小相等,该行不会出现
⑤ 当并发标记开始时出现。

Young GC后面是并发回收日志。

image.png

Young GC日志中还可能存在关于Mixed GC的日志:


image.png

①告诉我们Mixed GC开始,原因是可回收垃圾百分比(22.62%)大于了我们的阈值(5%)。

下面是Mixed GC开启-XX:+PrintAdaptiveSizePolicy之后执行日志

image.png

① 该阶段包括CSet和一部分Young Region的选择
②描述Mixed GC时,Old Region被加入到CSet中。默认情况下,G1只把10%的Old Region加入到CSet中,通过配置-XX:G1OldCSetRegionThresholdPercent=X可以更改
③提供最终的CSet和停顿预测
④描述Mixed GC状态细节。在这个案例中,我们仍然有535个Old Region可以被回收,大约305363768字节,占整个堆大小的14.22%。由于仍然大于阈值,下个阶段回收仍然是Mixed GC。

下面是Full GC开启-XX:+PrintAdaptiveSizePolicy之后执行日志

image.png

① 没有空的Region用来分配对象,请求扩容堆
② 扩容需要多少空间。到目前为止还没有真正执行扩容。
③ 不会尝试扩容。因为没有可用的Region,所有要执行Full GC。
④ 在最小堆小于最大堆时出现的日志。G1 在一次Full GC后,尝试缩小堆到70%。这个百分比可以通过-XX:InitiatingHeapOccupancyPercent(IHOP)调节,这个参数设置使用整个对的x%时,系统开始进行并行GC。注意是整个堆的百分比。
⑤ 堆正在被缩小,已经缩小了多少容量。

-XX:+PrintTenuringDistribution: 可以查看每次回收期间,Survivor区的分布信息。可以帮助我们查看对象年龄的变化。

image.png

上图主要从三个层面展示Survivor区:
-desired survivor size: 期望的Survivor大小。该值等于Survivor大小乘以TargetSurvivorRatio (默认50%)。

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

推荐阅读更多精彩内容