MySQL Support Team
Guest
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 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):
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 performance_schema.threads 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 events_statements_current table or the sys.session 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 events_statements_history 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 |
+-----------+------------------------------------------------------------------+
5 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
Note: 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)
Читать дальше...
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 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):
- 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 - Connection 2 (blocks for innodb_lock_wait_timeout seconds):
Connection 2> UPDATE world.City SET Population = Population + 999 WHERE ID = 130; - 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 performance_schema.threads 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 events_statements_current table or the sys.session 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 events_statements_history 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 |
+-----------+------------------------------------------------------------------+
5 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
Note: 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)
Читать дальше...