本番環境で発生したAurora MySQL 3 系のデッドロックの原因を調査した話

 はじめにこんにちは！Webサービスやモバイルアプリの開発において、必要となる共通機能＝会員プラットフォームや決済プラットフォームなどの企画・開発を手がける共通サービス開発グループの中谷(@tksnakatani)です。
本記事では、多くの方が一度は経験したことがある「ヒヤッとするインシデント」の中から、決済プラットフォームで実際に本番環境で発生したAurora MySQLのデッドロックの事例をご紹介します。
 デッドロックが発生した状況2024年の某日、ログ監視システムからインシデント通知が届きました。通知内容を確認したところ、クレジットカード決済を実行している処理で以下のエラーログが記録されていました。
Deadlock found when trying to get lock; try restarting transaction
さらに、Slackにはプロダクト担当者から「クレジットカード決済が失敗した」という問い合わせが寄せられていました。この時点で、非常に深刻な状況だと直感し、冷や汗をかいたことを今でも鮮明に覚えています。
 原因調査 ロジック確認デッドロック自体は約30分後に自然と解消されました。

エラーが発生した時間帯には、人気商品の発売があり、その商品への購入申し込みが集中していたことが判明しました。
通常、デッドロックとは、複数のトランザクションが互いに必要なリソースを保持し合い、いずれの処理も進行できなくなる状態を指します。このような状況を想定し、負荷試験を実施していたにもかかわらず、デッドロックが発生した点は謎でした。
当初は、リソースが競合するような処理が見当たらず、理論的にはデッドロックが発生する原因を特定するのが困難な状況でした。
 再現確認次にデッドロックが発生した前後のAPIへのリクエストをローカル環境で再現することを試みました。
本番環境で問題が発生したリクエストパラメータを使用し、curlコマンドで以下の2つのリクエストをほぼ同時に送信しました。その結果、本番環境と同様に1つのリクエストは成功しましたが、もう1つのリクエストではシステムエラーが返却されました。
curlコマンドの例curl --location 'http://localhost:8080/payments/cards' \
--header 'Content-Type: application/json' \
--data '{
    "amount": 10,
    "capture": false,
    "request_id": "ITEM-20240101-0000001"
}


curl --location 'http://localhost:8080/payments/cards' \
--header 'Content-Type: application/json' \
--data '{
    "amount": 10,
    "capture": false,
    "request_id": "ITEM-20240101-0000002"
}
またエラーログには次のメッセージが出力されていました。
Deadlock found when trying to get lock; try restarting transaction
が出力されていました。
再現できたことで調査の糸口が見え、ひとまず安堵しました。
 SHOW ENGINE INNODB STATUSさらに、MySQLのSHOW ENGINE INNODB STATUSコマンドを使い、InnoDBストレージエンジンの状態を確認しました。
SHOW ENGINE INNODB STATUSコマンドでは、InnoDBストレージエンジンの状態に関する広範囲な情報を提供します。

この情報を基に、ロックやトランザクションの詳細を調べ、デッドロック発生の具体的な原因を特定するための手がかりを得ることができます。
mysql> set GLOBAL innodb_status_output=ON;
mysql> set GLOBAL innodb_status_output_locks=ON;

・・・再びcurlコマンドを使って、２つのリクエストを送信。

mysql> SHOW ENGINE INNODB STATUS;

その時の結果は以下の通りです。

※一部抜粋、マスキング処理をしています。
=====================================
2024-xx-xx 10:05:27 0x7fe300290700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 463 srv_active, 0 srv_shutdown, 7176 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 318
OS WAIT ARRAY INFO: signal count 440
RW-shared spins 290, rounds 306, OS waits 16
RW-excl spins 1768, rounds 5746, OS waits 48
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1.06 RW-shared, 3.25 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-04-18 10:04:02 0x7fe3059a4700
*** (1) TRANSACTION:
TRANSACTION 12085, ACTIVE 6 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 3
MySQL thread id 70, OS thread handle 140612935517952, query id 28138 192.168.65.1 user update
insert into payments (....
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 297 page no 5 n bits 248 index uq_payments_01 of table `payment`.`payments` trx id 12085 lock_mode X locks gap before rec
Record lock, heap no 56 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 11; hex 6d65726368616e745f3031; asc merchant_01;;
 1: len 7; hex 5041594d454e54; asc PAYMENT;;
 2: len 30; hex 6276346c6178316736367175737868757676647963356737656c616a6466; asc bv4lax1g66qusxhuvvdyc5g7elajdf; (total 32 bytes);
 3: len 30; hex 70615f666f79706161656c6a71666f663378746332366b6d61756c38676e; asc pa_foypaaeljqfof3xtc26kmaul8gn; (total 35 bytes);
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 297 page no 5 n bits 248 index uq_payments_01 of table `payment`.`payments` trx id 12085 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 56 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 11; hex 6d65726368616e745f3031; asc merchant_01;;
 1: len 7; hex 5041594d454e54; asc PAYMENT;;
 2: len 30; hex 6276346c6178316736367175737868757676647963356737656c616a6466; asc bv4lax1g66qusxhuvvdyc5g7elajdf; (total 32 bytes);
 3: len 30; hex 70615f666f79706161656c6a71666f663378746332366b6d61756c38676e; asc pa_foypaaeljqfof3xtc26kmaul8gn; (total 35 bytes);
*** (2) TRANSACTION:
TRANSACTION 12084, ACTIVE 7 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 3
MySQL thread id 69, OS thread handle 140612935812864, query id 28139 192.168.65.1 user update
insert into payments (....
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 297 page no 5 n bits 248 index uq_payments_01 of table `payment`.`payments` trx id 12084 lock_mode X locks gap before rec
Record lock, heap no 56 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 11; hex 6d65726368616e745f3031; asc merchant_01;;
 1: len 7; hex 5041594d454e54; asc PAYMENT;;
 2: len 30; hex 6276346c6178316736367175737868757676647963356737656c616a6466; asc bv4lax1g66qusxhuvvdyc5g7elajdf; (total 32 bytes);
 3: len 30; hex 70615f666f79706161656c6a71666f663378746332366b6d61756c38676e; asc pa_foypaaeljqfof3xtc26kmaul8gn; (total 35 bytes);
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 297 page no 5 n bits 248 index uq_payments_01 of table `payment`.`payments` trx id 12084 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 56 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 11; hex 6d65726368616e745f3031; asc merchant_01;;
 1: len 7; hex 5041594d454e54; asc PAYMENT;;
 2: len 30; hex 6276346c6178316736367175737868757676647963356737656c616a6466; asc bv4lax1g66qusxhuvvdyc5g7elajdf; (total 32 bytes);
 3: len 30; hex 70615f666f79706161656c6a71666f663378746332366b6d61756c38676e; asc pa_foypaaeljqfof3xtc26kmaul8gn; (total 35 bytes);
*** WE ROLL BACK TRANSACTION (2)


----------------------------
END OF INNODB MONITOR OUTPUT
============================
ここから読み取れたこととしては
TRANSACTION 12085 とTRANSACTION 12084 が存在する。
TRANSACTION 12085 とTRANSACTION 12084 が同じ「ギャップロック」を取得した。
TRANSACTION 12085 がインサートする前に「挿入インテンションギャップロック」を取得しようとしたが、TRANSACTION 12084のギャップロックと競合し待ちになった。
TRANSACTION 12084 がインサートする前に「挿入インテンションギャップロック」を取得しようとしたが、TRANSACTION 12085のギャップロックと競合し待ちになった。
MySQLがデッドロックを検知してTRANSACTION 12084をロールバックした。
 ギャップロック・挿入インテンションギャップロックとは？ギャップロック
ギャップロックは、インデックスレコード間のギャップのロック、または最初のインデックスレコードの前または最後のインデックスレコードの後のギャップのロックです。

たとえば、SELECT c1 FROM t WHERE c1 BETWEEN 10 and 20 FOR UPDATE;では、範囲内の既存のすべての値間のギャップがロックされているため、カラムにそのような値がすでに存在するかどうかにかかわらず、

他のトランザクションが 15 の値をカラム t.c1 に挿入できなくなります。
https://dev.mysql.com/doc/refman/8.0/ja/innodb-locking.html#innodb-gap-locks
挿入インテンションギャップロック
挿入意図ロックは、行の挿入前に INSERT 操作によって設定されるギャップロックのタイプです。

このロックは、同じインデックスギャップに挿入する複数のトランザクションは、そのギャップ内の同じ場所に挿入しなければ相互に待機する必要がないように、意図的に挿入することを示しています。

値が 4 と 7 のインデックスレコードが存在すると仮定します。

5 と 6 の値をそれぞれ挿入しようとする個別のトランザクションでは、挿入された行の排他ロックを取得する前に、

挿入意図ロックを使用して 4 と 7 のギャップがロックされますが、行が競合していないため相互にブロックされません。
https://dev.mysql.com/doc/refman/8.0/ja/innodb-locking.html#innodb-insert-intention-locks
ギャップロックが今回の問題につながったことが判明したため、次にクレジットカード決済処理の中でギャップロックを取得している箇所を特定する作業を進めました。
決済処理の全体の流れは、以下の3つのステップに分かれています。
同じリクエストIDで決済が行われていないか確認する
決済代行会社に決済を依頼する
決済代行会社からの結果をデータベースに書き込み、レスポンスを返す
SQLが発行される箇所を中心にブレークポイントを設定し、ローカル環境でデバッグを行ったところ、以下のクエリの実行直後にギャップロックが取得されていることが確認されました。
SELECT * FROM PAYMENTS where request_id = '' FOR UPDATE;
その時のperformance_schema.data_locksのデータが以下です。

 原因全ての情報が揃い、原因の特定が完了しました。
決済プラットフォームでは、リクエストが重複していないかを確認するためにrequest_idをリクエスト元から受け取り、この値を後続の参照にも利用するため、ユニークなインデックスを付与していました。
一方、プロダクト側ではrequest_idを以下のルールで生成していました：
商品ID-YYYYMMDD-連番
デッドロックが発生した際には、人気商品の発売により同一商品の購入リクエストが短時間に集中して送信されていました。その結果、request_idの連番部分が急速にカウントアップされたリクエストが大量に送信されました。
curlコマンドの例curl --location 'http://localhost:8080/payments/cards' \
--header 'Content-Type: application/json' \
--data '{
    "amount": 10,
    "capture": false,
    "request_id": "ITEM-20240101-0000001"
}
前述の通りクレジットカード決済処理の主な流れは以下となっています。
同じリクエストIDで決済が行われていないか確認する
決済代行会社に決済を依頼する
決済代行会社からの結果をデータベースに書き込み、レスポンスを返す
問題は、1つ目の処理で発生しました：
SELECT * FROM PAYMENTS where request_id = '' FOR UPDATE;
このクエリは、通常は同じrequest_idのリクエストが来ない前提で実行されます。しかし、当該request_idのデータのINSERT前であるため、クエリが空振りしギャップロックを取得しました。
その後、3つ目の処理で結果を書き込むINSERT処理が発生し、挿入インテンションギャップロックを取得しようとしました。しかし、すでに取得されていたギャップロックと競合し、待ちが発生。その結果、MySQLがデッドロックを検知し、1つのトランザクションがロールバックされました。
 解決策重複決済の確認用として使用していたSELECT FROM ... FOR UPDATEが原因であることが判明したため、このクエリを廃止しました。代わりに、リクエストを受け付けた時点でデータを仮登録し、トランザクションをコミットする設計に変更しました。
コミットのタイミングが増えることでパフォーマンス劣化が懸念されましたが、負荷テストにより必要な性能を担保できることが確認されたため、この仕様でリリースしました。
 反省ギャップロックについての理解が十分ではありませんでした。

SELECT FROM ... FOR UPDATE で結果が0件の場合にギャップロックが取得されることを十分に理解していませんでした。普段からマニュアルをよく読み、設計に取り入れているつもりでしたが、すべてを知った気になっていたと反省しています。

https://dev.mysql.com/doc/refman/8.0/ja/innodb-locking.html
また、テストで気付けるポイントがあったことも残念に感じています。
負荷テストではインデックスの断片化や再構築によるパフォーマンス劣化を懸念し、request_idにランダムな値（UUID）を使用していました。このためデッドロックが発生せず、テストは正常に完了していました。
 まとめMySQLやInnoDBストレージエンジンを扱う際には、トランザクションやロックの動作を深く理解することが非常に重要です。日頃からドキュメントや仕様をしっかり読み込み、必要に応じて有識者のサポートを得ることの重要性を改めて認識しました。
また、本番環境で実際に利用されているパラメータを調査し、それに基づいたリクエスト値を使用してテストを行うことが、問題の早期発見や品質向上につながると学びました。