一个锁的奇怪问题分析总结

一个锁的奇怪问题分析总结
问题的发生
 下午收到一个业务同学反馈的yc_gd11x5_project表出现死锁的问题，现象是update的时候经常卡住很长时间，程序侧的日志如下：
 UPDATE yc_gd11x5_project SET chupiao_state='1', chupiao_time='1404261677',chupiao_uid=51,real_chupiao_money=project_price WHERE project_no in ("GDXR1OHC1BF266","GDXR1OHC12CEC3","GDXR1OHC182135","GDXR2OHC19E6F0","GDXR2OHC1273D3","GDXR2OHC157492","GDXR2OHC1510D0","GDXR2OHC1A8E7B","GDXR2OHC177716","GDXR2OHC12CEDE","GDXR2OHC11C818","GDXR2OHC1D0A4B","GDXR2OHC137173","GDXR3OHC1FBE5B","GDXR3OHC127BF9","GDXR3OHC1IB1EW","GDXR3OHC1EF0C3","GDXR3OHC10E9B4","GDXR3OHC1F5A07","GDXR3OHC1O4MNO","GDXR3OHC17SOHV","GDXR3OHC13717B","GDXR3OHC1092E7","GDXR3OHC135805","GDXR3OHC1371D8","GDXR3OHC106E07","GDXR3OHC1755E4","GDXR3OHC1A7D76","GDXR3OHC1FD9B9","GDXR3OHC15FC9E","GDXR3OHC17F5D3","GDXR3OHC1A766F","GDXR3OHC1A38C0","GDXR3OHC1886AC","GDXR3OHC1D3E61","GDXR3OHC127B6A","GDXR3OHC1FDDFD","GDXR3OHC10E256","GDXR3OHC14D2BC","GDXR4OHC109D1C","GDXR4OHC157C92","GDXR4OHC1AF2BE","GDXR4OHC1C73BB","GDXR4OHC1F3203","GDXR4OHC1CEF1E","GDXR4OHC13821E","GDXR4OHC135DDD","GDXR4OHC1A87E6","GDXR4OHC1E472C","GDXR5OHC154C24","GDXR5OHC10253D","GDXR5OHC16D315","GDXR5OHC19E539","GDXR5OHC1ZQQC8","GDXR5OHC18CDF4","GDXR5OHC13B589","GDXR5OHC13DE3F","GDXR5OHC19C295","GDXR5OHC176139","GDXR5OHC14C078","GDXR5OHC1FD7F5","GDXR5OHC1F9DB6","GDXR5OHC11A97E","GDXR5OHC1825E3","GDXR5OHC19EA99","GDXR5OHC1B8707","GDXR5OHC1U3EB6","GDXR5OHC11AB20","GDXR5OHC1F901A","GDXR5OHC1C54BB","GDXR5OHC127366","GDXR5OHC157A55","GDXR5OHC1B5793","GDXR5OHC1F587C","GDXR5OHC102A3C","GDXR5OHC1CE054","GDXR5OHC19C2BE","GDXR5OHC1770D5","GDXR5OHC191179","GDXR5OHC177358","GDXR5OHC136E24","GDXR5OHC1CE28D","GDXR5OHC1FA236","GDXR5OHC121D60","GDXR5OHC19B2B1","GDXR5OHC1370A1","GDXR5OHC1AB988","GDXR5OHC186305","GDXR5OHC1AF6E3","GDXR5OHC14NRTC","GDXR5OHC1E4DB0","GDXR5OHC1E99E4","GDXR5OHC13B7FC","GDXR5OHC121BBA","GDXR5OHC1C7F5D","GDXR5OHC1B5A55","GDXR5OHC127653","GDXR5OHC1B5E4A","GDXR5OHC18CF7D","GDXR5OHC1VLQ6A") and chupiao_state=0 and shenhe_state!=-1, msg:Lock wait timeout exceeded; try restarting transaction]/usermsg[pid:, SetBatchChupiaoState error]
在开始分析之前先介绍一下yc_gd11x5_project表的情况，具体情况如下图所示：
表名 数据量 字段数 唯一索引
yc_gd11x5_project 12863104 85 project_no

问题分析
问题分析之初步接触
第一反应应该是死锁导致，先用show full processlist去找到正在运行的线程,没有抓取到对一个堵住的SQL,可能是达到死锁的超时时间自动对小的事务做了回滚。使用show engine innodb status\G；查看innodb中锁的信息，发现如下线索

 

确实有死锁，不过时间不对，从innodb日志看锁是在14:16的时候发生的，业务开发的同学反馈在16点的时候也有发生过update超时的情况。如果16点有发生过那么show engine innodb status\G; 看到的最近的一次死锁就不应该还是14:16分。因此初步判断业务开发同学反馈的update超时不应该是死锁，而是update在等待某个锁的时候执行超时了。既然是update在等待锁，那么就肯定有某个线程在持有锁，而且很长时间不释放。下面弄个抓取脚本就来个“现场”体验吧。
第一次亲临“现场”：
为了防止innodb的锁情况被冲掉，先将show engine innodb status\G;记录到mysql的错误日志中，要激活这个方式只需要创建一张名字为innodb_monitor的表，代码如下:
CREATE TABLE innodb_monitor(a INT) ENGINE=INNODB;
如果要取消这种方式，直接drop掉这个表即可。
写了个简单的抓取脚本，如果出现update超过8秒的时候就记录，就抓取show engine innodb status\G和show full processlist的信息。根据以往的经验有了这两个如果是死锁或者锁等待的情况，基本都能定位到对应的问题。 过了20分钟左右又出现超时了，此时看peocesslist的信息update都处于updating状态。

很奇怪，这种根据唯一索引做update的不可能要update那么久，难道是对应的update语句在事务中没有提交?电话业务的开发同事进行确认，业务开发的同学答复那些SQL都是自动提交的，没有放在显式的事务中。好奇怪，那么是什么导致SQL执行那么长的时间呢？初步判断这个update最大的可能是在等待获取锁。那么是什么语句在持有锁呢？如何才能找到真正持有锁的线程呢？记得之前阅读《高性能MYSQL》里有提到mysqladmin开启debug模式能查看到具体哪个线程在持有锁。
第二次亲临“现场"
于是改进脚本，达到触发条件的时候开启debug，再继续等待，晚上9点半的时候终于又重现了，这次看看战果如何？
Processlist的信息有了，抓到两个执行10秒的SQL。

下面是debug模式找到的线程锁的情况：

诡异，这次debug显示是update的语句在持有锁，这个怎么解释都解释不通，怀疑这个debug有bug。
第三次亲临“现场”
继续尝试，记得之前看MYSQL 5.5的文档的时候有提到说信息库中能记录关于线程持有锁、锁等待、以及事务锁等信息，于是查看官方文档，发现了有三个很有用的表，分别介绍一下：
information_schema.INNODB_TRX
这个表包含了每个事务在innodb内部的当前状态，包括当事务开始的时候或者事务在执行中是否在等待锁。
information_schema.INNODB_LOCK_WAITS
顾名思义，这个表显示那个事务在等待锁。
information_schema.INNODB_LOCKS
这个表记录了innodb的所有锁的情况，这里可以看到锁的信息、SQL线程ID以及锁定的数据等东东。
有了这些法宝再去更改抓取程序，当出现问题的时候抓取这三个表的状态。上午10点的多的时候又重现了，这次清晰了，先截图来分析一下：
INNODB_LOCKS对应的信息如下：

INNODB_LOCK_WAITS对应的信息如下：

INNODB_TRX对应的信息如下：

有了这些信息足以了，综合上面3个表的信息可以知道，那个update语句是在等待锁，那个线程ID为718528318的线程才是真正持有锁的语句。通过抓取的线程过滤一下看看：

从这里可以断定是某个事物中执行了查询表的操作后没有提交事务导致，将10.205.138.165提供给开发的同学检查后反馈确实有一个地方存在问题，截图如下：

这里如果insert失败后就直接return了，由于是长连接，因此这个事务没有提交。再看失败的日志发现有duplicate key导致insert失败的情况造成事务没有提交。再结合INNODB_LOCKS进行分析可知，insert project_no为GDXR3OHD70840D的时候由于duplicate key冲突了，导致insert失败，但是对GDXR3OHD70840D的锁还没有释放，因此在对这个project_no更新的时候就一直在等待。

找到问题就好解决了，如果insert失败就执行rollback的操作就OK了。自此世界安静了。
这里为什么是共享锁的，应该是插入的时候根据唯一索引，还要查询一下数据是否存在，因此加了共享锁。
问题重现
通过上面的分析，模拟出分析的过程应该就能重现该问题，为了验证推论的结果是否正确，因此手工来重现一把。先创建一个表,并插入几条记录：

开启两个终端然后分别模拟线上出现的场景：
A终端模拟线上insert失败的操作

B终端模拟update的操作：

和线上出现的问题一样，当A终端进行commit或者rollback或者连接中断后B终端的update才能获取锁。和现场环境一样。

问题疑问
那三个lock的表只有5.5版本或者innodb plugin的版本才有。如果是5.1的没有安装innodb plugin的mysql该如何去找到持有锁的线程呢？等有时间了再来好好研究一下!