読者です 読者をやめる 読者になる 読者になる

InnoDB のロック待ち過多でデッドロックするやつ

mysql

ロック待ちでデッドロック

InnoDB は同じロックを待つクライアントが 200 を超えるとデッドロック扱いになる、というやつがある。

このへんに詳しく書いてある。

Open database life: InnoDBのAUTO_INCREMENTが遅い問題は5.1でどう改善されたのか

同じロックを待つクライアント数が一定ライン(ソース上の定数LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK:200固定)を超えると、デッドロック扱いにして強制的にロールバックさせる、というInnoDBの実装に起因します。

MySQL :: MySQL 5.0 Reference Manual :: 14.2.7.1 InnoDB Lock Modes

If the LATEST DETECTED DEADLOCK section of InnoDB Monitor output includes a message stating, “TOO DEEP OR LONG SEARCH IN THE LOCK TABLE WAITS-FOR GRAPH, WE WILL ROLL BACK FOLLOWING TRANSACTION,” this indicates that the number of transactions on the wait-for list has reached a limit of 200, which is defined by LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK. A wait-for list that exceeds 200 transactions is treated as a deadlock and the transaction attempting to check the wait-for list is rolled back.

MySQLのInnoDBでのデッドロック - mixi Engineers' Blog

どうやらbug fixとして5.0.13以降で追加された定数・ロジックのようです。 高負荷時にロックが増加した際、デッドロック検出のための再帰呼び出しの深さが深くなりすぎてスタックを消費していきデーモンごと落ちてしまう、という問題を解決するために追加したようです。

手元で再現したい

手元で再現するのに 200 クライアントも立ち上げるの面倒なので、コードを変更してビルドしたのを使おうと思った。最初 5.6.23 を使ってやってみたら再現しなくて、5.0.96 でやったら再現した。

以下は 5.0.96 の手順。

LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK を 2 にする

5.0.96 のソースをダウンロードしてきて、以下のように変更する。

diff --git a/innobase/lock/lock0lock.c b/innobase/lock/lock0lock.c
index acf76a0..b0e7558 100644
--- a/innobase/lock/lock0lock.c
+++ b/innobase/lock/lock0lock.c
@@ -24,7 +24,7 @@ graph of transactions */

/* Restricts the recursion depth of the search we will do in the waits-for
graph of transactions */
-#define LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK 200
+#define LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK 2

/* When releasing transaction locks, this specifies how often we release
the kernel mutex for a moment to give also others access to it */

ビルド、インストール、起動

こんな感じでやった。

$ ./configure —prefix=/Users/usr0600268/opt/mysql/5.0.96-debug
$ make
$ make install
$ cd /Users/usr0600268/opt/mysql/5.0.96-debug
$ bin/mysql_install_db
$ libexec/mysqld

バージョンはこうなってる。

mysql> show variables like '%version%' ;
+-------------------------+---------------------+
| Variable_name | Value |
+-------------------------+---------------------+
| protocol_version | 10 |
| version | 5.0.96 |
| version_comment | Source distribution |
| version_compile_machine | i386 |
| version_compile_os | apple-darwin13.4.0 |
+-------------------------+---------------------+
5 rows in set (0.00 sec)

データの準備

適当なテーブルを作る。

mysql> create table entries(id int not null auto_increment, title varchar(255) not null, count int not null, primary key(id)) type=innodb ;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show create table entries ;
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| entries | CREATE TABLE `entries` (
`id` int(11) NOT NULL auto_increment,
`title` varchar(255) NOT NULL,
`count` int(11) NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

1行だけ追加する。

mysql> insert into entries(title,count) values("test", 0) ;
Query OK, 1 row affected (0.00 sec)

トランザクションを開始して UPDATE する。

mysql> start transaction ;
Query OK, 0 rows affected (0.00 sec)

mysql> update entries set count = count + 1 where id = 1 ;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0

他のクライアントを立ち上げて UPDATE するとロック待ちになる。

mysql> start transaction ;
Query OK, 0 rows affected (0.00 sec)

mysql> update entries set count = count + 1 where id = 1 ;

これを繰り返していくと4回目でデッドロックになった。

mysql> start transaction ;
Query OK, 0 rows affected (0.00 sec)

mysql> update entries set count = count + 1 where id = 1 ;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

show innodb status したらこうなっていた。

------------------------
LATEST DETECTED DEADLOCK
------------------------
150220 23:31:12
*** (1) TRANSACTION:
TRANSACTION 0 773, ACTIVE 10 sec, OS thread id 4366577664 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368
MySQL thread id 6, query id 42 localhost root Updating
update entries set count = count + 1 where id = 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 50 n bits 72 index `PRIMARY` of table `test/entries` trx id 0 773 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000000304; asc ;; 2: len 7; hex 00000000330110; asc 3 ;; 3: len 4; hex 74657374; asc test;; 4: len 4; hex 80000001; asc ;;

*** (2) TRANSACTION:
TRANSACTION 0 772, ACTIVE 13 sec, OS thread id 4366303232
2 lock struct(s), heap size 368, undo log entries 1
MySQL thread id 1, query id 41 localhost root
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 50 n bits 72 index `PRIMARY` of table `test/entries` trx id 0 772 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000000304; asc ;; 2: len 7; hex 00000000330110; asc 3 ;; 3: len 4; hex 74657374; asc test;; 4: len 4; hex 80000001; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 50 n bits 72 index `PRIMARY` of table `test/entries` trx id 0 776 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000000304; asc ;; 2: len 7; hex 00000000330110; asc 3 ;; 3: len 4; hex 74657374; asc test;; 4: len 4; hex 80000001; asc ;;

TOO DEEP OR LONG SEARCH IN THE LOCK TABLE WAITS-FOR GRAPH
*** WE ROLL BACK TRANSACTION (2)

最初 5.6.23 を使ってやってみたら再現しなくて

これなぜかな、というのでソースコードを見比べてみた。

5.0.96

innobase/lock/lock0lock.c の lock_deadlock_recursive() を見る。

3248     for (;;) {
3249         if (lock_get_type(lock) & LOCK_TABLE) {
3250 
3251             lock = UT_LIST_GET_PREV(un_member.tab_lock.locks, lock);
3252         } else {
3253             ut_ad(lock_get_type(lock) == LOCK_REC);
3254             ut_a(bit_no != ULINT_UNDEFINED);
3255 
3256             lock = lock_rec_get_prev(lock, bit_no);
3257         }
3258 
3259         if (lock == NULL) {
3260             /* We can mark this subtree as searched */
3261             trx->deadlock_mark = 1;
3262 
3263             return(FALSE);
3264         }
3265 
3266         if (lock_has_to_wait(wait_lock, lock)) {
3267 
3268             ibool   too_far
3269                 = depth > LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK
3270                 || *cost > LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK;
3271 
3272             lock_trx = lock->trx;
3273 
3274             if (lock_trx == start || too_far) {
3275 
3276                 /* We came back to the recursion starting
3277                 point: a deadlock detected; or we have
3278                 searched the waits-for graph too long */

too_far というのが true になるとデッドロック判定。

5.6.23

storage/innobase/lock/lock0lock.cc の lock_deadlock_search() を見る。

3818     for (;;) {
3819
3820         /* We should never visit the same sub-tree more than once. */
3821         ut_ad(lock == NULL
3822               || lock->trx->lock.deadlock_mark <= ctx->mark_start);
3823
3824         while (ctx->depth > 0 && lock == NULL) {
3825             const lock_stack_t* stack;
3826
3827             /* Restore previous search state. */
3828
3829             stack = lock_deadlock_pop(ctx);
3830
3831             lock = stack->lock;
3832             heap_no = stack->heap_no;
3833             ctx->wait_lock = stack->wait_lock;
3834
3835             lock = lock_get_next_lock(ctx, lock, heap_no);
3836         }
3837
3838         if (lock == NULL) {
3839             break;
3840         } else if (lock == ctx->wait_lock) {
3841
3842             /* We can mark this subtree as searched */
3843             ut_ad(lock->trx->lock.deadlock_mark <= ctx->mark_start);
3844
3845             lock->trx->lock.deadlock_mark = ++lock_mark_counter;
3846
3847             /* We are not prepared for an overflow. This 64-bit
3848             counter should never wrap around. At 10^9 increments
3849             per second, it would take 10^3 years of uptime. */
3850
3851             ut_ad(lock_mark_counter > 0);
3852
3853             lock = NULL;
3854
3855         } else if (!lock_has_to_wait(ctx->wait_lock, lock)) {
3856
3857             /* No conflict, next lock */
3858             lock = lock_get_next_lock(ctx, lock, heap_no);
3859
3860         } else if (lock->trx == ctx->start) {
3861
3862             /* Found a cycle. */
3863
3864             lock_deadlock_notify(ctx, lock);
3865
3866             return(lock_deadlock_select_victim(ctx)->id);
3867
3868         } else if (lock_deadlock_too_deep(ctx)) {
3869
3870             /* Search too deep to continue. */
3871
3872             ctx->too_deep = TRUE;
3873
3874             /* Select the joining transaction as the victim. */
3875             return(ctx->start->id);
3876
3877         } else if (lock->trx->lock.que_state == TRX_QUE_LOCK_WAIT) {
3878
3879             /* Another trx ahead has requested a lock in an
3880             incompatible mode, and is itself waiting for a lock. */
3881
3882             ++ctx->cost;
3883
3884             /* Save current search state. */
3885             if (!lock_deadlock_push(ctx, lock, heap_no)) {
3886
3887                 /* Unable to save current search state, stack
3888                 size not big enough. */
3889
3890                 ctx->too_deep = TRUE;
3891
3892                 return(ctx->start->id);
3893             }
3894
3895             ctx->wait_lock = lock->trx->lock.wait_lock;
3896             lock = lock_get_first_lock(ctx, &heap_no);
3897
3898             if (lock->trx->lock.deadlock_mark > ctx->mark_start) {
3899                 lock = lock_get_next_lock(ctx, lock, heap_no);
3900             }
3901
3902         } else {
3903             lock = lock_get_next_lock(ctx, lock, heap_no);
3904         }
3905     }

ctx->too_deep が true になるとデッドロック扱いぽい。 で、LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK が出てこないけどそれはlock_deadlock_too_deepというマクロになってる。

3587 /** Check if the search is too deep. */
3588 #define lock_deadlock_too_deep(c)               \
3589     (c->depth > LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK        \
3590      || c->cost > LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK)

5.6.23 の方はこの定数による判定の前にいくつか条件があるので、今回試したケースではそっちに引っかかるようになってデッドロック扱いにならなかったのかなあと思った。デバッガで追ったらもうちょっとわかるかと思ってすこしやってみたけど、ブレークポイント張って複数クライアントからクエリ投げてデバッガ操作してとかやってるとロック待ちでタイムアウトしちゃったり、などという感じで難しかったので今日はここまでにしておきます。