作者：苏坡
袋鼠云云服务部-DBA团队
数据库工程师
前两日与一个客户交流，
客户提出了一些
对mysql隔离级别以及锁的疑问，
然后问到了出现锁等待现象的排查思路。
这不禁让我回想起
long long ago,
做过的一个诊断案例。
当年我还不是一枚老司机，
折腾了两三天才完全搞定，
现在回想还颇有些借鉴价值，
故，分享之~
1问题描述
数据库实例：主库XXXX:3306
问题详情：客户反映，涉及到user_site表相关的程序回调操作很慢，部分操作会超时报错；
下单操作很慢甚至直接报错失败
程序端报错信息如下：
General error: 1205 Lock wait timeout exceeded; try restarting transaction"
2分 析
这是个典型的锁等待超时退出的报错，原因可能是某些事务未及时提交导致锁资源不被释放导致。思路：通过rds控制台查看最近一段时间的慢SQL，看是否出现user_site表相关的DML或者select锁定读操作。
查看慢SQL方式见下图
很可惜，并没有找到相关的慢SQL，那么就代表SQL执行都很快，事务的处理上出现了问题，因此，我们更相信是某些程序没有及时提交事务导致的了。
不过，还是有些收获的，我们发现一些潜在的问题，就是top前几的慢SQL。都是非锁定select，因此和本次现象无关，但是这几个查询操作最长需要近百秒，十分消耗CPU以及内存资源，需要优化。
思路：通过一个脚本，定期采集出现阻塞的事务信息，只要再次进行相关操作，阻塞事件的参与事务信息便被计入日志，可对其进行详细分析。
采集脚本如下：
大约半小时后，日志中抓取到相关的信息
通过分析日志，我们发现每隔一段时间会出现较为严重的连环锁等待现象，主要是以下两种情况：
解释下上面的日志输出：
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，那么其余的时间程序在干什么？
有了针对性的目的后，该客户开发同学马上定位到程序并找到了问题所在，在提交之前，程序会去进行插入队列和删除缓存的操作，而这些操作，占用的都是事务的持有锁且非活动时间。
届此，该问题的分析过程全部结束，出现问题的原因就在于事务内部的非数据库操作 。
3处理方案
事务内部进行的不只是数据库操作，程序进行的插入队列以及删除缓存操作，让一个2S之内完成的事务，延长至十几分钟；也就意味着，这十几分钟内，凡是请求事务内部锁资源的SQL操作，必须进入锁等待状态。
1.事务内部只进行SQL操作，程序的处理一律放在事务提交之后或开始之前。
2.如果存在逻辑问题不可修改，可为相关处理过程设计处理队列，抛出指令即可，而不用等待这个过程处理完毕再提交事务。
