本文深入解析G1垃圾回收器的工作原理，涵盖年轻代、并发及混合垃圾回收的流程与日志解读，助您理解G1如何高效管理内存。
前言
启动 Java 服务时带上参数-Xloggc:/home/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps会打印 GC 的细节到文件 /home/gc.log。另外通过-XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo参数可以打印 G1 在清除阶段每个 Region 存活对象信息
1. G1 年轻代垃圾回收
1.1 Yong GC 日志样例
一次典型的G1 收集器 YGC如下。这是一个STW，所有的应用线程停止在安全点，日志通过缩进来区分子任务
2020-04-15T09:54:03.706+0800: 153105.710: [GC pause (G1 Evacuation Pause) (young), 0.0079319 secs]
[Parallel Time: 4.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 153105710.1, Avg: 153105711.9, Max: 153105713.8, Diff: 3.7]
[Ext Root Scanning (ms): Min: 0.3, Avg: 2.2, Max: 4.7, Diff: 4.4, Sum: 9.0]
[Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9]
[Processed Buffers: Min: 0, Avg: 5.8, Max: 13, Diff: 13, Sum: 23]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.1, Avg: 0.4, Max: 0.7, Diff: 0.6, Sum: 1.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 6]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 1.1, Avg: 2.9, Max: 4.7, Diff: 3.7, Sum: 11.6]
[GC Worker End (ms): Min: 153105714.8, Avg: 153105714.8, Max: 153105714.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 1.8 ms]
[Other: 1.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 24.0M(24.0M)->0.0B(24.0M) Survivors: 1024.0K->1024.0K Heap: 81.6M(128.0M)->57.6M(128.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
1. 2 日志解读
-
首行蓝色字体为 GC 开始的时间，绿色字体为GC 开始时距离 JVM 启动的秒数，红色字体表明这是G1的 Evacuation Pause(转移暂停)，在这个阶段年轻代分区存活的对象被从一个分区拷贝到另一个分区，最后是花费的时间
2020-04-15T09:54:03.706+0800: 153105.710: [GC pause (G1 Evacuation Pause) (young), 0.0079319 secs]
-
这部分列出了新生代收集中并行收集的详细过程
Parallel Time
并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费4.8 msGC Workers
4 个线程负责垃圾收集，线程数可通过参数-XX:ParallelGCThreads设置。这个参数的值的设置跟CPU有关，如果物理CPU支持的线程个数小于8，则最多设置为8；如果物理CPU支持的线程个数大于8，则默认值为支持的线程个数 * 5 / 8GC Worker Start
Min：垃圾收集线程开始工作时 JVM 启动后经过的最小时间
Avg：垃圾收集线程开始工作时 JVM 启动后经过的平均时间
Max：垃圾收集线程开始工作时 JVM 启动后经过的最大时间
Diff：表示 Min 和 Max 之间的差值，理想情况下所有 GC 线程几乎是同时开始工作，即 Diff 趋近于0Ext Root Scanning
扫描线程栈、JNI、全局变量、系统表等root根节点集合花费的时间，扫描 root 集合是垃圾收集的起点，该步骤扫描是否有root集合中的节点指向当前的收集集合（CSet），即对象是否可达Update RS
每个分区都有自己的RSet(Remembered Set)，用来记录其他分区指向当前分区的指针。如果RSet有更新，G1中会有一个post-write barrier管理跨分区的引用：新的被引用的 card 会被标记为 dirty，并放入一个日志缓冲区，如果这个日志缓冲区满了会被加入到一个全局的缓冲区。在 JVM 运行的过程中还有线程在并发处理这个全局日志缓冲区的dirty card，Update RS表示允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区，这可以确保当前分区的 RSet 是最新的Processed Buffers表明在Update RS这个过程中处理多少个日志缓冲区Scan RS
扫描每个新生代分区的 RSet，找出有多少指向当前分区的引用来自 CSet 花费的时间Code Root Scanning
扫描代码中的局部变量root节点花费的时间Object Copy
在暂停期间，所有在 CSet 中的分区的存活对象必须被转移疏散，该步骤就负责将当前分区中存活的对象拷贝到新的分区Termination
当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks），Min表示该垃圾收集线程什么时候尝试结束工作，Max表示该垃圾收集回收线程什么时候真正结束工作Termination Attempts
如果一个垃圾收集线程成功帮助其他线程完成任务，那么它会再次盗取更多的任务或尝试结束工作，每次重新尝试结束工作的时候，这个数值就会增加GC Worker Other
垃圾收集线程在完成其他任务的时间GC Worker Total
每个垃圾收集线程的最小、最大、平均、差值和总共时间GC Worker End
Min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；Max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下各个线程最好快速结束，并且最好是同一时间结束
[Parallel Time: 4.8 ms, GC Workers: 4] [GC Worker Start (ms): Min: 153105710.1, Avg: 153105711.9, Max: 153105713.8, Diff: 3.7] [Ext Root Scanning (ms): Min: 0.3, Avg: 2.2, Max: 4.7, Diff: 4.4, Sum: 9.0] [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9] [Processed Buffers: Min: 0, Avg: 5.8, Max: 13, Diff: 13, Sum: 23] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.1, Avg: 0.4, Max: 0.7, Diff: 0.6, Sum: 1.5] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 6] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 1.1, Avg: 2.9, Max: 4.7, Diff: 3.7, Sum: 11.6] [GC Worker End (ms): Min: 153105714.8, Avg: 153105714.8, Max: 153105714.8, Diff: 0.0] -
列出新生代 GC 中的一些任务
Code Root Fixup
释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行Code Root Purge
清理更多的数据结构，应该很快，耗时接近于0，也是线性执行Clear CT
清理card tableOtherChoose CSet：选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
Ref Proc：处理Java中的各种引用——soft、weak、final、phantom、JNI等等
Ref Enq：遍历所有的引用，将不能回收的放入pending列表
Redirty Card：在回收过程中被修改的card将会被重置为dirty
Humongous Register：巨型对象在新生代收集的时候被回收花费的时间，通过参数XX:+G1EagerReclaimHumongousObjects可设置是否在YGC时回收巨型对象，默认为 true
Humongous Reclaim：完成这些任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到 free 列表，并且更新空闲空间大小
Free CSet：将要释放的分区还回到 free 列表
[Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 1.8 ms] [Other: 1.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 1.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] -
不同代的内存空间大小变化，以及堆大小的自适应调整
[Eden: 24.0M(24.0M)->0.0B(24.0M) Survivors: 1024.0K->1024.0K Heap: 81.6M(128.0M)->57.6M(128.0M)] [Times: user=0.01 sys=0.00, real=0.01 secs]
2. G1 并发垃圾收集
2.1 日志样例
2020-04-16T09:20:50.450+0800: 62599.287: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0051579 secs]
......
[Eden: 53.0M(53.0M)->0.0B(55.0M) Survivors: 2048.0K->1024.0K Heap: 111.2M(128.0M)->57.9M(128.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2020-04-16T09:20:50.456+0800: 62599.292: [GC concurrent-root-region-scan-start]
2020-04-16T09:20:50.456+0800: 62599.292: Total time for which application threads were stopped: 0.0061480 seconds, Stopping threads took: 0.0001037 seconds
2020-04-16T09:20:50.458+0800: 62599.294: [GC concurrent-root-region-scan-end, 0.0025203 secs]
2020-04-16T09:20:50.458+0800: 62599.294: [GC concurrent-mark-start]
2020-04-16T09:20:50.572+0800: 62599.408: [GC concurrent-mark-end, 0.1137222 secs]
2020-04-16T09:20:50.573+0800: 62599.409: [GC remark 2020-04-16T09:20:50.573+0800: 62599.409: [Finalize Marking, 0.0002817 secs] 2020-04-16T09:20:50.573+0800: 62599.409: [GC ref-proc, 0.0019343 secs] 2020-04-16T09:20:50.575+0800: 62599.411
: [Unloading, 0.0315269 secs], 0.0340811 secs]
[Times: user=0.09 sys=0.00, real=0.03 secs]
2020-04-16T09:20:50.607+0800: 62599.443: Total time for which application threads were stopped: 0.0349111 seconds, Stopping threads took: 0.0000578 seconds
2020-04-16T09:20:50.608+0800: 62599.444: [GC cleanup 60M->60M(128M), 0.0009348 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2.2 日志解读
-
并发垃圾收集阶段的开始
GC pause(G1 Evacuation Pause)(young)(initial-mark)：为了充分利用 STW 的机会来扫描所有可达对象，initial-mark阶段是作为新生代垃圾收集中的一部分存在的。initial-mark设置了两个 TAMS（top-at-mark-start）变量用来区分存活的对象和在并发标记阶段新分配的对象，在TAMS之前的所有对象在当前周期内都会被视作存活的 -
并发标记阶段做的第一件事情：根分区扫描
GC concurrent-root-region-scan-start：根分区扫描开始，根分区扫描主要扫描的是新的 survivor 分区，找到这些分区内的对象指向当前分区的引用，如果发现有引用，则做个记录
GC concurrent-root-region-scan-end：根分区扫描结束 -
并发标记阶段
GC Concurrent-mark-start：并发标记阶段开始（1）并发标记阶段的线程是跟应用线程一起运行的，不会STW，所以称为并发；并发标记阶段的垃圾收集线程，默认值是Parallel Thread个数的25%，这个值也可以用参数
-XX:ConcGCThreads设置
（2）trace整个堆，并使用位图标记所有存活的对象，因为在top TAMS之前的对象是隐式存活的，所以这里只需要标记出那些在top TAMS之后、阈值之前的
（3）记录在并发标记阶段的变更，G1这里使用了SATB算法，该算法要求在垃圾收集开始的时候给堆做一个快照，在垃圾收集过程中这个快照是不变的，但实际上肯定有些对象的引用会发生变化，这时候G1使用了pre-write barrier记录这种变更，并将这个记录存放在一个SATB缓冲区中，如果该缓冲区满了就会将它加入到一个全局的缓冲区，同时G1有一个线程在并行得处理这个全局缓冲区
（4）在并发标记过程中，会记录每个分区的存活对象占整个分区的大小的比率GC Concurrent-mark-end：并发标记阶段结束 -
重新标记阶段，会 Stop the World
Finalize Marking：Finalizer列表里的Finalizer对象处理
GC ref-proc：引用（soft、weak、final、phantom、JNI等等）处理
Unloading：类卸载
这个阶段最关键的作用扫描出当前并发周期中整个堆的最后状态，剩余的SATB缓冲区会在这里被处理，所有存活的对象都会被标记 -
清理阶段，会Stop the World
- 计算出最后存活的对象
标记出initial-mark阶段后分配的对象；标记出至少有一个存活对象的分区 - 没有存活对象的老年代分区和巨型对象分区会被释放和清理
- 处理没有任何存活对象的分区的RSet
- 所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的CSet选择过程做准备
- 计算出最后存活的对象
-
并发清理阶段
GC concurrent-cleanup-start
完成第5步剩余的清理工作；将完全清理好的分区加入到二级free列表，等待最终还到总体的free列表GC concurrent-cleanup-end：并发清理阶段结束
3. G1 混合垃圾回收
混合收集阶段的日志如下所示，这份日志的大部分与新生代收集相同，只是首行不同：GC pause(G1 Evacuation Pause)(mixed)。这些表示这是一个混合垃圾收集周期，在这个阶段处理的CSet不仅包括新生代的分区，还包括老年代分区，也就是并发标记阶段标记出来的那些老年代分区
2020-04-16T09:48:03.283+0800: 64232.120: [GC pause (G1 Evacuation Pause) (mixed), 0.0063376 secs]
[Parallel Time: 5.4 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 64232119.9, Avg: 64232119.9, Max: 64232119.9, Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.5, Avg: 1.9, Max: 2.5, Diff: 1.0, Sum: 7.4]
[Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.6]
[Processed Buffers: Min: 0, Avg: 2.5, Max: 8, Diff: 8, Sum: 10]
[Scan RS (ms): Min: 0.5, Avg: 0.8, Max: 1.0, Diff: 0.5, Sum: 3.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 2.5, Diff: 2.5, Sum: 2.5]
[Object Copy (ms): Min: 0.3, Avg: 1.9, Max: 2.7, Diff: 2.4, Sum: 7.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 2.2, Max: 4, Diff: 3, Sum: 9]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.4, Diff: 0.0, Sum: 21.5]
[GC Worker End (ms): Min: 64232125.3, Avg: 64232125.3, Max: 64232125.3, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 5120.0K(5120.0K)->0.0B(63.0M) Survivors: 1024.0K->1024.0K Heap: 62.7M(128.0M)->50.3M(128.0M)]
[Times: user=0.02 sys=0.00, real=0.00 secs]
扫一扫
1791
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
