| Bug #115181 | performance_schema.metadata_locks table doesn't show EXCLUSIVE locks correctly | ||
|---|---|---|---|
| Submitted: | 31 May 2024 2:11 | Modified: | 3 Jun 2024 12:17 |
| Reporter: | Brian Yue (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Performance Schema | Severity: | S3 (Non-critical) |
| Version: | 8.0 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[31 May 2024 10:23]
MySQL Verification Team
Hi Mr. Yue, Thank you for your bug report. However, we were unable to repeat your report. We got the following output from the second connection which queried Performance_Schema. We have got the following output: ----------------------------------------- NOW() 2024-05-31 13:16:16 ERROR 1205 (HY000) at line 2: Lock wait timeout exceeded; try restarting transaction ----------------------------------------- Simply, you did not set DML lock properly, which is why this command: select NOW(); select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1'; had to wait for DML lock to be released. Can't repeat.
[31 May 2024 10:29]
Brian Yue
Hello, the query on performance_schema.metadata_locks is operated on connection 3 when query of connection 2 is blocking by DDL, which is described in section "How to repeat": -------- while 'select for update' is executing, operate session 3: [session 3] ysql> select NOW(); select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1';
[31 May 2024 10:34]
MySQL Verification Team
HI Mr. Yue, It is quite possible that we were not clear enough. Both statements in the connection 2 and connection 3 fail immediately with the same message.
[31 May 2024 11:01]
Brian Yue
Hello, Please try this method. Execute the following commands sequently in one shell (user and password to connect mysql server should be replaced): """ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "alter table t1 modify column c1 varchar(40);alter table t1 modify column c1 varchar(400);" > /dev/null 2>&1 & sleep 5; mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "set session lock_wait_timeout = 30;select * from t1 limit 1 for update;" > /dev/null 2>&1 & sleep 3; mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "select NOW(); select * from performance_schema.processlist where State like 'Waiting for table metadata lock'; select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1'; select * from performance_schema.processlist where State like 'Waiting for table metadata lock';" """ With these commands, I get the following result: [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "alter table t1 modify column c1 varchar(40);alter table t1 modify column c1 varchar(400);" > /dev/null 2>&1 & [1] 221577 [yxxdb_8031@localhost ~]$ [yxxdb_8031@localhost ~]$ sleep 5; [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "set session lock_wait_timeout = 30;select * from t1 limit 1 for update;" > /dev/null 2>&1 & [2] 221579 [yxxdb_8031@localhost ~]$ [yxxdb_8031@localhost ~]$ sleep 3; [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "select NOW(); select * from performance_schema.processlist where State like 'Waiting for table metadata lock'; select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1'; select * from performance_schema.processlist where State like 'Waiting for table metadata lock';" mysql: [Warning] Using a password on the command line interface can be insecure. +---------------------+ | NOW() | +---------------------+ | 2024-05-31 18:34:59 | +---------------------+ +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | EXECUTION_ENGINE | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | 52 | root | localhost | ddl | Query | 3 | Waiting for table metadata lock | select * from t1 limit 1 for update | PRIMARY | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | OWNER_THREAD_ID | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | TABLE | ddl | t1 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 117 | | TABLE | ddl | t1 | SHARED_WRITE | TRANSACTION | PENDING | 118 | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | EXECUTION_ENGINE | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | 52 | root | localhost | ddl | Query | 3 | Waiting for table metadata lock | select * from t1 limit 1 for update | PRIMARY | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ It can be seen that the status of query "select * from t1 limit 1 for update" is firstly checked as "Waiting for table metadata lock", then no EXCLUSIVE lock is observed from performance_schema.metadata_locks, after which status of slect qeury is again checked as "Waiting for table metadata lock". It meens that when SHARED_WRITE of select query is blocked by other MDL, but no EXCLUSIVE lock is observed. Please try again, thanks a lot.
[31 May 2024 12:04]
MySQL Verification Team
Hi Mr. Yue, Thank you for your comments. Please read the chapter on the ALTER TABLE in our Reference Manual. It clearly states that EXCLUSIVE metadata lock is not taken with the ALTER TABLE syntax that you used. That is why used ALTER TABLE with the options that take metadata lock. Hence, what you are reporting is expected behaviour. Thanks a lot for your efforts.
[3 Jun 2024 1:37]
Brian Yue
Hello, I improved my test case, "algorithm=COPY,LOCK=EXCLUSIVE" clause is used so that EXCLUSIVE is taken for each execution. The new test case is followed: """ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "alter table t1 modify column c1 varchar(40), algorithm=COPY,LOCK=EXCLUSIVE ;" > /dev/null 2>&1 & sleep 5; mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "set session lock_wait_timeout = 30;select * from t1 limit 1 for update;" > /dev/null 2>&1 & sleep 3; mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "select NOW(); select * from performance_schema.processlist where State like 'Waiting for table metadata lock'; select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1' and OBJECT_TYPE='TABLE'; select * from performance_schema.processlist where State like 'Waiting for table metadata lock';" """ With these commands, I get the following result: """ [yxxdb_8031@localhost ~]$ [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "alter table t1 modify column c1 varchar(40), algorithm=COPY,LOCK=EXCLUSIVE ;" > /dev/null 2>&1 & [2] 304162 [yxxdb_8031@localhost ~]$ [yxxdb_8031@localhost ~]$ sleep 5; [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "set session lock_wait_timeout = 30;select * from t1 limit 1 for update;" > /dev/null 2>&1 & [3] 304164 [yxxdb_8031@localhost ~]$ [yxxdb_8031@localhost ~]$ sleep 3; [2]- Exit 1 mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "alter table t1 modify column c1 varchar(40), algorithm=COPY,LOCK=EXCLUSIVE ;" > /dev/null 2>&1 [yxxdb_8031@localhost ~]$ mysql -uroot -p'db1x@NJ+1' -S bin/mysql1.sock ddl -e "select NOW(); select * from performance_schema.processlist where State like 'Waiting for table metadata lock'; select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1' and OBJECT_TYPE='TABLE'; select * from performance_schema.processlist where State like 'Waiting for table metadata lock';" mysql: [Warning] Using a password on the command line interface can be insecure. +---------------------+ | NOW() | +---------------------+ | 2024-06-03 09:05:43 | +---------------------+ +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | EXECUTION_ENGINE | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | 71 | root | localhost | ddl | Query | 3 | Waiting for table metadata lock | select * from t1 limit 1 for update | PRIMARY | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | OWNER_THREAD_ID | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | TABLE | ddl | t1 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 133 | | TABLE | ddl | t1 | SHARED_WRITE | TRANSACTION | PENDING | 137 | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | EXECUTION_ENGINE | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ | 71 | root | localhost | ddl | Query | 3 | Waiting for table metadata lock | select * from t1 limit 1 for update | PRIMARY | +----+------+-----------+------+---------+------+---------------------------------+-------------------------------------+------------------+ [yxxdb_8031@localhost ~]$ """ So the "select for update" statement is always waiting for table metadata lock (it must be the DDL statement holds a MDL lock that is in conflict with SHARED_WRITE which is aquiring by select statement), and actually we can observe only SHARED_UPGRADABLE LOCK on table t1, which is absolutely not in conflict with SHARED_WRITE LOCK. As a predict, the DDL holds EXCLUSIVE medata lock, but is't not shown in performance_schema.metadata_locks system table.
[3 Jun 2024 9:58]
MySQL Verification Team
Hi Mr. Yue, We have tried to repeat your report , but without success. We reduced those sleeping times and the other locks waiting did show up .....
[3 Jun 2024 11:59]
Brian Yue
Hello,
Thanks for your job sincerely. Now here is a simpler way to demonstrate the problem I'm talking.
[session 1]
mysql> desc t1;
+-------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-------+-------------+------+-----+---------+-------+
| c1 | varchar(40) | YES | | NULL | |
+-------+-------------+------+-----+---------+-------+
1 row in set (0.01 sec)
mysql> select count(*) from t1;
+----------+
| count(*) |
+----------+
| 27630793 |
+----------+
1 row in set (1.45 sec)
mysql> alter table t1 modify column c1 varchar(40), algorithm=COPY,LOCK=EXCLUSIVE ;
-----------------------------------------------------------------------
while the alter table statement is in execution, operate session 2:
-----------------------------------------------------------------------
[session 2]
mysql> set session lock_wait_timeout = 3;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into ddl.t1 values ('A');
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql> select * from performance_schema.metadata_locks where OBJECT_NAME like '%t1%';
+-------------+---------------+-------------+-------------+-----------------------+---------------------+---------------+-------------+-------------------+-----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | COLUMN_NAME | OBJECT_INSTANCE_BEGIN | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | SOURCE | OWNER_THREAD_ID | OWNER_EVENT_ID |
+-------------+---------------+-------------+-------------+-----------------------+---------------------+---------------+-------------+-------------------+-----------------+----------------+
| TABLE | ddl | t1 | NULL | 140163908904368 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | sql_parse.cc:6141 | 268119 | 15 |
| TABLESPACE | NULL | ddl/t1 | NULL | 140163909509600 | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | lock.cc:806 | 268119 | 15 |
+-------------+---------------+-------------+-------------+-----------------------+---------------------+---------------+-------------+-------------------+-----------------+----------------+
2 rows in set (0.00 sec)
mysql> insert into ddl.t1 values ('A');
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
So, in this case EXCLUSIVE lock is taken and concurrent DML is blocked (failed with error : ERROR 1205 (HY000): Lock wait timeout exceeded). Between the failed twice DML we check the performance_schema.metadata_locks table, and no EXCLUSIVE mdl lock is observed, which is impossible because there must be some lock that is in conflict with insert operation, and it's sure that EXCLUSIVE is taken due to LOCK=EXCLUSIVE clause.
Thanks again for your effort.
[3 Jun 2024 12:17]
MySQL Verification Team
Hi Mr. Yue, We have managed to repeat your latest test case. This is now a verified bug for the version 8.0 and above.
[3 Jun 2024 12:18]
MySQL Verification Team
Hi, We just had to change your OS/CPU comments, since those would just decrease the severity of the bug report. Thanks again.
Description: Hello, Recently we find a case that EXCLUSIVE metadata lock is not shown correctly during execution of DDL that is not online. Detail of the case: (1) firstly a big table with varchar field is created: create table t1 (c1 varchar(40) charset utf8mb4); (2) fill the table with 27630792 records: mysql> insert into t1 values ('A'),('A'),('A'),('A'),('A'),('A'),('A'),('A'); Query OK, 8 rows affected (0.01 sec) Records: 8 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 64 rows affected (0.00 sec) Records: 64 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 5184 rows affected (0.03 sec) Records: 5184 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 27625536 rows affected (1 min 56.49 sec) Records: 27625536 Duplicates: 0 Warnings: 0 (3) execute a DDL which is not online so that EXCLUSIVE MDL should be hold all time select NOW(); alter table t1 modify column c1 varchar(400); select NOW(); (4) during the execution of DDL, execute a select for update statement with another session, and it's expected to be blocked by DDL (DDL holds EXCLUSIVE MDL, and select for update statement should fail to aquire SHARED_WRITE MDL finally): set session lock_wait_timeout = 30; select NOW(); select * from t1 limit 1 for update; select NOW(); (5) during 'select for update' stamtement is blocked by DDL, check the performance_schema.metadata_locks table: mysql> select NOW(); select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1'; +---------------------+ | NOW() | +---------------------+ | 2024-05-31 09:21:17 | +---------------------+ 1 row in set (0.00 sec) +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | OWNER_THREAD_ID | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | TABLE | ddl | t1 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 72 | | TABLE | ddl | t1 | SHARED_WRITE | TRANSACTION | PENDING | 75 | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ 2 rows in set (0.00 sec) two mdl is observed: 1. a granted SHARED_UPGRADABLE that is aquired by DDL 2. a pending SHARED_WRITE that is aquiring by 'select for update', which is not granted now actually a granted EXCLUSIVE aquired by DDL should be seen, instead of SHARED_UPGRADABLE. because now SHARED_WRITE is blocked by other locks and shows PENDING status, I believe that EXCLUSIVE lock must have been aquired suceessfully by DDL. And it's confused that EXCLUSIVE lock on table ddl.t1 is not shown by performance_schema.metadata_locks. How to repeat: [session 1] mysql> create database ddl; Query OK, 1 row affected (0.00 sec) mysql> create table t1 (c1 varchar(40) charset utf8mb4); Query OK, 0 rows affected (0.01 sec) mysql> insert into t1 values ('A'),('A'),('A'),('A'),('A'),('A'),('A'),('A'); Query OK, 8 rows affected (0.01 sec) Records: 8 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 64 rows affected (0.00 sec) Records: 64 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 5184 rows affected (0.03 sec) Records: 5184 Duplicates: 0 Warnings: 0 mysql> insert into t1 select a.c1 from t1 a join t1 b; Query OK, 27625536 rows affected (1 min 56.49 sec) Records: 27625536 Duplicates: 0 Warnings: 0 # check current time and start DDL immediately mysql> select NOW(); alter table t1 modify column c1 varchar(400); select NOW(); +---------------------+ | NOW() | +---------------------+ | 2024-05-31 09:20:24 | +---------------------+ 1 row in set (0.00 sec) while DDL is executing, operate session 2: [session 2] mysql> set session lock_wait_timeout = 30; Query OK, 0 rows affected (0.00 sec) mysql> select NOW(); select * from t1 limit 1 for update; select NOW(); +---------------------+ | NOW() | +---------------------+ | 2024-05-31 09:20:28 | +---------------------+ 1 row in set (0.00 sec) while 'select for update' is executing, operate session 3: [session 3] ysql> select NOW(); select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,LOCK_TYPE,LOCK_DURATION,LOCK_STATUS,OWNER_THREAD_ID from performance_schema.metadata_locks where OBJECT_NAME = 't1'; +---------------------+ | NOW() | +---------------------+ | 2024-05-31 09:21:17 | +---------------------+ 1 row in set (0.00 sec) +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | OWNER_THREAD_ID | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ | TABLE | ddl | t1 | SHARED_UPGRADABLE | TRANSACTION | GRANTED | 72 | | TABLE | ddl | t1 | SHARED_WRITE | TRANSACTION | PENDING | 75 | +-------------+---------------+-------------+-------------------+---------------+-------------+-----------------+ 2 rows in set (0.00 sec) A granted EXCLUSIVE lock is expected to be observed, actually it's not. Suggested fix: performance_schema.metadata_locks shows granted EXCLUSIVE lock correctly during DDL execution.