之前一直没有机会碰到与MySQL相关的问题,缺乏一些对于线上环境排错的经验,今天刚好碰到这个一个例子,以此来做一些记录。
问题起因
某数据库中一张business表,当尝试update某一条记录时,会卡住一段时间,然后报一个获取锁错误。
问题初步确定
遇到这个问题第一反应是这个记录被加锁了,首先update了一下同一张表的其他数据,确定可以执行,因此初步确定是行锁引起的。
那么最直接的想法就是执行show full processlist;
,看一下能否找到蛛丝马迹。
然而结果并不乐观,上面命令告诉我当前这个数据库没有任何连接在执行SQL,唯一看到的就是我这条命令本身了。
但虽说没有执行SQL,但是有很多Sleep
中的连接,这种情况下,在此尝试update被锁死的数据,依然处于锁死状态。
进一步排查
这时想到了SHOW ENGINE INNODB STATUS;
查看一下InnoDB引擎的情况,可以看到我刚才执行的语句在尝试加锁的时候超时了,更印证了之前的推测。
首先考虑是不是出现了死锁,现在的MySQL基本比较智能了,如果一般的简单死锁会自动回滚一个事务。通过show status like '%lock%';
查看了一下,当前等待的锁数目为0,当我尝试update时数量变为1,说明只有当前一个锁在等待,并不是简单的一个死锁问题。
那么看一下SELECT * FROM information_schema.INNODB_TRX;
当前trx的结果,发现了令人卧槽的结果。
居然有一个事务运行了几个小时……并且加锁居然加了200多个行锁。这显然就是罪魁祸首了。
后续排查
那么原因很明了了,找到这个事务的线程,直接kill掉可以强行回滚释放掉锁,但是究竟是什么业务导致的这个问题,还需要细致排查。
首先看调用方,根据show full processlist;
的结果可以找到调用方,是一台Java服务,但这个很难知道究竟是什么业务引起的超长时间事务。
一开始想到去看binlog,但是谷歌过发现binlog并不会记录事务的操作,只有事务提交后才会被写入,然而我们这个超长时间没有提交的事务就无法看到内容了。
最后找到了general_log,这个日志文件会将事务中的动作也记录下来。
然而执行一下show variables like '%general%';
后发现居然是OFF状态,也就是没有在记录general_log(后来我反应过来,这是很正常的,开启了这个选项会在短时间内用这个日志把你的磁盘爆掉…)
那么此处我们set global general_log=1;
后,之后产生的动作便会被记录了。
最终解决
首先当前第一要务是把对应的线程kill掉,先释放行锁,恢复业务。
其次是打开general_log的记录,随时观察数据库,当数据库复现这个问题时,使用thread_id到general_log中搜索便可以一目了然了。
最后一定要记得观察一下general_log的情况,毕竟详细记录所有操作,日志量也是巨大的,用完之后要将开关关掉。