博客 一个锁等待现象的诊断案例

一个锁等待现象的诊断案例

   小美   发表于 2021-11-25 17:26  419  0

前两日与一个客户交流,

客户提出了一些

对mysql隔离级别以及锁的疑问,

然后问到了出现锁等待现象的排查思路。

这不禁让我回想起

long long ago,

做过的一个诊断案例。

当年我还不是一枚老司机,

折腾了两三天才完全搞定,

现在回想还颇有些借鉴价值,

故,分享之~

http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/5b95de21bee85b07f31a47f6b02e1aa6..jpg


1

问题描述


数据库实例:主库XXXX:3306 

问题详情:客户反映,涉及到user_site表相关的程序回调操作很慢,部分操作会超时报错;

下单操作很慢甚至直接报错失败

程序端报错信息如下:

General error: 1205 Lock wait timeout exceeded; try restarting transaction"


2

分  析


这是个典型的锁等待超时退出的报错,原因可能是某些事务未及时提交导致锁资源不被释放导致。

1、慢SQL分析


思路:通过rds控制台查看最近一段时间的慢SQL,看是否出现user_site表相关的DML或者select锁定读操作。 

查看慢SQL方式见下图

http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/bf49c70a5dd701eed1636504f2fb8d72..jpg


很可惜,并没有找到相关的慢SQL,那么就代表SQL执行都很快,事务的处理上出现了问题,因此,我们更相信是某些程序没有及时提交事务导致的了。

 

不过,还是有些收获的,我们发现一些潜在的问题,就是top前几的慢SQL。都是非锁定select,因此和本次现象无关,但是这几个查询操作最长需要近百秒,十分消耗CPU以及内存资源,需要优化。


2、事务阻塞分析


思路:通过一个脚本,定期采集出现阻塞的事务信息,只要再次进行相关操作,阻塞事件的参与事务信息便被计入日志,可对其进行详细分析。 

采集脚本如下:

http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/7571a3e64cdbbb383d34d7ce1a6bf1b2..jpg

大约半小时后,日志中抓取到相关的信息


通过分析日志,我们发现每隔一段时间会出现较为严重的连环锁等待现象,主要是以下两种情况:


http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/68dbb89cdbe5a97734b982eb9512d849..jpg

http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/8cd32654056d3984495241f11587adea..jpg


解释下上面的日志输出:

waiting_trx_id: 被阻塞的事务ID

waiting_thread:被阻塞的mysql线程ID

waiting_query:被阻塞的SQL语句

blocking_trx_id: 阻塞者的事务ID

blocking_thread: 阻塞者的mysql线程ID

blocking_query: 阻塞者的SQL语句

 

我们发现,阻塞者总是处于非活跃状态,而后的相继操作会进入一个等待队列。之所以会发生阻塞,就是这个空事务持有着被阻塞事务所需要的锁资源,也就是说,以锁定的方式,访问到了相同的记录。


参考前面的慢SQL分析结果,进一步推论,事务内部的SQL执行应该是较快的,那么程序可能处理完SQL之后没有进行提交操作。


定位程序


与客户开发同学后沟通后,对该场景进行重现。实时输出日志,得到阻塞者的线程ID,通过information_schema.processlist视图查询出访问mysql数据库的程序。

客户开发同学仔细排查代码,很可惜也并没有发现未提交事务的代码。那么问题就可能出现在程序自身,是程序处理慢,而并非SQL。提交事务之前,程序极有可能经过一个缓慢的处理过程,至于处理什么,需要下一步做进一步的验证。

接下来,对上面的推论做验证~

3、SQL审计分析


思路:想要找到是哪块代码的问题,盲目的找无疑是大海捞针,所幸的是,RDS提供SQL审计功能,只要找到事务提交之前的SQL操作,这个问题的定位就应该清晰明了了。

 

通过前面排查的线程ID,搜索相关的SQL审计记录。SQL审计可以通过下图方式查看。 


http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/68db75d85cd2ebb1b517abb9cfaf7819..jpg


点击数据库安全→SQL审计。输入筛选条件:database name,程序访问数据库的用户名,关键字输入线程ID,并选择有效的时间范围。

 

这次,终于有些收获了,并且应该可以对本次现象做出合理的解释了。以下是可疑的数据库操作 


http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/6ee5098a912ff5bb534c7d0cc61ac222..jpg

http://dtstack-static.oss-cn-hangzhou.aliyuncs.com/2021bbs/files_user166259/article/d62c06d703174ee28dfba33fbcc6d450..jpg

  

我们发现,事务开启后,立即进行了几个SQL操作,而这几个SQL都没有被计入慢日志,因此SQL执行很快(2S以内),从前面的日志输出我们也能看出,SQL执行是瞬间完成的,因为我们根本抓取不到事务的SQL语句。


而事务的提交操作却发生在十几分钟之后,那么现在的疑问就是解决问题的关键了。长达十几分钟的事务,而SQL执行总共不到2S,那么其余的时间程序在干什么?


有了针对性的目的后,该客户开发同学马上定位到程序并找到了问题所在,在提交之前,程序会去进行插入队列和删除缓存的操作,而这些操作,占用的都是事务的持有锁且非活动时间。

 

届此,该问题的分析过程全部结束,出现问题的原因就在于事务内部的非数据库操作 。


3

处理方案


根因分析

事务内部进行的不只是数据库操作,程序进行的插入队列以及删除缓存操作,让一个2S之内完成的事务,延长至十几分钟;也就意味着,这十几分钟内,凡是请求事务内部锁资源的SQL操作,必须进入锁等待状态。


处理建议

1.事务内部只进行SQL操作,程序的处理一律放在事务提交之后或开始之前。

2.如果存在逻辑问题不可修改,可为相关处理过程设计处理队列,抛出指令即可,而不用等待这个过程处理完毕再提交事务。汇见新可能,你准备好了吗?

0条评论
社区公告
  • 大数据领域最专业的产品&技术交流社区,专注于探讨与分享大数据领域有趣又火热的信息,专业又专注的数据人园地

最新活动更多
微信扫码获取数字化转型资料
钉钉扫码加入技术交流群