JDK8打印并分析GC日志
1 JDK8打印并分析GC日志
1.1 打印日志
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+UseSerialGC -Xmx1m -Xloggc:./gc-serial.log
参数 功能
-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:gc.log 日志文件的输出路径
使用Serial收集器打印日志
# JDK相关信息
Java HotSpot(TM) 64-Bit Server VM (25.221-b11) for windows-amd64 JRE (1.8.0_221-b11), built on Jul 4 2019 04:39:29 by "java_re" with MS VC++ 10.0 (VS2010)
# 内存相关信息
Memory: 4k page, physical 16647476k(6953016k free), swap 25560372k(12208608k free)
# 当前使用的JVM参数
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=1048576 -XX:+ManagementServer -XX:MaxHeapSize=1048576 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC
# Young GC
2022-01-04T21:59:21.976+0800: 0.058: [GC (Allocation Failure) 2022-01-04T21:59:21.976+0800: 0.058: [DefNew: 512K->63K(576K), 0.0008255 secs] 512K->437K(1984K), 0.0009437 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[当前时间戳:相对时间戳]：[[造成GC的原因]:[时间戳]:[年轻代: 回收前->回收后(年轻代总大小), 耗时] 回收前堆大小->回收后堆大小(堆总大小), 耗时] [用户耗时, 系统耗时，实际耗时]
# Full GC
2022-01-04T21:59:22.466+0800: 0.546: [Full GC (Allocation Failure) 2022-01-04T21:59:22.466+0800: 0.546: [Tenured: 1407K->1407K(1408K), 0.0032359 secs] 1983K->1519K(1984K), [Metaspace: 7463K->7463K(1056768K)], 0.0033010 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
格式分析类似于Young GC,打印老年代、元空间使用情况。
# 堆内存使用情况（年轻代、老年代、元空间）
Heap
def new generation total 576K, used 566K [0x00000000ffe00000, 0x00000000ffea0000, 0x00000000ffea0000)
eden space 512K, 100% used [0x00000000ffe00000, 0x00000000ffe80000, 0x00000000ffe80000)
from space 64K, 84% used [0x00000000ffe80000, 0x00000000ffe8d878, 0x00000000ffe90000)
to space 64K, 0% used [0x00000000ffe90000, 0x00000000ffe90000, 0x00000000ffea0000)
tenured generation total 1408K, used 1408K [0x00000000ffea0000, 0x0000000100000000, 0x0000000100000000)
the space 1408K, 100% used [0x00000000ffea0000, 0x0000000100000000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 9091K, capacity 9336K, committed 9472K, reserved 1056768K
class space used 1083K, capacity 1154K, committed 1280K, reserved 1048576K
- 对于不同内存区域，不同垃圾收集器展示名称不同。例如年轻代：DefNew（Serial收集器）、ParNew（ParNew收集器）、PSYoungGen（Parallel Scavenge收集器）。
CMS收集器
CMS触发垃圾回收时，打印各个GC环节。
# 初始标记
1.082: [GC (CMS Initial Mark) [1 CMS-initial-mark: 5895K(6848K)] 6267K(9920K), 0.0005152 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
# 并发标记
1.083: [CMS-concurrent-mark-start]
1.086: [CMS-concurrent-mark: 0.004/0.004 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
# 并发预清理
1.086: [CMS-concurrent-preclean-start]
1.087: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
# 重新标记
1.087: [GC (CMS Final Remark) [YG occupancy: 693 K (3072 K)]1.087: [Rescan (parallel) , 0.0006206 secs]1.088: [weak refs processing, 0.0000278 secs]1.088: [class unloading, 0.0012325 secs]1.089: [scrub symbol table, 0.0015527 secs]1.091: [scrub string table, 0.0002195 secs][1 CMS-remark: 5895K(6848K)] 6589K(9920K), 0.0037899 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
# 并发清理
1.091: [CMS-concurrent-sweep-start]
1.092: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
# 重置
1.093: [CMS-concurrent-reset-start]
1.093: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
G1收集器
# 这是一个年轻代GC，花费了0.0035900。下面的缩进，表示这行日志的子任务
2020-05-08T14:19:58.598-0800: 5.599: [GC pause (G1 Evacuation Pause) (young), 0.0035900 secs]
# 并行任务，并行GC花费2.4毫秒，并行阶段有8个线程
[Parallel Time: 2.4 ms, GC Workers: 8]
# 表示各个GC工作线程在应用启动多久(毫秒)后启动。
# 同时还做了个统计，例如这些GC线程最早启动的那个线程在应用启动后847.9毫秒后启动等
[GC Worker Start (ms): Min: 5598.7, Avg: 5599.1, Max: 5600.8, Diff: 2.1]
# 表示各个GC工作线程扫描跟对象花费的时间的统计
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.4]
# 表示各个GC工作线程更新Remembered Sets花费的时间的统计
# Remembered Sets是保存到堆中的区域的跟踪引用。设值方法线程持续改变对象图，自此引指向一个特定的区域。我们保存这些改变的跟踪信息到叫作Update Buffers的更新缓存中。Update RS子任务不能并发的处理更新缓存，更新一致所有区域的Remembered Sets
[Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.8, Diff: 1.8, Sum: 6.4]
# 表示每个GC工作线程处理的Update Buffers的数量统计
[Processed Buffers: Min: 0, Avg: 2.2, Max: 6, Diff: 6, Sum: 18]
# 每个GC工作线程扫描Remembered Sets花费的时间
# 一个区域的Remembered Sets包含指向这个区域的引用的相符合的卡片。这个阶段扫描这些卡片寻找指向所有这些区域的Collection Set的引用
[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耗时统计
[Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
# 各个GC工作线程完成任务后尝试中断GC线程到真正中断的耗时统计
# 在某个GC线程中断之前，会检查其它线程的工作队列，如果发现依然有任务，会帮助处理，之后再中断
[Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7]
# 尝试中断次数统计
[Termination Attempts: Min: 1, Avg: 2.4, Max: 12, Diff: 11, Sum: 19]
# 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: 0.2, Avg: 1.9, Max: 2.3, Diff: 2.2, Sum: 15.3]
# 各个GC工作线程线程的结束时间，min|max分别表示第一个|最后一个线程的结束时间。
[GC Worker End (ms): Min: 5601.0, Avg: 5601.0, Max: 5601.0, Diff: 0.0]
# 串行任务，修复GC期间code root指针改变的耗时
[Code Root Fixup: 0.0 ms]
# 串行任务，清除Code Root耗时
[Code Root Purge: 0.0 ms]
# 清除Card Table中的Dirty Card的耗时
[Clear CT: 0.1 ms]
# 其他任务
[Other: 1.1 ms]
# 为Collection Set选择区域所花费的时间
[Choose CSet: 0.0 ms]
# 花费在处理引用对象上的时间
[Ref Proc: 0.7 ms]
# 引用入队到ReferenceQueues花费的时间，可用-XX:+ParallelRefProcEnabled，并行处理这一步
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
# 处理超大对象
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
# 释放Collection Set数据结构花费的时间
[Free CSet: 0.0 ms]
# 各个区域的内存变化。
# 4096.0K：伊甸园当前占用4096.0K
# (4096.0K)：伊甸园总大小4096.0K
# 0.0B：收集后，伊甸园占用将会变成0
# (4096.0K)：伊甸园的目标大小（如有需要，JVM可能会自动增加伊甸园大小）
[Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 24.3M(30.0M)->20.6M(30.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]
# 2. 并发标记，标记线程数可用-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]
# 3. 最终标记(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]
# 4. 筛选回收(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]
JDK11打印日志
JDK11版本使用XLog统一管理日志，只需要一个日志参数。
-XX:+PrintGCDetails -XX:+UseG1GC -Xmx10m -Xloggc:./gc-serial.log
版权声明：本文为博主原创文章，未经博主允许不得转载。
