如何读懂MySQL死锁日志 |
您所在的位置：网站首页 › rec怎么读 › 如何读懂MySQL死锁日志 |
|
测试环境
CREATE TABLE `test` (
`id` INT(10) NOT NULL,
`str` VARCHAR(50),
`value` VARCHAR(50),
PRIMARY KEY (`id`),
UNIQUE INDEX `str` (`str`)
)
COLLATE='utf8_general_ci'
ENGINE=InnoDB
;
INSERT INTO `test` (`id`, `str`, `value`) VALUES (10234567, '1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg', NULL);
INSERT INTO `test` (`id`, `str`, `value`) VALUES (20023456, '2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud', NULL);
INSERT INTO `test` (`id`, `str`, `value`) VALUES (30123456, '3sdfsdfsdfsdf', NULL);
互相等待行锁
创建死锁现场 会话1执行： mysql> begin;select * from test where id = 10234567 for update; Query OK, 0 rows affected (0.00 sec) +----------+-------+---------------------+--------------------------------------------+ | id | value | datetime | str | +----------+-------+---------------------+---------------------------------------------+ | 10234567 | 100 | 2020-08-10 18:31:12 | 1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg | +----------+-------+---------------------+---------------------------------------------+ 1 row in set (0.00 sec)会话2执行： mysql> begin;select * from test where id = 20023456 for update; Query OK, 0 rows affected (0.00 sec) +----------+-------+---------------------+--------------------------------------------+ | id | value | datetime | str | +----------+-------+---------------------+--------------------------------------------+ | 20023456 | 100 | 2020-08-10 18:31:24 | 2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud | +----------+-------+---------------------+-------------------------------------------+ 1 row in set (0.00 sec)会话1继续执行： mysql> select * from test where id = 20023456 for update;会话1阻塞… 会话2继续执行： mysql> select * from test where id = 10234567 for update; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction显示发生死锁，同时会话1返回并输入： +----------+-------+---------------------+--------------------------------- -----------+ | id | value | datetime | str | +----------+-------+---------------------+---------------------------------------------+ | 20023456 | 100 | 2020-08-10 18:31:24 | 2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud | +----------+-------+---------------------+---------------------------------------------+ 1 row in set (5.02 sec)死锁日志分析 执行如下命令【show engine innodb status 】可看到最近一次死锁日志，也可以通过【set global innodb_print_all_deadlocks=on】命令记录全部死锁信息到【log_error 】指向的日志文件中，上述死锁的日志如下： LATEST DETECTED DEADLOCK ------------------------ 2020-08-10 18:50:18 0x7fb726fa5700 *** (1) TRANSACTION: TRANSACTION 110686664, ACTIVE 12 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s) MySQL thread id 347214, OS thread handle 140424592910080, query id 238824800 localhost root statistics select * from test where id = 20023456 for update *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686664 lock_mode X locks rec but not gap waiting Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 4; hex 013188a0; asc 1 ;; 1: len 6; hex 00000698f1a6; asc ;; 2: len 7; hex c00000021f0110; asc ;; 3: len 30; hex 3277657277657277657277657277657277657277656f696a6f6e73666f69; asc 2werwerwerwerwerwerweoijonsfoi; (total 47 bytes); *** (2) TRANSACTION: TRANSACTION 110686665, ACTIVE 9 sec starting index read mysql tables in use 1, locked 1 3 lock struct(s), heap size 1136, 2 row lock(s) MySQL thread id 347255, OS thread handle 140424609683200, query id 238824801 localhost root statistics select * from test where id = 10234567 for update *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686665 lock_mode X locks rec but not gap Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 4; hex 013188a0; asc 1 ;; 1: len 6; hex 00000698f1a6; asc ;; 2: len 7; hex c00000021f0110; asc ;; 3: len 30; hex 3277657277657277657277657277657277657277656f696a6f6e73666f69; asc 2werwerwerwerwerwerweoijonsfoi; (total 47 bytes); *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686665 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 4; hex 009c2ac7; asc * ;; 1: len 6; hex 00000698f1a4; asc ;; 2: len 7; hex bf000001300110; asc 0 ;; 3: len 30; hex 317364667364667364667364667364667364667364667364667364666c6b; asc 1sdfsdfsdfsdfsdfsdfsdfsdfsdflk; (total 46 bytes); *** WE ROLL BACK TRANSACTION (2)我们来看看这日志中的几个关键信息， 1、这个结果分成三部分： (1) TRANSACTION，是第一个事务的信息； (2) TRANSACTION，是第二个事务的信息； (3)WE ROLL BACK TRANSACTION (2)，是最终的处理结果，表示回滚了第2个事务。 2、第一个事务的信息中： select 语句是这个事务正在执行的语句；WAITING FOR THIS LOCK TO BE GRANTED，表示的是这个事务正在等待的锁信息；index PRIMARY of table，说明在等的是表的主键索引上的锁；lock_mode X locks rec but not gap waiting 表示这个事务正在等待的是行锁；Record lock 说明这是一个记录锁；n_fields 4 表示这个记录有4列，靠前的是索引信息0: len 4; hex 013188a0; asc 1 ;; 也就是主键 id，转换为10进制后是20023456；这里的 asc 表示的是，接下来要打印出值里面的“需打印字符”，但主键是整数，不需打印，因此就显示空格，如果是字符串类型的字段，则这里会显示字符串内容，但是asc只有4字节，因此可能只打印字符串前缀。第一个事务信息就只显示出了等锁的状态，在等待 (id=20023456) 行锁。当然你是知道的，既然出现死锁了，就表示这个事务也占有别的锁，但是没有显示出来。别着急，我们从第二个事务的信息中推导出来。3、第二个事务显示的信息要多一些： “ HOLDS THE LOCK(S)”用来显示这个事务持有哪些锁；index PRIMARY of table 表示持有锁主键索引 上的锁；0: len 4; hex 013188a0; asc 1 ;; 表示这个事务持有 id=20023456的记录锁；WAITING FOR THIS LOCK TO BE GRANTED，表示在等 id=10234567的记录锁。从上面这些信息中，我们可知道： 事务1正在执行【select * from test where id = 20023456 for update】语句，持有 id=10234567 的行锁，等待id=20023456的行锁。 事务2正在执行【select * from test where id = 10234567 for update】语句，持有id=20023456的行锁，等待 id=10234567 的行锁。 因此导致了死锁。 asc打印字段值和分析1一样的测试环境。 会话1执行： mysql> begin; update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg"; Query OK, 0 rows affected (0.00 sec) Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0会话2执行： mysql> begin; update test set str = "3333333" where str = '3sdfsdfsdfsdf'; Query OK, 0 rows affected (0.00 sec) Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0会话1继续执行： update test set str = "3333333" where str = '3sdfsdfsdfsdf';会话1被阻塞，会话2继续执行： mysql> update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg"; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction检测到死锁，会话1返回并输出： Query OK, 1 row affected (10.72 sec) Rows matched: 1 Changed: 1 Warnings: 0死锁日志如下： ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2020-08-10 19:23:54 0x7fb726fa5700 *** (1) TRANSACTION: TRANSACTION 110687265, ACTIVE 60 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1 MySQL thread id 347214, OS thread handle 140424592910080, query id 238841635 localhost root updating update test set str = "3333333" where str = '3sdfsdfsdfsdf' *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687265 lock_mode X waiting Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 32 0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;; 1: len 4; hex 01cba5c0; asc ;; *** (2) TRANSACTION: TRANSACTION 110687270, ACTIVE 53 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1 MySQL thread id 347255, OS thread handle 140424609683200, query id 238841636 localhost root updating update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg" *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687270 lock_mode X locks rec but not gap Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 32 0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;; 1: len 4; hex 01cba5c0; asc ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687270 lock_mode X waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 32 0: len 30; hex 317364667364667364667364667364667364667364667364667364666c6b; asc 1sdfsdfsdfsdfsdfsdfsdfsdfsdflk; (total 46 bytes); 1: len 4; hex 009c2ac7; asc * ;; *** WE ROLL BACK TRANSACTION (2)以上日志说明： 事务1正在执行【update test set str = “3333333” where str = ‘3sdfsdfsdfsdf’】语句，等待索引str=3sdfsdfsdfsdf上的锁，持有索引str = 1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg 上的锁 事务2正在执行【update test set str = “111111111” where str = “1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg”】语句，持有索引str=3sdfsdfsdfsdf上的锁，等待索引str = 1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg 上的锁。 需要注意的是因“1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg”长度太长，asc 仅显示了前31位字符。 间隙锁不互斥导致死锁会话1和会话2连续执行： mysql> begin;select * from test where str = '3abc' for update; Query OK, 0 rows affected (0.00 sec)会话1和会话2连续执行： mysql> insert into test(str) value('3abc');当会话2执行后立刻返回： ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction检测到死锁，死锁日志如下： LATEST DETECTED DEADLOCK ------------------------ 2020-08-10 20:52:16 0x7fb726fa5700 *** (1) TRANSACTION: TRANSACTION 110687354, ACTIVE 28 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1 MySQL thread id 347214, OS thread handle 140424592910080, query id 238864299 localhost root update insert into test(str) value('3abc') *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79352 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687354 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;; 1: len 4; hex 01cba5c0; asc ;; *** (2) TRANSACTION: TRANSACTION 110687353, ACTIVE 52 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1 MySQL thread id 347255, OS thread handle 140424609683200, query id 238864300 localhost root update insert into test(str) value('3abc') *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 79352 page no 4 n bits 72 index str of table `ssmdemo`.`test` trx id 110687353 lock_mode X locks gap before rec Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;; 1: len 4; hex 01cba5c0; asc ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 79352 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687353 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;; 1: len 4; hex 01cba5c0; asc ;; *** WE ROLL BACK TRANSACTION (2)事务1： 等待索引 str=3sdfsdfsdfsdf 前的【 gap before rec 】间隙锁。 事务2： 持有索引 str=3sdfsdfsdfsdf 前的间隙锁。 等到索引 str=3sdfsdfsdfsdf 前的间隙锁。 说明两个会话都持有（2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud，3sdfsdfsdfsdf）的间隙锁，当执行插入时又互相等待对方的间隙锁，因此导致死锁。 |
今日新闻 |
推荐新闻 |
| CopyRight 2018-2019 办公设备维修网 版权所有 豫ICP备15022753号-3 |