业务线最近有个应用,过不了十几天就会开始疯狂的Full GC,发生了两次了,业务线对业务dump后,发过来截图,说是qclient中的对象导致内存爆了。
qclient是我们这边分库分表的中间层,遵循了JDBC规范实现。
首先确定是否如业务线所说,用jmap -dump:format=b,file=/tmp/dump.jprof,用工具打开后,发现确实如期所说。那就开始看相关的代码。
首先看这几类相关的源码,QConfigExtractorLoader应该是这几类的入口,问题应该出在这个类上。
每次调用这个类的init时,静态属性store会将相关的runnable匿名类,增加到callbacks中,而这个callbacks是个CopyOnWriteArrayList,这个加入的callback一直有list指向,导致引用一直存在,导致gc不能将其清理掉。找到可能的原因,那么是谁调用了这么多次init方法了?
查看了所有代码,这个类的new就只有AdaptiveConfigLoader去反射调用,那么AdaptiveConfigLoader就是整个可能的入口,那又是什么调用了这么多次了?
查看AdaptiveConfigLoader的实例化的地方,一共有9个方法,向上肯几层的话,会发现都是在PostConstruct注解里面初始化的,而这几个类的bean应该是不会一直初始化的,问题定位陷入了胡同。感觉应该不是我们的中间件有问题,可能是业务线使用我们中间件的问题。
那就开始查业务线的机器日志,我的天,那日志看起来就不是给人看的。。。。打印的完全没有一点逻辑,时间线15点有,3点pm也有。。。warn事件也不打印,就打印info日志,debug日志,error日志,日志的信息也完全没有有用的信息,偏偏中间件的很多和这个相关的都是warn日志,从日志下手算是失败了。
那就jstack看线程栈吧,线程栈倒是有两个线程有关键字qclient,但都是sleep的状态,而且看代码,是个一分钟的任务,也不会创建和这个相关的实例。那这些实例是从哪来的,创建了这么多实例,线程栈应该是有关键字qclient去创建它的地方。
使用我们的工具集开始查问题,开启定时jstack和定时的统计实例个数(底层使用java的agent进程的java代码调用tools下的类,没有新开进程,比较轻量级),统计五分钟后发现一个比较有意思的地方,相关实例每分钟加60个,到这就可以看出问题了,应该是个定时任务,每秒加一个实例。
就应该不是中间件自身的问题了,在AdaptiveConfigLoader实例化的地方加个断点,果不其然,断点马上触发断点,看调用栈,是个定时任务线程池相关的栈,还看到业务线的代码package的开头,和业务线确认,问题找到了。
业务线自身的问题,反射的调用datasource的map,但是这个反射操作会增加callback,所以一秒加一个,15、6天正好加个100多万个。
问题解决。