Mysql DDL 查询在包裹在事务中时卡在等待 table 元数据锁定
Mysql DDL query stuck in Waiting for table metadata lock when wrapped in transaction
这是一个随机行为（在重新启动 mysql 会话后没有再次发生），当我将 DDL 查询包装在事务 T1 中并同时启动另一个事务 T2 时 select 查询相同 table，DDL 查询卡住等待 table 元数据锁定，这是预期的，任何其他 select 查询等待 DDL 查询完成。但是在提交 T2 之后，DDL 应该获得元数据锁定并完成，但它仍在等待 table 元数据锁定状态。
连接 1 查询：
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> ALTER TABLE merchants ADD COLUMN temp6 varchar(255);
连接 2 查询：
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> select * from merchants where account_id=null;
Empty set (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (0.00 sec)
查询顺序为：
- 连接 1：开始；
- 连接 2：开始；
- 连接 2：select * 来自 account_id=null 的商家；
- 连接 1：更改 TABLE 商家添加列 temp6 varchar(255)；
- 连接 2：提交；
Server version: 8.0.13 MySQL Community Server - GPL
mysql> select @@autocommit;
+--------------+
| @@autocommit |
+--------------+
| 1 |
+--------------+
1 row in set (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();
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_STATUS | THREAD_ID | PROCESSLIST_ID | PROCESSLIST_INFO |
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
| GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| SCHEMA | merchant_onboarding_dev | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | merchants | SHARED_UPGRADABLE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| BACKUP LOCK | NULL | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLESPACE | NULL | merchant_onboarding_dev/merchants | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | #sql-63_57 | EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | merchants | EXCLUSIVE | PENDING | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
7 rows in set (0.00 sec)
mysql> show full processlist;
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
| 4 | event_scheduler | localhost | NULL | Daemon | 115824 | Waiting on empty queue | NULL |
| 62 | root | localhost:59116 | merchant_onboarding_dev | Sleep | 107 | | NULL |
| 63 | root | localhost:59117 | merchant_onboarding_dev | Sleep | 107 | | NULL |
| 65 | root | localhost:59119 | NULL | Sleep | 1 | | NULL |
| 79 | root | localhost | merchant_onboarding_dev | Query | 0 | starting | show full processlist |
| 81 | root | localhost | merchant_onboarding_dev | Sleep | 838 | | NULL |
| 83 | root | localhost | merchant_onboarding_dev | Sleep | 821 | | NULL |
| 87 | root | localhost | merchant_onboarding_dev | Query | 842 | Waiting for table metadata lock | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
8 rows in set (0.00 sec)
mysql> SHOW ENGINE INNODB STATUS;
=====================================
2019-04-08 02:30:45 0x700006ef3000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 242 srv_active, 0 srv_shutdown, 73418 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 87
OS WAIT ARRAY INFO: signal count 516
RW-shared spins 722, rounds 723, OS waits 1
RW-excl spins 1110, rounds 3537, OS waits 28
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1.00 RW-shared, 3.19 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 15753
Purge done for trx's n:o < 15749 undo n:o < 0 state: running but idle
History list length 11
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281479647891952, not started
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647891040, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647893776, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647892864, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647890128, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647889216, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
950 OS file reads, 52924 OS file writes, 40911 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 7 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 89894761
Log buffer assigned up to 89894761
Log buffer completed up to 89894761
Log written up to 89894761
Log flushed up to 89894761
Added dirty pages up to 89894761
Pages flushed up to 89894761
Last checkpoint at 89894761
42886 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 1037251
Buffer pool size 8191
Free buffers 3332
Database pages 4835
Old database pages 1764
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 634, not young 1
0.00 youngs/s, 0.00 non-youngs/s
Pages read 911, created 3927, written 8771
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 4835, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=99, Main thread ID=0x700006689000 , state=sleeping
Number of rows inserted 176434, updated 4249, deleted 10814, read 2383183
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
我无法理解的是为什么 DDL 查询一直在等待 table 元数据锁，即使持有锁的事务已提交。
在 MySQL 中，大多数 DDL 语句实际上会生成一个 隐式提交 。 ALTER TABLE 语句属于这一类。来自 the documentation:
The statements listed in this section (and any synonyms for them) implicitly end any transaction active in the current session, as if you had done a COMMIT before executing the statement.
Most of these statements also cause an implicit commit after executing.
这个 internal documentation 进入了更多细节......事情往往会变得混乱：
In addition, some DDL statements issue interim transaction commits: for example, ALTER TABLE issues a commit after data is copied from the original table to the internal temporary table.
因此，当您执行 ALTER TABLE 时，MySQL 会隐式尝试在语句中提交，但不能，因为另一个事务正在进行中。该文档并未准确涵盖此用例，但我怀疑服务器未正确处理这种情况，并生成了您所看到的奇怪行为。文档本身指出这种类型的行为定义不当。
底线：当 运行 一个 ALTER TABLE 语句时，您不能依赖事务来处理并发。因此，您不想 ALTER 一个 table 而它正忙于其他事务：这是不安全的。在 运行 这样的语句之前，您要确保没有在 table 上设置锁。是的，在处理类似生产的数据库时，这肯定会带来痛苦的限制，但看起来 MySQL 就是这样做的...
这是一个随机行为（在重新启动 mysql 会话后没有再次发生），当我将 DDL 查询包装在事务 T1 中并同时启动另一个事务 T2 时 select 查询相同 table，DDL 查询卡住等待 table 元数据锁定，这是预期的，任何其他 select 查询等待 DDL 查询完成。但是在提交 T2 之后，DDL 应该获得元数据锁定并完成，但它仍在等待 table 元数据锁定状态。
连接 1 查询：
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> ALTER TABLE merchants ADD COLUMN temp6 varchar(255);
连接 2 查询：
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> select * from merchants where account_id=null;
Empty set (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (0.00 sec)
查询顺序为：
- 连接 1：开始；
- 连接 2：开始；
- 连接 2：select * 来自 account_id=null 的商家；
- 连接 1：更改 TABLE 商家添加列 temp6 varchar(255)；
- 连接 2：提交；
Server version: 8.0.13 MySQL Community Server - GPL
mysql> select @@autocommit;
+--------------+
| @@autocommit |
+--------------+
| 1 |
+--------------+
1 row in set (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();
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE | LOCK_STATUS | THREAD_ID | PROCESSLIST_ID | PROCESSLIST_INFO |
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
| GLOBAL | NULL | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| SCHEMA | merchant_onboarding_dev | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | merchants | SHARED_UPGRADABLE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| BACKUP LOCK | NULL | NULL | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLESPACE | NULL | merchant_onboarding_dev/merchants | INTENTION_EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | #sql-63_57 | EXCLUSIVE | GRANTED | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
| TABLE | merchant_onboarding_dev | merchants | EXCLUSIVE | PENDING | 126 | 87 | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
+-------------+-------------------------+-----------------------------------+---------------------+-------------+-----------+----------------+-----------------------------------------------------+
7 rows in set (0.00 sec)
mysql> show full processlist;
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
| 4 | event_scheduler | localhost | NULL | Daemon | 115824 | Waiting on empty queue | NULL |
| 62 | root | localhost:59116 | merchant_onboarding_dev | Sleep | 107 | | NULL |
| 63 | root | localhost:59117 | merchant_onboarding_dev | Sleep | 107 | | NULL |
| 65 | root | localhost:59119 | NULL | Sleep | 1 | | NULL |
| 79 | root | localhost | merchant_onboarding_dev | Query | 0 | starting | show full processlist |
| 81 | root | localhost | merchant_onboarding_dev | Sleep | 838 | | NULL |
| 83 | root | localhost | merchant_onboarding_dev | Sleep | 821 | | NULL |
| 87 | root | localhost | merchant_onboarding_dev | Query | 842 | Waiting for table metadata lock | ALTER TABLE merchants ADD COLUMN temp6 varchar(255) |
+----+-----------------+-----------------+-------------------------+---------+--------+---------------------------------+-----------------------------------------------------+
8 rows in set (0.00 sec)
mysql> SHOW ENGINE INNODB STATUS;
=====================================
2019-04-08 02:30:45 0x700006ef3000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 242 srv_active, 0 srv_shutdown, 73418 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 87
OS WAIT ARRAY INFO: signal count 516
RW-shared spins 722, rounds 723, OS waits 1
RW-excl spins 1110, rounds 3537, OS waits 28
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1.00 RW-shared, 3.19 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 15753
Purge done for trx's n:o < 15749 undo n:o < 0 state: running but idle
History list length 11
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281479647891952, not started
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647891040, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647893776, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647892864, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647890128, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479647889216, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
950 OS file reads, 52924 OS file writes, 40911 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 7 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 89894761
Log buffer assigned up to 89894761
Log buffer completed up to 89894761
Log written up to 89894761
Log flushed up to 89894761
Added dirty pages up to 89894761
Pages flushed up to 89894761
Last checkpoint at 89894761
42886 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 1037251
Buffer pool size 8191
Free buffers 3332
Database pages 4835
Old database pages 1764
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 634, not young 1
0.00 youngs/s, 0.00 non-youngs/s
Pages read 911, created 3927, written 8771
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 4835, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=99, Main thread ID=0x700006689000 , state=sleeping
Number of rows inserted 176434, updated 4249, deleted 10814, read 2383183
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
我无法理解的是为什么 DDL 查询一直在等待 table 元数据锁，即使持有锁的事务已提交。
在 MySQL 中，大多数 DDL 语句实际上会生成一个 隐式提交 。 ALTER TABLE 语句属于这一类。来自 the documentation:
The statements listed in this section (and any synonyms for them) implicitly end any transaction active in the current session, as if you had done a COMMIT before executing the statement.
Most of these statements also cause an implicit commit after executing.
这个 internal documentation 进入了更多细节......事情往往会变得混乱：
In addition, some DDL statements issue interim transaction commits: for example,
ALTER TABLEissues a commit after data is copied from the original table to the internal temporary table.
因此，当您执行 ALTER TABLE 时，MySQL 会隐式尝试在语句中提交，但不能，因为另一个事务正在进行中。该文档并未准确涵盖此用例，但我怀疑服务器未正确处理这种情况，并生成了您所看到的奇怪行为。文档本身指出这种类型的行为定义不当。
底线：当 运行 一个 ALTER TABLE 语句时，您不能依赖事务来处理并发。因此，您不想 ALTER 一个 table 而它正忙于其他事务：这是不安全的。在 运行 这样的语句之前，您要确保没有在 table 上设置锁。是的，在处理类似生产的数据库时，这肯定会带来痛苦的限制，但看起来 MySQL 就是这样做的...