こんにちは、DBREの周東（X: @dev_kngnr）です。
DBRE では、freee の全プロダクトが利用するデータストア層の信頼性向上をミッションとしています。その活動の一環としてDB障害の原因の調査や、再発防止策の検討を行っています。この記事では、freee のとあるサービスで実際に起こった DB 障害と、その引き金となった MySQL のロック継承の仕組みについて紹介します。
概要
今回紹介するDB障害では、Aurora MySQL への接続失敗が頻発し、最終的には Web を開くこともできない状態にまで発展しました。原因を調査したところ、ROLLBACK TO SAVEPOINTによって引き起こされるロック継承が予期しないロックを発生させることが判明しました。この挙動とロングトランザクションが組み合わさることによって、たった一行のレコードロックのロールバックが Web サービス全体をダウンさせる原因となった事例です。
障害の原因となった SAVEPOINT を利用したロールバックは、社内でも Rails の Active Record で無意識に利用されているケースが散見されました。具体的には、ActiveRecord::Base.transactionにrequires_new: trueを指定すると内部で SAVEPOINT を利用するようになります。また、#create_or_find_by #find_or_create_byなども内部でActiveRecord::Base.transaction(requires_new: true)を呼び出しており、利用には注意が必要です。
DB障害発生時の状況
DB障害発生時の Aurora MySQL の Writer インスタンスの状況は以下のようなものでした。
- CPU使用率（CPUUtilization） / 使用可能メモリ量（FreeableMemory） ともに異常はなく、高負荷状態とは言えない
- ロックによって待ち状態になったトランザクション数（BlockedTransactions）が急増している
- DB接続数（DatabaseConnections）が急増し、上限値に到達している
Web アプリケーション側は、DB が応答せずタイムアウトが頻発し新規のDB接続を行うことができないため、Web ページが開けずにサービス全体がダウンしている状況に陥りました。
問題の調査
Database Insights から実行されたSQLステートメントの状況を確認したところ、障害発生時刻付近で特定のテーブルへの INSERT がwait/synch/cond/innodb/row_lock_wait（行ロック待機）を起こしており、該当テーブルへのレコード追加がブロックされていました。 freee ではテーブルの主キーに AUTO_INCREMENT 値を用いており、新規レコードのINSERTがブロックされるようなギャップロックを取得するといったことは通常であれば考えにくいため、奇妙な状況です。
問題となったロック待機の詳細を SHOW ENGINE INNODB STATUS のログから確認してみると、 Primary Index の supremum に対して排他ロックを取得しているロングトランザクションが存在することがわかりました。この状況においては、 supremum に対する insert intention lock が取得できないため、テーブルへの INSERT が全てブロックされることになります。
RECORD LOCKS space id XXXXX page no XXXXXXXXX n bits XX index PRIMARY of table `XXXX`.`XXXX` trx id XXXXXXXXXXXX lock_mode X Record lock, heap no X PHYSICAL RECORD: n_fields X; compact format; info bits X 0: len 8; hex XXXXXXXXXXXXXXXX; asc supremum;;
insert intention lockとは
MySQL ではデフォルトのトランザクション分離レベルが REPEATABLE READ になっています。トランザクション中のファントム行の発生を許容しないため、通常のレコードロックだけでなくレコード間の隙間（ギャップ）にもギャップロックを取得します。 INSERT を実行する際には、まず挿入対象のギャップに対してinsert intention lock と呼ばれる特殊なギャップロックを取得します。insert intention lock が競合するのはその他のギャップロックのみです。supremumとは
supremumは、 MySQL における末尾のレコードより後にくるギャップを表す仮想的な上限値です。 auto_increment な主キーを採用する場合、 insert intention lock は Primary Index では supremum に対して取得されます。この supremum に対する排他ロック（ supremum ロック）をロングトランザクションが長時間保持し続けたことにより、多くのスレッドが supremum ロックの解放を待機し続ける状態で滞留してコネクションの枯渇とサービス停止に繋がっていました。
supremumロックの再現方法
問題を引き起こしたロングトランザクションでは、該当テーブルへロックを取得する処理が INSERT のみでした。それ以外には、その他のテーブルへの SELECT / UPDATE や SAVEPOINT / ROLLBACK TO SAVEPOINT です。これらを組み合わせて supremum ロックを再現するには、以下のステップを踏む必要があります。
- トランザクション開始
- 任意の読み取り
- SAVEPOINT発行
- 該当テーブルへの INSERT
- SAVEPOINT への ROLLBACK
実際に再現実験をしてみると、ROLLBACK 前後で supremum ロックが追加されていることがわかります。
mysql> CREATE TABLE supremum_lock_1 (id INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB; Query OK, 0 rows affected (0.02 sec) mysql> CREATE TABLE supremum_lock_2 (id INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB; Query OK, 0 rows affected (0.02 sec) mysql> INSERT INTO supremum_lock_1 VALUES (), (); Query OK, 2 rows affected (0.01 sec) Records: 2 Duplicates: 0 Warnings: 0 mysql> INSERT INTO supremum_lock_2 VALUES (), (); Query OK, 2 rows affected (0.01 sec) Records: 2 Duplicates: 0 Warnings: 0 mysql> BEGIN; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM supremum_lock_2 WHERE id = 2; +----+ | id | +----+ | 2 | +----+ 1 row in set (0.00 sec) mysql> SAVEPOINT sp; Query OK, 0 rows affected (0.00 sec) mysql> INSERT INTO supremum_lock_1 VALUES (); Query OK, 1 row affected (0.01 sec) mysql> SELECT THREAD_ID, OBJECT_NAME, LOCK_TYPE, LOCK_MODE, LOCK_STATUS, LOCK_DATA FROM performance_schema.data_locks; +-----------+-----------------+-----------+-----------+-------------+-----------+ | THREAD_ID | OBJECT_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA | +-----------+-----------------+-----------+-----------+-------------+-----------+ | 52 | supremum_lock_1 | TABLE | IX | GRANTED | NULL | +-----------+-----------------+-----------+-----------+-------------+-----------+ 1 row in set (0.00 sec) mysql> ROLLBACK TO SAVEPOINT sp; Query OK, 0 rows affected (0.00 sec) mysql> SELECT THREAD_ID, OBJECT_NAME, LOCK_TYPE, LOCK_MODE, LOCK_STATUS, LOCK_DATA FROM performance_schema.data_locks; +-----------+-----------------+-----------+-----------+-------------+------------------------+ | THREAD_ID | OBJECT_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA | +-----------+-----------------+-----------+-----------+-------------+------------------------+ | 52 | supremum_lock_1 | TABLE | IX | GRANTED | NULL | | 52 | supremum_lock_1 | RECORD | X | GRANTED | supremum pseudo-record | +-----------+-----------------+-----------+-----------+-------------+------------------------+ 2 rows in set (0.00 sec)
supremumロック取得の仕組み
上記の再現実験で ROLLBACK TO SAVEPOINT 実行後にsupremumロックが取得される挙動を理解するためには、 INSERT が取得するロックの流れと ROLLBACK 処理で行われるロック継承を理解する必要があります。
INSERT が取得するロックの流れ
Primary Index にレコードを追加する場合、以下のような流れでロックが取得されます。
- supremum に対する insert intention lock
- レコードの追加
- 追加したレコードに対する暗黙的な排他ロック
supremum に対する insert intention lock は、あくまでもレコード追加前の宣言であり、 insert intention lock が取得できた時点でその効力は失われています。そのため、 INSERT 直後の data_locks を確認しても insert intention lock は表示されません。
レコードの追加が終わると、トランザクションは追加したレコードに対する暗黙的な排他ロックを取得します。この INSERT 後のレコードロックについては、レコード追加を行ったトランザクションIDを紐づけておくことで、実際に競合が起きるまで明示的なロックをかけないという最適化が行われます。そのため、 INSERT 直後のdata_locksを確認してもこの排他ロックは表示されません。
ROLLBACK 時のロック継承
ROLLBACK が行われると、セーブポイント以降に追加されたレコードは undo 処理によって削除されます。しかし、 ROLLBACK 処理はレコードは巻き戻してもロックは解放しないという制限があります。レコードが削除された場合、そのレコードロックはその次のギャップに引き継がれてしまうのです。
今回のINSERTの場合には、末尾に追加されたレコードに対する暗黙的な排他ロックは、その次のギャップ（つまり supremum ）に引き継がれてしまうということです。
実際に MySQL 8.0 のコードを読んでみると、 Clustered Index に対して INSERT された行を undo 処理で巻き戻す場合には、レコードロックをギャップロックに継承させる処理が明示的に呼ばれています。
コールチェーン: row_undo_ins_remove_clust_rec() -> btr_cur_pessimistic_delete() -> lock_update_delete() -> lock_rec_inherit_to_gap()
void lock_update_delete(...) { ... // ここで第3引数にsupremumのヒープ番号、第4引数に末尾のレコードのヒープ番号が渡される lock_rec_inherit_to_gap(block, block, next_heap_no, heap_no); ... }
再発防止策
この障害を経て、 freee で検討した再発防止策を紹介します。
SAVEPOINT を利用するメソッドの利用制限
今回の障害の原因となった SAVEPOINT と ROLLBACK は、ActiveRecord などの ORM フレームワークで無意識的に利用してしまっています。特に、ネストしたトランザクション処理を行いたい場合に注意が必要です。多くのORMフレームワークでは、ネストしたトランザクションを実現するために SAVEPOINT を内部的に使用しています。
例えば、 ActiveRecord ではActiveRecord::Base.transactionにrequires_new: trueを指定すると内部で SAVEPOINT を利用したロールバックが実行される可能性があります。また、#create_or_find_by #find_or_create_byなども内部でActiveRecord::Base.transaction(requires_new: true)を呼び出しており、利用には注意が必要です。
supremum ロック単体では特に問題にならないですが、これにロングトランザクションが組み合わさることで今回のようなサービス停止に繋がってしまいます。そこで、 freee では原則として SAVEPOINT の発行を行わない方針を取ることにしました。部分的なロールバックが必要な場合はトランザクションそのものを分割させ、どうしてもトランザクションをネストさせたい場合はアプリケーション側でのタイムアウトを設けることとしました。
トランザクション分離レベルを READ COMMITTED へ下げる
MySQL のデフォルトのトランザクション分離レベルは REPEATABLE READ になっていますが、これを READ COMMITTED に下げることでファントム行の発生を許容する代わりにギャップロックの取得をしなくなります。トランザクション分離レベルはセッション単位でも指定できるため、ファントム行を許容できるユースケースでは READ COMMITED を利用することも視野に入れるよう、開発者に対する教育・周知を進めていくことにしました。
ロングトランザクションの監視と継続的な改善
ロングトランザクションが保持するロックは影響範囲が狭いこともあり、ブロックされるワークロードが少ない場合は見過ごされることも多いのが現状です。しかし、今回の一件でロングトランザクションの潜在的なリスクが浮き彫りになったため、全社的なロングトランザクション撲滅のための草の根活動が行われるムーブメントが起きています。ロングトランザクションは広く様々な問題を引き起こすため、未知の問題に直面する前に対策を講じるという文化が根付き始める良い機会となりました。
さいごに
DBRE では、 freee で発生した障害の根本原因を探求し、その学びを freee の組織全体の力に変えていくことに熱意を持って取り組んでいます。もし、データベースの観点からサービスの信頼性を根底から支えるようなチャレンジに魅力を感じるのであれば、 freee の DBRE は最適な環境かもしれません。
DBRE では、一緒に freee のデータストアの未来を切り拓いてくれる仲間を絶賛募集中です！データストア領域のテックリードを目指したい意欲のある方の応募をお待ちしています。
