如果对过程不太感兴趣,可以直接查看复盘章节。
一、背景
2023年底所有系统要去O,在此背景下,多个系统要上云。其中XXX系统于最近一周上线运行,但是运营人员反馈后台服务会不定期僵死,然后手工重启服务后系统恢复正常。僵死后,服务还在,k8s中pod还在,日志文件未丢失。
二、初步思路
运营人员反馈:每次后台服务僵死时,日志打印到业务代码运行的一个sql查询处戛然而止。数据源管理使用的alibaba druid框架,参数配置也是从其他框架拷贝而来;其他框架没问题,这个服务就有问题,古而怪哉!
初步分析和数据源管理有关。
1、调整日志级别,增加druid和mybatis相关日志输出。
2、打开druid监控组件,查看是否有数据库连接泄露。三、分析过程
有规律的服务僵死,现场得以保留,现场可以重现,针对此类问题就比较好解决。就怕那种忽隐忽现、朦朦胧胧的故障,最不好搞。
1、服务僵死之后,进入pod容器,使用curl测试服务是否可用;
###服务一直等待,没有相应
curl 127.0.0.1:8102
2、查看业务日志,一直打印几个重复的关键词
2023-10-28 20:13:49.185 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase -Start expire sessions StandardManager at 1698495229185 sessioncount 0
2023-10-28 20:13:49.185 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase -End expire sessions StandardManager processingTime 0 expired sessions: 0
2023-10-28 20:13:51.385 [http-nio-8102-Acceptor-0] DEBUG o.a.tomcat.util.threads.LimitLatch -Counting up[http-nio-8102-Acceptor-0] latch=2724
3、拷贝arthas到pod中,查看是否有占用cpu、内存较高的进程
kubectl cp arthas.tar iptv-pod-asdada1339jh:/arthas.tar –kubeconfig=./configiptv.txt
java -jar arthas-boot.jar
#dashboard
###发现没有占用资源较高的进程
4、jvm当前正在干啥呢?将jvm dump出来分析一下吧
jstack -l 8 >heapdump.hprof
5、从pod中拷贝dump文件到本地
kubectl cp iptv-pod-asdada1339jh:/heapdump.hprof heapdump.hprof –kubeconfig=./configiptv.txt
6、使用大杀器jprofile来分析,墙裂推荐大家安装,当你不知道jvm在干啥的时候,它可以窥见
发现dump线程中好多都是业务线程,一直在等待,而且都停止在DruidDataSource.taskLast()方法,这是为什么呢?
7、进一步查看关于DruidDataSource类相关对象,发现运行时DruidDataSource的参数与yml配置的参数不一致啊
yml代码中配置:
8、网上搜索关于DruidDataSource.taskLast的惨案有很多,进一步印证了问题所在
四、解决方案
使得DruidDataSource初始化使用正确的配置,而不是缺省配置。
五、回放复盘
1、服务为什么会僵死呢?
因为druid连接池配置使用了缺省的配置,导致连接池中没有可用的连接,一直等待,导致tomcat业务线程也阻塞,为啥会有500多个线程呢?发现代码中配置了tomcat.max-threads=500,并发线程超过500,tomcat不响应新的请求了,所以僵死了。
2、为啥druid连接池无可用连接会一直等待呢?
使用druid默认配置,初始化连接池为0,最大连接为8,在稍微高一点的并发环境下,连接都被使用,又从连接池中一直获取连接,获取不到就死等。
3、为啥上线之前没有发现问题呢?
测试强度不够,无法模拟线上环境,这种隐藏的问题很隐蔽,既不抛异常,也没有任何提示,直到惨案发生!
拓展思考:这种隐藏问题如何避免,大家有啥高招?