ERROR 1213 (40001): Deadlock found when trying to get lock
というエラーが発生するという事態に遭遇しました（350という具体的な数値はハードウェアの性能などで変動すると思います）。ちなみに試験環境のOSやMySQLのバージョンは簡単ですが下記のような感じです。
MySQL-5.0.45
Linux-2.6.22
まずはWebで検索してみる
筆者の英語力不足という説もありますが、なかなか「コレ！」というものが見つけられませんでした。
パラメータやSQL文等を色々試してみる
1カラムしかないのが逆に良くないのかと思い、主キーカラムを追加しWhere句で指定 → 変化なし
autocommitなのが良くないのかと思い、start transaction(またはbegin)とcommitを発行する → 変化なし
トランザクション分離レベルをserializableに変えてみる → 変化なし
innodb_table_locksパラメータを0にしてみる → 変化なし
他にもいくつか試しました。また、それらを組み合わせてみたりもしましたが解決しません。なので、ソースを読んでみることにします。
静的デバッグ
MySQLのソースの取得・展開は済んでおり、ソース群のトップディレクトリにいるものとします。
エラー番号は1213と分かっているので、ヘッダファイルに対してgrepをかけてみます。
% find ./ -name \\*.h | xargs grep -rn 1213
./include/mysqld_error.h:217:#define ER_LOCK_DEADLOCK 1213
./include/mysqld_ername.h:216:{ "ER_LOCK_DEADLOCK", 1213 },
となるので、今度はER_LOCK_DEADLOCKを参照しているところを探してみます。
% global -r ER_LOCK_DEADLOCK
include/sql_state.h
libmysqld/handler.cc
libmysqld/lock.cc
sql/handler.cc
sql/lock.cc
sql/slave.cc
./sql/handler.cc か ./sql/lock.cc あたりが怪しそうです。そしてどちらを見てみても、
case HA_ERR_LOCK_DEADLOCK:
textno=ER_LOCK_DEADLOCK;
となっているため、実際にはストレージエンジンレイヤーより HA_ERR_LOCK_DEADLOCK が返却された場合に前述のエラーが返却されるのであろうと予想がつきます（定数もファイル名もHA_(ha_)から始まるのは大体ストレージエンジンレイヤーです）。
というわけでinnodb関連のファイルで上記定数を使用しているところを探してみます。
% global -rx HA_ERR_LOCK_DEADLOCK
HA_ERR_LOCK_DEADLOCK 462 sql/ha_innodb.cc return(HA_ERR_LOCK_DEADLOCK);
おそらくこのあたりであろうと思われます。というわけで実際に動かしながらのデバッグに移ります。
動的デバッグ
gdbやddd等を使って上記付近の場所にブレークポイントをはってみます。今回は458行目にはりました。
453 } else if (error == (int) DB_DEADLOCK) {
454 /* Since we rolled back the whole transaction, we must
455 tell it also to MySQL so that MySQL knows to empty the
456 cached binlog for this transaction */
458 if (thd) {
459 ha_rollback(thd);
460 }
462 return(HA_ERR_LOCK_DEADLOCK);
そして高負荷をかけてみて引っかかるのを待ちます。しばらく待ってみると...見事ひっかかりました！下記がその際のbacktraceです（引数の値やライブラリのパス等は伏せさせていただいてます）。
(gdb) bt
#0 convert_error_code_to_mysql at ha_innodb.cc:458
#1 0x0829656a in ha_innobase::index_read at ha_innodb.cc:3852
#2 0x08293143 in ha_innobase::index_first at ha_innodb.cc:4083
#3 0x08295ec8 in ha_innobase::rnd_next at ha_innodb.cc:4177
#4 0x08280bf3 in rr_sequential at records.cc:295
#5 0x0823ce9f in mysql_update at sql_update.cc:460
#6 0x081c61ac in mysql_execute_command at sql_parse.cc:3465
#7 0x081cb975 in mysql_parse at sql_parse.cc:6097
#8 0x081cdc2a in dispatch_command at sql_parse.cc:1812
#9 0x081cf08f in do_command at sql_parse.cc:1586
#10 0x081d0018 in handle_one_connection at sql_parse.cc:1197
#11 0x005e045b in start_thread ()
#12 0x004c223e in clone ()
正常時は#0のconvert_error_code_to_mysqlは通らないのですが、#1のha_innobase::index_read() は通るようなので、どうやらこの中でデッドロックか正常か分かれるようです。というわけで実行を一時中断して再度ソースコードに戻ります。ha_innobase::index_read() のリターン周辺をみてみると、
3836 ret = row_search_for_mysql((byte*) buf, mode, prebuilt, match_mode, 0);
3838 innodb_srv_conc_exit_innodb(prebuilt->trx);
3840 if (ret == DB_SUCCESS) {
3841 error = 0;
3842 table->status = 0;
3844 } else if (ret == DB_RECORD_NOT_FOUND) {
3845 error = HA_ERR_KEY_NOT_FOUND;
3846 table->status = STATUS_NOT_FOUND;
3848 } else if (ret == DB_END_OF_INDEX) {
3849 error = HA_ERR_KEY_NOT_FOUND;
3850 table->status = STATUS_NOT_FOUND;
3851 } else {
3852 error = convert_error_code_to_mysql((int) ret, user_thd);
3853 table->status = STATUS_NOT_FOUND;
3854 }
となっており、retの値、すなわち row_search_for_mysql()の戻り値により正常かデッドロックか分かれているようです。なので、row_search_for_mysql() を追ってみます。
% global -x row_search_for_mysql
row_search_for_mysql 3041 innobase/row/row0sel.c row_search_for_mysql(
3040 ulint
3041 row_search_for_mysql(
3042 /*=================*/
3043 /* out: DB_SUCCESS,
3044 DB_RECORD_NOT_FOUND,
3045 DB_END_OF_INDEX, DB_DEADLOCK,
3046 DB_LOCK_TABLE_FULL, DB_CORRUPTION,
3047 or DB_TOO_BIG_RECORD */
3048 byte* buf, /* in/out: buffer for the fetched
3049 row in the MySQL format */
3050 ulint mode, /* in: search mode PAGE_CUR_L, ... */
3051 row_prebuilt_t* prebuilt, /* in: prebuilt struct for the
3052 table handle; this contains the info
3053 of search_tuple, index; if search
3054 tuple contains 0 fields then we
3055 position the cursor at the start or
3056 the end of the index, depending on
3057 'mode' */
3058 ulint match_mode, /* in: 0 or ROW_SEL_EXACT or
3059 ROW_SEL_EXACT_PREFIX */
3060 ulint direction) /* in: 0 or ROW_SEL_NEXT or
3061 ROW_SEL_PREV; NOTE: if this is != 0,
3062 then prebuilt must have a pcur
3063 with stored position! In opening of a
3064 cursor 'direction' should be 0. */
3065 {
というように DB_DEADLOCK を返却することがあるようなのですが、このファイル内にはDB_DEADLOCKという定数は現れません。なので、内部で何かの関数を呼び、そのreturnがDB_DEADLOCKで、それをそのままreturnしているのではないかと予想します。
なので、DB_DEADLOCKをreturnしてそうなところを探してみます。
% global -rx DB_DEADLOCK innobase/
DB_DEADLOCK 1850 innobase/lock/lock0lock.c return(DB_DEADLOCK);
DB_DEADLOCK 3557 innobase/lock/lock0lock.c return(DB_DEADLOCK);
DB_DEADLOCK 519 innobase/row/row0mysql.c } else if (err == DB_DEADLOCK
DB_DEADLOCK 1420 innobase/srv/srv0srv.c trx->error_state = DB_DEADLOCK;
DB_DEADLOCK 1514 innobase/srv/srv0srv.c trx->error_state = DB_DEADLOCK;
DB_DEADLOCK 453 libmysqld/ha_innodb.cc } else if (error == (int) DB_DEADLOCK) {
DB_DEADLOCK 453 sql/ha_innodb.cc } else if (error == (int) DB_DEADLOCK) {
先頭2つが怪しそうです。見てみると、1850行目と3557行目を見てみると、両方とも lock_deadlock_occurs() の戻り値が真であればDB_DEADLOCKを返却するようです。なので lock_deadlock_occurs() の内部を更に追ってみます。
3190 ret = lock_deadlock_recursive(trx, trx, lock, &cost, 0);
3192 if (ret == LOCK_VICTIM_IS_OTHER) {
3193 /* We chose some other trx as a victim: retry if there still
3194 is a deadlock */
3196 goto retry;
3197 }
3199 if (ret == LOCK_VICTIM_IS_START) {
3200 if (lock_get_type(lock) & LOCK_TABLE) {
3201 table = lock->un_member.tab_lock.table;
3202 index = NULL;
3203 } else {
3204 index = lock->index;
3205 table = index->table;
3206 }
3208 lock_deadlock_found = TRUE;
3210 fputs("*** WE ROLL BACK TRANSACTION (2)n",
3211 lock_latest_err_file);
3213 return(TRUE);
3214 }
というわけで、lock_deadlock_recursive()のreturnがLOCK_VICTIM_IS_STARTの場合に真が返るようです。
少々疲れてきましたがさらに追います。以下が、lock_deadlock_recursive() の戻り値がLOCK_VICTIM_IS_START になる条件です。
3351 if (too_far) {
3353 fputs("TOO DEEP OR LONG SEARCH"
3354 " IN THE LOCK TABLE"
3355 " WAITS-FOR GRAPHn", ef);
3357 return(LOCK_VICTIM_IS_START);
3358 }
3360 if (ut_dulint_cmp(wait_lock->trx->undo_no,
3361 start->undo_no) >= 0) {
3362 /* Our recursion starting point
3363 transaction is 'smaller', let us
3364 choose 'start' as the victim and roll
3365 back it */
3367 return(LOCK_VICTIM_IS_START);
3368 }
いよいよ大詰めな感じです。ここで再度デバッガを使ってみましたところ、どうやらtoo_farフラグが立っているようで、3357行目のほうに引っかかります。too_farは、
3293 ibool too_far
3294 = depth > LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK
3295 || *cost > LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK;
のようです。depthは本関数の引数で与えられ、再帰呼び出しの直前にインクリメントされる値です。また、これら2つの定数は同ファイルにて下記のように定義されています。
46 /* Restricts the length of search we will do in the waits-for
47 graph of transactions */
48 #define LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK 1000000
50 /* Restricts the recursion depth of the search we will do in the waits-for
51 graph of transactions */
52 #define LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK 200
too_farフラグが立った時、結局どちらの制限にひっかかっていたかというと、LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK のほうでした。
ここまで分かってから再度Webを検索してみるといとも簡単に見つかりました。
http://bugs.mysql.com/bug.php?id=12588 （リンク先はMySQL AB社のサイトです）
どうやらbug fixとして5.0.13以降で追加された定数・ロジックのようです。
高負荷時にロックが増加した際、デッドロック検出のための再帰呼び出しの深さが深くなりすぎてスタックを消費していきデーモンごと落ちてしまう、という問題を解決するために追加したようです。
と、ここまで分かると次に気になるのは、この値をもう少し増やしてみたらどうだろうか、というところです。
ですが、結論からいいますと、サーバーのハードのスペックにもよりますが、今回の検証用環境では多少の増加は出来ましたが、さらに負荷を上昇させていくとロック待ち時間が増加し、その結果innodb_lock_wait_timeoutに引っかかり始めました。じゃあinnodb_lock_wait_timeoutも増加させればいいじゃないか、と考えもしましたが、ただ実際にはそれによりパフォーマンスが向上するわけではなく、「90秒や120秒待てばデッドロック扱いもタイムアウト扱いもせずSQLが完了します」というのは、MySQL的にはエラーでなくとも実際のシステム的にはエラーも同然ですのであまり意味がないのではないかと判断しました。というわけで、現在mysqldを動作させる一般的なハードウェア上では200という数字はそれなりに適切な値なのではないかと思いました。
ちなみにMyISAMではこのような問題は起こらず、パフォーマンスも良好な結果でした。システムの要件にもよりますが、MyISAMに変更しても問題ない場合はそちらも検討されるのも良いかと思います。
デッドロックになるはずのないSQL文でデッドロックだとエラーメッセージが返却された場合にこのような例もあったなということを思い出していただけると幸いです。
