In this post, we will learn about the tools available to investigate issues with InnoDB locks preventing queries to run.
The two commands that can be used in all versions of MySQL to investigate locks preventing InnoDB queries to proceed are SHOW [FULL] PROCESSLIST and SHOW ENGINE INNODB STATUS. Additionally in MySQL 5.1 using InnoDB Plugin and in MySQL 5.5 and later, it is possible to use the InnoDB tables in the Information Schema to get details about InnoDB locks. Each of these methods will be discussed below.
SHOW [FULL] PROCESSLIST
The process list output is the most basic tool for investigating InnoDB locking issues. For example:
mysql> SHOW PROCESSLIST; +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------+ | 1 | event_scheduler | localhost | NULL | Daemon | 4 | Waiting for next activation | NULL | | 328 | root | localhost | locktest | Sleep | 222 | | NULL | | 332 | root | localhost | locktest | Query | 38 | updating | UPDATE t1 SET val = 'c2' WHERE id = 3 | | 340 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST | +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------+ 4 rows in set (0.00 sec)
So in this case it is suspicious that a single row update using the PRIMARY KEY (the t1.id column) to find the row is taking 38 seconds. Candidate queries that can be preventing the UPDATE to proceed will at least have to be older than the time the UPDATE has been waiting, however that can be difficult to determine from the process list. The issue is that InnoDB is transactional, which means that it may not be a query running right now that holds the lock. For example taking the following output:
mysql> SHOW PROCESSLIST; +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------------+ | 1 | event_scheduler | localhost | NULL | Daemon | 0 | Waiting for next activation | NULL | | 328 | root | localhost | locktest | Query | 1 | User sleep | SELECT COUNT(*) FROM t1 WHERE 0 = SLEEP(10) | | 332 | root | localhost | locktest | Query | 40 | updating | UPDATE t1 SET val = 'c2' WHERE id = 3 | | 340 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST | +-----+-----------------+-----------+----------+---------+------+-----------------------------+---------------------------------------------+ 4 rows in set (0.00 sec)
This is the same example from above, but the connection with Id = 328 has not started to run another query. So where in the first output it was possible to use the Time column to order the queries, in the second output the Id column appears to be a better candidate. However even that may be too simple: While the Id column will tell which order the connections were made, it is the order the locks were taken. This is simply not possible to determine from the process list, so at best the SHOW PROCESSLIST output can be used to give a hint of what is going on.
However in combination with the output of SHOW ENGINE INNODB STATUS, it can provide valuable information.
SHOW ENGINE INNODB STATUS
The InnoDB status output is much better than the process list to give insight into which transactions are holding locks. Continuing the example from above, the output can look like:
mysql> SHOW ENGINE INNODB STATUS\G *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2013-02-25 11:05:21 7f5d5b6cd700 INNODB MONITOR OUTPUT ===================================== ... ------------ TRANSACTIONS ------------ Trx id counter 497211 Purge done for trx's n:o < 497201 undo n:o < 0 state: running but idle History list length 1484 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0, not started MySQL thread id 340, OS thread handle 0x7f5d5b6cd700, query id 20971 localhost root init SHOW ENGINE INNODB STATUS ---TRANSACTION 497138, ACTIVE 47 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 332, OS thread handle 0x7f5d5b70e700, query id 20559 localhost root updating UPDATE t1 SET val = 'c2' WHERE id = 3 ------- TRX HAS BEEN WAITING 47 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 32 page no 3 n bits 96 index `PRIMARY` of table `locktest`.`t1` trx id 497138 lock_mode X locks rec but not gap waiting Record lock, heap no 28 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 4; hex 00000003; asc ;; 1: len 6; hex 0000000791e6; asc ;; 2: len 7; hex 5100000039232c; asc Q 9#,;; 3: len 2; hex 6331; asc c1;; ------------------ ---TRANSACTION 496102, ACTIVE 600 sec mysql tables in use 1, locked 0 2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1 MySQL thread id 328, OS thread handle 0x7f5d5b74f700, query id 20879 localhost root User sleep SELECT COUNT(*) FROM t1 WHERE 0 = SLEEP(10) Trx read view will not see trx with id >= 497195, sees < 497138 ...
From this output, it is possible to see which lock the 'UPDATE t1 SET val = 'c2' WEHRE id = 3' query is waiting for, and it is possible to see that there is a transaction that has been active for 600 seconds that holds one lock (see 1 row locks(s), undo log entries 1). So this identifies the transaction holding the lock.
The details in the transaction list also reveals the MySQL thread id (328 for the transaction holding the lock). You can use this information to go back to the process list output and see for example the username and host for the connection holding the lock.
To get InnoDB to include information about locks where there are currently no conflict, you must enabled the innodb_status_output_locks option:
mysql> SET GLOBAL innodb_status_output_locks = ON; Query OK, 0 rows affected (0.00 sec)
Sys Schema
In MySQL 5.6 and later you can use the innodb_lock_waits view in the sys schema to find the transactions waiting for locks and the transactions holding the blocking locks.
The sys schema is installed by default in MySQL 5.7 and later. In MySQL 5.6 you will need to install it manually. The innodb_lock_waits view uses the same Information Schema tables as discussed below.
To find all current cases of which transactions are waiting for locks and who is blocking, you can use:
mysql> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1. row ***************************
wait_started: 2019-05-20 08:25:11
wait_age: 00:00:09
wait_age_secs: 9
locked_table: `world`.`city`
locked_table_schema: world
locked_table_name: city
locked_table_partition: NULL
locked_table_subpartition: NULL
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 6419
waiting_trx_started: 2019-05-20 08:25:11
waiting_trx_age: 00:00:09
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 10
waiting_query: UPDATE world.city SET Population = Population + 1 WHERE ID = 130
waiting_lock_id: 139676533684912:3:7:41:139676430164472
waiting_lock_mode: X,REC_NOT_GAP
blocking_trx_id: 6415
blocking_pid: 9
blocking_query: NULL
blocking_lock_id: 139676533684016:3:7:41:139676430158520
blocking_lock_mode: X,REC_NOT_GAP
blocking_trx_started: 2019-05-20 08:20:56
blocking_trx_age: 00:04:24
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 9
sql_kill_blocking_connection: KILL 9
1 row in set (0.00 sec)
In the above example blocking_query is NULL. This is because the transaction holding the lock is currently not executing any query. In MySQL 5.6 and later, the most recently executed query can be found in the performance_schema.events_statements_current table and older queries using the statements history tables. See also Performance Schema Statement Event Tables in the Reference Manual.
The queries will by default be truncated to 64 characters or as configured with the statement_truncate_len Sys Schema option. To change the truncation cutoff for the session set the @sys.statement_truncate_len user variable, for example:
mysql> SET @sys.statement_truncate_len = 16;
Query OK, 0 rows affected (0.00 sec)
mysql> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1. row ***************************
wait_started: 2019-05-20 08:25:11
wait_age: 00:00:20
wait_age_secs: 20
locked_table: `world`.`city`
locked_table_schema: world
locked_table_name: city
locked_table_partition: NULL
locked_table_subpartition: NULL
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 6419
waiting_trx_started: 2019-05-20 08:25:11
waiting_trx_age: 00:00:20
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 10
waiting_query: UPDATE ... = 130
waiting_lock_id: 139676533684912:3:7:41:139676430164472
waiting_lock_mode: X,REC_NOT_GAP
blocking_trx_id: 6415
blocking_pid: 9
blocking_query: NULL
blocking_lock_id: 139676533684016:3:7:41:139676430158520
blocking_lock_mode: X,REC_NOT_GAP
blocking_trx_started: 2019-05-20 08:20:56
blocking_trx_age: 00:04:35
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 9
sql_kill_blocking_connection: KILL 9
1 row in set (0.00 sec)
To get the queries untruncated, use the the x$innodb_lock_waits view instead.
Performance Schema Lock Tables
In MySQL 8, the Information Schema tables with InnoDB locks that are described after this section were replaced with the data_locks and data_lock_waits tables in the Performance Schema. These are the tables that are used by the above sys.innodb_lock_waits view. In most cases, it is recommended to use the sys schema view as it is simpler to use. However, in some cases you may want to use the Performance Schema directly to get more details about locks.
The two tables for data locks are:
- data_locks: Contains the locks currently held.
- data_lock_waits: Contains information about the locks being waited for.
Unlike the Information Schema tables in 5.7 and earlier (see later), the data_locks table contains all currently held InnoDB locks. For example:
mysql> START TRANSACTION; Query OK, 0 rows affected (0.00 sec)
mysql> UPDATE world.city SET Population = Population + 1 WHERE ID = 130; Query OK, 1 row affected (0.01 sec) Rows matched: 1 Changed: 1 Warnings: 0
mysql> SELECT * FROM performance_schema.data_locks WHERE THREAD_ID = PS_CURRENT_THREAD_ID()\G
*************************** 1. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 139676533684016:1060:139676430161560
ENGINE_TRANSACTION_ID: 6413
THREAD_ID: 47
EVENT_ID: 15
OBJECT_SCHEMA: world
OBJECT_NAME: city
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139676430161560
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 2. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 139676533684016:3:7:41:139676430158520
ENGINE_TRANSACTION_ID: 6413
THREAD_ID: 47
EVENT_ID: 15
OBJECT_SCHEMA: world
OBJECT_NAME: city
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 139676430158520
LOCK_TYPE: RECORD
LOCK_MODE: X,REC_NOT_GAP
LOCK_STATUS: GRANTED
LOCK_DATA: 130
2 rows in set (0.00 sec)
The PS_CURRENT_THREAD_ID() function is available in MySQL 8.0.16 and later; before that use sys.ps_thread_id(NULL).
As it can be seen, the Performance Schema tables support other storage engines than InnoDB, but currently InnoDB is the only storage engine that has implemented support. You can see both the table level locks and the row level locks and whether gap mode is used. The LOCK_DATA column has the value that is used to determine which rows to lock. As the condition in the UPDATE query was WHERE ID = 130, LOCK_DATA has a value of 130 in this case.
To investigate why a lock wait occurs, you need to use the data_lock_waits table. You can join back on the data_locks table to get more information about the locks involved. There are two columns in data_lock_waits that effectively are foreign keys of the ENGINE_LOCK_ID column of the data_locks table:
- REQUESTING_ENGINE_LOCK_ID: This is the lock ID of the lock request that is waiting to be granted.
- BLOCKING_ENGINE_LOCK_ID: This is the lock ID of the lock that prevents the lock request to be granted.
An example of how to query for waiting locks (based on the sys.innodb_lock_waits view) is:
SELECT r.trx_wait_started AS wait_started,
TIMEDIFF(NOW(), r.trx_wait_started) AS wait_age,
TIMESTAMPDIFF(SECOND, r.trx_wait_started, NOW()) AS wait_age_secs,
CONCAT(sys.quote_identifier(rl.object_schema), '.', sys.quote_identifier(rl.object_name)) AS locked_table,
rl.object_schema AS locked_table_schema,
rl.object_name AS locked_table_name,
rl.partition_name AS locked_table_partition,
rl.subpartition_name AS locked_table_subpartition,
rl.index_name AS locked_index,
rl.lock_type AS locked_type,
r.trx_id AS waiting_trx_id,
r.trx_started as waiting_trx_started,
TIMEDIFF(NOW(), r.trx_started) AS waiting_trx_age,
r.trx_rows_locked AS waiting_trx_rows_locked,
r.trx_rows_modified AS waiting_trx_rows_modified,
r.trx_mysql_thread_id AS waiting_pid,
sys.format_statement(r.trx_query) AS waiting_query,
rl.engine_lock_id AS waiting_lock_id,
rl.lock_mode AS waiting_lock_mode,
b.trx_id AS blocking_trx_id,
b.trx_mysql_thread_id AS blocking_pid,
sys.format_statement(b.trx_query) AS blocking_query,
bl.engine_lock_id AS blocking_lock_id,
bl.lock_mode AS blocking_lock_mode,
b.trx_started AS blocking_trx_started,
TIMEDIFF(NOW(), b.trx_started) AS blocking_trx_age,
b.trx_rows_locked AS blocking_trx_rows_locked,
b.trx_rows_modified AS blocking_trx_rows_modified,
CONCAT('KILL QUERY ', b.trx_mysql_thread_id) AS sql_kill_blocking_query,
CONCAT('KILL ', b.trx_mysql_thread_id) AS sql_kill_blocking_connection
FROM performance_schema.data_lock_waits w
INNER JOIN information_schema.innodb_trx b ON b.trx_id = CAST(w.blocking_engine_transaction_id AS CHAR)
INNER JOIN information_schema.innodb_trx r ON r.trx_id = CAST(w.requesting_engine_transaction_id AS CHAR)
INNER JOIN performance_schema.data_locks bl ON bl.engine_lock_id = w.blocking_engine_lock_id
INNER JOIN performance_schema.data_locks rl ON rl.engine_lock_id = w.requesting_engine_lock_id
ORDER BY r.trx_wait_started;
Notice the last two joins between the data_lock_waits and the data_locks tables. The query also joins on the information_schema.innodb_trx view. That will be discussed in the next section.
InnoDB Information Schema Tables
With MySQL 5.1 using the InnoDB Plugin and in MySQL 5.5 and later, there is another way to obtain information about the locks. Three tables are of interest for investigating locks:
- INNODB_TRX: Contains information about the InnoDB transactions.
- strong>INNODB_LOCKS: Contains information about the following InnoDB lock:
- Locks that are requested and not yet acquired.
- Locks that are blocking other lock requests from being acquired.
- INNODB_LOCK_WAITS: Which locks are being requested but can't be granted because another transaction holds the lock.
In MySQL 5.1 with the InnoDB Plugin, the Information Schema tables are not enabled by default and must be enabled manually, for example setting the plugin-load configuration option like:
[mysqld] plugin-load = "innodb=ha_innodb_plugin.so;innodb_trx=ha_innodb_plugin.so;innodb_locks=ha_innodb_plugin.so;innodb_lock_waits=ha_innodb_plugin.so;innodb_cmp=ha_innodb_plugin.so;innodb_cmp_reset=ha_innodb_plugin.so;innodb_cmpmem=ha_innodb_plugin.so;innodb_cmpmem_reset=ha_innodb_plugin.so;innodb_buffer_page=ha_innodb_plugin.so;innodb_buffer_page_lru=ha_innodb_plugin.so;innodb_buffer_pool_stats=ha_innodb_plugin.so"
The value for plugin-load must all be on one line.
An advantage of the Information Schema tables over the process list and the InnoDB status output is that it is possible to write a query that directly gives information about the transactions and locks involved in a lock wait scenario. An example of such a query is:
SELECT r.trx_wait_started AS wait_started,
TIMEDIFF(NOW(), r.trx_wait_started) AS wait_age,
TIMESTAMPDIFF(SECOND, r.trx_wait_started, NOW()) AS wait_age_secs,
rl.lock_table AS locked_table,
rl.lock_index AS locked_index,
rl.lock_type AS locked_type,
r.trx_id AS waiting_trx_id,
r.trx_started as waiting_trx_started,
TIMEDIFF(NOW(), r.trx_started) AS waiting_trx_age,
r.trx_rows_locked AS waiting_trx_rows_locked,
r.trx_rows_modified AS waiting_trx_rows_modified,
r.trx_mysql_thread_id AS waiting_pid,
r.trx_query AS waiting_query,
rl.lock_id AS waiting_lock_id,
rl.lock_mode AS waiting_lock_mode,
b.trx_id AS blocking_trx_id,
b.trx_mysql_thread_id AS blocking_pid,
b.trx_query AS blocking_query,
bl.lock_id AS blocking_lock_id,
bl.lock_mode AS blocking_lock_mode,
b.trx_started AS blocking_trx_started,
TIMEDIFF(NOW(), b.trx_started) AS blocking_trx_age,
b.trx_rows_locked AS blocking_trx_rows_locked,
b.trx_rows_modified AS blocking_trx_rows_modified,
CONCAT('KILL QUERY ', b.trx_mysql_thread_id) AS sql_kill_blocking_query,
CONCAT('KILL ', b.trx_mysql_thread_id) AS sql_kill_blocking_connection
FROM information_schema.innodb_lock_waits w
INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id
INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id
INNER JOIN information_schema.innodb_locks bl ON bl.lock_id = w.blocking_lock_id
INNER JOIN information_schema.innodb_locks rl ON rl.lock_id = w.requested_lock_id
ORDER BY r.trx_wait_started\G
For the example discussed about, the output of this query will be:
*************************** 1. row ***************************
wait_started: 2015-11-24 11:29:48
wait_age: 00:00:04
wait_age_secs: 4
locked_table: `locktest`.`t1`
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 5399
waiting_trx_started: 2015-11-24 11:29:48
waiting_trx_age: 00:00:04
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 3
waiting_query: UPDATE t1 SET val = 'c2' WHERE id = 3
waiting_lock_id: 5399:45:3:6
waiting_lock_mode: X
blocking_trx_id: 5397
blocking_pid: 5
blocking_query: NULL
blocking_lock_id: 5397:45:3:6
blocking_lock_mode: X
blocking_trx_started: 2015-11-24 11:28:49
blocking_trx_age: 00:01:03
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 5
sql_kill_blocking_connection: KILL 5
1 row in set (0.00 sec)