前言
笔者在一个传统IT行业工作,目前维护着一个政府交易项目
2021年9月12日23点左右, 本是一个阳光明媚的周末,笔者正在家里吃着火锅唱着歌.
突然小组群报交易查看大范围失败。线上服务器挂了?没办法,996,
007, 24小时 on call 也不是闹着玩的,马上拿起电脑开始排查问题
排查过程
- 查看Mycat 服务器, 线上4台Mycat CPU 全部爆满。
- 查看应用日志, 发现当前活跃链接数只有几十个
注:这里有个特别不合理的地方,跟我们的业务特性有关,最近这个时间段不属于业务高峰期, 半夜11点不属于交易高峰时间段。应用刚经历过业务高峰期都平稳度过,那为什么会在一个不是高峰期,不是高峰时间段的时候突然资源不足呢?带着这些疑问我开始了苦逼的排查之旅
- 获取不到链接的日志
GetConnectionTimeoutException: wait millis 405, active 14, maxActive 300, creating 0
- 首先根据异常日志排查慢sql
i. 经过排查所有正在执行的sql都走了分表键+ 索引或者主键, 不存在慢sql
ii. 根据日志显示,有事务提交超时
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
- 这个时候怀疑是否有死锁问题导致
i. 直联mysql数据库 查询锁情况
ii. 发现完全没有死锁情况, 并且数据库资源正常,cpu 内存都很正常
SELECT * FROM information_schema.INNODB_TRX;
- 查到这个阶段,几乎已经要开始拽头发了。感觉已经到了死路
柳岸花明又一村
-
当时查到这里已经凌晨1点了, 应用还在持续故障,这个时候不得已 只好祭出重启大法,我先重启一台mycat, 观察mycat情况。
然后它就好了!!! 就好了!! 就好了!!!
如法炮制, 先恢复线上正常, 机智如我,当然不会全部都重启咯,留了一台机器继续查看问题。 -
分析一下,应用连接池没有满 并且非业务高峰期。
数据库资源正常。这个时候应该把问题锁定到应用到mycat 这个链路, 重启mycat后 mycat恢复到正常状态,资源消耗非常低。 -
没有慢sql 没有死锁 那是不是可以把问题锁定到mycat上?
-
怎么办? 上arthas吧, 启动arthas, 监控mycat服务,发现了异常。 6个BussinessExcutor 线程, 每个线程cpu资源都在98%左右, 这太不合理了
-
取一个线程id 查询一下堆栈信息
-
其实到这里就很明朗了, 这段代码在mycat里面到底是干嘛用的呢? 好,那就去扒一下mycat的源码。
-
实际上这段代码是mycat 用来管理对外内存的, 但是这里在老版本的mycat上有个bug, 如果mycat到mysql任务超时,那这里的while循环就变成了死循环, issue传送门
怎么引入的?
因为公司的mycat 是从mycat fork 的分支有一些个性化的修改,所以有些bug fix 因为之前脱离的主干太久 没有关注到。真是可惜了我风和日丽的周末和火锅。
解决
把mycat issue 代码合并到公司的分支, 重新打包发布, ok, 问题解决,继续吃火锅,
坑爹啊, 都要凌晨3点了, 吃什么火锅啊!!!