前两天与一个客户交流的时候，客户提出了一些对mysql隔离级别以及锁的疑问，然后问到了出现锁等待现象的排查思路。和客户进行了简单交流之后，翻了翻之前的一个诊断案例，当时折腾了两三天，现在看看还是有些借鉴价值的。
问题描述
数据库实例：主库XXXX:3306
问题详情：客户反映，涉及到user_site表相关的程序回调操作很慢，部分操作会超时报错；
下单操作很慢甚至直接报错失败
程序端报错信息如下：
General error: 1205 Lock wait timeout exceeded; try restarting transaction"
分析
这是个典型的锁等待超时退出的报错，原因可能是某些事务未及时提交导致锁资源不被释放导致
1、慢SQL分析
思路：通过rds控制台查看最近一段时间的慢SQL，看是否出现user_site表相关的DML或者select锁定读操作。
查看慢SQL方式见下图
很可惜，并没有找到相关的慢SQL，那么就代表SQL执行都很快，事务的处理上出现了问题，因此，我们更相信是某些程序没有及时提交事务导致的了。
不过，还是有些收获的，我们发现一些潜在的问题，就是top前几的慢SQL。都是非锁定select，因此和本次现象无关，但是这几个查询操作最长需要近百秒，十分消耗CPU以及内存资源，需要优化。
2、事务阻塞分析
思路：通过一个脚本，定期采集出现阻塞的事务信息，只要再次进行相关操作，阻塞事件的参与事务信息便被计入日志，可对其进行详细分析。
采集脚本如下：
|
#!/bin/bash SQL="select r.trx_id waiting_trx_id,r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query,b.trx_id blocking_trx_id,b.trx_mysql_thread_id blocking_thread,b.trx_query blocking_query from information_schema.innodb_lock_waits w inner join information_schema.innodb_trx b on b.trx_id=w.blocking_trx_id inner join information_schema.innodb_trx r ON r.trx_id=w.requesting_trx_id\G"
while : do echo "=================================" echo "采集时间："`date +%Y-%m-%d_%H:%M:%S` echo "=================================" mysql -hXXXX -uXXXX -pXXXXXXXX -e "$SQL" echo ""
sleep 5 done |
大约半小时后，日志中抓取到相关的信息
通过分析日志，我们发现每隔一段时间会出现较为严重的连环锁等待现象，主要是以下两种情况
|
*************************** 1. row *************************** waiting_trx_id: 8822773749 waiting_thread: 7297307 waiting_query: SELECT funding FROM user_site where user_id = 38440594 and site_id = 3 FOR UPDATE blocking_trx_id: 8822773748 blocking_thread: 7297310 blocking_query: SELECT funding FROM user_site where user_id = 4 and site_id = 3 FOR UPDATE *************************** 2. row *************************** waiting_trx_id: 8822773748 waiting_thread: 7297310 waiting_query: SELECT funding FROM user_site where user_id = 4 and site_id = 3 FOR UPDATE blocking_trx_id: 8822602949 blocking_thread: 7120018 blocking_query: NULL |
|
waiting_trx_id: 8814966658 waiting_thread: 15064606 waiting_query: UPDATE user_site SET id='85989170', user_id='71457291', site_id='3', password='a14f 2c3bae708de1d439c1d796ab319b', funding='0.64', subscribe_weixin='0', subscribe_alipay='0', rank='0', loginType='9', publishprojectNumber='0', supportNumber='4', followNumber='3', active='1', created=' 2016-08-11 15:41:46', updated='2016-09-26 18:19:19', conf=NULL, identity='31' WHERE id = 85989170 blocking_trx_id: 8814920762 blocking_thread: 15012709 blocking_query: NULL |
解释下上面的日志输出：
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，那么其余的时间程序在干什么？
有了针对性的目的后，该客户开发同学马上定位到程序并找到了问题所在，在提交之前，程序会去进行插入队列和删除缓存的操作，而这些操作，占用的都是事务的持有锁且非活动时间。
届此，该问题的分析过程全部结束，出现问题的原因就在于事务内部的非数据库操作
处理方案
根因分析
事务内部进行的不只是数据库操作，程序进行的插入队列以及删除缓存操作，让一个2S之内完成的事务，延长至十几分钟；也就意味着，这十几分钟内，凡是请求事务内部锁资源的SQL操作，必须进入锁等待状态
处理建议
1.事务内部只进行SQL操作，程序的处理一律放在事务提交之后或开始之前
2.如果存在逻辑问题不可修改，可为相关处理过程设计处理队列，抛出指令即可，而不用等待这个过程处理完毕再提交事务