How to solve MySQL innodb "Waiting for table metadata lock" on TRUNCATE TABLE?

Question

Running a test suite with hundreds of application unit tests in a GitLab CI server. After ran 10 tests in, somehow it always gets stuck on Waiting for table metadata lock on TRUNCATE TABLE, which is a tearDown step.

I am aware of the SHOW ENGINE INNODB STATUS command . Here are some diagnostic logs:

mysql> \s
--------------
mysql  Ver 14.14 Distrib 5.6.30, for Linux (x86_64) using  EditLine wrapper

Connection id:      190
Current database:   
Current user:       root@localhost
SSL:            Not in use
Current pager:      stdout
Using outfile:      ''
Using delimiter:    ;
Server version:     5.6.30 MySQL Community Server (GPL)
Protocol version:   10
Connection:     Localhost via UNIX socket
Server characterset:    utf8mb4
Db     characterset:    utf8mb4
Client characterset:    utf8mb4
Conn.  characterset:    utf8mb4
UNIX socket:        /var/run/mysqld/mysqld.sock
Uptime:         51 min 28 sec

Threads: 4  Questions: 3859  Slow queries: 0  Opens: 715  Flush tables: 1  Open tables: 131  Queries per second avg: 1.249
--------------

mysql> show processlist;
+-----+------+----------------+------------+---------+------+---------------------------------+-----------------------------+
| Id  | User | Host           | db         | Command | Time | State                           | Info                        |
+-----+------+----------------+------------+---------+------+---------------------------------+-----------------------------+
|   1 | root | 10.0.2.1:52773 | test_3926  | Query   | 2961 | Waiting for table metadata lock | TRUNCATE TABLE `capability` |
| 188 | root | 10.0.2.1:53658 | test_3926  | Sleep   | 2962 |                                 | NULL                        |
| 189 | root | 10.0.2.1:53660 | test_3926  | Sleep   | 2962 |                                 | NULL                        |
| 190 | root | localhost      | NULL       | Query   |    0 | init                            | show processlist            |
+-----+------+----------------+------------+---------+------+---------------------------------+-----------------------------+
4 rows in set (0.00 sec)


2016-05-18 16:10:37 7f03be9ba700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 126 srv_active, 0 srv_shutdown, 3047 srv_idle
srv_master_thread log flush and writes: 3173
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2408
OS WAIT ARRAY INFO: signal count 2525
Mutex spin waits 988, rounds 24557, OS waits 747
RW-shared spins 1339, rounds 45580, OS waits 1518
RW-excl spins 3, rounds 5283, OS waits 113
Spin rounds per wait: 24.86 mutex, 34.04 RW-shared, 1761.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 7574
Purge done for trx's n:o < 7493 undo n:o < 0 state: running but idle
History list length 778
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 190, OS thread handle 0x7f03be9ba700, query id 3941 localhost root init
SHOW ENGINE INNODB STATUS
---TRANSACTION 7489, not started
MySQL thread id 188, OS thread handle 0x7f03bea3c700, query id 3824 10.0.2.1 root cleaning up
---TRANSACTION 7548, not started
MySQL thread id 1, OS thread handle 0x7f03bea7d700, query id 3855 10.0.2.1 root Waiting for table metadata lock
TRUNCATE TABLE `capability`
---TRANSACTION 7490, ACTIVE 3047 sec
MySQL thread id 189, OS thread handle 0x7f03be9fb700, query id 3840 10.0.2.1 root cleaning up
Trx read view will not see trx with id >= 7491, sees < 7491
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
173 OS file reads, 6858 OS file writes, 6022 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 276671, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 10549488
Log flushed up to   10549488
Pages flushed up to 10549488
Last checkpoint at  10549488
0 pending log writes, 0 pending chkp writes
2555 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 545426
Buffer pool size   8191
Free buffers       7354
Database pages     835
Old database pages 288
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4257, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 160, created 4341, written 863
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: 835, 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
1 read views open inside InnoDB
Main thread process no. 1, id 139654053570304, state: sleeping
Number of rows inserted 1187, updated 37, deleted 0, read 650
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT

Now my question is, why TRUNCATE table would get stuck on table metalock? And how can this be resolved?

Answer 1

The question is already well answered by @Michael - sqlbot but I want to add some additional details. You can look through it why thread id 189 is waiting for this long.

The Waiting for table metadata lock may occur when we DELETE or CREATE an index and modify the table’s structure.

It can also occur when we perform maintenance operations on tables, DELETE tables, or try to access the WRITE lock on table-level (using this query LOCK TABLE table_name WRITE;). Different types of active transactions can lead to metadata lock waits. Some cases are listed below where the metadata lock wait can occur.

Query to a table that has been present for a long period. Failed to COMMIT or ROLLBACK the transaction opened implicitly or explicitly. When we have an unsuccessful query transaction on a table.

Truncate lock bug can also occur if you have a large buffer pool, you may have noticed a complete server lock-up or stall of multiple seconds. You can find more information how this bug occur in this MySQL troubleshooting article.

Answer 2

The problem here seems straightforward enough.

---TRANSACTION 7490, ACTIVE 3047 sec
MySQL thread id 189, OS thread handle 0x7f03be9fb700, query id 3840 10.0.2.1 root cleaning up
Trx read view will not see trx with id >= 7491, sees < 7491
---

Thread 189 (a client connection) is idle, and as been for a while, but it has left a transaction running. This is probably a bug in the code that's using the database, since it doesn't make sense to leave a running transaction going for almost an hour.

mysql> KILL 189;

That should release the metadata lock... but you need to find out why this is happening. Bad Things™ will happen if an application doesn't behave better than this.

Also... your application should not be connecting as root. Not related to the problem, but not good, if that's what this is.