LOGILESS TECH BLOG vol.2 ~RollbackSegmentHistoryListLengthの増加によるMySQL(Aurora)のパフォーマンス劣化とトランザクション分離レベル~
はじめに
こんにちわ、ロジレスでエンジニアをしている冨田(@seikoudoku2000) です。
先日発売となった、星野源さんのエッセイ集「いのちの車窓から 2」をちょっと贅沢して物理本で購入して何周かしつつ、特に「喜劇」のエピソードが最高すぎて、余韻に浸りながら楽曲を聞き直しつつ、自分も源さんに恥じない良い仕事がしたいなと、改めて背筋を正して仕事に取り組んでいる今日この頃です。
さて、前回の記事ではドキュメントの話を長々と書いたので、今回は、技術寄りのネタをサラッと紹介したいと思います。
お題はタイトルにある通り、RollbackSegmentHistoryListLengthなんですが、私自身、このメトリクスに起因する障害は別の職場でも経験してて、２回目なのですが、前回の対応時に色々と調べたはずなのに、内容をほとんど覚えていなくて残念な気持ちになったので、今回、テックブログにまとめてみることにしました。
tl;dr
MySQL使ってる場合はRollbackSegmentHistoryListLengthが異常に増えるタイミングが無いかのモニタリングを絶対するべし！
RDBMS奥が深い、、！(雑
RollbackSegmentHistoryListLengthの増加によるプチ障害の発生と対応
ある日の夕暮れ、皆んながぼちぼちと帰り支度を始めていた頃、突然アラートが鳴り響きました。確認してみると、あるWorker(PHPを常駐プロセスとして起動させて、)の処理が追いつかず、キューがどんどんと溜まってしまっている状態でした。
このWorkerは、Aurora MySQLのテーブルにキューとして利用しているテーブルがあって、そこから処理完了フラグがoffのレコードを取得して処理をするタイプのWorkerなのですが、調査の結果、そのテーブルからフラグがoffのデータを取得してくるクエリが普段の1000倍くらい時間がかかるようになってしまい、その結果、スループットが激しく悪化して、処理待ちのレコードがどんどんと溜まってしまう状態になっていることが分かりました。
ネットで調べると、このような問題を起こすのは変な状態で残ってるコネクションが引き金になっている事があるという情報がちらほらとあり、その場合、RollbackSegmentHistoryListLength というメトリクスが高い値になっていること、また、過去に経験した時もそんな感じだった記憶で、取り急ぎ、SHOW PROCESSLISTを実行し、怪しいコネクションをkillすることで、障害自体は収束しました。
また、↓は後から取得したメトリクスのグラフですが、青色の線がRollbackSegmentHistoryListLength、オレンジの線がselect latency となっていて、このグラフから、２つのメトリクスは相関関係があると結論づけるのは妥当であると判断しました。
(青色の線が急降下しているのが、変な状態で残っていたコネクションをkillしたタイミング)
当時行き当たった記事の１つ
AWSの公式(?)解説
また、恒久対応として、
RollbackSegmentHistoryListLengthのメトリクスをベースにしたモニタリングとアラートを追加
Auroraのwait_timeout の設定をデフォルトの8時間よりも短い値に変更する
という対応を入れて、障害対応自体は一段落となりました。
残された謎と調査結果
障害対応としては、一段落したのですが、大きく以下の２つの謎が残りました。
そもそも、RollbackSegmentHistoryListLengthというメトリクスが大きくなるとselect latencyが悪化するのはなぜ？
この障害発生中、該当のWorkerでは問題が起きていたが、同じDBを参照している他のWorkerやバッチ処理、webのサービスは問題なく動作していた。これはなぜ？
これはRDBMSともっと仲良くなるためのチャンス！ということで、その点を少し深堀りして調べてみた、、というのが今回の記事の本題になります。
それぞれについて、一部推測も混ざってしまってますが、理解した内容を記載していきたいと思います。
RollbackSegmentHistoryListLengthの増加とselect latencyの悪化の関係性
この問題を理解するには、何回読み直してもすぐに忘れてしまうw(私だけ？)トランザクション分離レベルの話を抑えておく必要があります。
トランザクション分離レベルについては、たくさんの情報が巷にありますので説明は割愛させていただきますが、以下の記事がよくまとまっていて、参考にさせていただきましたので、紹介させていただきます。
auroraのデフォルトのトランザクションレベルは、Repeatable Readで、ロジレスでもデフォルト設定での利用をしており、このトランザクションレベルでは、Non-repeatable readsを発生させないようにする必要があります。
このため、transactionが開いているコネクションのversionまでのレコードの状態は復元できるようになっている必要があるので、復元が必要となる分については履歴(= undoログ, history list)を保持しておき、長時間開いているtransactionからのselectの場合は、最新状態のレコード + そのtransaction開始時点の状態を再現するのに必要な分だけundoログを遡る必要が発生し、結果、SELECTクエリのパフォーマンスが悪化していきます。
↓の記事では以下のような表現で説明されていました。
As the InnoDB transaction history grows, SELECTs need to scan more and more previous versions of the rows, and performance suffers. That explains the issue: SELECT queries get slower and slower until restart
RollbackSegmentHistoryListLength とselect latency のメトリクスの相関関係について、一定、この関係性から説明できそうですが、このパターンでlaencyが悪化するのは、長時間実行されているトランザクションを有するクエリからのセッションのみであり、通常の処理では問題は出ないはずです。
今回、トランザクションが開きっぱなしになっていたのは、適切にコネクションをcloseできていなかったクライアントからのものばかりで、アクティブにクエリが実行されていたわけではなく、
また、特に大きなパフォーマンス問題が発生したクエリについて、長時間実行されているトランザクションからのクエリではなかったため、なぜ、そこで顕著なパフォーマンス劣化が発生したのか？について、謎が残ってしまいました。
特定のクエリのみで問題が発生した理由
今回、障害のトリガーとなったクエリでは、1000倍のパフォーマンス劣化が発生していましたが、他のシステムは(体感できない位のパフォーマンス劣化はあったかもしれないが)問題なく動作している状態でした。
このクエリを実行しているWorkerは常に新しいTransactionを開始しており、特別にundoログを遡った走査が発生しているわけではありません。
他の可能性として、例えば、undoログの蓄積によってメモリ領域やディスク領域が何らかの形で圧迫され、全てのクエリが1000倍のパフォーマンス劣化していた？、というような事も一瞬考えましたが、その場合は全てのクエリに影響が波及し、確実にサービス全断に陥るはず。
そうならなかったということは、このクエリのみが、何らかの理由で圧倒的なパフォーマンス劣化を引き起こしていた、、ということになります。何がどうなってこのような状態になったのか、、、？
この点については、かなり推測が混ざってしまうのですが、
↓の記事に以下のような記述があり、問題になったクエリの特性によるものでは？と結論づけました。
Where it can get even worse is Index Scan. This is because Indexes are structured in InnoDB to include all row versions corresponding to the key value, current and past. This means for example the index for KEY=5 will contain pointers to all rows that either have value 5 now or had value 5 some time in the past and have not been purged yet. Now where it can really bite is the following – InnoDB needs to know which of the values stored for the key are visible by the current transaction – and that might mean going through all long-version chains for each of the keys.
問題となったクエリは、↓というクエリなのですが、
SELECT * FROM transaction_log WHERE waiting_for_summary = 1
transaction_logというテーブルは、テーブル名から推測される通り、全ての在庫操作を記録しているテーブルで、LOGILESSの中で最も更新頻度が高いテーブルの一つです。かつ、waiting_for_summary フィールドにindexは貼ってはいますが、bool型のカーディナリティが低いクエリであり、かつ、新規登録された全てのレコードはwaiting_for_summary = 1 で作成されます。
このため、問題を引き起こしたtransactionが開始された以降に作成された、全てのレコードの全てのバージョンを走査する必要が出てくるため、時間の経過と共に走査対象が線形に増え続け、1,000倍ものクエリのパフォーマンス劣化に繋がってしまったのではないかと考えています。
他にも同じくらいの更新頻度のテーブルは存在(e.g. 在庫データを格納したテーブル)し、インデックスを利用した検索も各所で行われていますが、辿るべき行やバージョンが少なかったために、そこまでのパフォーマンス劣化には繋がらなかったと。
言い換えると、局所的な障害で済んだのはたまたまで、このカナリア的なクエリがいなかったら、他のindex scanでもクエリや、定期実行バッチ等で実行されるような広範囲のデータを対象としたクエリがどんどんと遅くなっていき、更に大きな障害を引き起こしてしまった可能性もあったと考えられます。
様々な形でシステムに襲いかかってくるhistory list length、しっかりとモニタリングして、異常を早めにキャッチするのが大事です。(大事な事なので2回書いた)
補足
ちなみにですが、私はこの問題に遭遇するのが２回目だと最初に書きましたが、
１回目に経験した時は、クエリのパフォーマンス悪化ではなく、history listが溜まりに溜まった状態で、大量のpurgeが発生したことで、短時間ではありますがディスクのI/Oを喰いつくしてしまい、DBの応答速度が全体的に著しく悪化し、システム全体の挙動が不安定になる、という形で問題が発生しました。
様々な形でシステムに襲いかかってくるhistory list length、しっかりとモニタリングして、異常を早めにキャッチするのが大事です。
また、history listが蓄積されていくのはNon-repeatable readsを発生させないようにするための機構という事なので、トランザクション分離レベルを変えて、例えば、Read Committedにしてしまうという手段もなくはなさそうですが、アプリケーションにどのような影響をもたらすのか想像がつかないので、その方法は検討しませんでした。
ただ、これまで何も考えずに、デフォルトのトランザクション分離レベルを使ってきていたので、設定を変更した上で、Non-repeatable readsとなるクエリを発行してみたり、今回の事象を再現させる行為を行った上でhistory list lengthが伸びない事やクエリパフォーマンスが悪化しない事を確認する、、というのは色々と学びがありそうなので、折を見て試してみたい所です。
まとめ
発生した障害に対して、恒久対策を打つ所で止まらずに、発生原因のメカニズムを知ろうとしたことで、色々と知識が増えて知的好奇心が満たされるとともに、何もない状態で読んでも中々頭に入ってこないトランザクション分離レベルの意味を身近に感じる事ができて、皆んな大好きRDBMSと少し仲良くなることができました。
また、将来、職場が変わって、またこの障害に遭遇した際には、サッとこの記事のリンクを引っ張ってきて、ドヤれることでしょう (知ってるなら防止しろよとツッコまれる可能性も少々w)し、この記事を読んでいただいた皆様も頭の片隅に引っ掛けておいて、同等の問題に遭遇した際に参考になったら嬉しいです。
ロジレスでは、既にデータベースと超仲良しなエンジニアも、これから仲良くなりたいエンジニアも、データベースとか気にせずに機能開発に没頭したいエンジニアも、超絶絶賛ウルトラ大募集中です！
エンジニア採用関連のYouTube動画や記事です。
求人に関するお問い合わせはこちらから↓