InnoDB Locks Analysis: Why is Blocking Query NULL and How To Find More Information About the Blocking Transaction?

This post was originally published on the MySQL Support Team Blog at https://blogs.oracle.com/mysqlsupport/entry/innodb_locks_analysis_why_is on 14 April 2017.

Consider the scenario that you execute a query. You expect it to be fast – typically subsecond – but now it take not return until after 50 seconds (innodb_lock_wait_timeout seconds) and then it returns with an error:

mysql> UPDATE world.City SET Population = Population + 999 WHERE ID = 130;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

You continue to investigate the issue using the sys.innodb_lock_waits view or the underlying Information Schema tables (INNODB_TRX, INNODB_LOCKS and INNODB_LOCK_WAITS).

Note

The above Information Schema tables with lock and lock waits information have been moved to the Performance Schema in 8.0 as the data_locks and data_lock_waits tables. The sys schema view however works the same.

However, when you query the locks information, the blocking query is returned as NULL. What does that mean and how to proceed from that to get information about the blocking transaction?

Setting Up an Example

Before proceeding, lets set up an example which will be investigated later in the blog. The example can be set up as (do not disconnect Connection 1 when the queries have been executed):

Step 1 – Connection 1:

Connection 1> START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 130;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 131;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 132;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 133;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Step 2 – Connection 2:

Connection 2> UPDATE world.City SET Population = Population + 999 WHERE ID = 130;

Step 3 – Connection 3:

The following output while Connection 2 is still blokcing from sys.innodb_lock_waits shows that the blocking query is NULL (slightly reformatted):

Connection 3> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1. row ***************************
                wait_started: 2017-04-15 09:54:53
                    wait_age: 00:00:03
               wait_age_secs: 3
                locked_table: `world`.`City`
                locked_index: PRIMARY
                 locked_type: RECORD
              waiting_trx_id: 2827
         waiting_trx_started: 2017-04-15 09:54:53
             waiting_trx_age: 00:00:03
     waiting_trx_rows_locked: 1
   waiting_trx_rows_modified: 0
                 waiting_pid: 5
               waiting_query: UPDATE world.City SET Populati ... opulation + 999
                              WHERE ID = 130
             waiting_lock_id: 2827:24:6:41
           waiting_lock_mode: X
             blocking_trx_id: 2826
                blocking_pid: 3
              blocking_query: NULL
            blocking_lock_id: 2826:24:6:41
          blocking_lock_mode: X
        blocking_trx_started: 2017-04-15 09:54:46
            blocking_trx_age: 00:00:10
    blocking_trx_rows_locked: 4
  blocking_trx_rows_modified: 4
     sql_kill_blocking_query: KILL QUERY 3
sql_kill_blocking_connection: KILL 3
1 row in set, 3 warnings (0.00 sec)

Connection 3> SHOW WARNINGS\G
*************************** 1. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCK_WAITS' is deprecated
         and will be removed in a future release.
*************************** 2. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCKS' is deprecated and
         will be removed in a future release.
*************************** 3. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCKS' is deprecated and
         will be removed in a future release. 3 rows in set (0.00 sec)

The warnings will only occur in the 5.7.14 and later as the InnoDB lock tables being moved to the Performance Schema in MySQL 8.0. It is recommended to use the sys.innodb_lock_waits view as that is updated accordingly in MySQL 8.0.

Investigating Idle Transactions

To investigate idle transactions, you need to use the Performance Schema to get this information. First determine the Performance Schema thread id for the blocking transaction. For this you need the blocking_pid, in the above example:

                blocking_pid: 3

and use this with the The threads Table table like:

Connection 3> SELECT THREAD_ID FROM performance_schema.threads WHERE PROCESSLIST_ID = 3;
+-----------+
| THREAD_ID |
+-----------+
|        28 |
+-----------+
1 row in set (0.00 sec)

For the following queries insert the thread id found above for the THREAD_ID = … where clauses.

To get the latest query executed, use the The events_statements_current Table table or the The session and x$session Views view:

Connection 3> SELECT THREAD_ID, SQL_TEXT
                FROM performance_schema.events_statements_current
               WHERE THREAD_ID = 28;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
1 row in set (0.00 sec)

or:

Connection 3> SELECT * FROM sys.session WHERE thd_id = 28\G
*************************** 1. row ***************************
                thd_id: 28
               conn_id: 3
                  user: root@localhost
                    db: NULL
               command: Sleep
                 state: NULL
                  time: 447
     current_statement: NULL
     statement_latency: NULL
              progress: NULL
          lock_latency: 117.00 us
         rows_examined: 1
             rows_sent: 0
         rows_affected: 1
            tmp_tables: 0
       tmp_disk_tables: 0
             full_scan: NO
        last_statement: UPDATE world.City SET Population = Population + 1 WHERE ID = 133
last_statement_latency: 321.06 us
        current_memory: 0 bytes
             last_wait: NULL
     last_wait_latency: NULL
                source: NULL
           trx_latency: NULL
             trx_state: ACTIVE
        trx_autocommit: NO
                   pid: 7717
          program_name: mysql
1 row in set (0.08 sec)

In this case this does not explain why the lock is held as the last query update a different row then where the lock issue occurs. However if the events_statements_history consumer is enabled (it is by default in MySQL 5.7 and later), the The events_statements_history Table table will include the last 10 statements (by default) executed for the connection:

Connection 3> SELECT THREAD_ID, SQL_TEXT
                FROM performance_schema.events_statements_history
               WHERE THREAD_ID = 28
               ORDER BY EVENT_ID;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | SELECT DATABASE()                                                |
|        28 | NULL                                                             |
|        28 | show databases                                                   |
|        28 | show tables                                                      |
|        28 | START TRANSACTION                                                |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 130 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 131 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 132 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
9 rows in set (0.00 sec)

So now the history of the blocking transaction can be seen and it is possible to determine why the locking issue occur.

Note

The history also includes some queries executed before the transaction started. These are not related to the locking issue.

If transaction monitoring is also enabled (only available in MySQL 5.7 and later), it is possible to get more information about the transaction and automatically limit the query of the history to the current transaction. Transaction monitoring is not enabled by default. To enable it, use:

mysql> UPDATE performance_schema.setup_consumers
          SET ENABLED = 'YES'
        WHERE NAME = 'events_transactions_current';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> UPDATE performance_schema.setup_instruments
          SET ENABLED = 'YES'
        WHERE NAME = 'transaction';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Information

This must be done before either of the transactions is started. Only transaction started after the transaction monitoring is enabled will be instrumented.

If the above was enabled before the blocking transaction started, you can get more details about the blocking transaction as:

Connection 3> SELECT *
                FROM performance_schema.events_transactions_current
               WHERE THREAD_ID = 28\G
*************************** 1. row ***************************
                      THREAD_ID: 28
                       EVENT_ID: 12
                   END_EVENT_ID: NULL
                     EVENT_NAME: transaction
                          STATE: ACTIVE
                         TRX_ID: NULL
                           GTID: AUTOMATIC
                  XID_FORMAT_ID: NULL
                      XID_GTRID: NULL
                      XID_BQUAL: NULL
                       XA_STATE: NULL
                         SOURCE: transaction.cc:209
                    TIMER_START: NULL
                      TIMER_END: NULL
                     TIMER_WAIT: NULL
                    ACCESS_MODE: READ WRITE
                ISOLATION_LEVEL: REPEATABLE READ
                     AUTOCOMMIT: NO
           NUMBER_OF_SAVEPOINTS: 0
NUMBER_OF_ROLLBACK_TO_SAVEPOINT: 0
    NUMBER_OF_RELEASE_SAVEPOINT: 0
          OBJECT_INSTANCE_BEGIN: NULL
               NESTING_EVENT_ID: 11
             NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.00 sec)

And to get the statement history of the transaction:

Connection 3> SELECT t.THREAD_ID, s.SQL_TEXT
                FROM performance_schema.events_transactions_current t
                     INNER JOIN performance_schema.events_statements_history s
                             ON s.THREAD_ID = t.THREAD_ID
                            AND s.NESTING_EVENT_ID = t.EVENT_ID
               WHERE t.THREAD_ID = 28
               ORDER BY s.EVENT_ID;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 130 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 131 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 132 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
4 rows in set (0.00 sec)