GC日志详细介绍

最新推荐文章于 2024-04-07 20:47:42 发布

weixin_42073629

最新推荐文章于 2024-04-07 20:47:42 发布

阅读量2.4k

点赞数 1

分类专栏：知识积累 JVM 文章标签： java 开发语言后端

本文链接：https://blog.csdn.net/weixin_42073629/article/details/116078938

版权

知识积累同时被 2 个专栏收录

62 篇文章 3 订阅

订阅专栏

JVM

46 篇文章 4 订阅

订阅专栏

JVM的GC日志参数

GC日志相关的JVM参数，我们这里就用了下面几个参数

-XX:+PrintGCDetails 在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况。
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式，如49.459，默认就是这个输出形式，可以不写）
-XX:+PrintGCDateStamps 输出GC的时间戳（以以日期的形式，如2019-03-01T12:57:54.486+0800）
-Xloggc:<file> 表示把GC日志写入到一个文件中去，而不是打印到标准输出中。
-XX:+PrintHeapAtGC 每一次GC前和GC后，都打印堆信息。这个参数用的话，会打印的日志比较多：每次GC前后的各个区域（Eden，from、to、Old、Metaspace等区域）的容量、使用量、使用占比等

我使用的是JDK1.8，使用一个springboot程序打的jar包，每种收集器的GC日志都会有区别，可以修改JVM参数修改所使用的垃圾收集器，然后观察不同的垃圾收集器的GC日志。

GC日志格式介绍

GC日志一般都是看两种GC：Minor GC（young GC）和Full GC，下面是从网上找到的两张young GC和Full GC的日志格式详解，图中会跟我发的日志有些许出入，但是不影响理解。

通过图示，我们可以发现GC日志格式的规律一般都是：GC前内存占用—>GC后内存占用（该区域内存总大小）

另外，我们还发现GC日志中有三个时间：user，sys和real

user – 进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
sys – 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间
real – 程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行gc，这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。

一般的GC事件中，real time是小于sys+user time的，因为一般是多个线程并发的去做GC，所以real time是要小于sys+user time的。如果real>sys+user的话，则你的应用可能存在下列问题：IO负载非常重或者是CPU不够用。

young GC日志：[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

Full GC日志介绍：[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

Parallel收集器GC日志

启动命令如下：

java -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log -jar demo.jar &

启动的时候如果不指定收集器默认使用的是并行收集器Parallel Scavenge+Parallel Old的组合，启动完成后GC日志如下：可以看到帮我们设置了一些默认的JVM参数，这种类型的GC日志格式上面已经介绍过了。

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for linux-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 17:07:08 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8009432k(5404404k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=128150912 -XX:MaxHeapSize=2050414592 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2019-10-24T17:46:38.455+0800: 0.466: [GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] 
2019-10-24T17:46:38.611+0800: 0.622: [GC (Allocation Failure) [PSYoungGen: 33936K->2704K(68608K)] 33944K->2720K(153600K), 0.0055295 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:38.805+0800: 0.816: [GC (Allocation Failure) [PSYoungGen: 66192K->3744K(68608K)] 66208K->3768K(153600K), 0.0078802 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:38.985+0800: 0.996: [GC (Allocation Failure) [PSYoungGen: 67232K->4673K(132096K)] 67256K->4705K(217088K), 0.0060158 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-10-24T17:46:39.187+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 75443K->5104K(132096K)] 75475K->5520K(217088K), 0.0071404 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:39.195+0800: 1.205: [Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-10-24T17:46:40.022+0800: 2.033: [GC (Allocation Failure) [PSYoungGen: 126976K->4692K(206336K)] 132429K->10217K(256512K), 0.0099817 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:40.900+0800: 2.911: [GC (Allocation Failure) [PSYoungGen: 205908K->6628K(259072K)] 211433K->19268K(309248K), 0.0168431 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]

上面打印的日志比较简单，如果启用了-XX:+PrintHeapAtGC参数，则打印的日志就会比较多了，如下所示：每次GC前后的各个区域（Eden，from、to、Old、Metaspace等区域）的容量、使用量、使用占比等都会被打印出来。

{Heap before GC invocations=2 (full 0):
 PSYoungGen      total 36864K, used 33968K [0x00000000d7400000, 0x00000000d9d00000, 0x0000000100000000)
  eden space 31744K, 100% used [0x00000000d7400000,0x00000000d9300000,0x00000000d9300000)
  from space 5120K, 43% used [0x00000000d9300000,0x00000000d952c010,0x00000000d9800000)
  to   space 5120K, 0% used [0x00000000d9800000,0x00000000d9800000,0x00000000d9d00000)
 ParOldGen       total 84992K, used 8K [0x0000000085c00000, 0x000000008af00000, 0x00000000d7400000)
  object space 84992K, 0% used [0x0000000085c00000,0x0000000085c02000,0x000000008af00000)
 Metaspace       used 10224K, capacity 10514K, committed 10624K, reserved 1058816K
  class space    used 1214K, capacity 1323K, committed 1408K, reserved 1048576K
2019-10-23T17:54:25.803+0800: 0.610: [GC (Allocation Failure) 
[PSYoungGen: 33968K->2656K(36864K)] 33976K->2672K(121856K), 0.0035263 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=2 (full 0):
 PSYoungGen      total 36864K, used 2656K [0x00000000d7400000, 0x00000000dbc00000, 0x0000000100000000)
  eden space 31744K, 0% used [0x00000000d7400000,0x00000000d7400000,0x00000000d9300000)
  from space 5120K, 51% used [0x00000000d9800000,0x00000000d9a98020,0x00000000d9d00000)
  to   space 5120K, 0% used [0x00000000d9300000,0x00000000d9300000,0x00000000d9800000)
 ParOldGen       total 84992K, used 16K [0x0000000085c00000, 0x000000008af00000, 0x00000000d7400000)
  object space 84992K, 0% used [0x0000000085c00000,0x0000000085c04000,0x000000008af00000)
 Metaspace       used 10224K, capacity 10514K, committed 10624K, reserved 1058816K
  class space    used 1214K, capacity 1323K, committed 1408K, reserved 1048576K
}

CMS收集器日志

启动命令如下：使用-XX:+UseConcMarkSweepGC命令启用了CMS+ParNew的收集器组合。

java -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log -jar demo.jar &

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for linux-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 17:07:08 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8009432k(5374436k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=128150912 -XX:MaxHeapSize=2050414592 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2019-10-25T15:17:22.103+0800: 0.474: [GC (Allocation Failure) 2019-10-25T15:17:22.103+0800: 0.474: [ParNew: 33856K->2195K(38080K), 0.0046083 secs] 33856K->2195K(122752K), 0.0047429 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.247+0800: 0.618: [GC (Allocation Failure) 2019-10-25T15:17:22.247+0800: 0.618: [ParNew: 36051K->1818K(38080K), 0.0115188 secs] 36051K->3679K(122752K), 0.0115990 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2019-10-25T15:17:22.370+0800: 0.741: [GC (GCLocker Initiated GC) 2019-10-25T15:17:22.370+0800: 0.741: [ParNew: 35675K->1754K(38080K), 0.0020893 secs] 37536K->3614K(122752K), 0.0021557 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.436+0800: 0.807: [GC (Allocation Failure) 2019-10-25T15:17:22.436+0800: 0.807: [ParNew: 35610K->2358K(38080K), 0.0031579 secs] 37470K->4219K(122752K), 0.0032263 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.542+0800: 0.913: [GC (Allocation Failure) 2019-10-25T15:17:22.542+0800: 0.913: [ParNew: 36214K->2849K(38080K), 0.0038451 secs] 38075K->4709K(122752K), 0.0039135 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.644+0800: 1.015: [GC (Allocation Failure) 2019-10-25T15:17:22.644+0800: 1.015: [ParNew: 36705K->2565K(38080K), 0.0065677 secs] 38565K->4976K(122752K), 0.0066423 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2019-10-25T15:17:22.763+0800: 1.134: [GC (Allocation Failure) 2019-10-25T15:17:22.763+0800: 1.134: [ParNew: 36421K->3713K(38080K), 0.0090066 secs] 38832K->6733K(122752K), 0.0090870 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.926+0800: 1.297: [GC (Allocation Failure) 2019-10-25T15:17:22.926+0800: 1.297: [ParNew: 37569K->2719K(38080K), 0.0067120 secs] 40589K->6168K(122752K), 0.0067936 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.940+0800: 1.310: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3449K(84672K)] 7830K(122752K), 0.0044113 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.944+0800: 1.315: [CMS-concurrent-mark-start]
2019-10-25T15:17:22.960+0800: 1.331: [CMS-concurrent-mark: 0.016/0.016 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
2019-10-25T15:17:22.960+0800: 1.331: [CMS-concurrent-preclean-start]
2019-10-25T15:17:22.961+0800: 1.332: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.961+0800: 1.332: [CMS-concurrent-abortable-preclean-start]
2019-10-25T15:17:23.086+0800: 1.457: [CMS-concurrent-abortable-preclean: 0.062/0.125 secs] [Times: user=0.48 sys=0.00, real=0.13 secs] 
2019-10-25T15:17:23.088+0800: 1.459: [GC (CMS Final Remark) [YG occupancy: 20583 K (38080 K)]2019-10-25T15:17:23.088+0800: 1.459: [Rescan (parallel) , 0.0053038 secs]2019-10-25T15:17:23.094+0800: 1.464: [weak refs processing, 0.0000257 secs]2019-10-25T15:17:23.094+0800: 1.464: [class unloading, 0.0036873 secs]2019-10-25T15:17:23.097+0800: 1.468: [scrub symbol table, 0.0022628 secs]2019-10-25T15:17:23.100+0800: 1.470: [scrub string table, 0.0003715 secs][1 CMS-remark: 3449K(84672K)] 24032K(122752K), 0.0120789 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:23.101+0800: 1.472: [CMS-concurrent-sweep-start]
2019-10-25T15:17:23.103+0800: 1.474: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:23.103+0800: 1.474: [CMS-concurrent-reset-start]
2019-10-25T15:17:23.174+0800: 1.544: [CMS-concurrent-reset: 0.070/0.070 secs] [Times: user=0.20 sys=0.05, real=0.07 secs]

可以看到设置了-XX:MaxTenuringThreshold=6这个参数，表示Survivor区的对象晋升老年代的年龄阈值为6，这个值在JDK 1.8之前默认为15。

young GC日志跟上面类似，就不再重复介绍了：2019-10-25T15:17:22.644+0800: 1.015: [GC (Allocation Failure) 2019-10-25T15:17:22.644+0800: 1.015: [ParNew: 36705K->2565K(38080K), 0.0065677 secs] 38565K->4976K(122752K), 0.0066423 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]

对CMS收集器的工作过程介绍，可以看以下六个步骤：

1、初始标记（CMS initial mark）——STW：这个阶段是标记从GCRoots直接可达的老年代对象、新生代引用的老年代对象，速度很快。
2、并发标记（CMS concurrent mark）：并发标记阶段就是进行GC Roots Tracing的过程，由前阶段标记过的对象出发，所有可到达的对象都在本阶段中标记。
3、并发预清理（CMS concurrent preclean）：此阶段标记从新生代晋升的对象、新分配到老年代的对象以及在并发阶段被修改了的对象，因此，这个阶段也需要扫描新生代+老年代。此阶段做的事情跟重新标记类似，目的是为了让重新标记阶段的STW尽可能短。
4、重新标记（CMS remark）——STW：而重新标记阶段则是为了修正并发标记期间因用户程序继续运作而导致标记产生变动的那一部分对象的标记记录，这个阶段的停顿时间一般会比初始标记阶段稍长一些，但远比并发标记的时间短。
5、并发清除（CMS concurrent sweep）：用户线程被重新激活，同时清理那些无效的对象。
6、并发重置（CMS concurrent reset）：CMS清除内部状态，为下次回收做准备。

Minor GC（新生代的ParNew收集器）

2016-08-23T02:23:07.219-02001: 64.3222:[GC3(Allocation Failure4) 64.322: [ParNew5: 613404K->68068K6(613440K)7, 0.1020465 secs8] 10885349K->10880154K9(12514816K)10, 0.1021309 secs11][Times: user=0.78 sys=0.01, real=0.11 secs]12

2016-08-23T02:23:07.219-0200 – GC发生的时间；
64.322 – GC开始，相对JVM启动的相对时间，单位是秒；
GC – 区别MinorGC和FullGC的标识，这次代表的是MinorGC;
Allocation Failure – MinorGC的原因，在这个case里边，由于年轻代不满足申请的空间，因此触发了MinorGC;
ParNew – 收集器的名称，它预示了年轻代使用一个并行的 mark-copy stop-the-world 垃圾收集器；
613404K->68068K – 收集前后年轻代的使用情况；
(613440K) – 整个年轻代的容量；
0.1020465 secs – 这个解释用原滋原味的解释：Duration for the collection w/o final cleanup.
10885349K->10880154K – 收集前后整个堆的使用情况；
(12514816K) – 整个堆的容量；
0.1021309 secs – ParNew收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代时间、垃圾收集周期结束一些最后的清理对象等的花销）；
[Times: user=0.78 sys=0.01, real=0.11 secs] – GC事件在不同维度的耗时，具体的用英文解释起来更加合理:
- user – Total CPU time that was consumed by Garbage Collector threads during this collection
- sys – Time spent in OS calls or waiting for system event
- real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.

我们来分析下对象晋升问题（原文中的计算方式有问题）：

开始的时候：整个堆的大小是 10885349K，年轻代大小是613404K，这说明老年代大小是 10885349-613404=10271945K，

收集完成之后：整个堆的大小是 10880154K，年轻代大小是68068K，这说明老年代大小是 10880154-68068=10812086K，

老年代的大小增加了：10812086-10271945=608209K，也就是说年轻代到年老代promot了608209K的数据；

图形分析：

Full/Major GC（CMS收集器）

2016-08-23T11:23:07.321-0200: 64.425: [GC (CMS Initial Mark)1 [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark2: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean3: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]
2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5)
[YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: 
[weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: 
[scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] 
[Times: user=0.06 sys=0.00, real=0.01 secs]
2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep6: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset7: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

Phase 1: Initial Mark

这是CMS中两次stop-the-world事件中的一次。它有两个目标：一是标记老年代中所有的GC Roots；二是标记被年轻代中活着的对象引用的对象。

标记结果如下：

分析：

2016-08-23T11:23:07.321-0200: 64.421: [GC (CMS Initial Mark2[1 CMS-initial-mark: 10812086K3(11901376K)4] 10887844K5(12514816K)6, 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]7

016-08-23T11:23:07.321-0200: 64.42 – GC事件开始，包括时钟时间和相对JVM启动时候的相对时间，下边所有的阶段改时间的含义相同；
CMS Initial Mark – 收集阶段，开始收集所有的GC Roots和直接引用到的对象；
10812086K – 当前老年代使用情况；
(11901376K) – 老年代可用容量；
10887844K – 当前整个堆的使用情况；
(12514816K) – 整个堆的容量；
0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] – 时间计量；

Phase 2: Concurrent Mark

这个阶段会遍历整个老年代并且标记所有存活的对象，从“初始化标记”阶段找到的GC Roots开始。并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记，因为标记的同时应用程序会改变一些对象的引用等。

标记结果如下：

在上边的图中，一个引用的箭头已经远离了当前对象（current obj）

分析：

2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark1: 035/0.035 secs2] [Times: user=0.07 sys=0.00, real=0.03 secs]3

CMS-concurrent-mark – 并发收集阶段，这个阶段会遍历整个年老代并且标记活着的对象；
035/0.035 secs – 展示该阶段持续的时间和时钟时间；
[Times: user=0.07 sys=0.00, real=0.03 secs] – 同上

Phase 3: Concurrent Preclean

这个阶段又是一个并发阶段，和应用线程并行运行，不会中断他们。前一个阶段在并行运行的时候，一些对象的引用已经发生了变化，当这些引用发生变化的时候，JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象，被认为"dirty")，这就是 Card Marking。

如下图：

在pre-clean阶段，那些能够从dirty card对象到达的对象也会被标记，这个标记做完之后，dirty card标记就会被清除了，如下：

另外，一些必要的清扫工作也会做，还会做一些final remark阶段需要的准备工作；

分析

2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean1: 0.016/0.016 secs2] [Times: user=0.02 sys=0.00, real=0.02 secs]3

CMS-concurrent-preclean – 这个阶段负责前一个阶段标记了又发生改变的对象标记；
0.016/0.016 secs – 展示该阶段持续的时间和时钟时间；
[Times: user=0.02 sys=0.00, real=0.02 secs] – 同上

Phase 4: Concurrent Abortable Preclean

又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。

2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean1: 0.167/1.074 secs2] [Times: user=0.20 sys=0.00, real=1.07 secs]3

CMS-concurrent-abortable-preclean – 可终止的并发预清理；
0.167/1.074 secs – 展示该阶段持续的时间和时钟时间（It is interesting to note that the user time reported is a lot smaller than clock time. Usually we have seen that real time is less than user time, meaning that some work was done in parallel and so elapsed clock time is less than used CPU time. Here we have a little amount of work – for 0.167 seconds of CPU time, and garbage collector threads were doing a lot of waiting. Essentially, they were trying to stave off for as long as possible before having to do an STW pause. By default, this phase may last for up to 5 seconds）；
[Times: user=0.20 sys=0.00, real=1.07 secs] – 同上

这个阶段很大程度的影响着即将来临的Final Remark的停顿，有相当一部分重要的 configuration options 和失败的模式；

Phase 5: Final Remark

这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的，它可能跟不上应用程序改变的速度，这个时候，STW是非常需要的来完成这个严酷考验的阶段。

通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候，目的是消除紧接着的连续的几个STW阶段。

分析：

2016-08-23T11:23:08.447-0200: 65.5501: [GC (CMS Final Remark2) [YG occupancy: 387920 K (613440 K)3]65.550: [Rescan (parallel) , 0.0085125 secs]465.559: [weak refs processing, 0.0000243 secs]65.5595: [class unloading, 0.0013120 secs]65.5606: [scrub string table, 0.0001759 secs7][1 CMS-remark: 10812086K(11901376K)8] 11200006K(12514816K) 9, 0.0110730 secs10] [[Times: user=0.06 sys=0.00, real=0.01 secs]11

2016-08-23T11:23:08.447-0200: 65.550 – 同上；
CMS Final Remark – 收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象；
YG occupancy: 387920 K (613440 K) – 年轻代当前占用情况和容量；
[Rescan (parallel) , 0.0085125 secs] – 这个阶段在应用停止的阶段完成存活对象的标记工作；
weak refs processing, 0.0000243 secs]65.559 – 第一个子阶段，随着这个阶段的进行处理弱引用；
class unloading, 0.0013120 secs]65.560 – 第二个子阶段(that is unloading the unused classes, with the duration and timestamp of the phase);
scrub string table, 0.0001759 secs – 最后一个子阶段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively）
10812086K(11901376K) – 在这个阶段之后老年代占有的内存大小和老年代的容量；
11200006K(12514816K) – 在这个阶段之后整个堆的内存大小和整个堆的容量；
0.0110730 secs – 这个阶段的持续时间；
[Times: user=0.06 sys=0.00, real=0.01 secs] – 同上；

通过以上5个阶段的标记，老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

Phase 6: Concurrent Sweep

和应用线程同时进行，不需要STW。这个阶段的目的就是移除那些不用的对象，回收他们占用的空间并且为将来使用。

如图：

分析：

2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep1: 0.027/0.027 secs2] [[Times: user=0.03 sys=0.00, real=0.03 secs] 3

CMS-concurrent-sweep – 这个阶段主要是清除那些没有标记的对象并且回收空间；
0.027/0.027 secs – 展示该阶段持续的时间和时钟时间；
[Times: user=0.03 sys=0.00, real=0.03 secs] – 同上

Phase 7: Concurrent Reset

这个阶段并发执行，重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用。

2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset1: 0.012/0.012 secs2] [[Times: user=0.01 sys=0.00, real=0.01 secs]3

CMS-concurrent-reset – 这个阶段重新设置CMS算法内部的数据结构，为下一个收集阶段做准备；
0.012/0.012 secs – 展示该阶段持续的时间和时钟时间；
[Times: user=0.01 sys=0.00, real=0.01 secs] – 同上

G1收集器日志

启动命令如下：使用-XX:+UseG1GC 命令启用了G1收集器。

java -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log -jar demo.jar &

weixin_42073629

关注

1
点赞
踩
13

收藏

觉得还不错? 一键收藏
0
评论
GC日志详细介绍

JVM的GC日志参数GC日志相关的JVM参数，我们这里就用了下面几个参数-XX:+PrintGCDetails在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况。 -XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式，如49.459，默认就是这个输出形式，可以不写） -XX:+PrintGCDateStamps 输出GC的时间戳（以以日期的形式，如2019-03-01T12:57:54.486+0800） -Xloggc:&lt...
复制链接

扫一扫