发现CMS GC有点傻 -- ebs full gc 问题排查

最新推荐文章于 2023-11-19 08:06:36 发布

白泽-默

最新推荐文章于 2023-11-19 08:06:36 发布

阅读量587

点赞数

分类专栏： java 文章标签： jvm java 算法

本文链接：https://blog.csdn.net/qq_35462834/article/details/128189042

版权

java 专栏收录该内容

5 篇文章 0 订阅

订阅专栏

背景

今年5月底开始，ebs机器陆续开始出现单机full gc，经过连续几天的排查也没有找到根因，临时解决办法是把4c8g的机器升配到4c16g，缓解内存压力。

9月份开始，16g的机器偶尔还是出现单机full gc，由于16g内存的机器整体性能还可以，一般单机full gc一次后机器就恢复正常，很难再抓到现场。但是单机抖动对业务的影响还是非常大，需要彻底解决。

问题排查思路

在5月份的时候，我们那个4c8g的机器挺不过full gc压力直接被打死了，我们拿到了不少当时的dump，但是通过分析也没有找到内存泄漏的点。而且9月份开始的full gc几秒钟后就恢复了，很难抓取现场。所以换个思路：

在full gc发生的前后分析下堆的使用情况，看看内存到底是怎么被填满的，是逐渐填满的还是突然填满的。
怀疑在full gc前有大对象内存分配，在还没来得及执行cms gc的时候把堆撑爆了，触发了Full GC，要尝试把大对象分配找出来。

先看看GC前后内存统计

背景知识：PrintFLSStatistics

-XX:PrintFLSStatistics=n

PrintFLSStatistics是用来统计内存分配情况和碎片统计的信息的，网上关于PrintFLSStatistics介绍比较少，相关细节需要看下源码，我们用的是JDK8，可以看这个源码：

shenandoah-jdk8u/compactibleFreeListSpace.cpp at master · openjdk/shenandoah-jdk8u

源码显示当设置PrintFLSStatistics>0的时候，会在gc的开始(prologue)和结束(epilogue)打印FreeList统计信息，FreeList是空闲内存的索引，堆内存分配的时候需要通过FreeList查询合适的空间。由于FreeList里面查找的空闲块大小很难与申请的大小一致，申请后剩余的内存还会还回到FreeList，这个过程会导致FreeList的空间不断别切割成更片段，造成内存不连续而无法使用，内存碎片就是这么产生的。

当PrintFLSStatistics>0时，首先打印的是BinaryTreeDictionary信息，这个信息就是可用的连续内存。

当PrintFLSStatistics>1时，会打印IndexedFreeLists信息，这里面包含FreeList所有的碎片信息。

ebs单机gc日志还原

下面我们看下ebs 11.192.243.44 这个机器在full gc时候的统计日志。

我们先看GC开始前（Before GC）：

2022-10-13T10:13:15.350+0800: 1358193.250: [GC (Allocation Failure) Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 16005 Max Chunk Size: 16005 Number of Blocks: 1 Av. Block Size: 16005 Tree Height: 1 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 165963191 Max Chunk Size: 254 Number of Blocks: 32379033 Av. Block Size: 5 free=165979196 frag=1.0000

第一行Allocation Failure表示没有更多的空闲内存分配了（主意这里需要的是连续的空间），我们可以看到在IndexedFreeLists统计下面的信息，剩余空间 Total Free Space: 165963191 = 165963191 * 8 / 1024 / 1024 / 1024 = 1.24GB，frag=1.0000 表示这个 1.24GB空间 100% 的碎片率，最大的连续空间才 Max Chunk Size: 254 = 254 * 8 = 2k，平均空间大小 Av. Block Size: 5 = 5 * 8 = 40bit，真是碎的一地鸡毛啊。

再看上面日志的BinaryTreeDictionary，在Full GC 前 Total Free Space: 16005 = 16005 * 8 / 1024 = 125k，也就说只要分配比125k大，内存就爆了。BinaryTreeDictionary （我们简单理解是多个大块的连续内存）是随着内存的分配不断减少的，Number of Blocks 是连续空间块的个数，也一样是随着内存分配不断减少。下图是在Full GC前几次BinaryTreeDictionary统计信息，总大小和可用块数都在不断减少。

我们知道碎片信息在CMS GC是无法避免的，只能通过Full GC回收。

Monitoring CMS free list BinaryTreeDictionary statistics

我们看下Full GC后（After GC）的内存统计情况：

CMS: Large block 0x00000006bddd5a90 : 4994842K->1529558K(6291456K), 6.2918770 secs] 8195071K->1529558K(9961472K), [Metaspace: 437386K->436770K(1476608K)]After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 609506478 Max Chunk Size: 609506478 Number of Blocks: 1 Av. Block Size: 609506478 Tree Height: 1 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 free=609506478 frag=0.0000 , 7.2442236 secs] [Times: user=7.42 sys=0.00, real=7.25 secs]

Full GC重建了世界的秩序，Total Free Space: 609506478，Number of Blocks: 1 表示整个空闲堆被整理成了1块连续的空间，大小=609506478 * 8 / 1024 / 1024 / 1024 = 4.5GB

IndexedFreeLists显示，碎片全被干掉了，frag=0.0000，世界清静了，同时整个GC耗时 7.25 secs。对于10G的大堆，7秒的Full GC时间也没什么好惊讶的。

ebs应用full gc原因

好了，现在我们通过上面日志分析，解释下ebs应用full gc的原因，先贴上ebs的内存和gc参数：

-server -Xmx10g -Xms10g -Xmn4g -Xss512k -XX:MetaspaceSize=512M -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC

整个堆10G，new generation=4g，old generation=6g，CMSInitiatingOccupancyFraction=80当老年代使用超过80%的时候还是CMS，就是说，剩余空间小于 6g * (1-80%) = 1.2G的时候才会触发cms gc，不幸的是通过我们上面的分析：

剩余空间 Total Free Space: 165963191 = 165963191 * 8 / 1024 / 1024 / 1024 = 1.24GB

明明1.24GB都是碎片，还认为有剩余的空间不进行CMS GC，由于最后一次内存申请超过125k，雪崩了触发了STW的Full GC（Allocation Failure），你说这算法是不是很傻？

总结一下： ebs full gc的原因是碎片太大，超过了 OldGen * (1-CMSInitiatingOccupancyFraction)，这个算法傻的地方是没有看内存的碎片率。

所以这里两个Action：

CMSInitiatingOccupancyFraction=70，可以缓解。
另外，在G1中是可以通过minor gc消除碎片的，jvm团队同学推荐用jdk11的G1，优化的比较成熟。

看看大对象分配

虽然通过上面的分析，即使没有大对象分配，也证明了会导致full gc。不过为了放心，索性把大对象分配的猜想也验证一下。

背景知识：打印大对象内存分配堆栈

-XX:ArrayAllocationWarningSize=20480k

ArrayAllocationWarningSize参数是阿里ajdk特有的参数，在Dragonwell 8.1.1后的版本支持，具体使用文档可以参考：Alibaba Dragonwell 8 Release Notes(中文) · 语雀 (antfin-inc.com)

这里需要注意一下，ArrayAllocationWarningSize的信息只会打印到标准输出里，所以在我们线上应用需要修改下启动脚本，把jetty或tomcat的标准输出重定向到一个文件，不然数据就丢失了，比如以jetty为例：

ebs 实验数据

实验机器：ebs 11.192.243.44

最近正好封网没有发布，经过5天的测试，在机器上发现的唯一大对象来自com.aliyun.rc.service.cache.ProductLocationWatcher.queryFullLocationTree(ProductLocationWatcher.java:176)，分配了30MB。详细日志如下：

==WARNING== allocating large array--thread_id[0x00007fd907e8e000]--thread_name[ProductLocationWatcher-1666232342702]--array_size[30669952 byt es]--array_length[15334967 elememts] os_prio=0 tid=0x00007fd907e8e000 nid=0x1fbe7 runnable at com.alibaba.fastjson.serializer.SerializeWriter.expandCapacity(SerializeWriter.java:306) at com.alibaba.fastjson.serializer.SerializeWriter.writeLong(SerializeWriter.java:757) at com.alibaba.fastjson.serializer.DateCodec.write(DateCodec.java:228) at com.alibaba.fastjson.serializer.JSONSerializer.writeWithFieldName(JSONSerializer.java:333) at com.alibaba.fastjson.serializer.ASMSerializer_11_LocationAttribute.writeNormal(Unknown Source) at com.alibaba.fastjson.serializer.ASMSerializer_11_LocationAttribute.write(Unknown Source) at com.alibaba.fastjson.serializer.CollectionCodec.write(CollectionCodec.java:101) at com.alibaba.fastjson.serializer.JSONSerializer.writeWithFieldName(JSONSerializer.java:333) at com.alibaba.fastjson.serializer.ASMSerializer_10_Location.writeNormal(Unknown Source) at com.alibaba.fastjson.serializer.ASMSerializer_10_Location.write(Unknown Source) at com.alibaba.fastjson.serializer.JSONSerializer.writeWithFieldName(JSONSerializer.java:333) at com.alibaba.fastjson.serializer.JSONSerializer.writeWithFieldName(JSONSerializer.java:311) at com.alibaba.fastjson.serializer.ASMSerializer_9_ListResult.writeNormal(Unknown Source) at com.alibaba.fastjson.serializer.ASMSerializer_9_ListResult.write(Unknown Source) at com.alibaba.fastjson.serializer.JSONSerializer.writeWithFieldName(JSONSerializer.java:333) at com.alibaba.fastjson.serializer.ASMSerializer_7_RpcLogExt.writeNormal(Unknown Source) at com.alibaba.fastjson.serializer.ASMSerializer_7_RpcLogExt.write(Unknown Source) at com.alibaba.fastjson.serializer.JSONSerializer.write(JSONSerializer.java:285) at com.alibaba.fastjson.JSON.toJSONString(JSON.java:758) at com.alibaba.fastjson.JSON.toJSONString(JSON.java:692) at com.aliyun.ecs.common.framework.trace.AbstractRpcLogEntryPointExt.toFullJsonString(AbstractRpcLogEntryPointExt.java:119) at com.aliyun.ecs.common.framework.trace.AbstractRpcLogEntryPointExt.processAndSaveRpcLog(AbstractRpcLogEntryPointExt.java:95) at com.aliyun.ecs.common.framework.trace.CommonRpcLogFilter.invoke(CommonRpcLogFilter.java:135) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.aliyun.ecs.common.framework.sentinel.filter.CustomizeSentinelDubboConsumerFilter.invoke(CustomizeSentinelDubboConsumerFilter.ja va:50) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:53) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.csp.sentinel.adapter.dubbo.DubboAppContextFilter.invoke(DubboAppContextFilter.java:41) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.ConsumerContextFilter.invoke(ConsumerContextFilter.java:48) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:74) at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53) at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:77) at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:226) at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72) at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52) at com.alibaba.dubbo.common.bytecode.proxy0.queryFullLocationTree(proxy0.java) at com.aliyun.rc.service.cache.ProductLocationWatcher.queryFullLocationTree(ProductLocationWatcher.java:176) at com.aliyun.rc.service.cache.ProductLocationWatcher.refresh(ProductLocationWatcher.java:107) at com.aliyun.rc.service.cache.ProductLocationWatcher.run(ProductLocationWatcher.java:59) at java.lang.Thread.run(Thread.java:858)