第32节：通过performance_schema获取造成死锁的事务语句

（本文由田兴椿编写）

数据库日常维护中我们经常遇到死锁的问题，由于无法获取造成死锁的事务内执行过的语句，对我们死锁的分析造成很大的困难。但是在MySQL 5.7中我们可以利用performance_schema来获取这些语句，为我们解决死锁问题提供了一个新的思路，下面我们将解释这种方法的使用。

一、开启相关统计的方法

如果打开performance_schema选项来收集执行过的语句和事务会有性能损失，一般建议需要的时候开启，然后在线关闭掉。

（1）在my.cnf中设置打开、关闭performance_schema选项随数据库启动

#设置setup_instruments表收集相关statement event
performance-schema-instrument='statement/%=ON'  
#开启events_statements_current表存储当前连接线程执行的最后一条statement event信息               
performance-schema-consumer-events-statements-current=ON   
#开启events-statements-history表默认存储每个线程最近10条statement event信息 
performance-schema-consumer-events-statements-history=ON        
#开启events-statements-history-long表默认存储最近10000条语句event信息
performance-schema-consumer-events-statements-history-long=ON   

performance-schema-consumer-statements-digest=ON       
         
#设置setup_instruments表收集transaction event
performance-schema-instrument='transaction=ON'    
#开启events_transactions_current表存储当前连接线程执行的transaction event信息              
performance-schema-consumer-events-transactions-current=ON      
#开启events_transactions_history表默认存储每个线程最近10条transaction event信息
performance-schema-consumer-events-transactions-history=ON   
#开启events_statements_history_long表默认存储最近10000条语句event信息。   
performance-schema-consumer-events-transactions-history-long=ON

（2）在my.cnf中设置关闭performance_schema选项语句和事务收集

performance-schema-instrument='statement/%=OFF'              
performance-schema-consumer-events-statements-current=OFF
performance-schema-consumer-events-statements-history=OFF
performance-schema-consumer-events-statements-history-long=OFF
performance-schema-consumer-statements-digest=OFF

performance-schema-instrument='transaction=OFF'
performance-schema-consumer-events-transactions-current=OFF
performance-schema-consumer-events-transactions-history=OFF
performance-schema-consumer-events-transactions-history-long=OFF

（3）在线打开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';

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

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）相关参数

performance_schema_events_statements_history_size：定义events_statements_history表中每个线程最大行数，静态参数，修改需要重启实例。
performance_schema_events_statements_history_long_size：定义events_statements_history_long表最大行数，静态参数，修改需要重启实例。
performance_schema_events_transactions_history_size：定义events_transactions_history表每个线程最大行数，静态参数，修改需要重启实例。
performance_schema_events_transactions_history_long_size：定义events_transactions_history_long表最大行数，静态参数，修改需要重启实例。

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

下面是一个典型的死锁日志：

*** (1) TRANSACTION:

TRANSACTION 897551, ACTIVE 48 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 4, OS thread handle 140029509830400, query id 123 localhost root 
statistics
select * from t1 where id=1 for update
2019-07-09T10:29:40.710270+08:00 3 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO 
BE GRANTED:

RECORD LOCKS space id 591 page no 3 n bits 80 index PRIMARY of table `txc_test`.`t1` 
trx id 897551 lock_mode X locks rec but not gap waiting
......

2019-07-09T10:29:40.711199+08:00 3 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 897550, ACTIVE 62 sec starting index read
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 3, OS thread handle 140029510035200, query id 124 localhost root 
statistics
select * from t2 where id=1 for update
2019-07-09T10:29:40.711364+08:00 3 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 591 page no 3 n bits 80 index PRIMARY of table `txc_test`.`t1` 
trx id 897550 lock_mode X locks rec but not gap
......
2019-07-09T10:29:40.712249+08:00 3 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO
BE GRANTED:

RECORD LOCKS space id 592 page no 3 n bits 80 index PRIMARY of table `txc_test`.`t2`
trx id 897550 lock_mode X locks rec but not gap waiting
......
2019-07-09T10:29:40.713153+08:00 3 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

（1）通过events_statements_history_long来查询死锁语句

事务1

在死锁日志中我们可以看到导致死锁的最后一个语句是‘select * from t1 where id=1 for update’，那么我们就可以使用它来查询events_statements_history_long表。

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 events_statements_history_long where sql_text like 
'select * from t1 where id=1 for update' \G
*************************** 1. row ***************************
         THREAD_ID: 37       
          EVENT_ID: 98
      END_EVENT_ID: 106
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t1 where id=1 for update
            DIGEST: be26f0b8bee2ac2bb34e9c651d655e7c
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 96
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 266799699801000
*************************** 2. row ***************************
         THREAD_ID: 38
          EVENT_ID: 35
      END_EVENT_ID: 37
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t1 where id=1 for update
            DIGEST: be26f0b8bee2ac2bb34e9c651d655e7c
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 19
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL

事务2

在死锁日志中我们可以看到导致死锁的最后一个语句是‘select * from t2 where id=1 for update’，那么我们就可以使用它来查询events_statements_history_long表。

 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 
from events_statements_history_long where sql_text like 
'select * from t2 where id=1 for update' \G
*************************** 1. row ***************************
(event关联的线程id)
         THREAD_ID: 38                                          
          EVENT_ID: 21                                       
      END_EVENT_ID: 29                                          
        EVENT_NAME: statement/sql/select                      
            SOURCE: socket_connection.cc:101                  
(执行的sql语句信息)
          SQL_TEXT: select * from t2 where id=1 for update      
            DIGEST: 315b4a6a8f7424bc7591256a8937a213 
    CURRENT_SCHEMA: txc_test                                
(父语句event id)  
  NESTING_EVENT_ID: 19                                                                                
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
(event开始时间(从实例启动到现在的时间差)，单位皮秒)
       timer_start: 280428752972000                             
*************************** 2. row ***************************
(event关联的线程id)
         THREAD_ID: 37                                          
          EVENT_ID: 112
      END_EVENT_ID: 114
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
(执行的sql语句信息)
          SQL_TEXT: select * from t2 where id=1 for update      
            DIGEST: 315b4a6a8f7424bc7591256a8937a213
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 96
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: Deadlock found when trying to get lock; try restarting transaction
(event开始时间(从实例启动到现在的时间差)，单位皮秒)
       timer_start: 328978250011000

虽然我们根据死锁日志进行了语句查询，但是我们发现没法确认哪一个是事务1，哪一个是事务2。不过我们可以通过MESSAGE_TEXT中的信息‘Deadlock found when trying to get lock; try restarting transaction’，确认THREAD_ID：37为事务2，THREAD_ID: 38为事务1的线程，因为我们的死锁日志显示事务2被回滚掉了。需要注意这里的THREAD_ID是performance_schema内部使用的，和我们平时show processlist访问的PROCESSLIST_ID不一样。它是一个performance_schema内部的计数器源码如下：

PFS_thread* create_thread(PFS_thread_class *klass, const void *identity,
                          ulonglong processlist_id){
  PFS_thread *pfs;
  pfs_dirty_state dirty_state;
  pfs= global_thread_container.allocate(& dirty_state);  if (pfs != NULL)
  {
    pfs->m_thread_internal_id=
      PFS_atomic::add_u64(&thread_internal_id_counter.m_u64, 1);
    pfs->m_parent_thread_internal_id= 0;
    pfs->m_processlist_id= static_cast<ulong>(processlist_id);

（2）提取信息

事务1

最后一条语句的END_EVENT_ID=37
最后一条语句的NESTING_EVENT_ID=19
THREAD_ID=38

因此我们可以通过如下语句得出经历的所有语句如下：

 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 events_statements_history_long where thread_id=38 and END_EVENT_ID>=19 and 
END_EVENT_ID <=37 \G

*************************** 1. row ***************************
         THREAD_ID: 38                                           
          EVENT_ID: 18                                            
      END_EVENT_ID: 19                                                                                        
        EVENT_NAME: statement/sql/begin
            SOURCE: socket_connection.cc:101
          SQL_TEXT: begin                                        
            DIGEST: f57daa74a09445d1e1c496f28fe6d906
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL                                       
      MESSAGE_TEXT: NULL
       timer_start: 274749880798000                          
*************************** 2. row ***************************
         THREAD_ID: 38
          EVENT_ID: 21
      END_EVENT_ID: 29
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t2 where id=1 for update
            DIGEST: 315b4a6a8f7424bc7591256a8937a213
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 19
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 280428752972000
*************************** 3. row ***************************
         THREAD_ID: 38
          EVENT_ID: 31
      END_EVENT_ID: 33
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t1 where id=3 for update
            DIGEST: be26f0b8bee2ac2bb34e9c651d655e7c
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 19
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 296208754204000
*************************** 4. row ***************************
         THREAD_ID: 38
          EVENT_ID: 35
      END_EVENT_ID: 37
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t1 where id=1 for update
            DIGEST: be26f0b8bee2ac2bb34e9c651d655e7c
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 19
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 319574947823000
4 rows in set (0.00 sec)

事务2

最后一条语句的END_EVENT_ID=114
最后一条语句的NESTING_EVENT_ID=96
THREAD_ID=37

因此我们可以通过如下语句得出经历的所有语句如下：

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 events_statements_history_long where thread_id = 37 and END_EVENT_ID >= 96 
and END_EVENT_ID <= 114\G
*************************** 1. row ***************************
         THREAD_ID: 37
          EVENT_ID: 95
      END_EVENT_ID: 96
        EVENT_NAME: statement/sql/begin
            SOURCE: socket_connection.cc:101
          SQL_TEXT: begin
            DIGEST: f57daa74a09445d1e1c496f28fe6d906
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
      MESSAGE_TEXT: NULL
       timer_start: 251219441701000
*************************** 2. row ***************************
         THREAD_ID: 37
          EVENT_ID: 98
      END_EVENT_ID: 106
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t1 where id=1 for update
            DIGEST: be26f0b8bee2ac2bb34e9c651d655e7c
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 96
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 266799699801000
*************************** 3. row ***************************
         THREAD_ID: 37
          EVENT_ID: 108
      END_EVENT_ID: 110
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t2 where id=6 for update
            DIGEST: 315b4a6a8f7424bc7591256a8937a213
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 96
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: NULL
       timer_start: 308095739676000
*************************** 4. row ***************************
         THREAD_ID: 37
          EVENT_ID: 112
      END_EVENT_ID: 114
        EVENT_NAME: statement/sql/select
            SOURCE: socket_connection.cc:101
          SQL_TEXT: select * from t2 where id=1 for update
            DIGEST: 315b4a6a8f7424bc7591256a8937a213
    CURRENT_SCHEMA: txc_test
  NESTING_EVENT_ID: 96
NESTING_EVENT_TYPE: TRANSACTION
      MESSAGE_TEXT: Deadlock found when trying to get lock; try restarting transaction
       timer_start: 328978250011000
4 rows in set (0.01 sec)

（3）猜测死锁形成过程

根据上面两个事务执行的sql大致可以推断出死锁的sql语句，如果两个事务里面执行的sql很多那可能就需要花更多的时间来找出造成死锁的语句：

TX1	TX2
	select * from t1 where id=1 for update;
select * from t2 where id=1 for update;
select * from t1 where id=3 for update;
	select * from t2 where id=6 for update;
select * from t1 where id=1 for update;
	select * from t2 where id=1 for update;

三、总结

通过以上的查询基本可以获取造成死锁的事务内执行的语句，由于线上业务量大可能造成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      |
         | %    | txc  | %    | YES     | YES     |
         +------+------+------+---------+---------+

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 159,219评论 4赞 362
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 67,363评论 1赞 293
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 108,933评论 0赞 243
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 44,020评论 0赞 206
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 52,400评论 3赞 287
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 40,640评论 1赞 219
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 31,896评论 2赞 313
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 30,597评论 0赞 199
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 34,327评论 1赞 244
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 30,581评论 2赞 246
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 32,072评论 1赞 261
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 28,399评论 2赞 253
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 33,054评论 3赞 236
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 26,083评论 0赞 8
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 26,849评论 0赞 195
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 35,672评论 2赞 274
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 35,585评论 2赞 270

第32节：通过performance_schema获取造成死锁的事务语句

（本文由田兴椿编写）

一、开启相关统计的方法

（1） 在my.cnf中设置打开、关闭performance_schema选项随数据库启动

（2） 在my.cnf中设置关闭performance_schema选项语句和事务收集

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

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

（5） 相关参数