MySQL(InnoDB)でのロック待ち状況の調査方法


# 前提

## MySQL version

```
Server version:         8.0.28 MySQL Community Server - GPL
```

## DBに [Sakila Sample Database](https://dev.mysql.com/doc/sakila/en/) を利用

Sakila Sample DatabaseはMySQL開発チームが提供しているMySQLの機能を検証したりするためのサンプルデータベースです。

[こちらのGitHubレポジトリ](https://github.com/jOOQ/sakila)からダウンロードすればMySQL以外のRDBMSへのデータ取り込みも可能です。

本記事では、このサンプルデータベースの一部テーブルを利用します。

# 検証

## ロック待ちの発生

ロック状況の調査方法を示すために意図的にロック待ちを発生させます。

セッション1 として以下のクエリを実行し共有ロックを取ります。

```sql
begin;
select * from customer where address_id between 1 and 5 for share;
```

セッション2 として以下の更新を実行するとロック待ちになることが確認できます。

このセッションでは検証の便宜上、レコードロックのタイムアウト時間を引き伸ばします。
```sql
SET innodb_lock_wait_timeout=600;
```

```sql
begin;
update customer set last_name = 'ITO' where customer_id = 1;
(セッション1のトランザクションが終わるか innodb_lock_wait_timeoutに達する までロック待ちが発生)
```

## ロック状況の調査

### ひとまず sys.innodb_lock_waits ビューを確認

ロック待ちが起こっていると推測されるとき sys.innodb_lock_waits ビュー を確認しましょう。

```sql
mysql> select * from sys.innodb_lock_waits\G
*************************** 1. row ***************************
                wait_started: 2024-08-28 08:47:24
                    wait_age: 00:00:07
               wait_age_secs: 7
                locked_table: `sakila`.`customer`
         locked_table_schema: sakila
           locked_table_name: customer
      locked_table_partition: NULL
   locked_table_subpartition: NULL
                locked_index: PRIMARY
                 locked_type: RECORD
              waiting_trx_id: 2082
         waiting_trx_started: 2024-08-28 08:47:24
             waiting_trx_age: 00:00:07
     waiting_trx_rows_locked: 1
   waiting_trx_rows_modified: 0
                 waiting_pid: 12
               waiting_query: update customer set last_name = 'ITO' where customer_id = 1
             waiting_lock_id: 275354136576:7:8:2:275213530512
           waiting_lock_mode: X,REC_NOT_GAP
             blocking_trx_id: 281750330846424
                blocking_pid: 9
              blocking_query: NULL
            blocking_lock_id: 275354135768:7:8:2:275213524680
          blocking_lock_mode: S,REC_NOT_GAP
        blocking_trx_started: 2024-08-28 08:46:33
            blocking_trx_age: 00:00:58
    blocking_trx_rows_locked: 3
  blocking_trx_rows_modified: 0
     sql_kill_blocking_query: KILL QUERY 9
sql_kill_blocking_connection: KILL 9
1 row in set (0.02 sec)
```

wait_started, wait_age, locked_table, locked_index, locked_type, waiting_query, blocking_trx_id, blocking_lock_mode, sql_kill_blocking_query などの情報を得ることができました。

locked_index, locked_type, blocking_lock_mode 等に関しては[InnoDBのロック](https://dev.mysql.com/doc/refman/8.0/ja/innodb-locking.html)について理解しておく必要がありますが、本記事では内容に言及しません。

:::note info
sys.innodb_lock_waits は 我々ユーザーに見やすい表示を提供してくれているビューであり以下のテーブルから構成されています。

* performance_schema.data_locks
  * ロック情報を持つ。ロックが競合しているかどうかの情報は持たない
* information_schema.INNODB_TRX
  * 実行中のトランザクションの情報を持つ
* performance_schema.data_lock_waits
  * ロックが競合して待ちになっているロックだけの情報を持つ
:::

:::note warn
上記のsys.innodb_lock_waitsの結果で `blocking_query: NULL` になっていることが確認できる。

blocking_queryカラムでのクエリは現在ロックを取っているトランザクションが現在実行しているクエリが出力される仕様である。

そのため、実際にどのクエリが該当のInnoDBロックを取得したかは以下の手順で確認することになる。
:::

### ブロックしているクエリの特定調査

sys.innodb_lock_waitsで得られた`blocking_trx_id`を使って `performance_schema.data_locks` テーブルで検索をかけます。

```sql
mysql> select * from performance_schema.data_locks where ENGINE_TRANSACTION_ID = 281750330846424;
+--------+---------------------------------+-----------------------+-----------+----------+---------------+-------------+----------------+-------------------+-------------------+-----------------------+-----------+---------------+-------------+-----------+
| ENGINE | ENGINE_LOCK_ID                  | ENGINE_TRANSACTION_ID | THREAD_ID | EVENT_ID | OBJECT_SCHEMA | OBJECT_NAME | PARTITION_NAME | SUBPARTITION_NAME | INDEX_NAME        | OBJECT_INSTANCE_BEGIN | LOCK_TYPE | LOCK_MODE     | LOCK_STATUS | LOCK_DATA |
+--------+---------------------------------+-----------------------+-----------+----------+---------------+-------------+----------------+-------------------+-------------------+-----------------------+-----------+---------------+-------------+-----------+
| INNODB | 275354135768:1072:275213527328  |       281750330846424 |        48 |      144 | sakila        | customer    | NULL           | NULL              | NULL              |          275213527328 | TABLE     | IS            | GRANTED     | NULL      |
| INNODB | 275354135768:7:6:2:275213524336 |       281750330846424 |        48 |      144 | sakila        | customer    | NULL           | NULL              | idx_fk_address_id |          275213524336 | RECORD    | S             | GRANTED     | 5, 1      |
| INNODB | 275354135768:7:6:3:275213524336 |       281750330846424 |        48 |      144 | sakila        | customer    | NULL           | NULL              | idx_fk_address_id |          275213524336 | RECORD    | S             | GRANTED     | 6, 2      |
| INNODB | 275354135768:7:8:2:275213524680 |       281750330846424 |        48 |      144 | sakila        | customer    | NULL           | NULL              | PRIMARY           |          275213524680 | RECORD    | S,REC_NOT_GAP | GRANTED     | 1         |
+--------+---------------------------------+-----------------------+-----------+----------+---------------+-------------+----------------+-------------------+-------------------+-----------------------+-----------+---------------+-------------+-----------+
4 rows in set (0.02 sec)
```

上記のように今回は4レコード分の結果が返りました。

:::note info
4レコードに関する簡単な解説をします。

* 1行目
  * LOCK_TYPEが`TABLE`で`LOCK_MODE`が`IS`とあり、これは[インテンションロック](https://dev.mysql.com/doc/refman/8.0/ja/innodb-locking.html#innodb-insert-intention-locks)でありテーブルレイヤーに対して発行されるものです
* 2行目,3行目
  * `address_id`カラムに付けられた`idx_fk_address_id`インデックスに対する共有ロック(S)です
    * (調査しようとしている)ブロッキングの原因である`select * from customer where address_id between 1 and 5 for share;`のクエリと実データ状況からLOCK_DATAが`5,1`と`6,2`に分けられています
* 4行目
  * 2,3行目での`idx_fk_address_id`インデックスはセカンダリインデックスであり、セカンダリインデックスからクラスタインデックス(主キー)たどった先にあった`PRIMARY`インデックスの行に対する共有ロック(S)です
    * 実データでは`address_id between 1 and 5`の条件に当てはまる`customer_id`は1のレコードしかないので、LOCK_DATAが1になっています
:::

sys.innodb_lock_waitsの結果で今回は `locked_index` と `blocking_lock_mode` がそれぞれ `PRIMARY`, `S,REC_NOT_GAP` で表示されているので、上記では4行目のロックがブロッキングの原因のロックであることがわかります。

そしてここで、data_locksテーブルの`THREAD_ID`を取得します。今回は`48`でした。

:::note info
data_locksではなく、performance_schema.threads テーブル または sys.processlist ビューを用いてプロセスリストIDからスレッドIDを特定することもできます。
:::

その`THREAD_ID`で performance_schema.events_statements_history テーブルからブロッキングしているクエリを特定します。data_locksテーブルの結果の2,3行目にて`idx_fk_address_id`のインデックスが含まれていたことから、クエリには`address_id`カラムが関係していると推測し address_id をwhere句の条件に加えまあす。

```sql
mysql> select * from performance_schema.events_statements_history where THREAD_ID = 48 and SQL_TEXT like '%address_id%'\G
*************************** 1. row ***************************
              THREAD_ID: 48
               EVENT_ID: 143
           END_EVENT_ID: 143
             EVENT_NAME: statement/sql/select
                 SOURCE: init_net_server_extension.cc:95
            TIMER_START: 21894906555751000
              TIMER_END: 21894911995042000
             TIMER_WAIT: 5439291000
              LOCK_TIME: 60000000
               SQL_TEXT: select * from customer where address_id between 1 and 5 for share
                 DIGEST: 7463a9dce0e2c0d0a20f412b9bc79ccb15bd99620f186e404c849bfa0d0c1f67
            DIGEST_TEXT: SELECT * FROM `customer` WHERE `address_id` BETWEEN ? AND ? FOR SHARE
         CURRENT_SCHEMA: sakila
            OBJECT_TYPE: NULL
          OBJECT_SCHEMA: NULL
            OBJECT_NAME: NULL
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: NULL
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 0
              ROWS_SENT: 1
          ROWS_EXAMINED: 1
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 1
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 0
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 0
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: 142
     NESTING_EVENT_TYPE: TRANSACTION
    NESTING_EVENT_LEVEL: 0
           STATEMENT_ID: 339
               CPU_TIME: 0
1 rows in set (0.01 sec)
```

上記のように SQL_TEXT カラムで `select * from customer where address_id between 1 and 5 for share` のクエリがブロッキングクエリであることを特定できました。

### ロック待ちのクエリの統計的情報の確認

performance_schema.events_statements_summary_by_digest テーブルを見ることでロック待ちになったクエリが普段どのくらいの割合でロック待ちになっているのかを確認できます。

```sql
mysql> select * from performance_schema.events_statements_summary_by_digest where QUERY_SAMPLE_TEXT like '%update customer set last_name =%'\G
*************************** 1. row ***************************
                SCHEMA_NAME: sakila
                     DIGEST: 0a0a6bf59c031afa43168450e0133be0ec42493574516a930e939b5924e72e60
                DIGEST_TEXT: UPDATE `customer` SET `last_name` = ? WHERE `customer_id` = ?
                 COUNT_STAR: 5
             SUM_TIMER_WAIT: 1259457903277000
             MIN_TIMER_WAIT: 20118625000
             AVG_TIMER_WAIT: 251891580655000
             MAX_TIMER_WAIT: 600310820667000
              SUM_LOCK_TIME: 1259426480000000
                 SUM_ERRORS: 4
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 1
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 1
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
               SUM_CPU_TIME: 0
                 FIRST_SEEN: 2024-08-28 07:48:44.163453
                  LAST_SEEN: 2024-08-28 08:45:47.055417
                QUANTILE_95: 602559586074375
                QUANTILE_99: 602559586074375
               QUANTILE_999: 602559586074375
          QUERY_SAMPLE_TEXT: update customer set last_name = 'ITO' where customer_id = 1
          QUERY_SAMPLE_SEEN: 2024-08-28 08:45:47.055417
    QUERY_SAMPLE_TIMER_WAIT: 600290001417000
1 row in set (0.02 sec)
```

## デッドロックの調査

### デッドロックを発生させる

以下のように2つのセッションを使ってデッドロックを発生させます。

セッション1
```sql
begin;
select * from customer where address_id between 1 and 5 for share;
```

セッション2
```sql
begin;
select * from customer where address_id between 11 and 15 for share;
```

セッション1
```sql
update customer set last_name = 'TANAKA' where customer_id = 10;
(ロック待ち発生)
```

セッション2
```sql
update customer set last_name = 'ITO' where customer_id = 1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
```

### デッドロックの調査

デッドロックが発生したら `SHOW ENGINE INNODB STATUS;` で `LATEST DETECTED DEADLOCK` の箇所を確認しましょう。

```
SHOW ENGINE INNODB STATUS;

(前略)
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-08-28 09:09:54 277462066944
*** (1) TRANSACTION:
TRANSACTION 2084, ACTIVE 38 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 4 row lock(s)
MySQL thread id 9, OS thread handle 279454582528, query id 387 172.20.0.1 root updating
update customer set last_name = 'TANAKA' where customer_id = 10

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 7 page no 8 n bits 256 index PRIMARY of table `sakila`.`customer` trx id 2084 lock mode S locks rec but not gap
Record lock, heap no 189 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 7 page no 8 n bits 256 index PRIMARY of table `sakila`.`customer` trx id 2084 lock_mode X locks rec but not gap waiting
Record lock, heap no 11 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

*** (2) TRANSACTION:
TRANSACTION 2085, ACTIVE 32 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 12 row lock(s)
MySQL thread id 12, OS thread handle 279589857024, query id 388 172.20.0.1 root updating
update customer set last_name = 'ITO' where customer_id = 1

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 7 page no 8 n bits 256 index PRIMARY of table `sakila`.`customer` trx id 2085 lock mode S locks rec but not gap
Record lock, heap no 8 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

Record lock, heap no 9 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

Record lock, heap no 10 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

Record lock, heap no 11 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

Record lock, heap no 12 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 7 page no 8 n bits 256 index PRIMARY of table `sakila`.`customer` trx id 2085 lock_mode X locks rec but not gap waiting
Record lock, heap no 189 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
(中略)

*** WE ROLL BACK TRANSACTION (2)
(後略)
```

2つのトランザクションそれぞれの
`(1/2) TRANSACTION`, `(1/2) HOLDS THE LOCK(S)`(保持しているロック), `(1/2) WAITING FOR THIS LOCK TO BE GRANTED`(待っているロック) 
から以下がわかります。


| トランザクション         | 実行クエリ                                              | 保持しているロック                                              | 待っているロック                                              |
|--------------------------|---------------------------------------------------------|----------------------------------------------------------------|--------------------------------------------------------------|
| トランザクション1 (2084)  | UPDATE customer SET last_name = 'TANAKA' WHERE customer_id = 10 | sakila.customerテーブルのPRIMARYキーに対する共有ロック (S lock) | sakila.customerテーブルのPRIMARYキーに対する排他ロック (X lock) |
| トランザクション2 (2085)  | UPDATE customer SET last_name = 'ITO' WHERE customer_id = 1  | sakila.customerテーブルのPRIMARYキーに対する共有ロック (S lock) | sakila.customerテーブルのPRIMARYキーに対する排他ロック (X lock) |

### デッドロックが頻発する場合

[innodb_print_all_deadlocks](https://dev.mysql.com/doc/refman/8.0/ja/innodb-parameters.html#sysvar_innodb_print_all_deadlocks)というパラメータを"ON"にすることでMySQLのエラーログに上記の`SHOW ENGINE INNODB STATUS`に出るデッドロックの履歴が出力されるようになります。