MySQL(InnoDB)でのDeadLock調査

最近MySQLでDeadLock問題にハマったのでその時の調査メモ

背景

とあるバッチプログラムで多数のBULK INSERT/UPDATEを行う処理の検証を行った際、
並列数を上げるとDeadLockが発生するという問題に直面。

一処理で同時に発行するSQLが多すぎてアプリのログからは原因が追いきれなかった。
（＜この時点でアプリの処理やログ出力を見直す必要がありそうだが、それはひとまず置いといて ^^;）

その原因調査に役立った情報やMySQLの仕様などを備忘。

原因調査

まずはロックの原因を特定するためにInnoDB ロックモニターを有効化

set GLOBAL innodb_status_output=ON;
set GLOBAL innodb_status_output_locks=ON;

⇒ SHOW ENGINE INNODB STATUSでロックの詳細情報が見れるようになる。

この状態でDeadLockを発生させてから結果を確認。

モニター結果

mysql> SHOW ENGINE INNODB STATUS;

-- (省略) --

=====================================
2017-09-30 06:06:40 0x7f215046a700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 47 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 35 srv_active, 0 srv_shutdown, 2694 srv_idle
srv_master_thread log flush and writes: 2729
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 576
OS WAIT ARRAY INFO: signal count 495
RW-shared spins 0, rounds 244, OS waits 117
RW-excl spins 0, rounds 222, OS waits 9
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 244.00 RW-shared, 222.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-09-30 05:34:37 0x7f215811b700
*** (1) TRANSACTION:
TRANSACTION 10214, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 37, OS thread handle 139781060650752, query id 6538 172.17.0.1 root update
insert into `lock_test` -- (省略) -- <= DeadLockとなったSQL文(1)

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 47 page no 3 n bits 96 index PRIMARY of table `temp`.`lock_test` trx id 10214 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) TRANSACTION:
TRANSACTION 10215, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 25, OS thread handle 139781188204288, query id 6540 172.17.0.1 root update
insert into `lock_test` -- (省略) -- <= DeadLockとなったSQL文(2)

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 47 page no 3 n bits 96 index PRIMARY of table `temp`.`lock_test` trx id 10215 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 47 page no 3 n bits 96 index PRIMARY of table `temp`.`lock_test` trx id 10215 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 10239
Purge done for trx's n:o < 10220 undo n:o < 0 state: running but idle
History list length 36
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421256463523440, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421256463522528, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421256463521616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)

-- (省略) --

----------------------------
END OF INNODB MONITOR OUTPUT
============================

⇒ LATEST DETECTED DEADLOCKセクションに、直前に発生したDeadLockの情報が表示されている

分かるところだけ読むと、

*** (1) TRANSACTION:
...
insert into `lock_test` -- (省略) -- <= DeadLockとなったSQL文(1)
...
*** (2) TRANSACTION:
...
insert into `lock_test` -- (省略) -- <= DeadLockとなったSQL文(2)
...
*** WE ROLL BACK TRANSACTION (2)

⇒lock_testテーブルへのINSERT処理で競合が起きている（※検証用にテーブル名は実行時のものと変更済み）
⇒二つ目のトランザクションがロールバックされた

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 47 page no 3 n bits 96 index PRIMARY of table `temp`.`lock_test` trx id 10215 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

⇒ RECORD LOCKS ... lock_mode X = 行レベルの排他ロック
⇒ supremum(= あるテーブルの最終レコードのさらに後ろにある終端を示すレコード、らしい) のロック競合が原因

・・・調査開始当初はテーブルロックを疑っていたが、そうではなかった模様

MySQLの行ロックモード

MySQL(InnoDB)の行ロックには

Record Locks
Gap Locks
Next-Key Locks

の三種類がある。

ギャップロック、ネクストキーロックはインデックスレコードに対する操作時にファントムリードを防ぐ為の機構で、MySQLのデフォルトトランザクション分離(ISOLATION)レベルREPEATABLE READではこのギャップロックが有効になっている。

Ref.) https://dev.mysql.com/doc/refman/5.6/ja/innodb-record-level-locks.html

ロックモニターの結果から今回のDeadLockは同一テーブルへのINSERT時のネクストキーロックによるインデックス挿入の競合と推察。

対応

問題となったバッチ処理プログラムでは、他の並列スレッドとの間で処理対象のPKが被ることはない(=ファントムリードが問題にならない)想定の為、ひとまずパフォーマンスを重視してISOLATIONレベルをREAD COMMITEDにすることで解決した。

結論

今回の事でまだまだDBやアプリケーションの並列処理についての理解が浅いと実感した。

本来もっとミッションクリティカルなアプリケーションでは、REPEATABLE READ(もしくはSERIALIZABLE)で(例え更新がない読み取り用のトランザクションでも)きちんと共有ロックなどを使い、他のトランザクションとの原子性を保証しなければならないらしい。

どこかで聞いた「MySQLはとりあえずインデックス貼っとけば行ロックになるから並列処理も安心」みたいな考えはやはり危険。

ギャップロックやISOLATIONレベルについてもまだ完全に理解できていないので、もう少し理解が進んだらまた追記していこうと思う。

参考ページ

調査の過程で下記の記事の情報などを参考にさせて頂きました。多謝。

InnoDBで行ロック/テーブルロックになる条件を調べた #mysqlcasual Advent Calendar 2013 - あおうさ＠日記
 InnoDB の行レベルロックについて解説してみる - あらびき日記
 InnoDBのロックの範囲とネクストキーロックの話 - かみぽわーる
 良く分かるMySQL Innodbのギャップロック - Qiita
MySQL - ネクストキーロックってどこまでロックされんの？ - Qiita
MySQL - InnoDBのロック関連まとめ - Qiita
MySQLでINSERTのデッドロックに嵌る人を1人でも減らすために - ichirin2501's diary
MySQL/MariaDBとTransactdのInnoDBロック制御詳細　その1 - BizStationブログ

おまけ

検証用のMySQL環境を作る際、下記の記事を参考にDockerを使ったら手軽＆便利で感動したのでついでにご紹介。

dockerでmysqlを使う - Qiita