VISITS Advent Calendar 22日目の記事です。

いま自分のチームではRailsのアプリケーションを運用しているのですが、MySQLのデータベースでごくまれにbulkのinsertでデッドロックが発生して原因究明に時間がかかったので、その内容を共有したいと思います。

状況

今回自分が遭遇したデッドロックは、RailsのコードからMySQLのDBに対して複数件のデータを一括挿入するタイミングで発生しました。

Rails6.0からbulk insertの機能が標準サポートされたんですが、Rails6.0以前ではactiverecord-importというgemで対応するケースが多いかと思います。
運用中のアプリケーションもRails6.0以前から運用していたこともあって切り替えられていないところも多く、今回のデッドロックもactiverecord-importの箇所で発生しました。

発生当時のライブラリ等のバージョンは以下の通りです。

ライブラリ	バージョン
ruby	2.6.5
Rails	6.0.3.2
MySQL	5.7.25
activerecord-import	0.27.0

挿入対象のテーブルは以下のような構成です（カラム名は適当に変えてます)。

CREATE TABLE `hoges` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `first` int(11) NOT NULL,
  `second` int(11) NOT NULL,
  `num` int(11) NOT NULL,
  `created_at` datetime NOT NULL,
  `updated_at` datetime NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `index_hoges_on_first_and_second` (`first`,`second`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

idがPKで設定されている他、(first, second)の組でユニークキーが設定されています。

このテーブルに対して、Railsから複数件のデータを突っ込みます。
コードとしては、

def save_hoges(first, seconds)
  hoges = seconds.map.with_index do |second, index|
    Hoge.new(first: first, second: second, num: index)
  end
  Hoge.import! hoges
end

といった形で、save内でfirstが一つの値、secondが重複なしで色々な値を取るようなイメージです。

Hoge.import!の部分がactiverecord-importを利用した部分です。
ここでは以下のようなクエリが発行されます。

INSERT INTO `hoges`
  (`id`,`first`,`second`,`num`,`created_at`,`updated_at`)
VALUES
  (...)
ON DUPLICATE KEY UPDATE `hoges`.`updated_at`=VALUES(`updated_at`)

そして今回、このinsert処理が同時に走ったためにデッドロックしてしまいました。

よくあるデッドロック

よくあるデッドロックになるケースは、2つのトランザクション(trx1, trx2)において

trx1: ある範囲にロックを取るクエリを実行
trx2: trx1のロック範囲にかぶる範囲にロックを取るクエリを実行しようとして待たされる
trx1: trx2がロックを取ろうとした範囲にロックを取るクエリを実行する => デッドロック!

という流れで、複数の処理が絡む場合が多いかと思います。

例えば、

trx1> BEGIN;
trx1> DELETE FROM hoges WHERE id = 1;

trx2> BEGIN;
trx2> UPDATE hoges SET num = 3 WHERE id = 1;

trx1> INSERT hoges (id, num) VALUES (1, 2); -- => deadlock!

のように、trx1でid=1をdeleteしてからinsertし、trx2でupdateかけようとすると、trx2が待たされた上でtrx1の2つ目も待たされてデッドロックになる、といった具合に複数のクエリが絡むことが多いかと思います。

一方クエリは一つでもbulkの場合は処理が複数になるためロックするケースもあります。

例えば以下のように、ユニークなカラムにまったく同時に昇順と降順でそれぞれ値を入れた場合、途中で値がかぶってしまってお互いそれ以降の処理ができなくなり、どちらかがrollbackされます。

trx1> INSERT INTO hoges (id) VALUES (1), (2), (3), ..., (98), (99);

trx2> INSERT INTO hoges (id) VALUES (99), (98), ... (3), (2), (1);

こちらの記事などでも紹介されているように、ユニーク制約があるケースで値が重複する場合は挿入順を揃えるといったことが解決策の一つです。
上のケースでは、trx2を1-99に並べておけば後に実行された方は値を入れられずエラーになります。（その場合は重複エラーになるのでそれはそれですけど、、）

とはいえ基本的には、よほど件数が多くて処理時間が長くなってしまったか、本当に間が悪く同時に処理を行った場合くらいにしか遭遇しなかったりします。

今回のケース

実際にデッドロックしたクエリは以下の2つのクエリです。(こちらも値を一部変えたりしています)

trx1

INSERT INTO `hoges`
  (`id`,`first`,`second`,`num`,`created_at`,`updated_at`)
VALUES
  (NULL,337,59,0,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  (NULL,337,311,1,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  (NULL,337,313,2,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  :
  (NULL,337,204,19,'2020-11-20 07:34:17','2020-11-20 07:34:17')
ON DUPLICATE KEY UPDATE `hoges`.`updated_at`=VALUES(`updated_at`)

trx2

INSERT INTO `hoges`
  (`id`,`first`,`second`,`num`,`created_at`,`updated_at`)
VALUES
  (NULL,336,41,0,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  (NULL,336,322,1,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  (NULL,336,57,2,'2020-11-20 07:34:17','2020-11-20 07:34:17'),
  :
  (NULL,336,611,19,'2020-11-20 07:34:17','2020-11-20 07:34:17')
ON DUPLICATE KEY UPDATE `hoges`.`updated_at`=VALUES(`updated_at`)

値が重複した？

まずよくあるケースで出てくるユニーク制約で値が重複したか見てみますが、(first, second) に関しては、firstはクエリごとに違う値(trx1で337、trx2で336)になっており、secondもクエリ内で異なる値になるため、(first, second)の組で値がかぶることはありません。

続いてPKですが、idはNULLなのでAUTO INCREMENTで値が入る想定です。

最初はこのidを取り合ってロックになったのかなと思ったのですが、調べてみるとinsertやinsert on duplicate key updateの場合は、「単純挿入」や「混在モード挿入」といったステートメントとして、先に件数分idを確保してしまうようです。

実際にdeadlockして生き残った方のデータを見てみてもidはきちんと連番になっており、rollbackした方は欠番になっていました。

ということで値重複の線はなさそうです。

ログを見る

こういうときは想像するよりも実際にログを見た方が早いですね。
deadlock周りのログを確認すると以下のようなログが出ていました。（ここも一部値変えたりしていて整合してないところあると思いますが、雰囲気だけ読み取っていただければ）

2020-11-20T07:34:17.385922Z 530894 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

2020-11-20T07:34:17.385945Z 530894 [Note] InnoDB:
*** (1) TRANSACTION:
TRANSACTION 95401769, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 530611, OS thread handle 140455369062144, query id 64945180 127.0.0.1 root update
INSERT INTO `hoges` (`id`,`first`,`second`,`choice_num`,`created_at`,`updated_at`) VALUES ...

2020-11-20T07:34:17.385983Z 530894 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 77 page no 33036 n bits 576 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401769 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;;

2020-11-20T07:34:17.386062Z 530894 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 95401768, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 5
MySQL thread id 530894, OS thread handle 140455383664384, query id 64945179 127.0.0.1 root update
INSERT INTO `hoges` (`id`,`first`,`second`,`choice_num`,`created_at`,`updated_at`) VALUES ...

2020-11-20T07:34:17.386091Z 530894 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 77 page no 33036 n bits 568 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401768 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;;

2020-11-20T07:34:17.386160Z 530894 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 77 page no 33036 n bits 576 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401768 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;;

2020-11-20T07:34:17.386234Z 530894 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1)

注目したのは以下のロック周りのログです。

1) WAITING FOR THIS LOCK TO BE GRANTED:
... n bits 576 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401769 lock_mode X insert intention waiting

(2) HOLDS THE LOCK(S):
... n bits 568 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401768 lock_mode X

(2) WAITING FOR THIS LOCK TO BE GRANTED:
... n bits 576 index index_hoges_on_first_and_second of table `database`.`hoges` trx id 95401768 lock_mode X insert intention waiting

これを見る限り、ロックはユニーク制約のインデックスの方で発生しています。
見方があってるかわかりませんが、流れとしては、

trx2は排他ネクストキーロックを取得している(n bits 568に相当する部分からsupremumまで?)
trx1は挿入インテンションギャップロックを取得しようとして待たされる(n bits 576なのでtrx2のロック範囲?)
trx2はさらに同じ範囲で挿入インテンションギャップロックを取得しようとして待たされる => デッドロック

みたいなことが起きた感じでしょうか？

なおlock_mode Xなどの表記の分類は以下のような認識でした。

lock_mode X locks rec but not gap: レコードロック
lock_mode X locks gap before rec: ギャップロック
lock_mode X: ネクストキーロック
lock_mode X locks gap before rec insert intention: 挿入インテンションギャップロック

lock_mode X insert intention waitingは gap before recがないけど同じく挿入インテンションギャップロックでしょうか。

今回はtrx2で排他ネクストキーロックが設定されていますが、発生するロックタイプを調べてみると、

INSERT は、挿入される行に排他ロックを設定します。このロックは、ネクストキーロックではなくインデックスレコードロックである (つまり、ギャップロックが存在しない) ため、ほかのセッションが挿入された行の前にあるギャップに挿入することは回避されません。

とあるので、これに該当した場合はlock_mode Xではなくlock_mode X but not gapになりそうです。
また、

INSERT ... ON DUPLICATE KEY UPDATE は、重複キーエラーが発生したときに、更新される行に共有ロックではなく、排他ネクストキーロックが配置されるという点で、単純な INSERT と異なります。

ということで、重複エラーが発生した場合は排他ネクストキーロック(lock_mode X)になるということですが、さきほどの話で重複はしなかったはずなのでこのケースでもなさそうです。

僥倖現る

長いこと調べていたんですが、最近になって一番近そうな記事を見つけました。

こちらの記事では、PKとUNIQUEなカラムがあるところでinsert on duplicate key updateすると、値の重複がないのにも関わらずギャップロックしてしまってデッドロックすると書かれていました(以下一部抜粋)。

CREATE TABLE `test_table` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`num` int(10) unsigned DEFAULT NULL,
`name` varchar(45) DEFAULT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `num_index` (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=138 DEFAULT CHARSET=utf8;

+----+------+-------+
| id | num  | name  |
+----+------+-------+
|  1 |   28 | Alice |
|  2 |   35 | Bob   |
|  3 |   40 | Jerry |
|  4 |   20 | Tom   |
|  5 |   51 | Mary  |
+----+------+-------+

-- First connection:
INSERT INTO test_table (id, num, name) VALUES (6, 36, "John") ON DUPLICATE KEY UPDATE name="John";

-- Second connection:
INSERT INTO test_table (id, num, name) VALUES (7, 37, "Mia") ON DUPLICATE KEY UPDATE name="Mia";

-- First connection: Deadlock!
INSERT INTO test_table (id, num, name) VALUES (8, 39, "Emilie") ON DUPLICATE KEY UPDATE name="Emilie";

最終的にinsertに変更したら解決したということで、重複エラー発生してないのに変な話だなと思っていたんですが、試しに手元でやってみてもロックが再現せず。。

まさか間違って投稿したのかと思いきや、よくよく手元のMySQLのバージョンを見ると5.7.29。
記事では5.7.25。

どうもそこに原因がありそうです。

結局のところ

5.7.26のリリース内容を見ていたら、insert on duplicate key update周りのバグfixについての言及が。

InnoDB: Two sessions concurrently executing an INSERT ... ON DUPLICATE KEY UPDATE operation generated a deadlock. During partial rollback of a tuple, another session could update it. The fix for this bug reverts fixes for Bug #11758237, Bug #17604730, and Bug #20040791. (Bug #25966845)

直接的には別のケースでのdeadlockを修正したようですが、5.7.25 <> 5.7.26前後で上記test_tableのdeadlockは直っていました。

fixのコメントを追っかけていても最終的な原因が分かりませんでしたが、ひとまず今回起きた結果からはinsert on duplicate key updateのときだけユニーク制約のindexに対して(重複してるかに依らず)排他ネクストキーロックを取ってしまい、deadlockしやすくなっていたと推測しました。

自分のケースでは、

trx2: first=336のネクストキー(つまり336からsupremumまで)でロック
trx1: first=337のinsertはtrx2のネクストキーに引っかかり待たされる
trx2: first=336で、直前に取ったロック範囲の方にinsertしようとしてtrx1とバッティング

のような流れが1案として考えられるかと思いました。
（この辺は全然確証がないので詳しい方いらっしゃればご指摘いただければありがたいです。）

ちなみに

そもそもPKとは別にユニーク制約があるテーブルに対して、insert on duplicate key updateは非推奨だったりします。

一般に、一意のインデックスが複数含まれているテーブルに対して ON DUPLICATE KEY UPDATE 句を使用することは避けるようにしてください。
:
さらに、MySQL 5.6.6 からは、一意のキーまたは主キーが複数含まれているテーブルに対する INSERT ... ON DUPLICATE KEY UPDATE ステートメントも安全ではないとしてマークされます。

たしかにユニーク制約が複数含まれているとなると、どのインデックスを使うかが安定しないのでロックも難しくなりそうです。

一方、Railsで普通にモデルを組むとサロゲートキーとしてidを設定することになるため、複数のユニーク制約がかかることはそれなりに発生するケースであるように思えます。
そういう意味ではon duplicate key updateを使用する場面に気をつける必要があります。

実はactiverecord-importもv1.0.0でon duplicate key updateによってupdated_atをupdateするのを辞めたようですので、v1.0.0以降をお使いの場合は大丈夫そうです。

逆にbulk時にupdated_atが更新できなくなるという話もあります。
一応activerecord-importで今まで通り更新するためには、以下のように明示的にカラムを指定すれば可能です。

Hoge.import!(hoges, on_duplicate_key_update: [:updated_at])

この辺はアプリケーションのupdated_atの取り扱い方のルールに依ると思いますが、無理にon duplicate key updateするよりはDBの自動更新機能などを用いて更新しておいた方が無難かもしれません。

Rails6.0に追加されたinsert_all/upsert_all等のbulk処理は一つのメソッドで追加と更新を混ぜて行えないようになっていて、こういう事態を引き起こさないためにあえて混ぜられないようにしているのかもしれません。

今回はactiverecord-importを使うことで意図せずon duplicate key updateが付与されてしまっていたんですが、ライブラリを使う際には注意が必要ですね。

対策

ということで、今回は色々ケースが重なってデッドロックしてしまったと思われるのですが、

MySQL5.7.26以降にする
複数ユニーク制約があるテーブルでは極力insert on duplicate key updateしない

のどちらかでもしていれば大丈夫でした。

前者は運用中のDBのバージョンアップは気を使ったり、そもそもGCPなどクラウドを使っていると指定できなかったりするケースもあって難しさを感じます。

一方後者は、activerecord-importのバージョンが低かったり、新しい形式に移行できていないなど、アプリケーション側で対応できる範囲でした。

改めて日々のメンテナンスの重要性を感じるいい機会になったと思います。

おわりに

ということでMySQLのbulk insertで発生したデッドロックの共有でした。
ロック周りは難しいので勘違いしているところもあるかと思いますが、もしお気づきの点があればご指摘いただければ。

参考にさせていただいた記事など

bulkのinsert on duplicate key updateでデッドロックした話

状況