大过年的生产项目频繁fullgc

2023-12-01 19:24:10

本想好好过个年，怎奈项目不给力。过年期间生产环境频繁告警。主要是xxljob调度失败，查看xxljob日志是调用超时，于是赶紧去查看下是不是项目挂掉了，查看了下健康状态发现，都很健康，怎么就调度失败了呢？不科学。

>>>>>>>>>>>触发调度<<<<<<<<<<<
触发调度：
address：172.19.5.242:9999
code：500
msg：com.xxl.rpc.util.XxlRpcException: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.19.5.242:9999
at com.xxl.rpc.remoting.invoker.reference.XxlRpcReferenceBean$1.invoke(XxlRpcReferenceBean.java:250)
at com.sun.proxy.$Proxy121.run(Unknown Source)
at com.xxl.job.admin.core.trigger.XxlJobTrigger.runExecutor(XxlJobTrigger.java:214)
at com.xxl.job.admin.core.trigger.XxlJobTrigger.processTrigger(XxlJobTrigger.java:167)
at com.xxl.job.admin.core.trigger.XxlJobTrigger.trigger(XxlJobTrigger.java:91)
at com.xxl.job.admin.core.thread.JobTriggerPoolHelper$3.run(JobTriggerPoolHelper.java:90)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748) Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.19.5.242:9999 Caused by: java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:715)
at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:688)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)
at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)

于是大胆猜测项目产生fullgc导致stw时间过长然后请求执行超时。于是给项目加上gc日志打印的参数发现果然频繁GC和fullGC太频繁了。

-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps

于是把堆内存dump下来，用jvisualvm工具分析发现
项目中ExceptionCode这个类对象有1千600多万个，占比百分31，占比靠前的对象如下图

于是着手排查为什么这个类会产生如此多的对象，春节期间，系统也没有什么流量。最后查到相关代码如下

public static ExceptionCode getMessage(String code, Object... args) {
        String locale = Optional.ofNullable(SystemContext.getLocale()).orElse("zh_CN");
        ExceptionCode unchecked = cache.getUnchecked(ExceptionCode.paramOf(code, locale));
        String message =MessageFormatter.arrayFormat(unchecked.getMessage(), args).getMessage();
        unchecked.setMessage(message);
        return unchecked;
    }

此处从缓存获取一个ExceptionCode 对象缓存使用的是google的LoadingCache<ExceptionCode, ExceptionCode>既然有缓存不至于出现这么多对象啊，此处的功能是通过异常码查询message，做了多语言的国际化，首先怀疑这个缓存有问题，点进去看了源码缓存是一个map结构，通过key.hash获取缓存对象，查了下数据库，总数据量只有4514条数据，常规来说，能产生1万个对象就很多了，可是这里是1千多万个对象，首先检查该ExceptionCode对象，发现好家伙没有重写hashcode和equals，所以每次都是把新对象丢到缓存里面，导致缓存暴涨。找到错误的地方了，但是数据的源头是哪里来的呢？

于是追踪相关对象的code，发现所有的code均为220004和105181通过code搜索代码，定位到对应功能发现是mq的消费者。忽然想起来节前由于mq很多数据卡在unack状态，只能通过重启项目才能重新消费，于是嘴贱让开发改了下代码，业务如果抛异常让它重新回到ready状态，重新消费。然后去看了下mq，发现有一个队列卡了10条数据，一直running中，每秒投递60次，一直循环投递，项目一直抛异常，然后一直产生新的Exception对象，加上缓存有问题，导致项目重启过后一两天就把内存撑爆,然后频繁GC，然后大过年的一直在重启项目中度过。
年后过来排查完问题，并且把ExceptionCode重写了hashcode和equals重新发个版，果断就好了。

码农公寓

相关文章