gc日志分析

GC日志分析,不同版本jdk和垃圾收集器的日志格式相差很多,以G1收集器,jdk8举例,参考:https://blog.csdn.net/weixin_42340670/article/details/121743655

gc日志中大部分都是young gc日志,即使有混合gc,在混合gc周期中也至少包含一次young gc。混合gc = 各种并发阶段 + n次young gc + n次mixed gc。并且标记为mixed gc日志的格式和young gc的日志格式相同,所以可以重点分析young gc日志。

young gc日志:

# 版本和环境信息
OpenJDK 64-Bit Server VM (25.292-b10) for linux-amd64 JRE (1.8.0_292-b10), built on Apr 21 2021 14:24:48 by "mockbuild" with gcc 4.8.5 20150623 (Red Hat 4.8.5-44)

# 内存信息,Memory:内存页大小,physical:物理内存,swap:交换分区
Memory: 4k page, physical 10485760k(10189192k free), swap 0k(0k free)

# 命令行参数,-XX:InitialHeapSize即参数中的-Xms XX:MaxHeapSize:即参数中的-Xmx
CommandLine flags: -XX:+AlwaysPreTouch -XX:ConcGCThreads=4 -XX:G1ReservePercent=10 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/logs/moa-service/live-link -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=4294967296 -XX:-OmitStackTraceInFastThrow -XX:ParallelGCThreads=4 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC

# 这是一个年轻代GC,花费了0.0035900。下面的缩进,表示这行日志的子任务,2020-05-08的14点19分58秒开始的young gc,距离jvm进程启动过去了5.599秒,(young)指的是年轻代gc,(mixed)指的是混合代gc即年轻代+老年代。(G1 Evacuation Pause)指的是产生本次gc的原因,空间使用达到阈值,如果是young gc则意味着年轻代已满,如果是mixed gc则大多数情况下是老年代空间占整个堆空间比例达到阈值(默认45%)。这个地方还可能是 (G1 Humongous Allocation) 表示巨型对象空间分配申请。每一个巨型对象的的内存分配都会触发一次gc尝试,如果当前已经处在并发标记周期阶段了,则不会主动发起gc,否则会主动发起gc。所以应用程序开发一定要注意避免产生巨型对象
2020-05-08T14:19:58.598-0800: 5.599: [GC pause (G1 Evacuation Pause) (young), 0.0035900 secs]

1) 并行执行的部分
# 多线程并行回收,并行GC花费2.4毫秒,并行阶段有8个工作线程
[Parallel Time: 2.4 ms, GC Workers: 8]

# 表示各个GC工作线程在应用启动多久(毫秒)后启动。这些数值指的是jvm进程启动时间点 - 当前时间点的毫秒时间差,min就是最早启动的,max就是最晚启动的,avg就是平均的启动时间,diff=max-min
[GC Worker Start (ms): Min: 5598.7, Avg: 5599.1, Max: 5600.8, Diff: 2.1]

# 外部根扫描(堆外扫描):外部根包括(JVM系统目录、VM数据结构、JNI线程句柄、硬件寄存器、全局变量、线程堆栈根)
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.4]

# 表示各个GC工作线程更新Remembered Sets花费的时间的统计
更新RSet:每个region都维护一个Rset,在有外部region引用本region内对象时,会记录外部region的card table索引。但这个引用信息的变更,是同步先写到一个队列,然后由一个单独的线程(叫做:并发优化线程)读取队列并异步更新RSet。所以,就可能存在这样的情况,垃圾回收时,队列中还存在着未被处理的变更日志,那么RSet信息就是不完整的。所以这个阶段要STW,检查队列中是否还有未处理完的变更记录,补充更新到RSet。
[Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.8, Diff: 1.8, Sum: 6.4]

# 已处理的缓冲:指的就是队列中那部分还没被消费完的变更记录
[Processed Buffers: Min: 0, Avg: 2.2, Max: 6, Diff: 6, Sum: 18]

#扫描所有region的RSet,来确定自己内部的存活对象。
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

# 扫描Code Root耗时统计。Code Root是JIT编译后的代码里引用了heap中的对象
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

# 这一步就是将存活对象迁移到新的region和survivor,也有一部分会晋升到老年代region。
[Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]

# 各个GC工作线程完成任务后尝试中断GC线程到真正中断的耗时统计
[Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7]

# 尝试中断次数统计,1次
[Termination Attempts: Min: 1, Avg: 2.4, Max: 12, Diff: 11, Sum: 19]

# GC工作线程花费在其他工作上的时间统计例如JNI编译,这部分不是GC活动
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.9, Diff: 0.9, Sum: 0.9]

# 各个GC工作线程花费的时间总和统计
[GC Worker Total (ms): Min: 97.4, Avg: 97.4, Max: 97.5, Diff: 0.1, Sum: 389.8]

# 各个GC工作线程线程的结束时间,min|max分别表示第一个|最后一个线程的结束时间。
[GC Worker End (ms): Min: 5601.0, Avg: 5601.0, Max: 5601.0, Diff: 0.0]

2)串行执行的部分
# 代码根修正:代码根所引用的存活对象,从一个region迁移到了另外的region,那么就需要更新他对这个对象的引用地址
[Code Root Fixup: 0.0 ms]

# 代码根清理:清理代码根中不再被使用的代码
[Code Root Purge: 0.0 ms]

# 清除Card Table中的Dirty Card的耗时
[Clear CT: 0.1 ms]

# 其他任务
[Other: 1.1 ms]
# 选择要回收的集合(只有在混合回收时,这一步才有意义,需要基于停顿时间的考量,利用启发性算法重新界定需要回收哪些region。单纯的young gc,就是所有年轻代region)
[Choose CSet: 0.0 ms]

# 引用处理:针对软引用(内存不足才回收)、弱引用(发生gc就可回收)、虚引用、final引用、JNI引用
[Ref Proc: 0.7 ms]

# 可以被回收的引用入队。
[Ref Enq: 0.0 ms]

# 上一步的引用处理,会更新RSet信息,所以也需要同步标记全局开标中对应的card table为脏卡片
[Redirty Cards: 0.3 ms]

# 巨型对象注册(统计):虽然巨型对象是存储在老年代分区的,但是G1内部也做了特殊优化手段,在young gc是也会顺带回收一些巨型对象分区。在young gc时,会基于region的RSet确定外部对自己的引用。而一旦Rset所对应的region是一个Humongous region(以下简称:H-Region),又通过逐层引用排查发现该H-Region已经不再被引用。那么就意味着这个H-Region可被回收。
[Humongous Register: 0.0 ms]

# 回收H-Region的耗时
[Humongous Reclaim: 0.0 ms]

# 回收CSet中region的空间,并将这些region重新置为空闲。
[Free CSet: 0.0 ms]

# 各个区域的内存变化。
# 伊甸区:回收前总内存一共2366M,使用了2366M。回收后变为0M,但是总内存增长了6M,变为2372M(如有需要,JVM可能会自动增加伊甸园大小)
# Suvivor区:回收前内存使用90M,回收后内存使用84M
# 整个堆空间:总内存是4096M,回收前使用了3410.9M,回收后使用了1055.1M,差值是2355M。其中eden区减少2366M,Suvivor区减少8M,新生代减少了2366+8=2374,整个堆减少2355M,所以老年代增加了约19M(2374-2355=19),有19M的对象晋升到了老年代。
[Eden: 2366.0M(2366.0M)->0.0B(2372.0M) Survivors: 92160.0K->86016.0K Heap: 3410.9M(4096.0M)->1055.1M(4096.0M)]

# 用户耗时、系统耗时、实际耗时
[Times: user=0.01 sys=0.00, real=0.01 secs]

# 开始扫描初始标记阶段Survivor区的Root Region
2020-05-08T14:19:54.087-0800: 1.087: [GC concurrent-root-region-scan-start]

# 扫描完成
2020-05-08T14:19:54.091-0800: 1.092: [GC concurrent-root-region-scan-end, 0.0049225 secs]

# 并发标记,标记线程数可用-XX:ConcGCThreads指定
2020-05-08T14:19:54.092-0800: 1.092: [GC concurrent-mark-start]

# 并发标记结束
2020-05-08T14:19:54.102-0800: 1.103: [GC concurrent-mark-end, 0.0106528 secs]

# 最终标记(stop the world)
2020-05-08T14:19:54.103-0800: 1.104: [GC remark 2020-05-08T14:19:54.103-0800: 1.104: [Finalize Marking, 0.0028699 secs] 2020-05-08T14:19:54.106-0800: 1.107: [GC ref-proc, 0.0001689 secs] 2020-05-08T14:19:54.106-0800: 1.107: [Unloading, 0.0053988 secs], 0.0087250 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]

# 筛选回收(stop the world)
# 没有存活对象的Old Region和Humongous Region将被释放和清空。
# 为了准备下次GC,在CSets中的Old Regions会根据他们的回收收益的大小排序。
2020-05-08T14:19:54.114-0800: 1.114: [GC cleanup 15M->14M(30M), 0.0006027 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

# 并发清理开始
2020-05-08T14:19:54.114-0800: 1.115: [GC concurrent-cleanup-start]

# 并发清理结束
2020-05-08T14:19:54.114-0800: 1.115: [GC concurrent-cleanup-end, 0.0000133 secs]

mixed gc:是一套动作,包含多个步骤,下面看下完整的mixed gc日志样例。

{Heap before GC invocations=439 (full 0):
garbage-first heap total 4194304K, used 3719960K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 895 young (1832960K), 25 survivors (51200K)
Metaspace used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
class space used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
2021-11-06T14:24:22.132+0800: 53382.293: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0597538 secs]
[Parallel Time: 51.9 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 53382297.2, Avg: 53382297.2, Max: 53382297.2, Diff: 0.1]
[Ext Root Scanning (ms): Min: 5.2, Avg: 5.5, Max: 5.7, Diff: 0.5, Sum: 22.0]
[Update RS (ms): Min: 7.1, Avg: 7.2, Max: 7.2, Diff: 0.1, Sum: 28.8]
[Processed Buffers: Min: 52, Avg: 57.8, Max: 67, Diff: 15, Sum: 231]
[Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.0, Sum: 1.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 37.5, Avg: 37.8, Max: 38.1, Diff: 0.6, Sum: 151.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.5]
[GC Worker Total (ms): Min: 50.8, Avg: 50.8, Max: 50.9, Diff: 0.1, Sum: 203.4]
[GC Worker End (ms): Min: 53382348.0, Avg: 53382348.1, Max: 53382348.1, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 7.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 2.2 ms]
[Eden: 1740.0M(1740.0M)->0.0B(1736.0M) Survivors: 51200.0K->51200.0K Heap: 3632.8M(4096.0M)->1896.8M(4096.0M)]
Heap after GC invocations=440 (full 0):
garbage-first heap total 4194304K, used 1942303K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 25 young (51200K), 25 survivors (51200K)
Metaspace used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
class space used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
}
[Times: user=0.16 sys=0.04, real=0.06 secs]
2021-11-06T14:24:22.192+0800: 53382.353: [GC concurrent-root-region-scan-start]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-root-region-scan-end, 0.0567419 secs]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-mark-start]
2021-11-06T14:24:22.776+0800: 53382.938: [GC concurrent-mark-end, 0.5277478 secs]
2021-11-06T14:24:22.778+0800: 53382.939: [GC remark 2021-11-06T14:24:22.778+0800: 53382.939: [Finalize Marking, 0.0004157 secs] 2021-11-06T14:24:22.778+0800: 53382.940: [GC ref-proc, 1.2651008 secs] 2021-11-06T14:24:24.043+0800: 53384.205: [Unloading, 0.0628071 secs], 1.3315890 secs]
[Times: user=1.33 sys=0.19, real=1.33 secs]
2021-11-06T14:24:24.111+0800: 53384.272: [GC cleanup 1908M->1577M(4096M), 0.0058486 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2021-11-06T14:24:24.118+0800: 53384.279: [GC concurrent-cleanup-start]
2021-11-06T14:24:24.119+0800: 53384.280: [GC concurrent-cleanup-end, 0.0009447 secs]
{Heap before GC invocations=441 (full 0):
garbage-first heap total 4194304K, used 3380949K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 893 young (1828864K), 25 survivors (51200K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
[Parallel Time: 60.2 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 53533231.3, Avg: 53533231.4, Max: 53533231.4, Diff: 0.2]
[Ext Root Scanning (ms): Min: 4.3, Avg: 5.2, Max: 7.3, Diff: 2.9, Sum: 20.8]
[Update RS (ms): Min: 22.6, Avg: 24.2, Max: 25.1, Diff: 2.6, Sum: 96.9]
[Processed Buffers: Min: 54, Avg: 69.0, Max: 104, Diff: 50, Sum: 276]
[Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 20.1, Avg: 21.5, Max: 22.7, Diff: 2.6, Sum: 86.1]
[Termination (ms): Min: 7.3, Avg: 8.6, Max: 10.4, Diff: 3.1, Sum: 34.5]
[Termination Attempts: Min: 455, Avg: 509.0, Max: 567, Diff: 112, Sum: 2036]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
[GC Worker Total (ms): Min: 59.9, Avg: 60.0, Max: 60.1, Diff: 0.3, Sum: 239.9]
[GC Worker End (ms): Min: 53533291.3, Avg: 53533291.3, Max: 53533291.4, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 88.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 82.9 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 1.5 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 2.3 ms]
[Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
garbage-first heap total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 25 young (51200K), 25 survivors (51200K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
[Times: user=0.26 sys=0.07, real=0.14 secs]
{Heap before GC invocations=442 (full 0):
garbage-first heap total 4194304K, used 1765803K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 102 young (208896K), 25 survivors (51200K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
[Parallel Time: 35.3 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 53545230.0, Avg: 53545230.1, Max: 53545230.1, Diff: 0.1]
[Ext Root Scanning (ms): Min: 2.1, Avg: 2.5, Max: 3.3, Diff: 1.3, Sum: 10.0]
[Update RS (ms): Min: 4.0, Avg: 4.4, Max: 4.6, Diff: 0.6, Sum: 17.8]
[Processed Buffers: Min: 32, Avg: 48.2, Max: 59, Diff: 27, Sum: 193]
[Scan RS (ms): Min: 2.8, Avg: 3.1, Max: 3.4, Diff: 0.6, Sum: 12.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 1.1]
[Object Copy (ms): Min: 24.5, Avg: 24.9, Max: 25.1, Diff: 0.6, Sum: 99.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 35.2, Avg: 35.2, Max: 35.3, Diff: 0.1, Sum: 140.9]
[GC Worker End (ms): Min: 53545265.3, Avg: 53545265.3, Max: 53545265.3, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 5.2 ms]
[Choose CSet: 0.4 ms]
[Ref Proc: 1.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.8 ms]
[Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
garbage-first heap total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 8 young (16384K), 8 survivors (16384K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
[Times: user=0.13 sys=0.02, real=0.04 secs]
{Heap before GC invocations=443 (full 0):
garbage-first heap total 4194304K, used 1365899K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 102 young (208896K), 8 survivors (16384K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
[Parallel Time: 101.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 53560789.1, Avg: 53560789.1, Max: 53560789.1, Diff: 0.1]
[Ext Root Scanning (ms): Min: 2.2, Avg: 2.5, Max: 2.7, Diff: 0.5, Sum: 9.8]
[Update RS (ms): Min: 15.1, Avg: 15.1, Max: 15.1, Diff: 0.0, Sum: 60.5]
[Processed Buffers: Min: 57, Avg: 70.8, Max: 85, Diff: 28, Sum: 283]
[Scan RS (ms): Min: 11.7, Avg: 12.3, Max: 12.9, Diff: 1.3, Sum: 49.1]
[Code Root Scanning (ms): Min: 0.4, Avg: 1.0, Max: 1.5, Diff: 1.1, Sum: 4.0]
[Object Copy (ms): Min: 65.4, Avg: 66.1, Max: 66.9, Diff: 1.4, Sum: 264.6]
[Termination (ms): Min: 4.3, Avg: 4.7, Max: 5.3, Diff: 1.1, Sum: 18.8]
[Termination Attempts: Min: 408, Avg: 490.0, Max: 617, Diff: 209, Sum: 1960]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 101.6, Avg: 101.7, Max: 101.7, Diff: 0.1, Sum: 406.7]
[GC Worker End (ms): Min: 53560890.7, Avg: 53560890.8, Max: 53560890.8, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 5.4 ms]
[Choose CSet: 0.5 ms]
[Ref Proc: 1.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.7 ms]
[Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
garbage-first heap total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
region size 2048K, 8 young (16384K), 8 survivors (16384K)
Metaspace used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
class space used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
[Times: user=0.36 sys=0.06, real=0.10 secs]

mixed gc日志分析:

一个完整的mixed gc是从(young) (initial-mark)开始,到(mixed)结束。如日志所示,一个完整的mixed gc可能有多个(mixed)即混合回收。整个mixde gc过程由几部分组成:并发标记周期(1个或者N个)+ 普通young gc(0次或者多次) + 混合回收周期

1、并发标记周期:从(young) (initial-mark)开始,到GC concurrent-cleanup-end结束。

initial-mark 初始标记:GC pause (G1 Evacuation Pause) (young) (initial-mark)

并发标记周期的开始步骤,一定是伴随着一次young gc一起产生。初始标记做的事情是标记根节点。这一步是需要STW的,正好可以和young gc一起做了,因为young gc也是STW,等于是搭个顺风车

concurrent-root-region 根分区扫描:

初始标记完成之后,也就意味着完成了一个young gc,存活的对象都被转移到了survivor分区。那么这些survivor分区的对象就是存活对象,他们都会被标记为根对象,这个过程称为根分区扫描,实际上扫描的是survivor分区。这个过程因为扫描的是survivor分区,所以这个过程不能和young gc同时进行,因为young gc会造成survivor分区的变化。

GC concurrent-mark 并发标记:

并发标记和应用线程并发执行。这一过程会扫描老年代,标记可达对象。

GC remark 重新标记:

STW的。这一过程会处理引用变更日志缓冲区的未被处理的日志。同时,[GC ref-proc]引用处理也是重新标记阶段的一部分。这一步是可以多线程并行执行。

GC cleanup 独占清理:紧跟重新标记,此时还是STW的,同时这一步还会做三个事情

  • RSet梳理:启发式算法或根据Rset尺寸对分区定义不同的等级。(RSet尺寸越大,说明对本分区的引用越多,那么本分区的等级也会越高)
  • 堆分区梳理:针对老年代的分区,基于释放空间和暂停目标,定识别出回收收益高的region。
  • 识别所有空闲分区:标记那些内部对象都是非存活的分区。

GC concurrent-cleanup 并发清理:回收线程和应用程序并发执行,回收上一步被标记为空闲的分区

2、mixed(混合)回收周期

在上面介绍的并发标记周期中,虽然也经历了回收(清理)动作(GC concurrent-cleanup),但是只是仅仅清理了那些对象都不存活的空闲分区。对于那些部分对象存活的年轻代和老年代分区还没有进行数据的迁移和分区的清理动作。但是在并发标记周期中已经识别出了应该回收哪些分区,所以接下来都是gc pause动作,会包含一次或多次的GC pause。最后一次的GC pause是mixed类型。混合回收周期内,也是可以发生单纯的young gc的。
     我们上面的的例子里,混合回收周期内就包含了一次young gc + 两次mixed gc。第一次单纯的young gc,只清理了年轻代,堆空间由3301M减少到1570M。young gc后面的mixed gc,年轻代和老年代都被清理,但年轻代被清理前仅仅使用了154M,清理后整个堆空间从1724M减少到1145M,我们大约可估算,即使年轻代都被清理堆空间大概减少到1570M,而当前是1145M,所以老年代被清理释放的空间应该>=425M。第二次mixed gc,年轻代和老年代都被清理,年轻代被清理前仅仅使用了188M,清理后整个堆空间从1334M减少到859M,老年代至少被清理了287M。

 

posted @   MarkLeeBYR  阅读(149)  评论(0编辑  收藏  举报
相关博文:
阅读排行:
· CSnakes vs Python.NET:高效嵌入与灵活互通的跨语言方案对比
· 【.NET】调用本地 Deepseek 模型
· Plotly.NET 一个为 .NET 打造的强大开源交互式图表库
· 上周热点回顾(2.17-2.23)
· DeepSeek “源神”启动!「GitHub 热点速览」
点击右上角即可分享
微信分享提示