JVM各类GC日志剖析
2016 年 03 月 15 日
jvm
-
不同的GC收集器组合
-
Serial GC
-
参考文献
在日常开发中，除了编写程序外，其他比较关注的会有垃圾收集器(GC)相关的问题，在默认的JVM行为下，可能会随着业务量或应用需求，这样的默认行为可能无法满足需求(主要可从吞吐量或系统暂停响应等因素考虑)，对垃圾收集器(GC)的调整，是比较普遍的，当然也可能会针对使用不同的垃圾收集器(GC)时，进一步调整一些JVM参数，如堆大小，分代配额等信息，而能帮助开发人员在调整这些参数前，作一些跟踪判断的重要信息，则是垃圾收集日志。本文将详述相关的一些GC日志细节。
尽管在Java内存管理基础中，提到了一些常见的垃圾收集器，但在现实应用中，比较常见的组合使用大概就四种：
年轻代和老年代均使用Serial GC。
年轻代和老年代均使用Parallel GC。
年轻代使用Parallel GC，年轻代使用CMS收集器。
不进行年轻代和老年代区分，使用G1收集器。
为了触发各类GC组合触发垃圾收集，本文将使用如下代码：
public class GCLogDetailTest {
// 1M
private static int M_1 = 1024 * 1024;
public static void main(String[] args) {
Set<byte[]> lives = new HashSet<>();
byte[] dead = null;
dead = new byte[M_1 * 2];
System.out.println("dead allocated 2M");
dead = new byte[M_1 * 3];
System.out.println("dead allocated 3M");
lives.add(new byte[M_1 * 2]);
System.out.println("lives allocated 2M");
lives.add(new byte[M_1 * 2]);
System.out.println("lives allocated 2M");
lives.add(new byte[M_1 * 2]);
System.out.println("lives allocated 2M");
lives.add(new byte[M_1 * 2]);
System.out.println("lives allocated 2M");
lives.add(new byte[M_1 * 2]);
System.out.println("lives allocated 2M");
dead = new byte[M_1 * 2];
System.out.println("dead allocated 2M");
}
}
运行的Java环境为:
java -version
java version "1.7.0_80"
Java(TM) SE Runtime Environment (build 1.7.0_80-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.80-b11, mixed mode)
VM参数设置为:
-Xms20M -Xmx20M -XX:+PrintGCDetails -XX:+PrintGCDateStamps {定义垃圾收集器}
开发人员可通过-XX:+UseSerialGC启用Serial GC，此时，年轻代将使用标记-复制(mark-copy)算法，老年代使用标记-清理-压缩(mark-sweep-compact)算法，并且均以单线程，stop-the-world的方式运行垃圾收集过程。
Minor GC日志
2016-03-14T14:57:43.807-0800: 0.260: [GC2016-03-14T14:57:43.807-0800: 0.260: [DefNew: 4185K->6K(6144K), 0.0046780 secs] 11665K->11583K(19840K), 0.0047270 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
| 日志项 | 描述 |
|---|---|
| 2016-03-14T14:57:43.807-0800 | GC触发时的系统时间 |
| 0.260 | GC触发时，相对于JVM启动后的时间 |
| DefNew | 使用的垃圾收集器名称。DefNew表示的是发生在年轻代的单线程，标记-复制，stop-the-world的垃圾收集器 |
| 4185K->6K | 垃圾收集前后，年轻代的占用情况 |
| 6144K | 年轻代的总大小 |
| 11665K->11583K | 垃圾收集前后，整个堆的占用情况 |
| 19840K | 整个堆的总大小 |
| 0.0047270 secs | Young GC耗时 |
| Times: user=0.00 sys=0.00, real=0.01 secs |
Young GC不同维度的耗时。
user：GC线程在垃圾收集过程中消耗的CPU时间。
sys：OS调用或等待系统事件所耗费的时间。
real：应用暂停的时钟时间。理论上，由于Serial GC是单线程，串行执行，因此real = user + sys，但实时并不是那么精确。
|
Full GC日志
2016-03-14T14:57:43.813-0800: 0.265: [GC2016-03-14T14:57:43.813-0800: 0.265: [DefNew: 4157K->4157K(6144K), 0.0000210 secs]2016-03-14T14:57:43.813-0800: 0.266: [Tenured: 11576K->13630K(13696K), 0.0111960 secs] 15733K->13630K(19840K), [Perm : 2934K->2934K(21248K)], 0.0112660 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
| 日志项 | 描述 |
|---|---|
| Tenured | 使用的垃圾收集器名称。Tenured表示的是发生在老年代的单线程，标记-清理-压缩，stop-the-world的垃圾收集器 |
| 11576K->13629K | 垃圾收集前后，老年代的占用情况 |
| 13696K | 老年代的总大小 |
| 15733K->13630K | 垃圾收集前后，年轻代和老年代的占用情况 |
| Perm : 2923K->2923K(21248K) | 永久代垃圾收集前后的占用情况，总大小为21248K。 |
Parallel GC
开发人员可通过-XX:+UseParallelGC启用Parallel GC，此时，年轻代将使用标记-复制(mark-copy)算法，老年代使用标记-清理-压缩(mark-sweep-compact)算法，并且均以多线程，stop-the-world的方式运行垃圾收集过程，还可通过-XX:ParallelGCThreads=N来指定运行垃圾收集过程的线程数，默认为CPU核数。Parallel GC收集器将有效提升应用吞吐量，也常被称为吞吐量收集器。
Minor GC日志
2016-03-14T20:24:01.895-0800: 0.181: [GC [PSYoungGen: 4525K->384K(6656K)] 11693K->11648K(20480K), 0.0169150 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
| 日志项 | 描述 |
|---|---|
| GC | 表示发生一次Minor GC。 |
| PSYoungGen | 垃圾收集器名称。PSYoungGen表示发生在年轻代的并行，标记-复制，stop-the-world的垃圾收集器。 |
| 4525K->384K | 垃圾收集前后，年轻代的占用情况 |
| 6656K | 年轻代的总大小 |
| 11693K->11648K | 垃圾收集前后，整个堆的占用情况 |
| 20480K | 整个堆的总大小 |
Full GC日志
2016-03-14T20:24:01.912-0800: 0.198: [Full GC [PSYoungGen: 384K->0K(6656K)] [ParOldGen: 11264K->11591K(13824K)] 11648K->11591K(20480K) [PSPermGen: 2936K->2935K(21504K)], 0.0216520 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
| 日志项 | 描述 |
|---|---|
| Full GC | 发生一次Full GC。 |
| ParOldGen | 垃圾收集器名称。ParOldGen表示发生在老年代的并行，标记-清理-压缩，stop-the-world的垃圾收集器。 |
| 11264K->11591K | 垃圾收集前后，老年代的占用情况 |
| 13824K | 老年代的总大小 |
| 15733K->13630K | 垃圾收集前后，年轻代和老年代的占用情况 |
| PSPermGen: 2936K->2935K(21504K) | 永久代垃圾收集前后的占用情况，总大小为21504K。 |
Concurrent Mark and Sweep(CMS)
在Java内存管理基础一文中，已经知道CMS并非完全并发执行，仅第二个和第四个阶段是并发执行的。当使用CMS垃圾收集器时，年轻代将采用并行，stop-the-world，标记-复制的收集算法，老年代则采用并发-标记-清理(Concurrent Mark-Sweep)的收集算法，该算法有利于降低应用暂定时间，可通过-XX:+UseConcMarkSweepGC开启。
Minor GC日志
2016-03-14T22:08:21.466-0800: 0.148: [GC2016-03-14T22:08:21.466-0800: 0.148: [ParNew: 3039K->334K(6144K), 0.0024730 secs] 3039K->2384K(19840K), 0.0025280 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
| 日志项 | 描述 |
|---|---|
| GC | 表示发生一次Minor GC。 |
| ParNew | 垃圾收集器名称。PSYoungGen表示发生在年轻代的并行，标记-复制，stop-the-world的垃圾收集器，与老年代的并发-标记-清理算法协同工作。 |
Full GC日志
2016-03-14T22:00:06.326-0800: 0.155: [GC [1 CMS-initial-mark: 7172K(13696K)] 9689K(19840K), 0.0004470 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T22:00:06.327-0800: 0.156: [CMS-concurrent-mark-start]
2016-03-14T22:00:06.329-0800: 0.158: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T22:14:39.383-0800: 2.163: [CMS-concurrent-preclean-start]
2016-03-14T22:14:39.383-0800: 2.163: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T22:00:06.329-0800: 0.158: [CMS-concurrent-abortable-preclean-start]
2016-03-14T22:00:06.336-0800: 0.165: [CMS-concurrent-abortable-preclean: 0.002/0.006 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
2016-03-14T22:00:06.336-0800: 0.165: [GC[YG occupancy: 2535 K (6144 K)]
2016-03-14T22:00:06.336-0800: 0.165: [Rescan (parallel) , 0.0005600 secs]
2016-03-14T22:00:06.336-0800: 0.166: [weak refs processing, 0.0000350 secs]
2016-03-14T22:00:06.336-0800: 0.166: [scrub string table, 0.0001500 secs] [1 CMS-remark: 11268K(13696K)] 13803K(19840K), 0.0008010 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2016-03-14T22:00:06.337-0800: 0.166: [CMS-concurrent-sweep-start]
2016-03-14T22:00:06.337-0800: 0.166: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T22:00:06.337-0800: 0.166: [CMS-concurrent-reset-start]
2016-03-14T22:00:06.337-0800: 0.166: [CMS-concurrent-reset: 0.000/0.000 secs]
| 日志项 | 描述 |
|---|---|
| 1 CMS-initial-mark | CMS第一阶段初始化标记。 |
| 7172K | 老年代当前占用的大小。 |
| 13696K | 老年代的总大小。 |
| 9689K | 整个堆的占用大小 |
| 19840K | 整个堆的大小 |
| CMS-concurrent-mark-start | 标志CMS的并发标记阶段开始，该阶段将标记出存活的对象。 |
| CMS-concurrent-mark | CMS的并发标记阶段结束。 |
| 0.002/0.002 secs | 消耗的用户时间和及CPU时钟时间。 |
| CMS-concurrent-preclean-start | 标志CMS的并发预清理阶段开始，该阶段将统计出上一阶段引用发生变化的对象。 |
| CMS-concurrent-preclean | CMS的并发标记阶段结束。 |
| CMS-concurrent-abortable-preclean-start | 标志CMS的并发中止预清理阶段开始，该阶段将为后面的最终重标记阶段(Final Remark)尽可能作一些工作。 |
| CMS-concurrent-abortable-preclean | CMS的并发中止预清理阶段结束。 |
| GC[YG occupancy: 2535 K (6144 K)] | 当前年轻代的总大小为6144K，已占用2535K。 |
| Rescan (parallel) , 0.0005600 secs | Rescan将以并行，stop-the-world的方式标记存活的对象，并耗时0.00056秒。 |
| weak refs processing, 0.0000350 secs | 处理弱引用对象，耗时0.000035秒。 |
| scrub string table, 0.0001500 secs | 清理符号及字符串表，耗时0.00015秒。 |
| [1 CMS-remark: 11268K(13696K)] 13803K(19840K) | CMS重标记后，老年代总大小为13696K，被占用11268K，整个堆总大小为19840K，被占用13803K。 |
| CMS-concurrent-sweep-start | 标志并发清理阶段开始，准备清理未标记的对象，以释放内存空间。 |
| CMS-concurrent-sweep | 标志并发清理阶段结束。 |
| CMS-concurrent-reset-start | 标志并发重置阶段开始，准备重置CMS算法的内部数据结构，及为下一次GC作准备。 |
| CMS-concurrent-reset | 标志并发重置阶段结束。 |
以上则是CMS垃圾收集器的过程，其通过尽可能并发执行某些阶段，以达到降低暂停应用的时间，但CMS垃圾收集器也有一个明显的缺点，由于不进行内存压缩(Compact)，将导致内存碎片的堆积，在大堆的场景下，应用暂停时间可能不可预测。还有一个不利就是，有可能增加年轻代垃圾收集暂停时间，由于老年代回收的内存片段通过链表想连接，在分配晋升的对象时，需要通过链表索引一块足够容纳晋升对象的内存。开发人员可通过启用G1垃圾收集器，其工作原理可见这里。
G1(Garbage First)
G1垃圾收集器的关键设计之一则是使得由于垃圾收集造成的应用暂停时间和分布变得可预测，可配置。G1物理上将整个堆分成了不同大小的固定区域(差不多2048个)，每个区域都可以被称为Eden区，Survivor区，或Old区，逻辑上Eden区+Survivor区为年轻代，Old区则为老年代，从而避免了每次GC时，回收整个堆空间。
GC日志
2016-03-14T14:25:26.731-0800: 0.150: [GC pause (young) (initial-mark), 0.0018610 secs]
[Parallel Time: 1.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 149.6, Avg: 149.7, Max: 149.9, Diff: 0.3]
[Ext Root Scanning (ms): Min: 0.5, Avg: 0.8, Max: 1.1, Diff: 0.6, Sum: 3.3]
[Code Root Marking (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 2.8, Max: 11, Diff: 11, Sum: 11]
[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.2, Avg: 0.4, Max: 0.6, Diff: 0.3, Sum: 1.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[GC Worker Total (ms): Min: 1.1, Avg: 1.3, Max: 1.4, Diff: 0.3, Sum: 5.3]
[GC Worker End (ms): Min: 151.0, Avg: 151.0, Max: 151.0, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 1024.0K(14.0M)->0.0B(6144.0K) Survivors: 0.0B->1024.0K Heap: 7886.9K(25.0M)->7560.1K(25.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T14:25:26.733-0800: 0.152: [GC concurrent-root-region-scan-start]
2016-03-14T14:25:26.734-0800: 0.152: [GC concurrent-root-region-scan-end, 0.0008520 secs]
2016-03-14T14:25:26.734-0800: 0.152: [GC concurrent-mark-start]
2016-03-14T14:25:26.734-0800: 0.152: [GC concurrent-mark-end, 0.0000760 secs]
2016-03-14T14:25:26.735-0800: 0.153: [GC remark 2016-03-14T14:25:26.735-0800: 0.153: [GC ref-proc, 0.0000390 secs], 0.0006540 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2016-03-14T14:25:26.735-0800: 0.154: [GC cleanup 9669K->7621K(25M), 0.0003380 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T14:25:26.736-0800: 0.154: [GC concurrent-cleanup-start]
2016-03-14T14:25:26.736-0800: 0.154: [GC concurrent-cleanup-end, 0.0000270 secs]
| 日志项 | 描述 |
|---|---|
| 0.150: GC pause (young) (initial-mark), 0.0018610 secs | G1以并行，stop-the-world的方式清理年轻代，触发时间在JVM启动后0.15秒，暂停的时间为0.001861secs(CPU时钟时间)。 |
| Parallel Time: 1.5 ms, GC Workers: 4 |
表示以下的操作以4个线程并行，耗时1.5ms：
GC Worker Start：GC Worker线程开始工作的时间，若Min和Max相差(Diff)太大，说明有其他进程在争用CPU。
Ext Root Scanning：扫描堆外的GC Root对象，如累加载器，JNI引用，JVM系统root对象等，其中Sum为CPU时间。
Code Root Scanning：扫描代码中的GC Root对象，如局部变量等。
Object Copy：从收集区中复制存活对象。
Termination：GC Worker线程确认可以安全停止并且没有其他工作要做时，则终止。
GC Worker Other：GC Worker线程锁作的其他一些琐碎工作。
GC Worker Total：GC Worker线程总共工作了多长时间。
GC Worker End：GC Worker线程完成工作所耗时间。
|
| Code Root Fixup: 0.0 ms | 释放在管理并行操作中使用到的数据结构，该操作为串行操作。 |
| Clear CT: 0.1 ms | 清理卡表(card table)数据耗时0.1ms。 |
| Other: 0.3 ms |
其他操作耗时0.3ms，通常是并行执行的：
Choose CSet：选定收集区所耗时间，通常耗时很短，当需要选择Old区时，要稍微长些。
Ref Proc：处理soft，weak等引用耗时。
Ref Enq：将soft，weak等引用放入ReferenceQueue队列的耗时。
Free CSet：释放收集区空闲内存所耗时。
|
| Eden: 1024.0K(14.0M)->0.0B(6144.0K) | 暂停前后，Eden区的占用内存/总内存分别为1024.0K(14.0M)和0.0B(6144.0K)。 |
| Survivors: 0.0B->1024.0K | 暂停前后，Survivor区的内存占用分别为0.0B和1024.0K。 |
| Heap: 7886.9K(25.0M)->7560.1K(25.0M) | 暂停前后，整个堆的占用内存/总内存分别为7886.9K(25.0M)和7560.1K(25.0M)。 |
| GC concurrent-root-region-scan-start | 标志扫描根对象区开始，该阶段将标记从Root对象区可达的对象。 |
| GC concurrent-root-region-scan-end, 0.0008520 secs | 标志扫描根对象区结束，耗时0.0008520secs。 |
| GC concurrent-mark-start | 标志并发标记阶段开始，该阶段类似于CMS中的并发标记，会记录可达的对象，但G1中的该阶段，会记录当对象引用会应用线程改变时，需要记录对象之前的引用，以达到Snapshot-At-The-Beginning的语义，为了实现这样的目的，主要使用了预写屏障(Pre-Write barriers)，当发生字段写操作时，会将该字段之前的引用记录到日志缓冲区中。 |
| GC concurrent-mark-end, 0.0000760 secs | 标志并发标记阶段结束，耗时0.0000760secs。 |
| GC remark | 标志重标记阶段开始，该阶段会stop-the-world， |
| GC ref-proc | 处理weak，soft等引用。 |
| GC cleanup 9669K->7621K(25M) | 清理前后，整个堆的占用分别为9669K，7621K，总大小为25M。 |
| GC concurrent-cleanup-start | 标志并发清理一些只包含垃圾对象的区域开始。 |
| GC concurrent-cleanup-end | 标志并发清理一些只包含垃圾对象的区域结束。 |
以上，则是JVM使用不同垃圾收集器时，记录了一些GC日志，这将有助于开发人员在遇到Java应用出现一些GC性能问题时，能分析其中有可能的原因及其问题根源。
https://plumbr.eu/java-garbage-collection-handbook
http://www.oracle.com/technetwork/tutorials/tutorials-1876574.html
好人，一生平安。