根据死锁信息来获取造成死锁的语句

2020-11-18 本文已影响0人醉红尘丶

1. 环境与测试数据

mysql 5.6
mysql 5.7
mysql 8.0 尚未测试

-- 测试数据
create table yqlock1
(
    id int auto_increment primary key,
    a int,
    b varchar(30),
    key idx_a(a)
);
INSERT INTO yqlock1 (id, a, b) VALUES 
(1, 3, '5'),(2, 5, '2'),(3, 9, '3'),(4, 7, '1'),(5, 8, '5'),(6, 15, '20');

2.开启相关统计功能

注意：历史表默认值存放10000条数据，若业务增长很快的话，需要及时发现下死锁。

2.1 在线打开performance_schema选项收集执行过的语句和事务

update setup_consumers set ENABLED='yes' where name like 'events_statements%';
update setup_consumers set ENABLED='yes' where name like 'events_transactions%';
update setup_consumers set ENABLED='yes' where name like 'statements-digest';
update setup_instruments set ENABLED='yes',TIMED='yes' where name ='transaction';

3.模拟死锁

模拟死锁的产生

TX1	TX2
begin;
	begin;
delete from yqlock1 where a = 5;
	delete from yqlock1 where id = 3;
update yqlock1 set b = '老王' where id = 3; 等待...
	update yqlock1 set b = '老A' where a = 5; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

4.查看死锁日志

show engine innodb status\G

------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-11-19 16:47:41 7fe2d639a700
*** (1) TRANSACTION:
TRANSACTION 741395, ACTIVE 12 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 1
MySQL thread id 477895, OS thread handle 0x7fe2e407d700, query id 5581270 212.64.20.7 root updating
update yqlock1 set b = '老王' where id = 3
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 9078 page no 3 n bits 80 index `PRIMARY` of table `test1`.`yqlock1` trx id 741395 lock_mode X locks rec but not gap waiting
Record lock, heap no 8 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 0000000b5014; asc     P ;;
 2: len 7; hex 73000080172bc1; asc s    + ;;
 3: len 4; hex 80000009; asc     ;;
 4: len 1; hex 33; asc 3;;

*** (2) TRANSACTION:
TRANSACTION 741396, ACTIVE 9 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 360, 2 row lock(s), undo log entries 1
MySQL thread id 477898, OS thread handle 0x7fe2d639a700, query id 5581285 212.64.20.7 root updating
update yqlock1 set b = '老A' where a = 5
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 9078 page no 3 n bits 80 index `PRIMARY` of table `test1`.`yqlock1` trx id 741396 lock_mode X locks rec but not gap
Record lock, heap no 8 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 0000000b5014; asc     P ;;
 2: len 7; hex 73000080172bc1; asc s    + ;;
 3: len 4; hex 80000009; asc     ;;
 4: len 1; hex 33; asc 3;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 9078 page no 4 n bits 80 index `idx_a` of table `test1`.`yqlock1` trx id 741396 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 80000005; asc     ;;
 1: len 4; hex 80000002; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

根据上面死锁日志可得知：

根据WE ROLL BACK TRANSACTION (2)，可得知事务2被回滚了，事务2【TRANSACTION 720273】的语句是最后执行的，语句为update yqlock1 set b = '老A' where a = 5
和事务1【TRANSACTION 720272】产生了死锁，事务1包含 update yqlock1 set b = '老王' where id = 3.

4.1 在线关闭performance_schema选项收集执行过的语句和事务

得到死锁产生的信息后就可以关闭了，防止events_statements_history_long被刷覆盖了，否则会有性能损耗

update setup_consumers set ENABLED='no' where name like 'events_statements%';
update setup_consumers set ENABLED='no' where name like 'events_transactions%';
update setup_consumers set ENABLED='no' where name like 'statements-digest';
update setup_instruments set ENABLED='no',TIMED='no' where name ='transaction';

5. 查看死锁语句的历史信息

5.1 事务1【TRANSACTION 741395】语句信息

mysql> select THREAD_ID,EVENT_ID,END_EVENT_ID,EVENT_NAME,SOURCE,SQL_TEXT,
DIGEST, CURRENT_SCHEMA,NESTING_EVENT_ID,NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from performance_schema.events_statements_history_long 
where sql_text like 'update yqlock1 set b = ''老王'' where id = 3'\G
*************************** 1. row ***************************
         THREAD_ID: 477908
          EVENT_ID: 64
      END_EVENT_ID: 64
        EVENT_NAME: statement/sql/update
            SOURCE: mysqld.cc:967
          SQL_TEXT: update yqlock1 set b = '老王' where id = 3
            DIGEST: 3771ae1a6c56ebed8a52d8b5e8e73f87
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Rows matched: 1  Changed: 1  Warnings: 0
       timer_start: 1710040555142106384
1 row in set (0.00 sec)

5.2 事务2【TRANSACTION 741396】语句信息

mysql> select THREAD_ID,EVENT_ID,END_EVENT_ID,EVENT_NAME,SOURCE,SQL_TEXT,
DIGEST, CURRENT_SCHEMA,
NESTING_EVENT_ID,NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from performance_schema.events_statements_history_long 
where sql_text like 'update yqlock1 set b = ''老A'' where a = 5'\G
*************************** 1. row ***************************
         THREAD_ID: 477911
          EVENT_ID: 62
      END_EVENT_ID: 62
        EVENT_NAME: statement/sql/update
            SOURCE: mysqld.cc:967
          SQL_TEXT: update yqlock1 set b = '老A' where a = 5
            DIGEST: 227c911880957e7d4c501e39a650badc
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Deadlock found when trying to get lock; try restarting transaction
       timer_start: 1710044599773023384
1 row in set (0.00 sec)

5.3 根据上面查出的信息，获取信息

事务1
THREAD_ID: 477908
END_EVENT_ID: 64
NESTING_EVENT_ID: NULL
事务2
THREAD_ID: 477911
END_EVENT_ID: 62
NESTING_EVENT_ID: NULL

5.4 查看事务执行的历史语句信息

将值替换进去查看这事务所执行的语句记录,若NESTING_EVENT_ID值不为null,则替换为NESTING_EVENT_ID>=xx

5.4.1 事务1

-- 事务1
mysql> select THREAD_ID,END_EVENT_ID,EVENT_NAME,SQL_TEXT, CURRENT_SCHEMA,NESTING_EVENT_ID,
NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from events_statements_history_long 
where thread_id=477908 and NESTING_EVENT_ID is null and END_EVENT_ID <=64\G
*************************** 1. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 62
        EVENT_NAME: statement/sql/begin
          SQL_TEXT: begin
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710027177007940384
*************************** 2. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 63
        EVENT_NAME: statement/sql/delete
          SQL_TEXT: delete from yqlock1 where a = 5
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710032172207519384
*************************** 3. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 64
        EVENT_NAME: statement/sql/update
          SQL_TEXT: update yqlock1 set b = '老王' where id = 3
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Rows matched: 1  Changed: 1  Warnings: 0
       timer_start: 1710040555142106384
3 rows in set (0.00 sec)

5.4.2 事务2

mysql> select THREAD_ID,END_EVENT_ID,EVENT_NAME,SQL_TEXT,CURRENT_SCHEMA,NESTING_EVENT_ID,
NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from events_statements_history_long 
where thread_id=477911 and NESTING_EVENT_ID is null and END_EVENT_ID <=62\G
*************************** 1. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 60
        EVENT_NAME: statement/sql/begin
          SQL_TEXT: begin
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710028920657774384
*************************** 2. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 61
        EVENT_NAME: statement/sql/delete
          SQL_TEXT: delete from yqlock1 where id = 3
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710035217737737384
*************************** 3. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 62
        EVENT_NAME: statement/sql/update
          SQL_TEXT: update yqlock1 set b = '老A' where a = 5
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Deadlock found when trying to get lock; try restarting transaction
       timer_start: 1710044599773023384
3 rows in set (0.00 sec)

5.5 结果排序下，根据语句推理

排序后，根据语句的结果，就比较好根据顺序推测了

select * from
(
select THREAD_ID,END_EVENT_ID,EVENT_NAME,SQL_TEXT, CURRENT_SCHEMA,
NESTING_EVENT_ID,NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from events_statements_history_long 
where thread_id=477908 and NESTING_EVENT_ID is null and END_EVENT_ID <=64
union all
select THREAD_ID,END_EVENT_ID,EVENT_NAME,SQL_TEXT,CURRENT_SCHEMA,NESTING_EVENT_ID,
NESTING_EVENT_TYPE, MESSAGE_TEXT,timer_start 
from events_statements_history_long 
where thread_id=477911 and NESTING_EVENT_ID is null and END_EVENT_ID <=62
) a order by a.timer_start\G
*************************** 1. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 62
        EVENT_NAME: statement/sql/begin
          SQL_TEXT: begin
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710027177007940384
*************************** 2. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 60
        EVENT_NAME: statement/sql/begin
          SQL_TEXT: begin
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710028920657774384
*************************** 3. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 63
        EVENT_NAME: statement/sql/delete
          SQL_TEXT: delete from yqlock1 where a = 5
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710032172207519384
*************************** 4. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 61
        EVENT_NAME: statement/sql/delete
          SQL_TEXT: delete from yqlock1 where id = 3
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 1710035217737737384
*************************** 5. row ***************************
         THREAD_ID: 477908
      END_EVENT_ID: 64
        EVENT_NAME: statement/sql/update
          SQL_TEXT: update yqlock1 set b = '老王' where id = 3
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Rows matched: 1  Changed: 1  Warnings: 0
       timer_start: 1710040555142106384
*************************** 6. row ***************************
         THREAD_ID: 477911
      END_EVENT_ID: 62
        EVENT_NAME: statement/sql/update
          SQL_TEXT: update yqlock1 set b = '老A' where a = 5
    CURRENT_SCHEMA: test1
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: Deadlock found when trying to get lock; try restarting transaction
       timer_start: 1710044599773023384
6 rows in set (0.00 sec)

根据以上，就不难推断出，死锁是这么产生的：

TX1	TX2
begin;
	begin;
delete from yqlock1 where a = 5;
	delete from yqlock1 where id = 3;
update yqlock1 set b = '老王' where id = 3; 等待...
	update yqlock1 set b = '老A' where a = 5; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

总结

通过以上的查询基本可以获取造成死锁的事务内执行的语句，由于线上业务量大可能造成events_statements_history_long查询不到需要的语句(默认存储10000条)，需要及时监控发现死锁。
打开performance_schema的选项，有性能损失。
如果线上实例是每个database对应一个独立用户，可以通过设置收集指定用户执行的所有event。
1).关闭收集所有用户的event
update setup_actors set ENABLED='NO',HISTORY='NO';
2).插入需要收集event的指定用户（例如我只想收集txc用户下的所有event,参考如下）
insert into setup_actors select '%','txc','%','YES','YES';
3).select * from setup_actors;

         +------+------+------+---------+---------+
         | HOST | USER | ROLE | ENABLED | HISTORY |
         +------+------+------+---------+---------+
         | %    | %    | %    | NO      | NO      |
         | %    | abc  | %    | YES     | YES     |
         +------+------+------+---------+---------+

参考：https://www.jianshu.com/p/268889c997e8