With MySQL 8.0, engineers improved the visibility of data locking. Usually it was not that easy to deal with the output of SHOW ENGINE INNODB STATUS and mixing Information_Schema tables like INNODB_LOCKS and INNODB_LOCK_WAITS.
So in MySQL 8.0 we instrument data locks in Performance_Schema and we changed the SYS Schema view related to the InnoDB Locks Wait too.
This means that when a transaction A is locking row R, and transaction B is waiting on this very same row, B is effectively blocked by A. What we added is extra instrumentation to expose which data is locked (R), who owns the lock (A), and who is waiting for the data (B).
Testing
Let’s have a look at this simple scenario in MySQL 5.7.21 and 8.0.4 to compare:
2 clients starting a transaction and updating the same row, the transaction is not committed or rolled back on the want getting the lock (mysql1):
mysql client1> start transaction; Query OK, 0 rows affected (0.00 sec) mysql client1> update sbtest1 set k = k + 1 where id = 14; Query OK, 1 row affected (0.09 sec) Rows matched: 1 Changed: 1 Warnings: 0 mysql client1>
mysql client2> start transaction; Query OK, 0 rows affected (0.00 sec) mysql client2> update sbtest1 set k = k + 1 where id = 14;
Of course after 50 seconds (default value of innodb_lock_wait_timeout), client2 receives:
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
But that’s not important for us, if it’s the case during the test, I just restart the update on client2.
MySQL 5.7.21
On MySQL 5.7, I was using the following query to find who’s locking when sys was not installed:
SELECT
CONCAT('thread ', b.trx_mysql_thread_id, ' from ', p.host) AS who_blocks,
IF(p.command = "Sleep", p.time, 0) AS idle_in_trx,
MAX(TIMESTAMPDIFF(SECOND, r.trx_wait_started, CURRENT_TIMESTAMP)) AS max_wait_time,
COUNT(*) AS num_waiters
FROM INFORMATION_SCHEMA.INNODB_LOCK_WAITS AS w
INNER JOIN INFORMATION_SCHEMA.INNODB_TRX AS b ON b.trx_id = w.blocking_trx_id
INNER JOIN INFORMATION_SCHEMA.INNODB_TRX AS r ON r.trx_id = w.requesting_trx_id
LEFT JOIN INFORMATION_SCHEMA.PROCESSLIST AS p ON p.id = b.trx_mysql_thread_id
GROUP BY who_blocks ORDER BY num_waiters DESC
Let’s use it and see its output:
+-------------------------+-------------+---------------+-------------+ | who_blocks | idle_in_trx | max_wait_time | num_waiters | +-------------------------+-------------+---------------+-------------+ | thread 4 from localhost | 98 | 12 | 1 | +-------------------------+-------------+---------------+-------------+
We see that it’s thread 4 from localhost who’s blocking another trx… Of course we can run SHOW ENGINE INNODB STATUS to find more info:
... ------------ TRANSACTIONS ------------ Trx id counter 1860 Purge done for trx's n:o < 1858 undo n:o < 0 state: running but idle History list length 6 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421392876332896, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 1859, ACTIVE 21 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 5, OS thread handle 139917553682176, query id 169 localhost root updating update sbtest1 set k = k + 1 where id = 14 ------- TRX HAS BEEN WAITING 21 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 39 page no 4 n bits 144 index PRIMARY of table `sbtest`.`sbtest1` trx id 1859 lock_mode X locks rec but not gap waiting Record lock, heap no 15 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 4; hex 8000000e; asc ;; 1: len 6; hex 000000000742; asc B;; 2: len 7; hex 3c000001320301; asc < 2 ;; 3: len 4; hex 8000c31c; asc ;; 4: len 30; hex 30333035373937303339372d37363834343539383231392d353739313936; asc 03057970397-76844598219-579196; (total 120 bytes); 5: len 30; hex 35383238393534373334392d37303232313835393939362d393831303831; asc 58289547349-70221859996-981081; (total 60 bytes); ------------------ ---TRANSACTION 1858, ACTIVE 28 sec 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 4, OS thread handle 139917553952512, query id 168 localhost root ...
We know which transaction is waiting for…
So now, let’s see what the amazing sys schema tell us about this:
mysql 5.7> select * from innodb_lock_waits\G
*************************** 1. row ***************************
wait_started: 2018-03-07 09:15:49
wait_age: 00:00:08
wait_age_secs: 8
locked_table: `sbtest`.`sbtest1`
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 1859
waiting_trx_started: 2018-03-07 09:13:26
waiting_trx_age: 00:02:31
waiting_trx_rows_locked: 3
waiting_trx_rows_modified: 0
waiting_pid: 5
waiting_query: update sbtest1 set k = k + 1 where id = 14
waiting_lock_id: 1859:39:4:15
waiting_lock_mode: X
blocking_trx_id: 1858
blocking_pid: 4
blocking_query: NULL
blocking_lock_id: 1858:39:4:15
blocking_lock_mode: X
blocking_trx_started: 2018-03-07 09:13:19
blocking_trx_age: 00:02:38
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 4
sql_kill_blocking_connection: KILL 4
1 row in set, 3 warnings (0.00 sec)
Wow that’s much more interesting !
Let’s now have a look at MySQL 8.0
MySQL 8.0.4
I do exactly the same and let’s see directly in sys as it’s shipped by default:
MySQL 8> select * from innodb_lock_waits\G
*************************** 1. row ***************************
wait_started: 2018-03-07 08:25:09
wait_age: 00:00:22
wait_age_secs: 22
locked_table: `sbtest`.`sbtest1`
locked_table_schema: sbtest
locked_table_name: sbtest1
locked_table_partition: NULL
locked_table_subpartition: NULL
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 17000
waiting_trx_started: 2018-03-07 08:25:09
waiting_trx_age: 00:00:22
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 14
waiting_query: update sbtest1 set k = k + 1 where id = 14
waiting_lock_id: 17000:195:5:15
waiting_lock_mode: X
blocking_trx_id: 16999
blocking_pid: 12
blocking_query: NULL
blocking_lock_id: 16999:195:5:15
blocking_lock_mode: X
blocking_trx_started: 2018-03-07 08:25:04
blocking_trx_age: 00:00:27
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 1
sql_kill_blocking_query: KILL QUERY 12
sql_kill_blocking_connection: KILL 12
1 row in set (0.00 sec)
We have equivalent result, very interesting of course… but… what’s new then ?
data_locks
In fact now, in performance_schema, we have new tables (data_locks and data_lock_waits) and in contrast to MySQL 5.7 (I_S.INNODB_LOCKS), here the data is present in data_locks even when there is no conflict causing wait.
Let’s run only the first transaction (client1) in 5.7 and 8.0 to see the difference:
In 5.7:
mysql 5.7> select * from INNODB_LOCKS\G Empty set, 1 warning (0.00 sec)
In 8.0:
MySQL 8> select * from data_locks \G
*************************** 1. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17000:1278
ENGINE_TRANSACTION_ID: 17000
THREAD_ID: 45
EVENT_ID: 11
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140305374449784
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
1 row in set (0.00 sec)
So here we can see that some lock even without conflict is already visible. Now let’s run the second transaction in client2 and check again:
In 5.7, the data is now visible:
mysql 5.7> select * from INNODB_LOCKS\G
*************************** 1. row ***************************
lock_id: 1863:39:4:15
lock_trx_id: 1863
lock_mode: X
lock_type: RECORD
lock_table: `sbtest`.`sbtest1`
lock_index: PRIMARY
lock_space: 39
lock_page: 4
lock_rec: 15
lock_data: 14
*************************** 2. row ***************************
lock_id: 1865:39:4:15
lock_trx_id: 1865
lock_mode: X
lock_type: RECORD
lock_table: `sbtest`.`sbtest1`
lock_index: PRIMARY
lock_space: 39
lock_page: 4
lock_rec: 15
lock_data: 14
2 rows in set, 1 warning (0.00 sec)
And in 8.0:
MySQL 8> select * from data_locks \G
*************************** 1. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17000:1278
ENGINE_TRANSACTION_ID: 17000
THREAD_ID: 45
EVENT_ID: 11
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140305374449784
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 2. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17000:195:5:15
ENGINE_TRANSACTION_ID: 17000
THREAD_ID: 45
EVENT_ID: 14
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374447888
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 14
2 rows in set (0.00 sec)
Once again this is almost equivalent…
Now let’s change the first transaction like this:
mysql client1> update sbtest1 set k = k + 1 where id in (14,15,16,7000);
If we check before running the second transaction, in MySQL 5.7, INNODB_LOCKS is still empty but on MySQL 8.0 we can already see this:
*************************** 1. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:1278
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140305374443832
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 2. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:15
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 14
*************************** 3. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:16
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 15
*************************** 4. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:17
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 16
*************************** 5. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:128:30
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374441136
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 7000
5 rows in set (0.00 sec)
All the locked records are already present and when we run the second transaction (in client2), the extra locks are also showed and there is a LOCK_STATUS = WAITING too:
*************************** 1. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17009:1278
ENGINE_TRANSACTION_ID: 17009
THREAD_ID: 45
EVENT_ID: 17
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140305374449784
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 2. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17009:195:5:15
ENGINE_TRANSACTION_ID: 17009
THREAD_ID: 45
EVENT_ID: 17
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374446856
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: WAITING
LOCK_DATA: 14
*************************** 3. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:1278
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140305374443832
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 4. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:15
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 14
*************************** 5. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:16
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 15
*************************** 6. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:5:17
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374440792
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 16
*************************** 7. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 17008:195:128:30
ENGINE_TRANSACTION_ID: 17008
THREAD_ID: 43
EVENT_ID: 44
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
PARTITION_NAME: NULL
SUBPARTITION_NAME: NULL
INDEX_NAME: PRIMARY
OBJECT_INSTANCE_BEGIN: 140305374441136
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 7000
Conclusion
The new instrumentation for data locks is much more complete in MySQL 8.0 and will help understanding and resolving locking issues. You may also have noticed that the new tables (not in sys), are also not only dedicated to InnoDB, so if you are maintaining a 3rd party engine and you add the required instrumentation, your data locks will also be available in Performance_Schema.
Please find more information directly in the manual :
- http://dev.mysql.com/doc/refman/8.0/en/data-locks-table.html
- http://dev.mysql.com/doc/refman/8.0/en/data-lock-waits-table.html
- http://dev.mysql.com/doc/refman/8.0/en/innodb-locks-table.html
- http://dev.mysql.com/doc/refman/8.0/en/innodb-lock-waits-table.html
- http://dev.mysql.com/doc/refman/8.0/en/sys-innodb-lock-waits.html
- http://dev.mysql.com/doc/refman/8.0/en/innodb-information-schema-transactions.html
[…] データロックについて、performance schemaに実装しました。トランザクションAが行Rをロックし、トランザクションBが正に同じ行を待っている場合、BはAにブロックされています。今回実装された機能では、どのデータがRで、誰がロックAを持ち、誰がデータを待っているBなのかがわかります。こちらのFrederic Descampsのブログ記事をご覧ください。 […]