记一次没有保留现场的fullgc排除

0
fullgc

起因

12点00分在核心应用告警群竞价系统的单台机器出现fullgc告警，我看到后于12点10分接手，此时fullgc情况已经消失，因此第一时间无法通过dump内存保留现场，只能排查监控和机器日志来间接定位问题，下面是具体排查流程

sunfire监控排查

基础监控

应用基础监控

cpu利用率&网络流量

考虑到有几个原因：

  1. 外部hsf访问流量激增

  2. metaq瞬间流量

  3. 定时任务调度

  4. db访问有慢sql或大批量查询

  5. 。。。

因此转向中间件监控排查

中间件监控

JVM监控

  • 内存&gc情况分析

时间GC情况Eden区Survivor区Old区分析
11:58ygc:2次fgc:0次1243M17.9M525M 
11:59ygc:12次fgc:10次979M17M525M此时ygc次数陡增，且出现频繁fgc（似乎不太合理，后续会说明）
12:00ygc:9次fgc:12次5M0M1821Meden区和s区几乎被完全清空，old出现大亮内存占用，出现大量ygc和fgc
12:01ygc:9次fgc:12次16.5M0M1929M(超过老年代80%阈值)fgc无法释放old区大对象，导致一直fgc
12:02ygc:22次fgc:0次70M0M1278M成功释放掉大对象，gc情况恢复
HSF监控

hsf qps水位正常，但rt有增幅，大概率是fgc导致

MetaQ监控

  • qps

  • rt

metaQ消费&发送水位/rt无异常

TDDL监控

  • qps

  • rt

  • 慢sql监控

通过上述我们可以看出在12点开始的确有一个抖峰出现大量查询，但没有慢sql情况

初步结论

  1. 外部hsf访问流量激增导致

  2. metaq瞬间流量导致

  3. 定时任务调度(重点排查是否有异常定时任务)

  4. db访问有慢sql或大批量查询

SLS日志排查

业务日志

  • 定时器相关日志

  1. 趋势品自动审核定时器

  1. 官补业务画像定时器BidCreatePortraitSkuDimJob更新子任务GbBidPortraitCheckAndUpdateProcessor

  2. 首坑画像产出主任务日志BidCreatePortraitItemDimJob

可以发现画像生成时会捞取上游算法同步到mysql表中的数据量进行子任务分发，首坑画像数据源已经到了将近30万（该表包含33个字段，就算一个对象占用2kb内存，30万也有600M内存占用显然非常容易gc），同时在代码发现该大对象的引用（大list，大Map等）一直在主任务分发调用链路里，显然无法被gc，同时查询下线子任务构造日志可以发现大对象被回收时间也是对的上的（该子任务分发逻辑大约跑了将近2分钟，由于大对象无法被gc掉导致频繁fullgc），显然本次fullgc告警和这个逻辑脱不了干系

 

gc日志

  • 12:00:08开始fgc,无法正常回收内存

  • 12:03:06 gc恢复正常

基于日志的时间线串连

image-20230706135609114

可以看出业务/gc的发生和恢复情况是match上的

代码分析

img

img

img

 

疑问

  • sunfire fgc时间为何有点对不上

理论上这个大内存的驻留明显是关键凶手，但从sunfire 监控我们可知fullGc是从11:59分开始，而画像定时器逻辑是12:00才开始运行在这台机器上的，这一分钟的偏差令我在动车快要开的时候很纠结这是什么情况（在58-59分并未发现其他异常日志）。。。而我的动车在1点多就要开了，只能先打车去高铁站，等上了高铁后我在sunfire平台上查询了是不是有可能采集的时间会有偏差的case，发现有不少类似的疑问，显然sunfire通过alimetrics接口采集的数据不是非常准确，准确的数据应该还是通过鹰眼系统来看：

通过这张图完美可以很明显的看到随着画像定时任务不断向jvm申请大内存（线程池并发获取对象速度很快），导致触发频繁ygc，这部分原先在eden/s0区的几百M内存仍被引用的对象过大ygc无法被转移到s1区直接进入old区以及部分对象通过年龄很快达到阈值（默认15（2+2+2+11 > 15））后进入老年代（这也说明了eden区的内存几乎变700M->18M的原因）,同时后续的大对象也进入老年代，导致触发fullgc，但这些大对象被引用时间过长一直无法被gc掉，最终这两分钟内jvm频繁fullgc

  • 为何之前没有暴露这个fgc问题？

11.05

img

11.03

img

本质上前几次也是在临界点了，在主任务执行时eden区和old区有明显增幅，只是在触发ygc/fgc时我们的大对象已经没有引用就能被回收恢复正常

结论

  • 优化画像定时器循环取数逻辑后发布，明天手动执行，dump上下文以及观察jvm情况

  • 同时也发现随着定时任务申请的大对象被回收后我们老年代的内存占用仍然很高，通过上面的分析我们可以知道之前有几百M可能已经没有引用的对象进入了老年代，但此后系统一直没有fgc（eden区能够cover住对象申请），导致老年代这些对象一直没被释放，最终在2点07分的一次fgc后这些垃圾内存也被瞬间释放了。。。

11.7更新

今日于上午11:06分开始执行定时任务（主任务ip：33.44.193.44），11点09分执行了dump操作（这里会触发一次fgc），于11点16分完成各个子任务构造并分发

dump文件

优化后可以明显看出创建了大量的整形数组对象(保留堆占用17M)，从大对象数组到整形对象数组的优化显然极大缓解了jvm内存的压力，说明优化是OK的

jvm监控水位

  • gc情况

本次fgc是dump触发，gc情况正常

  • 堆内存

内存水位正常

 

11.9日更新

跑任务之前old区内存使用率较高，一次fullgc后恢复正常