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