HuKai's Blog
HuKai
2022-02-13
目录

GC日志详解

# 常见配置汇总

# 堆参数配置

  • -Xms：设置堆的初始容量。示例：-Xms2M
  • -Xmx：设置堆的最大容量。示例：-Xms3M
  • -Xmn：设置年轻代的堆的初始容量，此选项相当于-XX:NewSize。示例：-Xmn1M或-XX:NewSize=1M
  • -XX:NewRatio=n：设置年轻代和年老代的比值。示例:-XX:NewRatio=3，表示年轻代与年老代比值为1：3，年轻代占整个年轻代年老代和的1/4。一般情况下，不允许-XX:Newratio值小于1，即Old要比Yong大
  • -XX:SurvivorRatio=n：年轻代中Eden区与两个Survivor区的比值，注意Survivor区有两个。示例：-XX:SurvivorRatio=5，表示Eden：Survivor=5：2，此时Eden区占年轻代的5/7。

# 栈和方法区参数配置

  • -Xss：设置线程堆栈大小，此选项相当于-XX:ThreadStackSize。示例：-Xss1m
  • -XX:MetaspaceSize=n：设置分配的类元数据空间的大小
  • -XX:MaxMetaspaceSize=n：设置可以为类元数据分配的最大本机内存量

# 打印参数

  • -XX:+PrintCommandLineFlags：打印出用户手动设置或者JVM自动设置的XX选项（如堆空间大小和所选垃圾收集器）
  • -XX:+PrintFlagsInitial：打印出所有XX选项的默认值
  • -XX:+PrintFlagsFinal：打印出XX选项在运行程序时生效的值

示例：java -XX:+PrintCommandLineFlags -version

# 垃圾回收统计信息参数

  • -verbose:gc：显示有关每个垃圾回收（GC）事件的信息
  • -Xloggc:/path/gc.log：指定GC日志路径
  • -XX:+PrintGC：允许在每个GC上打印消息
  • -XX:+PrintGCDateStamps：允许在每个GC上打印日期戳
  • -XX:+PrintGCDetails：允许在每个GC上打印详细消息
  • -XX:+PrintGCTaskTimeStamps：允许为每个GC工作线程任务打印时间戳
  • -XX:+PrintGCTimeStamps：允许在每个GC上打印时间戳
  • -XX:+PrintHeapAtGC：在GC发生之前与之后打印堆的详细信息

GC日志测试推荐组合：

-Xmn2m -Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseSerialGC -XX:+PrintCommandLineFlags
-Xmn2m -Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseSerialGC -XX:+PrintCommandLineFlags
1
2

# Serial+Serial Old日志解析

参数：-Xmn2m -Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseSerialGC -XX:+PrintCommandLineFlags

# GC调用前堆详细信息

Heap before GC invocations=0 (full 0):// ①
 def new generation   total 1856K, used 1664K [0x00000000ffa00000, 0x00000000ffc00000, 0x00000000ffc00000)// ②
  eden space 1664K, 100% used [0x00000000ffa00000, 0x00000000ffba0000, 0x00000000ffba0000)// ③
  from space 192K,   0% used [0x00000000ffba0000, 0x00000000ffba0000, 0x00000000ffbd0000)// ④
  to   space 192K,   0% used [0x00000000ffbd0000, 0x00000000ffbd0000, 0x00000000ffc00000)// ⑤
 tenured generation   total 4096K, used 0K [0x00000000ffc00000, 0x0000000100000000, 0x0000000100000000)// ⑥
   the space 4096K,   0% used [0x00000000ffc00000, 0x00000000ffc00000, 0x00000000ffc00200, 0x0000000100000000)// ⑦
 Metaspace       used 2969K, capacity 4494K, committed 4864K, reserved 1056768K// ⑧
  class space    used 324K, capacity 386K, committed 512K, reserved 1048576K
1
2
3
4
5
6
7
8
9
  • ①：GC调用前输出Heap详细信息、GC第0次调用、第0次full gc
  • ②：def new generation在使用Serial收集器时代表新生代。新生代总空间1856K，已使用1664K
  • ③：eden区（总空间、已使用百分比）
  • ④：from区（总空间、已使用百分比）
  • ⑤：to区（总空间、已使用百分比）
  • ⑥：tenured generation在使用Serial收集器时代表老年代。老年代总空间4096K，已使用0K
  • ⑦：老年代（总空间、已使用百分比）
  • ⑧：元空间（已使用空间、总空间、已提交、预留）

# Minor GC

2019-11-29T14:18①:31.938+0800②: [GC③ (Allocation Failure)④ 2019-11-29T14:18:31.939+0800⑤: [DefNew: 1664K->191K(1856K), 0.0025245 secs]⑥ 1664K->689K(5952K), 0.0030027 secs⑦] [Times: user=0.02 sys=0.00, real=0.00 secs] ⑧

  • ①：GC发生的起始时间。日期时间戳
  • ②：GC开始，相对JVM启动的相对时间，单位是秒
  • ③：GC类型。这里代表Minor GC
  • ④：GC发生的原因。新生代内存分配失败
  • ⑤：同①和②
  • ⑥：DefNew代表新生代。1664K->191K(1856K) 回收前新生代使用大小->回收后新生代使用大小（新生代总大小）。耗时0.0025245s
  • ⑦：1664K->689K(5952K)。回收前使用堆大小->回收后使用堆大小（堆总大小）。耗时0.0030027s
  • ⑧：GC事件在不同维度的耗时，不做深究

通过分析这段日志，我们可以得到这样一段信息：

在2019-11-29 14:18分左右，JVM因为新生代内存分配失败引发了一次Minor GC，回收前新生代已使用了1664K，堆空间已使用1664K，回收后新生代已使用空间变为191K，整堆已使用空间变为689K。GC耗时0.0030027s

# Full/Major GC

2019-11-29T14:18:31.969+0800: [Full GC① (Allocation Failure)② 2019-11-29T14:18:31.969+0800: [DefNew: 1120K->1120K(1856K), 0.0000288 secs]③2019-11-29T14:18:31.970+0800: [Tenured: 3761K->3761K(4096K), 0.0027653 secs]④ 4882K->4851K(5952K)⑤, [Metaspace: 3445K->3445K(1056768K)], 0.0031942 secs]⑥ [Times: user=0.00 sys=0.00, real=0.00 secs]

  • ①：GC类型。这里代表Full GC
  • ②：GC发生的原因。内存分配失败
  • ③：DefNew新生代回收详情。回收前新生代使用大小->回收后新生代使用大小（新生代总大小）、回收耗时
  • ④：Tenured老年代回收详情。回收前老年代使用大小->回收后老年代使用大小（新生代总大小）、回收耗时
  • ⑤：回收前使用堆大小->回收后使用堆大小（堆总大小）、回收耗时
  • ⑥：Metaspace元空间回收详情。回收前元空间使用大小->回收后元空间使用大小（元空间总大小）、回收耗时

# GC调用后堆详细信息

Heap after GC invocations=3 (full 1):
 def new generation   total 1856K, used 1089K [0x00000000ffa00000, 0x00000000ffc00000, 0x00000000ffc00000)
  eden space 1664K,  65% used [0x00000000ffa00000, 0x00000000ffb10740, 0x00000000ffba0000)
  from space 192K,   0% used [0x00000000ffba0000, 0x00000000ffba0000, 0x00000000ffbd0000)
  to   space 192K,   0% used [0x00000000ffbd0000, 0x00000000ffbd0000, 0x00000000ffc00000)
 tenured generation   total 4096K, used 3761K [0x00000000ffc00000, 0x0000000100000000, 0x0000000100000000)
   the space 4096K,  91% used [0x00000000ffc00000, 0x00000000fffac5d8, 0x00000000fffac600, 0x0000000100000000)
 Metaspace       used 3445K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 375K, capacity 388K, committed 512K, reserved 1048576K
1
2
3
4
5
6
7
8
9

GC调用前后的日志结构是一样的，可以参考GC调用前堆详细信息，在此不做赘述。

# Minor GC和Full GC简化模式日志

参数：-Xmn2m -Xmx6M -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+UseSerialGC -XX:+PrintCommandLineFlags

// Minor GC
2019-12-02T09:29:20.203+0800: [GC (Allocation Failure)  1664K->689K(5952K), 0.0055664 secs]

//Full GC
2019-12-02T09:29:20.222+0800: [Full GC (Allocation Failure)  4910K->4824K(5952K), 0.0021004 secs]
1
2
3
4
5

结合上面的详细日志不难发现，简化日志只输出了总体回收结果，没有各区域的详细信息。

# ParNew+CMS、Parallel+Parallel Old日志解析

参数：

  • ParNew+CMS：-Xmn2m -Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintCommandLineFlags
  • Parallel+Parallel Old：-Xmn2m -Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseParallelGC -XX:+PrintCommandLineFlags

这两种收集器组合的GC日志总体上和Serial+Serial Old类似，下面只标注不同点。

# GC调用前后堆详细信息

ParNew+CMS：

Heap before GC invocations=0 (full 0):
 par new generation   total 1856K, used 1664K [0x00000000ffa00000, 0x00000000ffc00000, 0x00000000ffc00000)// ①
  eden space 1664K, 100% used [0x00000000ffa00000, 0x00000000ffba0000, 0x00000000ffba0000)
  from space 192K,   0% used [0x00000000ffba0000, 0x00000000ffba0000, 0x00000000ffbd0000)
  to   space 192K,   0% used [0x00000000ffbd0000, 0x00000000ffbd0000, 0x00000000ffc00000)
 concurrent mark-sweep generation total 4096K, used 0K [0x00000000ffc00000, 0x0000000100000000, 0x0000000100000000)// ②
 Metaspace       used 2969K, capacity 4494K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 386K, committed 512K, reserved 1048576K
1
2
3
4
5
6
7
8

Parallel+Parallel Old：

Heap before GC invocations=1 (full 0):
 PSYoungGen      total 1536K, used 1024K [0x00000000ffe00000, 0x0000000100000000, 0x0000000100000000)// ①
  eden space 1024K, 100% used [0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 4096K, used 0K [0x00000000ffa00000, 0x00000000ffe00000, 0x00000000ffe00000)// ②
  object space 4096K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffe00000)
 Metaspace       used 2506K, capacity 4480K, committed 4480K, reserved 1056768K
  class space    used 272K, capacity 384K, committed 384K, reserved 1048576K
1
2
3
4
5
6
7
8
9
  • ①：par new generation是ParNew收集器下的新生代。PSYoungGen是Parallel收集器下的新生代
  • ②：concurrent mark-sweep是CMS收集器下的老年代。ParOldGen是Parallel Old收集器下的老年代

# Minor GC

ParNew+CMS：

2019-12-02T10:15:41.384+0800: [GC (Allocation Failure) 2019-12-02T10:15:41.384+0800: [ParNew①: 1664K->192K(1856K), 0.0021344 secs] 1664K->712K(5952K), 0.0021918 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Parallel+Parallel Old：

2019-12-02T11:22:32.526+0800: [GC (Allocation Failure) [PSYoungGen①: 1024K->488K(1536K)] 1024K->648K(5632K), 0.0008680 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

  • ①：ParNew是ParNew收集器下的新生代，PSYoungGen是Parallel收集器下的新生代

# Full/Major GC

ParNew+CMS：

2019-12-02T10:15:41.400+0800: [Full GC (Allocation Failure) 2019-12-02T10:15:41.400+0800: [CMS①: 2774K->2755K(4096K), 0.0020522 secs] 2774K->2755K(5952K), [Metaspace: 3342K->3342K(1056768K)], 0.0020812 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Parallel+Parallel Old：

2019-12-02T11:22:32.561+0800: [Full GC (Allocation Failure) [PSYoungGen: 488K->0K(1536K)] [ParOldGen①: 2424K->2793K(4096K)] 2912K->2793K(5632K), [Metaspace: 3361K->3361K(1056768K)], 0.0055714 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

  • ①：CMS是CMS收集器下的老年代，ParOldGen是Parallel Old收集器下的老年代

# G1日志解析

参数：-Xmx6M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseG1GC -XX:+PrintCommandLineFlags

G1的GC日志相对复杂，想要理解日志内容，首先要搞清楚G1垃圾回收的过程，如果不清楚，请先回顾一下。

# Young GC

下面这张图是新生代收集的标准流程，我在这里将它分成了6个步骤：

1. 4个关键信息

  • 新生代垃圾收集发生的时间——2016-12-12T10:40:18.811-0500，通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间
  • JVM启动后的相对时间——25.959
  • 这次收集的类型——新生代收集，只回收Eden分区
  • 这次收集花费的时间——0.0305171s，即30ms

2. 列出了新生代收集中并行收集的详细过程

  • Parallel Time：并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费26.6ms
  • GC Workers：有4个线程负责垃圾收集，通过参数-XX:ParallelGCThreads设置，这个参数的值的设置，跟CPU有关，如果物理CPU支持的线程个数小于8，则最多设置为8；如果物理CPU支持的线程个数大于8，则默认值为number * 5/8
  • GC Worker Start：第一个垃圾收集线程开始工作时JVM启动后经过的时间（min）；最后一个垃圾收集线程开始工作时JVM启动后经过的时间（max）；diff表示min和max之间的差值。理想情况下，你希望他们几乎是同时开始，即diff趋近于0
  • Ext Root Scanning：扫描root集合（线程栈、JNI、全局变量、系统表等等）花费的时间，扫描root集合是垃圾收集的起点，尝试找到是否有root集合中的节点指向当前的收集集合（CSet）
  • Update RS(Remembered Set or RSet)：每个分区都有自己的RSet，用来记录其他分区指向当前分区的指针，如果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中的分区必须被转移疏散，Object Copy就负责将当前分区中存活的对象拷贝到新的分区
  • Termination：当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks），min表示该垃圾收集线程什么时候尝试terminatie，max表示该垃圾收集回收线程什么时候真正terminated。
  • Termination Attempts：如果一个垃圾收集线程成功盗取了其他线程的任务，那么它会再次盗取更多的任务或再次尝试terminate，每次重新terminate的时候，这个数值就会增加
  • GC Worker Other：垃圾收集线程在完成其他任务的时间
  • GC Worker Total：展示每个垃圾收集线程的最小、最大、平均、差值和总共时间
  • GC Worker End：min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，你希望它们快速结束，并且最好是同一时间结束

3. 列出了新生代GC中的一些任务

  • Code Root Fixup：释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行的；
  • Code Root Purge：清理更多的数据结构，应该很快，耗时接近于0，也是线性执行。
  • Clear CT：清理card table

4. 包含一些扩展功能

  • Choose CSet：选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先） Ref Proc：处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
  • Ref Enq：遍历所有的引用，将不能回收的放入pending列表
  • Redirty Card：在回收过程中被修改的card将会被重置为dirty
  • Humongous Register：JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true。
  • Humongous Reclaim：做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
  • Free CSet：将要释放的分区还回到free列表。

5. 展示了不同代的大小变化，以及堆大小的自适应调整

  • Eden:1097.0M(1097.0M)->0.0B(967.0M)：（1）当前新生代收集触发的原因是Eden空间满了，分配了1097M，使用了1097M；（2）所有的Eden分区都被疏散处理了，在新生代结束后Eden分区的使用大小成为了0.0B；（3）Eden分区的大小缩小为967.0M
  • Survivors:13.0M->139.0M：由于年轻代分区的回收处理，survivor的空间从13.0M涨到139.0M；
  • Heap:1694.4M(2048.0M)->736.3M(2048.0M)：（1）在本次垃圾收集活动开始的时候，堆空间整体使用量是1694.4M，堆空间的最大值是2048M；（2）在本次垃圾收集结束后，堆空间的使用量是763.4M，最大值保持不变。

6. 展示了本次新生代垃圾收集的时间

  • user=0.8：垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关，可能会比real time大很多；
  • sys=0.0：内核态线程消耗的CPU时间
  • real=0.03：本次垃圾收集真正消耗的时间；

# 并发垃圾收集

G1的第二种收集活动是并发垃圾收集，并发垃圾收集的触发条件有很多，但是做的工作都相同，它的日志如下图所示：

1. 标志着并发垃圾收集阶段的开始

  • GC pause(G1 Evacuation Pause)(young)(initial-mark)：为了充分利用STW的机会来trace所有可达（存活）的对象，initial-mark阶段是作为新生代垃圾收集中的一部分存在的（搭便车）。initial-mark设置了两个TAMS（top-at-mark-start）变量，用来区分存活的对象和在并发标记阶段新分配的对象。在TAMS之前的所有对象，在当前周期内都会被视作存活的。

2. 表示第并发标记阶段做的第一个事情：根分区扫描

  • GC concurrent-root-region-scan-start：根分区扫描开始，根分区扫描主要扫描的是新的survivor分区，找到这些分区内的对象指向当前分区的引用，如果发现有引用，则做个记录；
  • GC concurrent-root-region-scan-end：根分区扫描结束，耗时0.0030613s

3. 表示并发标记阶段

  • 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：并发标记阶段结束，耗时0.3055438s

4. 重新标记阶段，会Stop the World

  • Finalize Marking：Finalizer列表里的Finalizer对象处理，耗时0.0014099s；
  • GC ref-proc：引用（soft、weak、final、phantom、JNI等等）处理，耗时0.0000480s；
  • Unloading：类卸载，耗时0.0025840s；
  • 除了前面这几个事情，这个阶段最关键的结果是：绘制出当前并发周期中整个堆的最后面貌，剩余的SATB缓冲区会在这里被处理，所有存活的对象都会被标记；

5. 清理阶段，也会Stop the World

  • 计算出最后存活的对象：标记出initial-mark阶段后分配的对象；标记出至少有一个存活对象的分区；
  • 为下一个并发标记阶段做准备，previous和next位图会被清理；
  • 没有存活对象的老年代分区和巨型对象分区会被释放和清理；
  • 处理没有任何存活对象的分区的RSet；
  • 所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的CSet选择过程做准备；

6. 并发清理阶段

  • GC concurrent-cleanup-start：并发清理阶段启动。完成第5步剩余的清理工作；将完全清理好的分区加入到二级free列表，等待最终还会到总体的free列表；
  • GC concurrent-cleanup-end：并发清理阶段结束，耗时0.0012954s

# Mixed GC

在并发收集阶段结束后，你会看到混合收集阶段的日志，如下图所示，该日志的大部分跟之前讨论的新生代收集相同，只有第1部分不一样：GC pause(G1 Evacuation Pause)(mixed),0.0129474s，这一行表示这是一个混合垃圾收集周期；在混合垃圾收集处理的CSet不仅包括新生代的分区，还包括老年代分区——也就是并发标记阶段标记出来的那些老年代分区。

# Full GC

如果堆内存空间不足以分配新的对象，或者是Metasapce空间使用率达到了设定的阈值，那么就会触发Full GC——你在使用G1的时候应该尽量避免这种情况发生，因为G1的Full GC是单线程、会Stop The World，代价非常高。Full GC的日志如下图所示，从中你可以看出三类信息：

  • Full GC的原因，这个图里是Allocation Failure，还有一个常见的原因是Metadata GC Threshold；
  • Full GC发生的频率，每隔几天发生一次Full GC还可以接受，但是每隔1小时发生一次Full GC则不可接受；
  • Full GC的耗时，这张图里的Full GC耗时150ms（PS：按照我的经验，实际运行中如果发生Full GC，耗时会比这个多很多）

编辑 (opens new window)
#JVM
上次更新: 2022/03/20, 11:17:00
GC算法与收集器
敬请期待

← 敬请期待→

最近更新
01
MyBatisPlus
03-20
02
MyBatis源码剖析-延迟加载
03-20
03
MyBatis源码剖析-二级缓存
03-20
更多文章>
Theme by Vdoing | Copyright © 2021-2022 HuKai | 赣ICP备17016768号