在配置文件中设置
[mysqld]performance-schema-instrument='wait/lock/metadata/sql/mdl=ON'
测试场景
下面结合一个简单的Demo,来看看在MySQL 5.7中如何定位DDL操作的阻塞问题。
session1> begin;
Query OK,0 rows affected (0.00sec)
session1> delete from slowtech.t1 where id=2;
Query OK,1 row affected (0.00sec)
session1> select * fromslowtech.t1;+------+------+
| id | name |
+------+------+
| 1 | a |
+------+------+
1 row in set (0.00sec)
session1> update slowtech.t1 set name='c' where id=1;
Query OK,1 row affected (0.00sec)
Rows matched:1 Changed: 1 Warnings: 0session2> alter table slowtech.t1 add c1 int; ##被阻塞
session3>show processlist;+----+------+-----------+------+---------+------+---------------------------------+------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+------+---------+------+---------------------------------+------------------------------------+
| 2 | root | localhost | NULL | Sleep | 51 | | NULL |
| 3 | root | localhost | NULL | Query | 0 | starting | show processlist |
| 4 | root | localhost | NULL | Query | 9 | Waiting for table metadata lock | alter table slowtech.t1 add c1 int |
+----+------+-----------+------+---------+------+---------------------------------+------------------------------------+
3 rows in set (0.00sec)
session3> select object_type,object_schema,object_name,lock_type,lock_duration,lock_status,owner_thread_id fromperformance_schema.metadata_locks;+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+
| object_type | object_schema | object_name | lock_type | lock_duration | lock_status | owner_thread_id |
+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+
| TABLE | slowtech | t1 | SHARED_WRITE | TRANSACTION | GRANTED | 27 |
| GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | STATEMENT | GRANTED | 29 |
| SCHEMA | slowtech | NULL | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | 29 |
| TABLE | slowtech | t1 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 29 |
| TABLE | slowtech | t1 | EXCLUSIVE | TRANSACTION | PENDING | 29 |
| TABLE | performance_schema | metadata_locks | SHARED_READ | TRANSACTION | GRANTED | 28 |
+-------------+--------------------+----------------+---------------------+---------------+-------------+-----------------+
6 rows in set (0.00 sec)
这里,重点关注lock_status,"PENDING"代表线程在等待MDL,而"GRANTED"则代表线程持有MDL。
如何找出引起阻塞的会话
结合owner_thread_id,可以可到,是29号线程在等待27号线程的MDL,此时,可kill掉52号线程。
但需要注意的是,owner_thread_id给出的只是线程ID,并不是show processlist中的ID。如果要查找线程对应的processlist id,需查询performance_schema.threads表。
session3> select * from performance_schema.threads where thread_id in (27,29)\G*************************** 1. row ***************************THREAD_ID:27NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID:2PROCESSLIST_USER: root
PROCESSLIST_HOST: localhost
PROCESSLIST_DB:NULLPROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME:214PROCESSLIST_STATE:NULLPROCESSLIST_INFO:NULLPARENT_THREAD_ID:1ROLE:NULLINSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: Socket
THREAD_OS_ID:9800
*************************** 2. row ***************************THREAD_ID:29NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID:4PROCESSLIST_USER: root
PROCESSLIST_HOST: localhost
PROCESSLIST_DB:NULLPROCESSLIST_COMMAND: Query
PROCESSLIST_TIME:172PROCESSLIST_STATE: Waitingfor tablemetadata lock
PROCESSLIST_INFO:alter table slowtech.t1 add c1 intPARENT_THREAD_ID:1ROLE:NULLINSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: Socket
THREAD_OS_ID:9907
2 rows in set (0.00 sec)
将这两张表结合,借鉴sys.innodb_lock _waits的输出,实际上我们也可以直观地呈现MDL的等待关系。
SELECTa.OBJECT_SCHEMAASlocked_schema,
a.OBJECT_NAME ASlocked_table,
"Metadata Lock"ASlocked_type,
c.PROCESSLIST_IDASwaiting_processlist_id,
c.PROCESSLIST_TIMEASwaiting_age,
c.PROCESSLIST_INFOASwaiting_query,
c.PROCESSLIST_STATEASwaiting_state,
d.PROCESSLIST_IDASblocking_processlist_id,
d.PROCESSLIST_TIMEASblocking_age,
d.PROCESSLIST_INFOASblocking_query,
concat('KILL', d.PROCESSLIST_ID) ASsql_kill_blocking_connectionFROMperformance_schema.metadata_locks aJOIN performance_schema.metadata_locks b ON a.OBJECT_SCHEMA =b.OBJECT_SCHEMAAND a.OBJECT_NAME = b.OBJECT_NAME
AND a.lock_status = 'PENDING'
AND b.lock_status = 'GRANTED'
AND a.OWNER_THREAD_ID <>b.OWNER_THREAD_IDAND a.lock_type = 'EXCLUSIVE'
JOIN performance_schema.threads c ON a.OWNER_THREAD_ID =c.THREAD_IDJOIN performance_schema.threads d ON b.OWNER_THREAD_ID =d.THREAD_ID\G*************************** 1. row ***************************locked_schema: slowtech
locked_table: t1
locked_type: Metadata Lock
waiting_processlist_id:4waiting_age:259waiting_query:alter table slowtech.t1 add c1 intwaiting_state: Waitingfor tablemetadata lock
blocking_processlist_id:2blocking_age:301blocking_query:NULLsql_kill_blocking_connection:KILL 2
1 row in set (0.00 sec)
输出一目了然,DDL操作如果要获得MDL,执行kill 2即可。
官方的sys.schematablelock_waits
实际上,MySQL 5.7在sys库中也集成了类似功能,同样的场景,其输出如下,
mysql> select * fromsys.schema_table_lock_waits\G*************************** 1. row ***************************object_schema: slowtechobject_name: t1
waiting_thread_id:29waiting_pid:4waiting_account: root@localhostwaiting_lock_type: EXCLUSIVE
waiting_lock_duration:TRANSACTIONwaiting_query:alter table slowtech.t1 add c1 intwaiting_query_secs:446waiting_query_rows_affected:0waiting_query_rows_examined:0blocking_thread_id:27blocking_pid:2blocking_account: root@localhostblocking_lock_type: SHARED_READ
blocking_lock_duration:TRANSACTIONsql_kill_blocking_query:KILL QUERY 2sql_kill_blocking_connection:KILL 2
*************************** 2. row ***************************object_schema: slowtechobject_name: t1
waiting_thread_id:29waiting_pid:4waiting_account: root@localhostwaiting_lock_type: EXCLUSIVE
waiting_lock_duration:TRANSACTIONwaiting_query:alter table slowtech.t1 add c1 intwaiting_query_secs:446waiting_query_rows_affected:0waiting_query_rows_examined:0blocking_thread_id:29blocking_pid:4blocking_account: root@localhostblocking_lock_type: SHARED_UPGRADABLE
blocking_lock_duration:TRANSACTIONsql_kill_blocking_query:KILL QUERY 4sql_kill_blocking_connection:KILL 4
2 rows in set (0.00 sec)
具体分析下官方的输出,
只有一个alter table操作,却产生了两条记录,而且两条记录的kill对象竟然还不一样,对表结构不熟悉及不仔细看记录内容的话,难免会kill错对象。
不仅如此,如果有N个查询被DDL操作堵塞,则会产生N*2条记录。在阻塞操作较多的情况下,这N*2条记录完全是个噪音。
而之前的SQL,无论有多少操作被阻塞,一个alter table操作,就只会输出一条记录。
如何查看阻塞会话已经执行过的操作
但上面这个SQL也有遗憾,其blocking_query为NULL,而在会话1中,其明明已经执行了三个SQL。
这个与performance_schema.threads(类似于show processlist)有关,其只会输出当前正在运行的SQL,对于已经执行过的,实际上是没办法看到。
但在线上,kill是一个需要谨慎的操作,毕竟你很难知道kill的是不是业务关键操作?又或者,是个批量update操作?那么,有没有办法抓到该事务之前的操作呢?
答案,有。
即Performance Schema中记录Statement Event(操作事件)的表,具体包括events_statements_current,events_statements_history,events_statements_history_long,prepared_statements_instances。
常用的是前面三个。
三者的表结构完全一致,其中,events_statements_history又包含了events_statements_current的操作,所以我们这里会使用events_statements_history。
终极SQL如下,
SELECTlocked_schema,
locked_table,
locked_type,
waiting_processlist_id,
waiting_age,
waiting_query,
waiting_state,
blocking_processlist_id,
blocking_age,
substring_index(sql_text,"transaction_begin;" ,-1) ASblocking_query,
sql_kill_blocking_connectionFROM(SELECTb.OWNER_THREAD_IDASgranted_thread_id,
a.OBJECT_SCHEMAASlocked_schema,
a.OBJECT_NAME ASlocked_table,
"Metadata Lock"ASlocked_type,
c.PROCESSLIST_IDASwaiting_processlist_id,
c.PROCESSLIST_TIMEASwaiting_age,
c.PROCESSLIST_INFOASwaiting_query,
c.PROCESSLIST_STATEASwaiting_state,
d.PROCESSLIST_IDASblocking_processlist_id,
d.PROCESSLIST_TIMEASblocking_age,
d.PROCESSLIST_INFOASblocking_query,
concat('KILL', d.PROCESSLIST_ID) ASsql_kill_blocking_connectionFROMperformance_schema.metadata_locks aJOIN performance_schema.metadata_locks b ON a.OBJECT_SCHEMA =b.OBJECT_SCHEMAAND a.OBJECT_NAME = b.OBJECT_NAME
AND a.lock_status = 'PENDING'
AND b.lock_status = 'GRANTED'
AND a.OWNER_THREAD_ID <>b.OWNER_THREAD_IDAND a.lock_type = 'EXCLUSIVE'
JOIN performance_schema.threads c ON a.OWNER_THREAD_ID =c.THREAD_IDJOIN performance_schema.threads d ON b.OWNER_THREAD_ID =d.THREAD_ID
) t1,
(SELECTthread_id,
group_concat(CASE WHEN EVENT_NAME = 'statement/sql/begin' THEN "transaction_begin" ELSE sql_text END ORDER BY event_id SEPARATOR ";" ) ASsql_textFROMperformance_schema.events_statements_historyGROUP BYthread_id
) t2WHEREt1.granted_thread_id=t2.thread_id \G*************************** 1. row ***************************locked_schema: slowtech
locked_table: t1
locked_type: Metadata Lock
waiting_processlist_id:4waiting_age:294waiting_query:alter table slowtech.t1 add c1 intwaiting_state: Waitingfor tablemetadata lock
blocking_processlist_id:2blocking_age:336blocking_query:delete from slowtech.t1 where id=2;select * from slowtech.t1;update slowtech.t1 set name='c' where id=1sql_kill_blocking_connection:KILL 2
1 row in set, 1 warning (0.00 sec)
从上面的输出可以看到,blocking_query中包含了会话1中当前事务的所有操作,按执行的先后顺序输出。
需要注意的是,默认情况下,events_statements_history只会保留每个线程最近的10个操作,如果事务中进行的操作较多,实际上也是没办法抓全的。
Anyway, it is better than nothing!