本文转载自微信公众号《再见Logger》，作者再见Logger。转载本文请联系再见记录器公众号。事务的查询服务调用组件的ES进行查询，ES服务每隔3-4天会间歇性抖动一次（发生mixedGC），每次mixedGC耗时700ms+，而正常的dubbotimeout设置在1s左右，所以当GC发生时，会造成短时间的集中查询超时，引起大量报警。之前的处理方式是在凌晨4点手动触发GC，防止白天业务应用抖动。插曲在这里，我要纠正很多人的一个误解。G1的老年代收集为什么叫mixedGC？首先，G1收集老年代垃圾的时候，并不一定都是老年代，通常是老年代的一部分，而且因为老年代的收集是可以和younggc同时进行的，所以叫做mixedgc.我遇到并协助排查过的GC案例，几乎都是代码问题。比较满意的系统运行场景是Ygc每次都能很好的消化垃圾对象。毕竟G1的垃圾收集器默认的参数少而且好看。一开始（如上图），我们从一个正常服务调用的链接开始：从链接跟踪的角度来看，上游应用发送请求的时间和下游应用开始处理请求的时间要求应该差不多。但是，不管业务逻辑如何，一个rpc流程需要哪些流程呢？（此图转自网络，如有抄袭嫌疑，请联系我删图保命。）可以看到有连载，网传等。哪些因素会导致一般接口超时？穷举法：网络问题、服务硬件问题、GC问题等历史重现。小哥过来问我，对话如下：张哥：鸡哥，我想问你一个问题鸡哥：告诉我，我不应该（图）张哥：加了-XX:+之后ParallelRefProcEnabled参数给G1，GC耗时还是会很长，造成一波超时。你知道是什么情况吗？鸡哥：你确定？我们来分析一下这个参数。从逻辑上讲，这个参数（-XX:+ParallelRefProcEnabled）的意思是：尽可能启用Parallelreferenceprocessing是好的。我们来探究一下他为什么要加这个参数？是什么原因让他加了这个参数？原来张姓老板通过gclog发现GC的[refproc]阶段耗时很长，于是从网上搜到这个参数试了一下。如上图所示，我们可以发现在gc过程中，ref-proc(mixedgc)阶段出现了700ms+的停顿。[refproc]阶段在做什么？其实图中的ref-proc0.7034259secs就是soft,weak,phantom,final,JNI等引用的处理时间。Oracle官方文档是这样描述的：其实是在G1的remark阶段。引用根据其特定类型进行更新以进行额外分析。这还得从G1的Ygc说起。我们都知道Ygc就是填充Eden区域然后触发Ygc的对象。一般在G1-XX:MaxGCPauseMillisGC最大Pause时间里有个设置，默认200ms这个参数会影响Ygc的STW时间，为什么呢？大家想一想，MaxGCPauseMillis时间越小，STW时间越小，年轻代出现的概率就越小；STW时间越大，新生代出现的概率就越大。这个时候还有人有疑问吗？为了减少STW时间，我会减少MaxGCPauseMillis。这个说法是错误的！！！！MaxGCPauseMillis越小，新生代越小，导致很多生命周期短的对象被删除过早地提升到老年代。老年代大家都知道，打标和清洗的过程要比年轻代复杂很多，整体效率也比较低。这样一来，虽然GC停滞时间减少了，但GC的数量可能会增加，整体吞吐量会下降。而GC次数的增加也会导致CPU资源占用的增加。我和业务线程竞争CPU的第一个处理。然后当天晚些时候，我被拉进了一个三人组成的GC问题处理组，实验三组对比参数。调试：不加ParallelRefProcEnabled，新生代自动分配17g，Ygc(40ms)，mixedgc(500ms)调试1：-XX:+ParallelRefProcEnabled，新生代自动分配2g，Ygc(50ms)，Ygc的个数增加，mixedgc(200ms)Debugging2:-XX:+ParallelRefProcEnabledand-XX:ParallelgCThreads=8,younggeneration17g,Ygc(40ms),Ygc的数量和未调试的情况差不多，mixedgc还没有被触发，所以耗时未知，我们基本可以看到明显的问题是添加(-XX:+ParallelRefProcEnabled)的现象：综上，我们发现官网推荐的引导方式将gc时间从700ms+减少到大约300ms，但还是引起了业务端的一波超时抖动。当然300ms的处理时间是完全支持不了的，还是会带来很多抖动，但是现有的gclog不足以观察本质，所以推荐如下参数观察更具体的信息-XX：+PrintReferenceGC第二个现象终于在X月X日，终于触发了一次Mixedgc，日志出来了（如下）。在第二次处理中，我们可以看到Softreference和FinalReference占了两个大头，一个是132ms，一个是255ms。其实这个问题差不多压缩到了最后这时候可以看到第三个现象Applicationstop621ms。所以，定位到问题就可以着手解决了！因为大家都知道软引用是在内存不足的时候收集的，所以项目中产生的软引用对象太大。如果过多，在gc过程中会产生较大的处理压力。这次我们添加了-XX:SoftRefLRUPolicyMSPerMB=0。官方解释：软引用在虚拟机中的存活时间比在客户端集群中长。它的清除频率可以通过命令行参数-XX:SoftRefLRUPolicyMSPerMB=来控制，可以指定每个megaheap空闲空间的软引用保持存活的毫秒数（一旦不是强可达），这意味着每个megaheap的自由空间中的软引用存活1秒（在最后一个强引用被收集之后）。请注意，这是一个近似值，因为软引用仅在垃圾回收期间被清除，这并不总是发生。系统默认为一秒。我认为没有必要等待一秒钟。如果客户没有使用，它会立即被清除。改成-XX:SoftRefLRUPolicyMSPerMB=0;第三个结果是什么？我们可以看到的是softreference和finalreference在每一个ygc过程中都会收集一部分，数量是之前的两倍。finalReference的问题是什么？因为java8的SocketServiceImpl中实现了Object的finalize方法，为了防止socket连接忘记释放资源，以及帮助释放以后有大量短链接需要及时释放时，会导致太多的Finalizer对象，导致我们一开始看到的现象，所以我们猜测ES使用的OKHTTP调用方式，但是无法dump，所以没法验证。这次在ygc收的，其实也达到了预期，但还算不上完美。当然，JDK9中的AbstractPlainSocketImpl似乎不再重写finalize方法，因为finalize()方法是Object类的一个方法，用来在类被GC回收时进行一些处理操作，但是JVM不能保证一定要执行finalize()方法，调用finalize()方法的时机是不确定的，从一个对象变得不可达到执行finalize()方法所花费的时间是任意长的。我们不能依赖finalize()方法来及时回收占用的资源。有可能在我们耗尽资源之前还没有触发gc。所以，通常的做法是提供一个displayclose()方法供客户端手动调用episode很多人认为软引用会在内存不足时被回收？其实也不一定。软引用的回收需要一定的条件。看看官方文档是怎么说的clock-timestamp<=freespace*SoftRefLRUPolicyMSPerMBclock:LastGCTimestamptimestamp:表示最后一次读取软引用对象的时间戳。两者之间的差异表示软引用对象多久没有被使用过。差值越大，软参照物的价值越低。负数表示软引用对象刚被使用过。Freespace是可用空间的大小。SoftRefLRUPolicyMSPerMB表示每MB空闲内存空间可以让软引用对象存活多长时间。这也间接解释了空间不够的原因。可用空间越小，软应用程序对象将被回收，因为它的生命周期随着可用空间的减少而减少。[freespace*SoftRefLRUPolicyMSPerMB]可以理解为tolerance，软应用对象的容忍度。waiting其实从gclog和现象上也猜到基本已经算成功了，但是加上这个参数[SoftRefLRUPolicyMSPerMB]也是有风险的，如下面我举的例子：假设程序中有很多创建反射的操作，因为通过反射创建的类本身的类对象被SoftReference软引用。加上以上参数，软引用会尽快释放，所以会生成。反射创建大量类->刚刚创建GC回收了很多->反射执行继续创建大量类，最终导致Metaspace区域被填满->等了4天FullGC结果后，我听张姓老板第1集激动的喊声后发现mixedgc已经稳定在85ms左右。为什么jvm中没有默认开启软引用收集参数[SoftRefLRUPolicyMSPerMB]？答：因为软引用的特性特别适合Cache，所以设计者的目的就是让cache常驻内存，所以内存不够的时候就会触发collection2.要引用ZGC吗？中间有人向姓张的老板推荐了ZGC，于是拿出这种图，JDK11开始存在，2018年9月左右发布，先试试，不过这个算是屏蔽了如果有的话问题，走捷径；第二，谁也扛不住，出了问题谁来负责修？GC调优的几个核心要素：1.自信；2、不断把问题压缩到死胡同；参数实验对比毕竟没有兼容所有场景的参数，只有符合自己业务场景的调参附件（供大家参考，gclog中每一步是干什么的）：【GC暂停（G1EvacuationPause）（年轻）,0.0022483secs]young->YounggenerationEvacuation->Copysurvivingobjects[ParallelTime:1.0ms,GCWorkers:10]#并发执行的GC线程数，以下阶段并发执行[GCWorkerStart(ms):Min:109.0,Avg:109.1,Max:109.1,Diff:0.2][ExtRootScanning(ms):Min:0.1,Avg:0.2,Max:0.3,Diff:0.2,Sum:2.3]#ExternalRootScanning[更新RS（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差异:0.0,Sum:0.0]#更新记忆集UpdateRSet，检测从年轻代指向老年代的对象[ProcessedBuffers:Min:0,Avg:0.0,Max:0,Diff:0,Sum:0][ScanRS(ms):Min:0.0,Avg:0.0,Max:0.0,Diff:0.0,Sum:0.0]#RSetscanning[CodeRootScanning(ms):Min:0.0,Avg:0.0,Max:0.0,Diff:0.0,Sum:0.1]#代码根扫描[ObjectCopy(ms):Min:0.3,Avg:0.3,Max:0.4,Diff:0.1,Sum:3.5]#转移和回收，将幸存对象复制到survivor/oldArea[Termination(ms):Min:0.0,Avg:0.0,Max:0.0,Diff:0.0,Sum:0.0]#完成以上任务后，如果任务队列为空，工作线程会发起终止请求[终止尝试：最小值：1，平均值：5.8，最大值：9，差异：8，总和：58][GCWorker其他（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差异：0.0，总和：0.1]#GC外部并行活动，这部分不是GC活动，而是JVM活动导致GC暂停时间（比如JNI编译）。[GCWorkerTotal(ms):Min:0.5,Avg:0.6,Max:0.7,Diff:0.2,Sum:5.9][GCWorkerEnd(ms):Min:109.7,Avg:109.7,Max:109.7,Diff:0.0][CodeRootFixup:0.0ms]#串行任务，根据传输对象更新代码根[CodeRootPurge:0.0ms]#串行任务，代码根清理[ClearCT:0.5ms]#串行任务，清除GlobalcardCardTablemark[Other:0.8ms][ChooseCSet:0.0ms]#选择下一个collectionsetCSet[RefProc:0.4ms]#引用处理RefProc，处理软引用，弱引用，虚引用，最终引用,JNIreference[RefEnq:0.0ms]#referencequeuingRefEnq[RedirtyCards:0.3ms]#cardre-dirtyRedirtyCards:re-dirtycard[HumongousRegister:0.0ms][HumongousReclaim:0.0ms]#回收HumongousReclaimoftheidlegiantpartition，通过查看所有根对象和新生代分区的RSet，如果确定RSet中没有对huge对象的引用，则对象分区回收。[FreeCSet:0.0ms]#释放分区FreeCSet[Eden:12288.0K(12288.0K)->0.0B(11264.0K)Survivors:0.0B->1024.0KHeap:12288.0K(20480.0K)->832.0K(20480.0K)][Times:user=0.01sys=0.00,real=0.00secs]从新生代分区复制存活对象时，找不到可用的空闲分区。从老年代分区转移存活对象时，找不到可用的空闲分区。这两种情况之一导致的YGC的ConcurrentMarkingCycle中的rootpartitionscanningphase[GCpause(G1EvacuationPause)(young)(to-spaceexhausted),0.0916534secs]被YGC中断[GCpause(G1疏散暂停）（年轻）[GCconcurrent-root-region-scan-end,0.0007157secs]
