MySQL 8.0 : Data Locking Visibility

on

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 :

One thought on “MySQL 8.0 : Data Locking Visibility

Leave a Reply

Your email address will not be published. Required fields are marked *

recent

Last Tweets

Locations of visitors to this page
categories