最近在研究一个服务和数据库之间的耗时问题，发现了服务端的GC。我分析了GC日志，在这里做了记录。如下只记录了G1的新生代收集的流程！！！{HeapbeforeGCinvocations=11035(full0):garbage-firstheaptotal2097152K,used1878984K[0x0000000640000000,0x0000000640202000,0x00000007c0000000)regionsize2048K,594young(1216512K),2个幸存者(4096K)元空间使用96639K，容量100818K，提交101120K，保留1138688K类空间使用10423K，容量11153K，提交11264K，保留1048576K2021-11-21T16:13:30.692+0800:2.053515[GC暂停疏散暂停）（年轻），0.0107390秒][并行时间：7.4毫秒，GC工作人员：4][GC工作人员开始（毫秒）：最小值：2055582832.5，平均：2055582832.5，最大值：2055582832.6，差异：0.1][外部根扫描（毫秒）：最小值：2.7，平均值：2.8，最大值：2.8，差异：0.2，总和：11.0][更新RS（毫秒）：最小值：2.6，平均值：2.6，最大值：2.7，差异：0.2，总和：10.4][已处理缓冲区：最小值：118，平均值：136.8，最大值：165，差异：47，总和：547][扫描RS（毫秒）：最小值：0.0，平均值：0.1，最大值：0.2，差异：0.1，总和：0.4][代码Root扫描（毫秒）：最小值：0.0，平均值：0.0，最大值：0.1，差异：0.1，总和：0.1][对象复制（毫秒）：最小值：1.6，平均值：1.7，最大值：1.7，差异：0.1，总和：6.6][终止（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差异：0.0，总和：0.0][终止尝试：最小值：1，平均值：1.0，最大值：1，差异：0，总和:4][GCWorkerOther(ms):Min:0.0,Avg:0.1,Max:0.1,Diff:0.1,Sum:0.2][GCWorkerTotal(ms):Min:7.1,Avg:7.2,Max:7.3,Diff:0.2,Sum:28.8][GCWorkerEnd(ms):Min:2055582839.7,Avg:2055582839.7,Max:2055582839.8,Diff:0.1][CodeRootFixup:0.2ms][CodeRootPurge:0.0ms][清除CT：0.2ms][其他：2.9ms][选择CSet：0.0ms][RefProc：1.1ms][RefEnq：0.1ms][RedirtyCards：0.1ms][HumongousRegister：0.1ms][HumongousReclaim:0.0ms][FreeCSet:0.5ms][Eden:1184.0M(1184.0M)->0.0B(1184.0M)Survivors:4096.0K->4096.0KHeap:1834.9M(2048.0M)->652.4M(2048.0M)]堆GC调用=11036（完整0）：垃圾-先前总计2097152K，使用了668097K[0x00000000000640000000，0x000000000640202000，0x00000007000007c00000000000000000000000000000年，区域尺寸尺寸2048k，2Young（4096k），2Young（4096k），248.48396k）,reserved1138688Kclassspaceused10423K,capacity11153K,committed11264K,reserved1048576K}[Times:user=0.03sys=0.00,real=0.01secs]StartGCflag(HeapbeforeGC)firstrecyclinginvocations=1110355representativesRowoverview2021-11-21T16:13:30.692+0800——新生代垃圾回收发生的时间，可以通过设置-XX:+PrintGCDateStamps参数打印出来2055582.832——JVM开始GC暂停后的相对时间（G1EvacuationPause)(young)-这个集合的类型：新生代集合，只回收了Eden区（代表是一个yongGC，原因是：EvacuationPause（疏散暂停）是将活体对象从一个area(youngoryoung+oldcopytoanotherarea)第二行：ParallelTime详解：并行采集任务在运行过程中造成的STW（StopTheWorld）时间，从new开始一代垃圾收集到最后一个任务结束，共26.6msGCWorkers：负责垃圾收集的线程有4个，由参数-XX:ParallelGCThreads设置。该参数的值与CPU有关。如果物理CPU支持的线程数小于8，则最多设置为8；如果物理CPU支持线程数大于8的话，默认值为number*5/8GCWorkerStart：从JVM启动到第一个垃圾回收线程开始工作所经过的时间（min）；从JVM启动到最后一个垃圾收集线程开始工作所经过的时间（最大值）；diff表示min和max之间的理想差异在某些情况下，你希望它们几乎同时启动，即diff趋于0。codeGCWorkerOther：垃圾回收线程完成其他任务所花费的时间GCWorkerTotal：显示每个垃圾回收线程总时间的最小值、最大值、平均值、差值和总和。GCWorkerEnd:min表示JVM启动后最早的垃圾回收线程结束的时间；max表示JVM启动后到最新的垃圾回收线程结束的时间。理想情况下，diff无限接近0CodeRootFixup：释放用于管理并行垃圾收集活动的数据结构，应该接近于0，这一步是线性执行的CodeRootPurge：清理更多的数据结构，应该很快，耗时为接近于0，也是ChooseCSet的线性执行：选择要回收的分区放入CSet（G1选择的标准是垃圾最多的分区在前，也就是垃圾最少的分区survivalobjectratefirst）RefProc：Java中处理各种引用，如soft，weak，final，phantom，JNI等RefEnq：遍历所有引用，将不可回收的放入pendinglistHumongousRegister：JDK8提供了一个特性巨型对象可以被新生代回收Reclaim可以通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为trueHumongousReclaim：确保巨型对象可以回收，释放巨型对象占用的分区，重置分区类型，将分区归还给freelist，并更新空闲空间大小FreeCSet：将被释放分区也返回到freelist更改前后GCEden:1184.0M(1184.0M)->0.0B(1184.0M):(1)当前新生代收集触发的原因是Eden空间满了，分配了1184.0M，使用1184.0M(2)Eden分区已经全部撤离。新生代结束后，Eden分区的大小变成了0.0B。Survivors:4096.0K->4096.0K回收了Eden区，但是survivors没变，说明很多对象都回收到了Eden区Heap:1834.9M(2048.0M)->652.4M(2048.0M)(1)在本次垃圾回收活动开始时，堆空间的整体使用量为1834.9M，堆空间最大值为2048M；(2)经过这次垃圾回收，堆空间的使用量为652.4M，最大值保持不变（注意：这里我的启动脚本设置-xmn和-xmx大小相同，所以Eden分区保持不变。如果值不一样，会自适应调整堆大小）Time-consuminguser=0.03ineachstage：垃圾回收线程在新生代垃圾回收过程中消耗的CPU时间。这个时候跟垃圾回收线程数有关sys=0.00:内核态线程消耗的CPU时间real=0.01：本次垃圾回收实际消耗的时间总结：基本上GC上的日志基本够用了。如果想更精确一点，可以加上-XX:+PrintAdaptiveSizePolicy来打印内存调整的过程备注：1.之前收藏了一篇老哥写的博客。大家可以来这里看看G1GC的日志分析。它也很详细，并合理使用工具。我常用的工具是GcEasy和MAT。对于dump文件分析，我一般使用heaphero和fastthread。
