当前位置: 首页 > 科技观察

一个从未见过的告警,打开曲折的MySQL死锁排查

时间:2023-03-12 05:31:38 科技观察

故障背景国庆期间,收到一个从未见过的告警,接着是断断续续的类似偶发告警,然后突然来了兴趣,我挑了一个他们并探索了这个故事。***(1)TRANSACTION:TRANSACTION6286508066,ACTIVE0secupdatingordeletingmysqltablesinuse1,locked1LOCKWAIT9lockstruct(s),heapsize1136,14rowlock(s),undologentries1MySQLthreadid189619143,OSthreadhandle140619931252480,queryid114880319610.200.18.103ke_informationupdatingupdate`user_feed_26`set`notification`=1,`mtime`='2020-10-0309:11:11'where`user_id`=2000000126212250and`action`in('resblock_weekly','bizcircle_weekly','district_weekly')and`notification`=0***(1)WAITINGFORTHOSLOCKTOBEGRANTED:RECORDLOCKSspaceid2229pageno263938nbits`ed_user_indexofidxidx`user_feed_26`trxid6286508066lock_modeXlocksgapbeforerecinsertintentionwaitingRecordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;从日志的字面意思来看,很明显是MySQL数据库在执行事务时发现了死锁,那么这个死锁是怎么产生的,背后隐藏着什么?存在哪些隐患,如何解决?一起排查吧~排查过程中,刚开始接到这个告警。我的第一反应是不同的事务互相锁定,导致死锁。这么糟糕,十有八九是某个代码片段写的逻辑有问题。但是经过全面排查,这个sql相关的代码既没有开启一个事务,也没有开启多个事务,所以基本可以排除代码中的bug。那么这些东西是怎么来的呢?众所周知,MySQL对事务的支持与存储引擎有关。MyISAM不支持事务,而INNODB支持事务。行级锁用于更新。由于我们的数据库使用的是INNODB引擎,所以意味着update语句会被当作一个事务来处理。更新同一条数据时是否冲突?于是找我的DBA同学要一份死锁日志(数据库版本:5.7.24事务隔离级别为RR)。事务一日志:***(1)TRANSACTION:TRANSACTION6286508066,ACTIVE0secupdatingordeletingmysqltablesinuse1,locked1LOCKWAIT9lockstruct(s),heapsize1136,14rowlock(s),undologentries1MySQLthreadid189619143,OSthreadhandle140619931252480,queryid114880319610.200.18.103ke_informationupdatingupdate`user_feed_26`set`notification`=1,`mtime`='2020-10-0309:11:11'其中`user_id`=2000000126212250and`action`in('resblock_weekly','bizcircle_weekly','district_weekly')and`notification`=0***(1)WAITINGFORTISLOCKTOBEGRANTED:RECORDLOCKSspaceid2229pageno263934indexofnbits2229pageno263934indexofnbits`lianjia_user_feed`.`user_feed_26`trxid6286508066lock_modeXlocksgapbeforerecinsertintentionwaitingRecordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;从日志中可以看出,事务1执行的sql语句为:update`user_feed_26`set`notification`=1,`mtime`='2020-10-0309:11:11'where`user_id`=2000000126212250and`action`in('resblock_weekly','bizcircle_weekly','district_weekly')and`notification`=0in等待的锁是:***(1)WAITINGFORTHISLOCKTOBEGRANTED:ECORDLOCKSspaceid2229pageno263938nbits264indexidx_user_idoftable`lianjia_user_feed`.`user_feed_26`trxid6286508066lock_modeXlocksgapbeforerecinsertintentionwaiting这里显示的是事务在等待什么锁RECORDLOCKS表示记录锁,并且可以看出要加锁的索引为idx_user_id,spaceTheidis2229,thepagenois263938,lock_modeXindicatesthattherecordlockisanexclusivelock,andinsertintentionwaitingindicatesthatthelocktobeaddedisaninsertintentionlockandisinalockwaitingstate.Recordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;结合第二行索引信息on_shelf_again,我们可以知道这一行锁的action字段是on_shelf_again;Transaction2log:***(2)TRANSACTION:TRANSACTION6286508067,ACTIVE0secupdatingordeleting,threaddeclaredinsideInnoDB4980mysqltablesinuse1,locked112lockstruct(s),36(heapsize2s),undologentries3MySQLthreadid189619144,OSthreadhandle140620050204416,queryid114880319710.200.17.37pt_userupdatingUPDATE`user_feed_26`SET`notification`='1',`mtime`='2020-10-0309:11:11'WHERE`user_id`='2000000126212250'AND`action`in('deal','price_changed','ting_shou','house_new_picture','house_new_vr','price_changed_rise','on_shelf_again')AND`notification`='0'***(2)HOLDSTHELOCK(S):RECORDLOCKSspaceid2229pageno263938nbits264indexidx_user_idoftable`lianjia_user_feed`.`user_feed_26`trxid6286508067lock_modeXlocksgapbeforerecRecordlock,heapno83PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len4;hex6465616c;ascdeal;;2:len1;hex81;asc;;3:len12;hex313034313032363731333238;asc104102671328;;4:len4;hex95e14632;ascF2;;Recordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;***省略……***(2)WAITINGFORTHISLOCKTOBEGRANTED:RECORDLOCKSspaceid2229pageno263938nbits264indexidx_user_idoftable`lianjia_user_feed`.`user_feed_26`trxid6286508067lock_modeXlocksgapbeforerecinsertintentionwaitingRecordlock,heapno87PHYSICALRECORD:n_fields5;compactformat;infobits320:len8;hex80071afd5112d89a;ascQ;;1:len15;hex64697374726963745f7765656b6c79;ascdistrict_weekly;;2:len1;hex80;asc;;3:len8;hex3233303038373831;asc23008781;;4:len4;hex95f63035;asc05;;事务二的日志,相比于事务一多了持有锁的信息:***(2)HOLDSTHELOCK(S):RECORDLOCKSspaceid2229pageno263938nbits264indexidx_user_idoftable`lianjia_user_feed`.`user_feed_26`trxid6286508067lock_modeXlocksgapbeforerecRecordlock,heapno83PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len4;hex6465616c;ascdeal;;2:len1;hex81;asc;;3:len12;hex313034313032363731333238;asc104102671328;;4:len4;hex95e14632;ascF2;;Recordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;***省略...从日志中可以看出,事务2持有记录锁,RECORDLOCKS为记录锁,空间id为2229,页号为263938,从索引信息可以看出事务2只持有事务1需要的记录锁,即:Recordlock,heapno93PHYSICALRECORD:n_fields5;compactformat;infobits00:len8;hex80071afd5112d89a;ascQ;;1:len14;hex6f6e5f7368656c665f616761696e;ascon_shelf_again;;2:len1;hex81;asc;;3:len12;hex313034313033373433363737;asc104103743677;;4:len4;hex95f12ab5;asc*;;lock_modeXlocksgapbeforerec表示这是独占锁和间隙锁***(2)WAITINGFORTHISLOCKTOBEGRANTED:RECORDLOCKSspaceid2229pageno263938nbits264indexidx_user_idoftable`lianjia_user_feed`.`user_feed_26`trxid6286508067lock_modeXlocksgapbeforerecinsertintentionwaitingRecordlock,heapno87PHYSICALRECORD:n_fields5;compactformat;infobits320:len8;hex80071afd5112d89a;ascQ;;1:len15;hex64697374726963745f7765656b6c79;ascdistrict_weekly;;2:len1;hex80;asc;;3:len8;hex3233303038373831;asc23008781;;4:len4;hex95f63035;asc05;;同样,这是锁事务2正在等待的内容。RECORDLOCKS表示记录锁,可以看出要加锁的索引为idx_user_id,空间id为2229,pageno为263938lock_modeX表示记录锁为排他锁,插入意向等待表示加锁待添加的是插入意向锁,处于锁等待状态。虽然事务1的日志中并没有标明持有哪些锁,但是结合等待事务2的锁结构体中的district_weekly字段,事务1持有锁。因此,两个事务形成了相互等待锁释放的场景,从而产生了死锁。那么问题来了,两条sql:#sql1:update`user_feed_26`set`notification`=1,`mtime`='2020-10-0309:11:11'where`user_id`=2000000126212250and`action`in('resblock_weekly','bizcircle_weekly','district_weekly')and`notification`=0#sql2:UPDATE`user_feed_26`SET`notification`='1',`mtime`='2020-10-0309:11:11'WHERE`user_id`='2000000126212250'AND`action`in('deal','price_changed','ting_shou','house_new_picture','house_new_vr','price_changed_rise','on_shelf_again')AND`notification`='0'两条语句的where条件不同,又不重叠,为什么会互相占用对方的锁呢?为了验证这个案例,我们尝试离线复现。表结构如下:#CREATETABLE`user_feed_26`(`feed_id`int(10)NOTNULLAUTO_INCREMENT,`user_id`bigint(20)NOTNULL,...PRIMARYKEY(`feed_id`),KEY`idx_user_id`(`user_id`,`action`,`notification`,`feed_target`),...)ENGINE=InnoDBAUTO_INCREMENT=371826027DEFAULTCHARSET=utf8COMMENT='用户推表';但是无论如何都是锁等待,不会形成死锁。这里发生了什么?抱着怀疑的态度,我们查看了该语句的执行计划:通过执行计划,我们发现这里并没有使用死锁日志中出现的idx_user_id索引,而是使用了主键索引,所以没有发生死锁。大胆猜测:是因为模拟数据量太少,所以没有使用复合索引。于是,我们向离线模拟库中注入了大约100万条随机数据,再次查看了执行计划:果然,当数据量变大的时候,就会使用对应的复合索引。又一次尝试,重现了线上的死锁场景,但问题是,为什么会出现这样的情况呢?为了弄明白背后真正的原理,我们又去研究了MySQL锁相关的资料,才知道了事情的真相。首先简单说一下MySQL加锁的基本原理:原理1:加锁的基本单位是next-keylock。next-keylock为前开后闭区间;原则二:只有在搜索过程中访问到的对象才会被锁定。优化一:当对唯一索引的等价查询加锁时,next-key锁退化为行锁。优化2:在非唯一索引上锁定等价查询时,向where条件中的值所在区间向右(向后)遍历时,当区间右边界不满足等价条件时,下一键锁退化为间隙锁。这个比较难理解,比如:如果表ta的a列有一个非唯一索引:index_a,这个索引里面的值分别是:1,1,3,3,7,9:当你执行selectafromtawhereta.a=5时,会从3向右(向后)遍历,对应的是(3,7]但是因为这个区间的最后一个值7不满足=5的条件,所以下一个-key锁退化成了gaplock(3,7)。可以看出,当我们执行update语句的时候,查询的时候,在对应的索引idx_user_id上加了一个gaplock,导致了各个之间的死锁其他的我举个简单的例子来说明:事务2执行了更新,条件为3,所以获取了(1,3)的Gap锁;事务1也执行了更新,条件为5,所以它获取了一个(5,+∞),同时等待(1,7)插入意向锁;事务2再次执行更新,条件为8,那么他将等待(5,+∞)。自从,就会出现死锁。那么,如何避免这种僵局再次发生呢?使用唯一索引(一般是主键)进行更新,首先通过select语句找出符合条件的记录的唯一索引,然后使用唯一索引进行更新。selectidfromtablewherea=?andb=?;updatetablesetcolumn=xxxwhereidid=id;避免运行多个同时读写同一张表的脚本,特别注意锁操作大量数据的语句;我们经常有一些定时脚本,避免它们在同一时间点运行;正如本次事件所示,间隙锁往往是造成程序死锁的罪魁祸首。由于MySQL的隔离级别默认是RR,如果能判断幻读和不可重复读对应用影响不大。可以考虑将隔离级别改为RC,避免Gap锁导致的死锁。