简介本文记录一次线上GC问题的排查过程和思路，希望对读者有所帮助。过程中也走了一些弯路。现在有时间静下心来想一想，总结出来分享给大家。希望对大家以后排查在线GC问题有所帮助。后台服务新功能发布一周后的下午，突然收到CMSGC告警，导致单个节点被拉出，然后集群中的每个节点都接连进行了一次CMSGC，并且被拉出的节点在垃圾回收后接收到的流量恢复正常（经过排查发现是重启了）。告警信息如下（已经脱敏）：多个节点几乎同时出现GC问题，查看自然流量监控后发现并没有明显增加。基本可以确定是GC问题，需要解决。排查流程GC日志排查GC问题首先要检查的应该是GC日志。在GC发生的那一刻，日志可以很清楚的判断是什么原因导致了GC。通过分析GC日志，可以很清楚的判断是哪一部分GC出了问题，如下GC日志示例：0.514:[GC(AllocationFailure)[PSYoungGen:4445K->1386K(28672K)]168285K->165234K(200704K），0.0036830秒][时间：用户=0.00系统=0.00，实际=0.00秒]0.518：[完整GC（人体工程学）[PSYoungGen：1386K->0K(28672K)][ParOldGen：163848K->165101K(172032K)]165234K->165101K(200704K),[Metaspace:3509K->3509K(105)0.0103061secs][Times:user=0.05sys=0.00,real=0.01secs]0.528:[GC(AllocationFailure)[PSYoungGen:0K->0K(28672K)]165101K->165101K(200704K)，0.0019968秒][时间：用户=0.00系统=0.00，实际=0.00秒]0.530：[完整GC（分配失败）[PSYoungGen：0K->0K（28672K)][ParOldGen:165101K->165082K(172032K)]165101K->165082K(200704K),[元空间:3509K->3509K(1056768K)??],0.0108352秒][时间:user=0.03sys=0.01,real=0.01】从上面的GC日志可以明显的看出引起FullGC的问题是：FullGC之后，新生代的内存没有变化，老年代的内存占用从165101K减少低至165082K（几乎没有变化）程序最终溢出内存，因为没有可用于创建70m大对象的堆内存。但是在生产环境中总是会出现奇怪的问题。由于服务部署在K8s容器中，运维对服务有心跳检测，当程序触发FullGC时，整个系统停止World，如果连续多次心跳检测失败，则为如果判断当前节点可能出现故障（硬件、网络、BUG等），则当前节点将被拉出并立即重建。此时之前打印的GC日志都在当前容器卷中。一旦重建，所有日志都会丢失，无法通过GC日志排查问题。上面提到的GC日志丢失问题，基本没有通过JVM监控埋点的方式来解决。如果发生GC，会立即重建。除非人为干预，否则很难获得当时的GC日志，也很难预测下一次GC问题发生的时间（如果能报告GC日期就不会有这个问题，我发现之后，但我没有找到它......）。这时，另一种方式就是通过JVM埋点监控来排查问题。企业应用都会配备完整的JVM监控板，就是为了能够看清“事故现场”。通过监控，可以清楚的看到JVM内部是如何在时间轴上分配和回收内存的。JVM监控用于监控重要的JVM指标，包括堆内存、非堆内存、directbuffer、内存映射buffer、GC累积信息、线程数等，主要关注的核心指标如下：GC（garbagecollection）FullGC次数YoungGC次数FullGC时间消耗YoungGC时间消耗堆内存详情heap内存sumheapmemoryoldgenerationbytesheapmemoryyounggenerationSurvivorareabytesnumberheapmemoryYoungGenerationEdenAreaBytesCommittedMemoryBytesMetaspaceMetaspaceBytesNon-heapMemoryNon-heapMemoryCommittedBytesNon-heapMemoryInitialBytesNon-heapMemoryMaximumBytesNon-heapMemoryDirectBufferTotalSize(bytes)DirectBufferusagesize(bytes)JVM线程数线程总数死锁线程数新建线程数阻塞线程数可运行线程数终止线程数限时等待线程数等待线程数GC问题，重点关注这些指标可以大致勾勒出GC问题。检查堆内存，首先检查堆内存，确认是否存在内存溢出（无法申请到足够的内存导致）。内部监控如下：FullGC发生后，堆内存明显减少，但在大量FullGC发生前，最终有部分内存被回收到与FullGC相同的位置，所以可以可以断定堆内存是可以正常回收的，并不是造成大量FullGC的罪魁祸首。非堆内存检查非堆内存指的是Metaspace区域，监控点如下：可以看到发生告警后，瞬间回收了很多非堆内存（因为服务器是重建的被健康检查判断无效后，相当于重启并重新初始化JVM），这里有GC排查经验的人肯定能第一时间判断出是metaspace有问题。元空间有什么用？随着JDK8的到来，JVM不再有PermGen（永久代），但是类的元数据信息（metadata）还在，只是不再存储在连续的堆空间中，而是移到了名为localmemory的内存中“元空间”。（本机内存）。那么类信息什么时候加载呢？程序运行时：Java程序运行时，程序所需要的类和方法。当一个类被引用时：当一个程序第一次引用一个类时，这个类被加载。反射：当使用反射API访问类时，将加载该类。动态代理：当使用动态代理创建代理对象时，加载该对象所需的类。由上可知，如果一个服务没有反射或动态代理等大量类加载需求，合理的是程序启动后加载的类数量应该波动很小（确实如此不排除一些异常的栈反射也会导致加载类增加），但如上监控所示，在GC之后，metaspace的内存使用量一直在缓慢增加，也就是在不断的创建“类”程序。查看JVM加载类监控如下：从上面的监控来看确实加载了大量的类，而且数量的趋势与非堆使用的趋势是一致的。查看当前JVM设置的非堆内存大小如下：MetaspaceSize&MaxMetaspaceSize=1024M，根据上面的非堆内存使用监控，使用量接近1000M，无法分配足够的内存加载类，最终导致FullGC问题。程序代码调查从以上调查得出结论：程序中大量创建的类导致非堆内存被炸毁。考虑到目前服务中有大量的Groovy动态脚本函数，大概率是创建脚本有问题。在脚本中创建动态类的代码如下：publicstaticGroovyObjectbuildGroovyObject(Stringscript){GroovyClassLoaderclassLoader=newGroovyClassLoader();尝试{ClassgroovyClass=classLoader.parseClass(script);GroovyObjectgroovyObject=(GroovyObject)groovyClass.newInstance();类加载器.clearCache();log.info("groovybuildScript成功:{}",groovyObject);返回常规对象；(Exceptione){thrownewRuntimeException("buildScript错误",e);}最后{尝试{classLoader.关闭（）;}赶上（IOExceptione）{日志。error("关闭GroovyClassLoader错误",e);}}}在线打开日志确实证明类在不断创建。脚本创建类导致堆内存被炸飞，坑也被踩了。对于同一个脚本（MD5值相同），直接取缓存，不会重复创建类。缓存检查逻辑如下：publicstaticGroovyObjectbuildScript(StringscriptId,Stringscript){Validate.notEmpty(scriptId,"scriptIdisempty");Validate.notEmpty(scriptId,"脚本为空");//尝试缓存获取StringcurrScriptMD5=DigestUtils.md5DigestAsHex(script.getBytes());if(GROOVY_OBJECT_CACHE_MAP.containsKey(scriptId)&&currScriptMD5.equals(GROOVY_OBJECT_CACHE_MAP.get(scriptId).getScriptMD5())){log.info("groovyObjectCachehit,scriptId:{}",scriptId);scriptId).getGroovyObject();}//创建try{GroovyObjectgroovyObject=buildGroovyObject(script);//放入缓存GROOVY_OBJECT_CACHE_MAP.put(scriptId,GroovyCacheData.builder().scriptMD5(currScriptMD5).groovyObject(groovyObject).build());}赶上（异常e）{thrownewRuntimeException(String.format("scriptId:%sbuildGroovyObjecterror",scriptId),e);}returnGROOVY_OBJECT_CACHE_MAP.get(scriptId).getGroovyObject();}这里的代码逻辑在之前的测试中已经反复验证过了，不会有问题，也就是cachekey的问题导致了重复加载班级。结合最近网上修改的逻辑，经过排查，发现可能是scriptId重复，导致不同的脚本，重复加载同一个scriptId（加载频率每10分钟更新一次，所以non-heap使用率上升慢慢地）。这里埋下一个小坑：加载的类使用Map存储，即同一个cacheKey调用Map.put()方法，重复加载的类会被后面加载的类替换，即加载的类before不再被使用地图“持有”的内容将被垃圾收集器回收。按理说Metaspace不应该一直增长下去！？提示：当元空间被回收时，类加载与Groovy类加载。由于篇幅原因，本文在此不再赘述。有兴趣的朋友可以google或者关注我，我会开一个章节详细说明原因。总结知道你知道什么以及为什么。如果你想系统地掌握如何处理GC问题，你还是要了解GC的基础知识：基本概念、内存划分、分配对象、收集对象、收集器等。掌握分析GC问题的常用工具，比如作为gceasy.io在线GC日志分析工具。这里笔者参考了美团技术团队用Java编写的9个CMSGC常见问题的分析与解决方案。昔日精彩的性能调优——小日志大坑性能优化必不可少——Flink在风控场景下对实时特性的实现。欢迎关注公众号：咕咕鸡技术专栏个人技术博客：https://jifuwei.github.io/>
