一、背景
没想到24年上半年经历了两次域内服务G1的GC问题，上次是Mixed GC。这次是业务服务BizService，它承担了子域内几乎所有的业务能力，场景主要为吸纳增量用户，所以注定不会承担极高流量，但会写入较多的业务代码，20240613 15:38:23开始了G1 Young GC耗时较高告警。
| 监控告警 | |
|---|---|
二、现象收集
先看告警配置，其中120s内，连续触发超过 分钟内1000ms的GC，就会产生告警；
(一) 仅为Young GC
在结合工具针对问题节点的监控，果然，在15:35-15:38期间，存在三次1000ms+ 的分钟聚合Young GC，统计此时间段内触发了22次young gc，且无Mixed 和Full gc。
至此，进一步的分析只能去看gc日志。
(二) 日常Young GC日常到100ms
结合GC日志可以看到，Biz服务日常的youngGC就一直在100ms上下：
(三) GC在Update RS和Object Copy耗时较高
并且age threshold常常撑不到15：
三、问题定位
(一) dump文件分析
遇到GC相关问题，我们首先想到的方式还是通过jmap来打印服务的内存快照文件进行分析，我们先后0614、0617、0621进行了三次快照拉取，最小的1G，最大的12G。
拿到快照后就进行了多轮的排查，问题发生的前几天，公司有一篇关于YoungGC的文章在内网和公众号被推送，所以借此正好拜读了下，想看看能不能发现什么共性，并且在作者的帮助下，分析了AreaDTO，因为早期的现象是RS耗时较高，恰好包名带response，所以觉得是AreaDTO对象和请求响应有关，new出后被老年代的本地缓存引用着，然后记忆集被频繁更新，而且越来越大，进而解释了RS和Object Copy耗时较高，但排查发现其实该对象仅在某任务定时执行时被创建，任务下午2点多执行，我dump的时间为下午3：30左右，所以此时应该已经没有新的引用，仅是老年代的内存而已，所以，继续分析；
之后，还分析过下面特多的Thread，但其实是soa的线程，还有各种看起来异常的大对象，但均无功而返，被一一排除。但有一个让我们怀疑过很多次的大对象，如下图红框内，但很多次梳理下来，没能找到来源，只能先搁置，继续往后排查。
(二) jvm参数调优
dump文件上没看出什么大问题，在0702的时候便从jvm参数下手，看看能否发现一些参数上不合理的地方，通过对比BizService和UserSerivce，发现最明显的差距在NewSize的大小上，UserSerivce的预设4000M，但BizService却仅有1.3M不到，针对这样的现象，我们问了GPT，其回答是“避免设置 -XX:NewSize 和 -XX:MaxNewSize 之间存在巨大差距，以防止 G1 垃圾收集器在调整过程中产生较大的性能波动”，所以我们怀疑，可能是虚拟机长期在1M和6000M之间苦苦徘徊，经常性的申请和释放资源，只为了达到MaxGCPauseMillis的要求，
同时对比了其他兄弟高流量服务，发现确实只有BizService的老年代和新生代大小是不断波动的，这一刻我们几乎笃定是找到原因了，于是立即拉分支，结合其他服务，设置Jvm参数为
-Xmn5120m，当天便上线，
但现实却是，对于垃圾回收时间并未起效，仅有的效果是垃圾收集的次数倒是变的比较稳定了，并且老年代和新生代的预设大小上也没有了波动。
如今换一种方式再问GPT，才明白这其实如果设置了期望回收时间，是没有必要非得预设新生代大小的，特别是BizService这种量并不特别大的服务，除非特殊场景：比如资源有限，又想寻求G1的极致体验。
(三) 控制变量：
注：这种方式属于比较凑巧的场景，并不普世（更靠谱的还得是dump和火焰图等内存分析）。
在20240703的17:37分，某我们依赖的三方服务提示突然不可用，作为上游的我们，发现服务不可用时，会打印错误日志，30分钟内打印了16071条错误日志，这些日志对象可能就成为了服务新建对象数量边界的最后一根稻草（排查服务响应时长在问题前后并无差别，并不会拖长持有对象的周期），报错期间导致我们频繁YoungGC，反正三方服务也不可用，我们决定关掉入口灰度开关，顺便看下关掉这个接口对YGC时间是否有影响，没想到的是，关掉开关开关后，GCTime应声下跌：
第二天三方接口恢复，放开灰度，GCTime随之上升：
这一试，使问题几乎可以锁定到这个接口内部，大大缩小了排查范围。
(四) Arthas跟踪接口耗时和火焰图
0704，来到了大决战。
我们希望在极小的范围内可以排查出更加具体的原因，于是进行了接口耗时跟踪，并下载了火焰图：
1. 接口耗时跟踪，trace命令
所使用的相关指令为：
//1.启动Arthas
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
//2.输入相关命令 trace <class-name> <method-name>
trace com.xxx.yyy.ZZZImpl methodName
结果如下，耗时主要体现在调用三方接口上传AC证书接口上和获取跳转链接，
- 证书上传有较多文件操作，并且依赖外部的接口，此接口在对接时就知道确实慢；
- 获取外部跳转链接，此处需要创建HttpClient去调用，相比其它内部操作，故耗时也在预期之中：
2. alloc层面火焰图
所使用的相关指令为：
profiler start -d 60 -e alloc
结果如下：
除了不可避免的根基父类调用，首先看到的就是下图红框中的A接口和B接口，其中A上游为UserService，为本服务Qps（近3000）最高的接口，对象多是合理的，但B接口（问题接口）最高为10，平均0.4，它也这么显眼就说明主要问题在此。
alloc火焰图的主要关注点：
- 水平轴：代表调用链的宽度，越宽表示该调用占用的内存（或时间）越多。
- 垂直轴：代表调用栈深度，越高表示调用栈越深。
- 矩形块：每个块代表一个方法或者函数调用。宽度表示该函数在分析期间分配的内存数量。
经过更近一步梳理，认为有以下优化点：
首先需要声明的是，B接口内和外部相关的逻辑，包括两部分，分别为上传AC证书和从外部获取跳转链接。基于此再看：
- 每次调用都会现场创建HttpClient，并且疑似不会自动关闭资源，此次将优化为单例；
- 上传AC证书接口，会拿本地服务中的一个协议文件(497KB)，目前逻辑每次都是现拿并且转为byte[]供三方使用，由于原始文件不会变，可优化为缓存在本地，不需要每次请求都转一份byte[]，并且删除不必要的对于文件结果的打印日志；
- 同时可以考虑针对外部接口设置最大过期时间，以避免接口耗时增加导致的对象堆积。
五、优化结果
0705晚上10点进行了单台发布，以下是单台运行结果，分钟内的GC耗时来到了80ms以内：
再次拉取此节点alloc火焰图来看，所占内存明显减少8.43%->0.96% ：
节点推全后的GCTime：
分钟垃圾回收耗时也来到了100ms内，相比之前，下降了90+% ！
六、总结&心得：
本次问题排查，为了尽快找出根因，其实尝试了很多种排查工具和方式，走了一些弯路，但也有一些收获，比如：
1.先尝试火焰图
定位运行期且可被回收的对象，尤其YoungGC阶段的对象，其实火焰图是一种很好的方式，准确、快捷、又轻量，所以不一定遇到GC问题就先去打印快照，可以先尝试火焰图，如果拿不准再去dump4。
2.dump可能更适合看一些内存泄漏的问题
通过这次排查，其实也让我觉得，dump可能更适合看一些内存泄漏的问题，运行时的内存问题不是最佳实践。
3.生产上打印日志要小心
之前总觉得流量低打印了也不会有多少占用，但是忽略了这个日志比较大，并且这样的日志对于定位问题并无多大帮助。
七、Q&A：
(一) 接口的qps并不高，对象的能占用很大内存吗？
答：首先，问题接口YGC主要在高峰期，高峰期的Qps能到10+，然后根据测试环境debug看，对象的大小可以到470KB，然后分析代码可见的至少会创建三份这个大小的对象，log4j内部还会有更多创建对象的操作，并且一次请求会有两次日志的打印，那我们来计算下一分钟可以创建多大对象：104703260=1692000/1024 = 1652.34M，单台节点每分钟1652.34/6 = 275.39M。
(二) Hlog对于内存占用的影响
此次场景中，同一个对象，分别在进入公司封装的log方法和FastJson处理，都知道FastJson有内存和cpu的消耗，没想到log在内存上的消耗竟是FastJson的（3.65 + 3.87）/(0.17+0.19) ≈ 21倍！
e.g.：
Json占用内存
Hlog占用内存：
