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

Last updated at 2024-09-24Posted at 2024-08-28

前提

MySQL version

Server version:         8.0.28 MySQL Community Server - GPL

DBに Sakila Sample Database を利用

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

こちらのGitHubレポジトリからダウンロードすればMySQL以外のRDBMSへのデータ取り込みも可能です。

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

検証

ロック待ちの発生

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

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

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

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

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

SET innodb_lock_wait_timeout=600;

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

ロック状況の調査

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

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

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のロックについて理解しておく必要がありますが、本記事では内容に言及しません。

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

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

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

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

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

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

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

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レコード分の結果が返りました。

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

1行目
- LOCK_TYPEがTABLEでLOCK_MODEがISとあり、これはインテンションロックでありテーブルレイヤーに対して発行されるものです
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でした。

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句の条件に加えまあす。

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 テーブルを見ることでロック待ちになったクエリが普段どのくらいの割合でロック待ちになっているのかを確認できます。

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

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

セッション2

begin;
select * from customer where address_id between 11 and 15 for share;

セッション1

update customer set last_name = 'TANAKA' where customer_id = 10;
(ロック待ち発生)

セッション2

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というパラメータを"ON"にすることでMySQLのエラーログに上記のSHOW ENGINE INNODB STATUSに出るデッドロックの履歴が出力されるようになります。

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up