• Skip to primary navigation
  • Skip to main content
  • Skip to primary sidebar
  • Skip to footer navigation

The Geek Diary

  • OS
    • Linux
    • CentOS/RHEL
    • Solaris
    • Oracle Linux
    • VCS
  • Interview Questions
  • Database
    • oracle
    • oracle 12c
    • ASM
    • mysql
    • MariaDB
  • DevOps
    • Docker
    • Shell Scripting
  • Big Data
    • Hadoop
    • Cloudera
    • Hortonworks HDP

How to Troubleshoot InnoDB Lock Issues

by admin

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
...
Note: The output of SHOW ENGINE INNODB STATUS varies between versions. The above output is from MySQL 5.6.10.

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)
Tip: If you are using Connector/J (JDBC), you can request to have the SHOW ENGINE INNODB STATUS output included in the exception message when there is a deadlock. To do that, set includeInnodbStatusInDeadlockExceptions=true when creating the connection. If you enable this, you may also want to consider enabling includeThreadNamesAsStatementComment.

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.

Note: The information_schema.INNODB_TRX table stores at most the first 1024 bytes of the query, so it is not possible to get more of the queries even with the x$innodb_lock_waits view.

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)
Removed: The InnoDB lock tables in the Information Schema has been removed as of MySQL 8 and replaced with tables in the Performance Schema (see above). In MySQL 5.6 and later with the sys schema installed, it is generally recommended to use the sys.innodb_lock_waits view instead. That view has been updated in MySQL 8, so it uses the new tables. See above for details of using the view. In MySQL 5.7.14 and later, the Information Schema tables will cause deprecation warnings. Those warnings are meant to ensure you are aware that in MySQL 8, you need to use the Performance Schema tables.

Filed Under: mysql

Some more articles you might also be interested in …

  1. MySQL – How to Set Maximum Rates for Connections and Queries
  2. MySQL Cluster Point-In-Time Recovery (PITR)
  3. MySQL : What is the Slow Query Log and How to Control Where the Log is Stored and What is Logged
  4. Can MySQL Cluster Run Multiple Nodes On a Single Server
  5. “Another MySQL daemon already running with the same unix socket” – error while starting MYSQL
  6. What’s a good process to find and eliminate slow queries in MySQL
  7. How to Create a MySQL Docker Container for Testing
  8. Changing the value of lower_case_table_names in MySQL 8
  9. What is the meaning of the TRX_TABLES_LOCKED column in the information_schema.INNODB_TRX MySQL table
  10. How to find Which Process Is Killing mysqld With SIGKILL or SIGTERM on Linux

You May Also Like

Primary Sidebar

Recent Posts

  • nixos-rebuild Command Examples in Linux
  • nixos-option: Command Examples in Linux
  • nixos-container : Command Examples in Linux
  • nitrogen Command Examples in Linux

© 2023 · The Geek Diary

  • Archives
  • Contact Us
  • Copyright