【MySQL】借助binlog排查一次生产问题

问题背景

最近生产环境经常有报警，原因在于数据库中同一条任务被连续消费了2次。我们的任务是存到mysql数据库中的，其实为了避免分布式多实例环境下同一个任务被消费两次，我使用了mysql乐观锁的方式。但是根据日志查看，确实有任务被连续消费了两次。

 

问题分析

1、mysql乐观锁失效？

分析：其实mysql乐观锁是非常经典的并发应用场景，一般不可能出问题。为了避免我代码有bug，我还是测试一下，使用 CountDownLatch 模拟了一下并发。结果证明我们的乐观锁还是很稳的！

2、有人手动重置了任务状态为待处理？

分析：收集这些报警发生的时间点，有夜晚的，有凌晨的，，，应该不会有人这个时间点乱搞吧。。？纯属猜测，我们继续往下看

3、代码中有其他地方修改了任务状态？

分析：这是非常有可能的，但是想了一圈似乎没有什么地方会修改这个状态。

那怎么办呢？#2、#3都有可能呀。那就请今天的主角mysql-binlog登场吧！

 

获取binlog

先看看binlog是开启的

 

 

 

找到一个任务被连续消费发生的时间区间2020-04-19 17:43:00  -  2020-04-19 17:45:00。那我们就导出这个时间区间数据库执行了哪些sql语句吧！如下：

mysqlbinlog --base64-output=decode-rows -v --start-datetime='2020-04-19 17:43:00' --stop-datetime='2020-04-19 17:45:00' /home/mysql/data3039/mysql/mysql-bin.000001 -d my-db > tmp/binlog.sql

 

--base64-ouput=decode-rows 代表解码，不然你看到的sql是经过64位编码转换后的内容。
-v 代表换行显示这些语句，如果没有-v 你依然看不到具体的语句。

mysqlbinlog命令其它参数：
-d -database
-h -host
-p -password
-P -port
--start-datetime
--start-position
--stop-datetime
--stop-position

 

让我们继续，根据报警的那条数据主键id搜索。果然找到了这条SQL，本应该执行一次的，确执行了两次！并且执行的sql明显是我们mybaties拼接的！那就是发生在我们的代码中！

 

 

排除猜想#2，我们在代码里面继续深扒吧！

最后问题很快找到了。

 

总结
往往bug就发生在我们觉得不会出问题的地方，有了这个心理暗示，寻找原因的时候，心理上往往刻意避开这些。其实bug离我们不远，坚持继续深挖，很快就能知道了。想起以前学过的一篇古文《游褒禅山记》：
　　"余与四人拥火以入，入之愈深，其进愈难，而其见愈奇。有怠而欲出者，曰：“不出，火且尽。”遂与之俱出。盖余所至，比好游者尚不能十一，然视其左右，来而记之者已少。盖其又深，则其至又加少矣。方是时，予之力尚足以入，火尚足以明也。既其出，则或咎其欲出者，而余亦悔其随之而不得极夫游之乐也。"