mixi engineer blog

＊＊＊ 引っ越しました。最新の情報はこちら → https://medium.com/mixi-developers ＊＊＊ ミクシィ・グループで、実際に開発に携わっているエンジニア達が執筆している公式ブログです。様々なサービスの開発や運用を行っていく際に得た技術情報から採用情報まで、有益な情報を幅広く取り扱っています。

MySQLのInnoDBでのデッドロック

mixi MySQL

こんにちは、mixi開発部にてアプリケーション開発をしていますyouheiです。
今回は、MySQL-5.0.45のInnoDBで連番を管理するテーブルのパフォーマンス測定をしていたのですが、その際に少し変わったデッドロック問題に遭遇しましたので、そのあたりをネタとして書いてみたいと思います。

まずは、今回使用したデータベースのスキーマは下記のようなものです。 

CREATE TABLE num (
    id bigint unsigned NOT NULL default '0'
) Engine=InnoDB;

AUTO_INCREMENTは使用していません。
そこに1レコードだけ登録します。 

INSERT INTO num (id) values (1);

そして実際連番を取得する際には、 

UPDATE num SET id = LAST_INSERT_ID(id+1);

といったクエリを発行しインクリメントしていき、最新のidはSELECTするのではなくUPDATE時のMySQL応答パケットに含まれるmysql_insertidを参照します。

上記のような内容をベンチマークテストのために同時接続を増やしながらテストしていると、350を超えたあたりで 

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 */
457
458         if (thd) {
459             ha_rollback(thd);
460         }
461
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);
3837
3838     innodb_srv_conc_exit_innodb(prebuilt->trx);
3839
3840     if (ret == DB_SUCCESS) {
3841         error = 0;
3842         table->status = 0;
3843
3844     } else if (ret == DB_RECORD_NOT_FOUND) {
3845         error = HA_ERR_KEY_NOT_FOUND;
3846         table->status = STATUS_NOT_FOUND;
3847
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);
3191
3192   if (ret == LOCK_VICTIM_IS_OTHER) {
3193     /* We chose some other trx as a victim: retry if there still
3194     is a deadlock */
3195
3196     goto retry;
3197   }
3198
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     }
3207
3208     lock_deadlock_found = TRUE;
3209
3210     fputs("*** WE ROLL BACK TRANSACTION (2)n",
3211       lock_latest_err_file);
3212
3213     return(TRUE);
3214   }

というわけで、lock_deadlock_recursive()のreturnがLOCK_VICTIM_IS_STARTの場合に真が返るようです。
少々疲れてきましたがさらに追います。以下が、lock_deadlock_recursive() の戻り値がLOCK_VICTIM_IS_START になる条件です。 

3351                 if (too_far) {
3352
3353                     fputs("TOO DEEP OR LONG SEARCH"
3354                           " IN THE LOCK TABLE"
3355                           " WAITS-FOR GRAPHn", ef);
3356
3357                     return(LOCK_VICTIM_IS_START);
3358                 }
3359
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 */
3366
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
49
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文でデッドロックだとエラーメッセージが返却された場合にこのような例もあったなということを思い出していただけると幸いです。