技本功丨一个锁等待现象的诊断案例

1、慢SQL分析

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

查看慢SQL方式见下图

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

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

2、事务阻塞分析

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

采集脚本如下：

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

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

解释下上面的日志输出：

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审计可以通过下图方式查看。 

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

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

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

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

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

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