SFLYQ

大话一次离奇的问题排查经历

2020-05-27
SFLYQ

这里记录一次莫名其妙的问题排查的经历,一天快下班之际,测试反馈说测试环境出现了调度脚本报错,输出错误日志,如下:



# 日志输出时间:[2020-05-14 17:37:00] 

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction[SQL]


并且后面无法重现问题,时间:18:10 左右我开始排查问题

定位错误问题:

就是执行的事物没提交COMMIT/ROLLBACK,然后其他执行语句对锁住的数据进行UPDATE操作,等待锁释放,最终导致锁等待超时

问题就是这么一个问题,就是不知道哪里触发了事物,而且没提交

于是开始了后面的排查的故事 … …

首先排查了业务相关表操作的代码,并没有发现有启用事物的操作,然后就一脸闷逼,这是啥操作,不应该啊,没有启动事物,怎么就数据被锁住导致超时了呢?

排查了一轮代码后还是没定位到问题,并且这个调度的脚本线上也一直再跑,并没有出现过类似的问题

因为时间有晚了,就先回家了

在回家的路上,左思右想,开始怀疑是不是代码里其他的业务数据执行,操作了事物没有提交,然后导致后面执行的语句也在事物中执行

晚饭休息了会儿,因为有件事情在心头没解决,就很不舒服,开始继续排查问题

又排查了一轮代码,还是依然没有思绪

在排查问题到开始怀疑人生的时候,突然灵光一现,有没可能除了业务代码之外对表进行了事物操作,然后没提交

回想到测试也会经常使用NAVICAT去操作表,去构建测试数据,不会是测试操作数据,使用了事物,然后没提交吧,这个也是有可能的

隔天在公司,一大早等测试到了工位,马上就杀到测试的PC上查看了下,NAVICAT的执行日志

看了日志后,真相大白,此时心中一万只羊驼狂奔而过~

日志如下:


[2020-05-14 17:36:21] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:36:21] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:36:21] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:36:26] [7370770] [test] [MYSQL]
BEGIN

[2020-05-14 17:36:26] [7370770] [test] [MYSQL]
delete from `xxxxx`.`table_xxx` where `id`='691' 

[2020-05-14 17:36:27] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:36:27] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:36:27] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:36:28] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:36:29] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:36:29] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:36:29] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:36:29] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:36:31] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:36:31] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:36:31] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:36:31] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:36:32] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:36:32] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:36:32] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:36:32] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:37:17] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:37:18] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:37:18] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:37:18] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:37:20] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:37:20] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:37:20] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:37:20] [7370770] [test] [MYSQL]
show create table `database`.`table_xxx`

[2020-05-14 17:37:22] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:37:22] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:37:22] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:37:22] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 17:37:23] [7370770] [test] [MYSQL]
select * from `xxxxx`.`table_xxx` where `baby_id` = '1269'  limit 0,1000

[2020-05-14 17:37:23] [7370770] [test] [MYSQL]
show columns from `xxxxx`.`table_xxx`

[2020-05-14 17:37:24] [7370770] [test] [MYSQL]
show index from `xxxxx`.`table_xxx`

[2020-05-14 17:37:24] [7370770] [test] [MYSQL]
show create table `xxxxx`.`table_xxx`

[2020-05-14 18:05:00] [7370770] [test] [MYSQL]
ROLLBACK

梳理整个事件

看日志,还原整个事件

时间:17:36:26
测试使用NAVICAT工具,在操作语句的时候无意间起用了事物,并且事物没提交

时间:17:37:00
测试反馈到我这里

时间:18:10:00
我开始排查问题,并且无法重现(看日志,事物已经回滚)

时间:18:10:00-隔天
排查了N次代码,一脸闷逼,怀疑人生,最后相信自己,开始怀疑外部,最终找到问题

就此结束,全剧终

记录下一次莫名其妙,看上去还有点荒唐的错误排查的经历


首发于Github:🌈大话WEB开发,欢迎star 😻


有任何想说的请留言哦
转载请申明原文地址,谢谢合作

Follow @sflaqiu

老铁们关注我的《大话WEB开发》微信公众号,跟踪我的原创博文

并不定时推荐WEB开发相关技术博文,共勉与学习交流!二维码↓

我的公众号


留言