MySQL DeadLock故障排查全过程记录

0: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007eea14; asc

持有的锁信息为:4YE码友部落

登录Mysql服务器查看日志:4YE码友部落

可以看到485 SEK这两个资源形成了一个环状,最终发生死锁。4YE码友部落

Using intersect(column5_index,idxColumn6)

从5.1开始,引入了 index merge 优化技术,对同一个表可以使用多个索引分别进行条件扫描。4YE码友部落

时间点Session1Session2 4YE码友部落

id: 14YE码友部落

rows: 74YE码友部落

MySQL,DeadLock,故障排查4YE码友部落

最佳的方法是添加column5和Column6的联合索引。4YE码友部落

mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id4YE码友部落

2   UPDATE TestTable SET Column2 = sysdate() Column4 = 0 AND Column5 = 47 AND Column6 = 'SEK 
执行成功,影响7行
      4YE码友部落
4YE码友部落

32231892617   53454b/80000000007eea14   53454b/80000000007eeac4   4YE码友部落
mysql> 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;*************************** 1. row ***************************waiting_trx_id: 103006waiting_thread: 36waiting_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK'blocking_trx_id: 103003blocking_thread: 37blocking_query: NULL*************************** 2. row ***************************waiting_trx_id: 421500433538672waiting_thread: 39waiting_query: select count(Column5) from TestTable where Column5 = 485blocking_trx_id: 103006blocking_thread: 36blocking_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK'2 rows in set, 1 warning (0.00 sec)mysql> select * from information_schema.innodb_lock_waits /G;*************************** 1. row ***************************requesting_trx_id: 103006requested_lock_id: 103006:417:1493:859blocking_trx_id: 103003blocking_lock_id: 103003:417:1493:859*************************** 2. row ***************************requesting_trx_id: 421500433538672requested_lock_id: 421500433538672:417:749:2blocking_trx_id: 103006blocking_lock_id: 103006:417:749:22 rows in set, 1 warning (0.00 sec)mysql> select * from INNODB_LOCKS /G;*************************** 1. row ***************************lock_id: 103006:417:1493:859lock_trx_id: 103006lock_mode: Xlock_type: RECORDlock_table: test.TestTablelock_index: idxColumn6lock_space: 417lock_page: 1493lock_rec: 859lock_data: 'SEK', 8262738*************************** 2. row ***************************lock_id: 103003:417:1493:859lock_trx_id: 103003lock_mode: Xlock_type: RECORDlock_table:test.TestTablelock_index: idxColumn6lock_space: 417lock_page: 1493lock_rec: 859lock_data: 'SEK', 8262738*************************** 3. row ***************************lock_id: 421500433538672:417:749:2lock_trx_id: 421500433538672lock_mode: Slock_type: RECORDlock_table: test.TestTablelock_index: column5_indexlock_space: 417lock_page: 749lock_rec: 2lock_data: 485, 8317620*************************** 4. row ***************************lock_id: 103006:417:749:2lock_trx_id: 103006lock_mode: Xlock_type: RECORDlock_table: test.TestTablelock_index: column5_indexlock_space: 417lock_page: 749lock_rec: 2lock_data: 485, 83176204 rows in set, 1 warning (0.00 sec)

可以看到Session2,trx_id 103006阻塞了trx_id 421500433538672,而trx_id 421500433538672 requested_lock也正好是lock_data: 485, 8317620。由此可见Session2虽然别block了,但是还是获取到了Index column5_index相关的锁。被Block是因为intersect的原因,还需要idxColumn6的锁,至此思路已经清晰,对整个分配锁的信息简化一下,如下表格(请求到的锁用青色表示,需获取但未获取到的锁用红色表示):4YE码友部落

possible_keys: column5_index,idx_column5_column6_Column1,idxColumn64YE码友部落

0: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007eeac4; asc

再先分析下(1) TRANSACTION,TRANSACTION 32231892617。4YE码友部落

key_len: 8,94YE码友部落

【环境】4YE码友部落

key: column5_index,idxColumn64YE码友部落

10:55左右删除索引后,报错没有再发生:4YE码友部落

版本号:5.6.214YE码友部落

【解决方法】4YE码友部落

时间序列Session1Session2 4YE码友部落
3       Begin;   4YE码友部落

filtered: 100.004YE码友部落

根据以上初步分析,猜测应该就是intersect造成的,于是在测试环境模拟验证,开启2个session模拟死锁:4YE码友部落

【初步分析】4YE码友部落

等待的锁信息为:4YE码友部落

0: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007eeac4; asc

于是可以画出的死锁表,两个资源相互依赖,造成死锁:4YE码友部落

Extra: Using intersect(column5_index,idxColumn6); Using where4YE码友部落

select_type: UPDATE4YE码友部落

1   477 SEK       4YE码友部落

mysql>desc UPDATE TestTable SET Column1=1, Column2 = sysdate(),Column3 = '025' Column4 = 0 AND Column5 = 477 AND Column6 = 'SEK' /G;4YE码友部落

table: TestTable4YE码友部落

接到监控报警,有一个线上的应用DeadLock报错,每15分钟会准时出现,报错统计如下图:4YE码友部落

The Index Merge method is used to retrieve rows with several range scans and to merge their results into one. The merge can produce unions, intersections, or unions-of-intersections of its underlying scans. This access method merges index scans from a single table; it does not merge scans across multiple tables.4YE码友部落

刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理。4YE码友部落

让我们再看一下explain结果:4YE码友部落

32231892482   53454b/80000000007eeac4   53454b/80000000007eea14   4YE码友部落

可以看到 EXTRA 列:4YE码友部落

1   Begin;       4YE码友部落

隔离级别:REPEATABLE READ4YE码友部落

2       485 SEK   4YE码友部落
3   485 SEK   死锁发生   4YE码友部落

type: index_merge4YE码友部落

ref: NULL4YE码友部落

【问题描述】4YE码友部落

依据以上信息可以发现Session2虽然被Block了,但也获取了一些Session1在时间序列5时所需资源的X锁,可以再开启一个查询select count(Column5) from TestTable where Column5 = 485,设置SET TRANSACTION ISOLATION LEVEL SERIALIZABLE,去查询Column5 = 485的行,观察锁等待的信息:4YE码友部落

相关文档:4YE码友部落

TRANSACTIONHoldWait 4YE码友部落

partitions: NULL4YE码友部落

【模拟与验证】4YE码友部落

*************************** 1. row ***************************4YE码友部落

我们环境当时的情况发现Column6的筛选度非常低,就删除了Column6的索引。4YE码友部落

先分析下(2) TRANSACTION,TRANSACTION 32231892482。4YE码友部落

mysql> show engine innodb status/G*** (1) TRANSACTION:TRANSACTION 102973, ACTIVE 11 sec starting index readmysql tables in use 3, locked 3LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s)MySQL thread id 6, OS thread handle 140024996574976, query id 83 localhost us updatingUPDATE TestTableSET column1 = 1,Column2 = sysdate(),Column3= '026'Column4 = 0AND column5 = 485AND column6 = 'SEK'*** (1) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_column6 of table test.TestTable trx id 102973 lock_mode X waitingRecord lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 00: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007e1452; asc ~ R;;*** (2) TRANSACTION:TRANSACTION 102972, ACTIVE 26 sec starting index readmysql tables in use 3, locked 3219 lock struct(s), heap size 24784, 2906 row lock(s), undo log entries 7MySQL thread id 5, OS thread handle 140024996841216, query id 84 localhost us updatingUPDATE TestTableSET Column1 = 1,Column2 = sysdate(),Column3 = '026'Column4 = 0AND Column5 = 485AND Column6 = 'SEK'*** (2) HOLDS THE LOCK(S):RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_Column6 of table test.TestTable trx id 102972 lock_mode XRecord lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 00: len 8; hex 73757072656d756d; asc supremum;;Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 00: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007e1452; asc ~ R;;*** (2) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 601 page no 89642 n bits 1000 index idx_column6 of table test.TestTable trx id 32231892482 lock_mode X locks rec but not gap waitingRecord lock, heap no 38 PHYSICAL RECORD: n_fields 2; compact format; info bits 00: len 3; hex 53454b; asc SEK;;1: len 8; hex 80000000007eea14; asc ~ ;;

大致一看,更新同一索引的同一行,应该是一个Block,报TimeOut的错才对,怎么会报DeadLock?4YE码友部落

等待的锁信息为:4YE码友部落

5   UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
执行成功
  ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction   4YE码友部落
4       UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
被Blocking
  4YE码友部落