MySQLでロック待機タイムアウト（Lock wait timeout）をデバッグする方法

MySQLで「Lock wait timeout exceeded」エラーが発生する主な原因は、あるスレッド（トランザクション）がレコードのロックを長時間保持し続けていることにあります。別のトランザクションがそのレコードにアクセスしようとしても、ロックが解放されるまで待機するしかなく、待機時間が innodb_lock_wait_timeout の設定値（デフォルトは50秒）を超えるとタイムアウトエラーとなります。

ロック待機タイムアウトの原因

この問題は、以下のようなケースでよく発生します。

• あるトランザクションが更新中のレコードのコミットやロールバックを行わず、ロックを長時間保持している
• アプリケーションのバグにより、トランザクションが開かれたまま放置されている
• バッチ処理などの長時間実行されるクエリが大量の行ロックを取得している

つまり、あるスレッドが特定のレコードを非常に長い間ロックし続けている状態が続くと、そのスレッドはタイムアウト超過とみなされます。

SHOW ENGINE INNODB STATUSで詳細を確認する

ロックやトランザクションに関するすべての詳細情報を確認するには、次のクエリを実行します。

mysql> SHOW ENGINE INNODB STATUS;

実行すると、以下のような出力が得られます。

+--------+------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Type   | Name | Status                                                           |
+--------+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| InnoDB |      |
=====================================
2018-10-23 09:55:05 0x19e8 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 17805 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3
OS WAIT ARRAY INFO: signal count 3
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 21000
Purge done for trx's n:o < 20998 undo n:o < 0 state: running but idle
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 283438498772800, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (write thread)
I/O thread 7 state: wait Windows aio (write thread)
I/O thread 8 state: wait Windows aio (write thread)
I/O thread 9 state: wait Windows aio (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
1025 OS file reads, 545 OS file writes, 11 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 1 buffer(s)
Hash table size 2267, node heap has 3 buffer(s)
Hash table size 2267, node heap has 1 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.29 non-hash searches/s
---
LOG
---
Log sequence number          24309079
Log buffer assigned up to    24309079
Log buffer completed up to   24309079
Log written up to            24309079
Log flushed up to            24309079
Added dirty pages up to      24309079
Pages flushed up to          24309079
Last checkpoint at           24309079
388 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 8585216
Dictionary memory allocated 361173
Buffer pool size   512
Free buffers       251
Database pages     256
Old database pages 0
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1002, created 132, written 144
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 256, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID = 3260, Main thread ID = 000000000000106C , state = sleeping
Number of rows inserted 0, updated 313, deleted 0, read 4534
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.14 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
                                                                                      |
+--------+------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

この出力には、トランザクションやI/Oに関連するすべての詳細情報が含まれています。

出力結果の見どころ

ロック待機タイムアウトを調査する際は、特に以下のセクションに注目しましょう。

• TRANSACTIONSセクション： 現在アクティブなトランザクションの一覧が表示され、どのトランザクションがロックを保持しているか、「LOCK WAIT」ステータスになっているトランザクションがどれかを確認できます。
• SEMAPHORESセクション： 内部の同期処理に関する競合状況を把握できます。
• ROW OPERATIONSセクション： InnoDB内部で実行中のクエリ数や読み書きされた行数を確認できます。

補足：より手軽にロック情報を確認する方法

MySQL 5.5以降では、パフォーマンススキーマやInformation Schemaを利用して、ロックの状況をより簡潔に確認することもできます。例えば、現在実行中のトランザクション一覧は次のクエリで取得できます。

mysql> SELECT * FROM information_schema.INNODB_TRX\G

また、performance_schema.data_locks（MySQL 8.0以降）や sys.innodb_lock_waits ビューを参照すれば、どのトランザクションがどのロックを待っているのかを一目で把握でき、ブロックしている犯人となるトランザクションを特定するのに役立ちます。

問題のトランザクションを特定したら、アプリケーション側で適切にコミット・ロールバックが行われているかを確認し、不要に長いトランザクションがないかを見直すことが、ロック待機タイムアウトへの根本的な対策となります。