Dec
28
2016
--

Quickly Troubleshoot Metadata Locks in MySQL 5.7

Metadata Locks

Metadata LocksIn 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:

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:

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!

Apr
06
2015
--

More on (transactional) MySQL metadata locks

Two years ago Ovais Tariq had explained in detail what kinds of problems existed before MySQL introduced metadata locks in 5.5.3 and how these locks help to prevent them. Still, some implications of metadata locking in MySQL remain unclear for users – DBAs and even software developers that target recent MySQL versions. I’ve decided to include a slide or two into the presentation about InnoDB locks and deadlocks I plan to make (with my colleague Nilnandan Joshi) on April 16 at Percona Live 2015.

I decided to do this as recently I’ve got an issue to work on where it was claimed that the behavior of SELECT blocking TRUNCATE TABLE is wrong, just because transaction isolation level was set to READ COMMITTED and thus there should be no locks set by SELECT and transaction should not even start no matter what the value of autocommit is (it was explicitly set to 0 by smart software).

The MySQL manual clearly says:

“To ensure transaction serializability, the server must not permit one session to perform a data definition language (DDL) statement on a table that is used in an uncompleted explicitly or implicitly started transaction in another session. The server achieves this by acquiring metadata locks on tables used within a transaction and deferring release of those locks until the transaction ends. A metadata lock on a table prevents changes to the table’s structure. This locking approach has the implication that a table that is being used by a transaction within one session cannot be used in DDL statements by other sessions until the transaction ends.”

So, the real challenge was to show these metadata locks still set in a transaction that started implicitly, by SELECT immediately following SET autocommit=0 in a session. It was a good chance to check how metadata locks are exposed in MySQL 5.7 via Performance Schema, so I’ve set up a simple test.

First of all, I’ve enabled instrumentation for metadata locks:

[openxs@centos 5.7]$ bin/mysql --no-defaults -uroot -proot
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or g.
Your MySQL connection id is 4
Server version: 5.7.6-m16 MySQL Community Server (GPL)
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or 'h' for help. Type 'c' to clear the current input statement.
mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME = 'global_instrumentation';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1 Changed: 0 Warnings: 0
mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1 Changed: 0 Warnings: 0

Then I’ve set up a simple test based on the details from the issue (I’ve create the InnoDB table, t, and added a row to it before this):

mysql> set session autocommit=0;
Query OK, 0 rows affected (0.00 sec)
mysql> select @@autocommit, @@tx_isolation;
+--------------+----------------+
| @@autocommit | @@tx_isolation |
+--------------+----------------+
| 0 | READ-COMMITTED |
+--------------+----------------+
1 row in set (0.00 sec)
mysql> select * from t limit 1;
+----+------+
| id | val |
+----+------+
| 1 | 1 |
+----+------+
1 row in set (0.00 sec)

Now, from another session I tried to TRUNCATE the table before the fist session got a chance to do explicit or implicit COMMIT (In the issue I mentioned software used just had not cared to do this, assuming transaction had not started. It worked with MySQL 5.1 really well that way.)

mysql> truncate table t;

I was not surprised that TRUNCATE hung. Manual clearly says that until transaction is committed we do not release metadata locks. But let’s check them in Performance Schema (from the first session, where we executed SELECT):

mysql> select * from performance_schema.metadata_locksG
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: test
OBJECT_NAME: t
OBJECT_INSTANCE_BEGIN: 140450128308592
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_parse.cc:5585
OWNER_THREAD_ID: 27
OWNER_EVENT_ID: 17
*************************** 2. row ***************************
OBJECT_TYPE: GLOBAL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140450195436144
LOCK_TYPE: INTENTION_EXCLUSIVE
LOCK_DURATION: STATEMENT
LOCK_STATUS: GRANTED
SOURCE: sql_base.cc:5224
OWNER_THREAD_ID: 30
OWNER_EVENT_ID: 8
*************************** 3. row ***************************
OBJECT_TYPE: SCHEMA
OBJECT_SCHEMA: test
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140450195434272
LOCK_TYPE: INTENTION_EXCLUSIVE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_base.cc:5209
OWNER_THREAD_ID: 30
OWNER_EVENT_ID: 8
*************************** 4. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: test
OBJECT_NAME: t
OBJECT_INSTANCE_BEGIN: 140450195434368
LOCK_TYPE: EXCLUSIVE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: PENDING
SOURCE: sql_parse.cc:5585
OWNER_THREAD_ID: 30
OWNER_EVENT_ID: 8
*************************** 5. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140450128262384
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_parse.cc:5585
OWNER_THREAD_ID: 27
OWNER_EVENT_ID: 18
5 rows in set (0.00 sec)

Note SHARED_READ lock set on table t and EXCLUSIVE lock is pending on the same table t above. TRUNCATE is blocked (as DDL).

Note also locks related  to out SELECT from the metadata_locks table in the output. Yes, access to Performance Schema is also protected with metadata locks!

We can get a nice view of all metadata locks from other sessions, excluding our current one, and check also all we could get about them before MySQL 5.7 (just a thread state in the SHOW PROCESSLIST output):

mysql> 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 |
+-------------+---------------+-------------+---------------------+-------------+-----------+----------------+------------------+
| GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | GRANTED | 30 | 8 | truncate table t |
| SCHEMA | test | NULL | INTENTION_EXCLUSIVE | GRANTED | 30 | 8 | truncate table t |
| TABLE | test | t | EXCLUSIVE | PENDING | 30 | 8 | truncate table t |
+-------------+---------------+-------------+---------------------+-------------+-----------+----------------+------------------+
3 rows in set (0.00 sec)
mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+------+---------+------+---------------------------------+------------------+
| 5 | root | localhost | test | Query | 0 | starting | show processlist |
| 8 | root | localhost | test | Query | 50 | Waiting for table metadata lock | truncate table t |
+----+------+-----------+------+---------+------+---------------------------------+------------------+
2 rows in set (0.00 sec)

As soon as I complete transaction where SELECT was executed, TRUNCATE completes and we see no pending metadata locks:

mysql> commit;
Query OK, 0 rows affected (0.00 sec)
mysql> 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();
Empty set (0.01 sec)
mysql> select * from t;
Empty set (0.00 sec)

To summarize, MySQL 5.7 allows you to study all metadata locks in detail. They are set for both transactional and non-transactional tables, but remember that if you use autocommit=0 or start transaction explicitly they are released only when commit happens, implicit or explicit. If you want single statement SELECT to not block any DDL after it is completed, make sure to COMMIT immediately or use autocommit=1.

We can surely call the behavior of metadata locks for this case a “bug” or file a “feature request” to change it, but for now any software that is supposed to work with MySQL 5.5.3+ should just take all implications of metadata locks into account.

The post More on (transactional) MySQL metadata locks appeared first on MySQL Performance Blog.

Powered by WordPress | Theme: Aeros 2.0 by TheBuckmaker.com