In a previous article, Ovais demonstrated how a DDL can render a table blocked from new queries. In another article, Valerii introduced performance_schema.metadata_locks, which is available in MySQL 5.7 and exposes metadata lock details. Given this information, here’s a quick way to troubleshoot metadata locks by creating a stored procedure that can:
- Find out which thread(s) have the metadata lock
- Determine which thread has been waiting for it the longest
- Find other threads waiting for the metadata lock
Setting up instrumentation
First, you need to enable instrumentation for metadata locks:
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl';
Second, you need to add this stored procedure:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 | USE test; DROP PROCEDURE IF EXISTS procShowMetadataLockSummary; delimiter // CREATE PROCEDURE procShowMetadataLockSummary() BEGIN DECLARE table_schema VARCHAR(64); DECLARE table_name VARCHAR(64); DECLARE id bigint; DECLARE time bigint; DECLARE info longtext; DECLARE curMdlCount INT DEFAULT 0; DECLARE curMdlCtr INT DEFAULT 0; DECLARE curMdl CURSOR FOR SELECT * FROM tmp_blocked_metadata; DROP TEMPORARY TABLE IF EXISTS tmp_blocked_metadata; CREATE TEMPORARY TABLE IF NOT EXISTS tmp_blocked_metadata ( table_schema varchar(64), table_name varchar(64), id bigint, time bigint, info longtext, PRIMARY KEY(table_schema, table_name) ); REPLACE tmp_blocked_metadata(table_schema,table_name,id,time,info) SELECT mdl.OBJECT_SCHEMA, mdl.OBJECT_NAME, t.PROCESSLIST_ID, t.PROCESSLIST_TIME, t.PROCESSLIST_INFO FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON mdl.OWNER_THREAD_ID = t.THREAD_ID WHERE mdl.LOCK_STATUS='PENDING' and mdl.LOCK_TYPE='EXCLUSIVE' ORDER BY mdl.OBJECT_SCHEMA,mdl.OBJECT_NAME,t.PROCESSLIST_TIME ASC; OPEN curMdl; SET curMdlCount = (SELECT FOUND_ROWS()); WHILE (curMdlCtr < curMdlCount) DO FETCH curMdl INTO table_schema, table_name, id, time, info; SELECT CONCAT_WS(' ','PID',t.PROCESSLIST_ID,'has metadata lock on', CONCAT(mdl.OBJECT_SCHEMA,'.',mdl.OBJECT_NAME), 'with current state', CONCAT_WS('','[',t.PROCESSLIST_STATE,']'), 'for', t.PROCESSLIST_TIME, 'seconds and is currently running', CONCAT_WS('',"[",t.PROCESSLIST_INFO,"]")) AS 'Process(es) that have the metadata lock' FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON t.THREAD_ID = mdl.OWNER_THREAD_ID WHERE mdl.LOCK_STATUS='GRANTED' AND mdl.OBJECT_SCHEMA = table_schema and mdl.OBJECT_NAME = table_name AND mdl.OWNER_THREAD_ID NOT IN(SELECT mdl2.OWNER_THREAD_ID FROM performance_schema.metadata_locks mdl2 WHERE mdl2.LOCK_STATUS='PENDING' AND mdl.OBJECT_SCHEMA = mdl2.OBJECT_SCHEMA and mdl.OBJECT_NAME = mdl2.OBJECT_NAME); SELECT CONCAT_WS(' ','PID', id, 'has been waiting for metadata lock on',CONCAT(table_schema,'.', table_name),'for', time, 'seconds to execute', CONCAT_WS('','[',info,']')) AS 'Oldest process waiting for metadata lock'; SET curMdlCtr = curMdlCtr + 1; SELECT CONCAT_WS(' ','PID', t.PROCESSLIST_ID, 'has been waiting for metadata lock on',CONCAT(table_schema,'.', table_name),'for', t.PROCESSLIST_TIME, 'seconds to execute', CONCAT_WS('','[',t.PROCESSLIST_INFO,']')) AS 'Other queries waiting for metadata lock' FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON t.THREAD_ID = mdl.OWNER_THREAD_ID WHERE mdl.LOCK_STATUS='PENDING' AND mdl.OBJECT_SCHEMA = table_schema and mdl.OBJECT_NAME = table_name AND mdl.OWNER_THREAD_ID AND t.PROCESSLIST_ID <> id ; END WHILE; CLOSE curMdl; END// delimiter ; |
Testing
Now, let’s call the procedure to see if there are threads waiting for metadata locks:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 | mysql> CALL test.procShowMetadataLockSummary(); +----------------------------------------------------------------------------------------------------------------+ | Process(es) that have the metadata lock | +----------------------------------------------------------------------------------------------------------------+ | PID 10 has metadata lock on sbtest.sbtest with current state [] since 274 seconds and is currently running [] | | PID 403 has metadata lock on sbtest.sbtest with current state [] since 291 seconds and is currently running [] | +----------------------------------------------------------------------------------------------------------------+ 2 rows in set (0.00 sec) +------------------------------------------------------------------------------------------------------------------------+ | Oldest process waiting for metadata lock | +------------------------------------------------------------------------------------------------------------------------+ | PID 1264 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [truncate table sbtest.sbtest] | +------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec) +---------------------------------------------------------------------------------------------------------------------------+ | Other queries waiting for metadata lock | +---------------------------------------------------------------------------------------------------------------------------+ | PID 1269 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] | | PID 1270 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] | | PID 1271 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] | | PID 1272 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] | | PID 1273 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] | +---------------------------------------------------------------------------------------------------------------------------+ 5 rows in set (0.00 sec) |
So, as you can see above, you have several choices. You could (a) do nothing and wait for threads 10 and 403 to complete and then thread 1264 can get the lock.
If you can’t wait, you can (b) kill the threads that have the metadata lock so that the TRUNCATE TABLE in thread 1264 can get the lock. Although, before you decide to kill threads 10 and 403, you should check SHOW ENGINE INNODB STATUS to see if the undo log entries for those threads are high. If they are, rolling back these transactions might take a long time.
Lastly, you can instead (c) kill the DDL thread 1264 to free up other queries. You should then reschedule the DDL to run during offpeak hours.
Happy metadata lock hunting!
nice job
Thank you Jaime! I have implemented this solution because we have from time to time some long running processes accumulating in one of the nodes of our Percona cluster. Just waiting for the next occurrence of the problem!
Thank you. This helps us to identify blocking sessions for metadatalock.
I am using the mysql version as follows
Server version: 5.7.19-17-log Percona Server (GPL), Release 17, Revision e19a6b7b73f
However, I can not view the thread holding the MDL lock.
I refer to the following article
https://www.percona.com/blog/2016/12/28/quickly-troubleshooting-metadata-locks-mysql-5-7/
the test is described below
The following is the official version of the phenomenon (5.7.19)
test@Test 06:13:51>select * from performance_schema.metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140091634556304
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_parse.cc:5993
OWNER_THREAD_ID: 30
OWNER_EVENT_ID: 52
1 row in set (0.00 sec)
test@Test 06:13:55>select * from performance_schema.setup_instruments where name like ‘wait/lock/metadata/sql/mdl’;
+—————————-+———+——-+
| NAME | ENABLED | TIMED |
+—————————-+———+——-+
| wait/lock/metadata/sql/mdl | YES | NO |
+—————————-+———+——-+
1 row in set (0.00 sec)
The following is the percona version of the phenomenon (5.7.19)
dbadmin@Test 10:03:01>select * from performance_schema.metadata_locks\G
Empty set (0.00 sec)
dbadmin@Test 10:12:19>select * from performance_schema.setup_instruments where name like ‘wait/lock/metadata/sql/mdl’;
+—————————-+———+——-+
| NAME | ENABLED | TIMED |
+—————————-+———+——-+
| wait/lock/metadata/sql/mdl | YES | NO |
+—————————-+———+——-+
1 row in set (0.00 sec)
thank you very mach.
test@(none) 01:55:16>select version();
+—————+
| version() |
+—————+
| 5.7.19-17-log |
+—————+
1 row in set (0.00 sec)
test@(none) 01:54:44>select * from information_schema.processlist where command!=’sleep’ and user!=’system user’\G
*************************** 1. row ***************************
ID: 101176
USER: test
HOST: localhost
DB: test
COMMAND: Query
TIME: 64
STATE: Waiting for table metadata lock
INFO: alter table t1 add column name5 char(10)
TIME_MS: 64148
ROWS_SENT: 0
ROWS_EXAMINED: 0
test@(none) 01:55:30>CALL test.procShowMetadataLockSummary();
Query OK, 0 rows affected (0.00 sec)
test@(none) 01:55:53>SELECT OBJECT_TYPE, OBJECT_SCHEMA, OBJECT_NAME, LOCK_TYPE, LOCK_STATUS, THREAD_ID, PROCESSLIST_ID, PROCESSLIST_INFO FROM performance_schema.metadata_locks INNER JOIN performance_schema.threads ON THREAD_ID = OWNER_THREAD_ID WHERE PROCESSLIST_ID CONNECTION_ID();
+————-+——————–+——————-+————-+————-+———–+—————-+——————+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_STATUS | THREAD_ID | PROCESSLIST_ID | PROCESSLIST_INFO |
+————-+——————–+——————-+————-+————-+———–+—————-+——————+
| TABLE | performance_schema | global_status | SHARED_READ | GRANTED | 53741 | 53559 | NULL |
| TABLE | performance_schema | session_variables | SHARED_READ | GRANTED | 53741 | 53559 | NULL |
+————-+——————–+——————-+————-+————-+———–+—————-+——————+
2 rows in set (0.05 sec)
But when i restart mysqld, I can see it.
He is unstable
Hi, what about pre 5.7 versions?
I am facing same issue while creating index on table other queries hitting on table so process list shows waiting for table metadata lock ..and these sessions increasing more than 200 sessions
And currently max_connectio is 100 mysql server.
How to avoid increasing session because table
Pleas help I am not able to find why number of sessions increasing?