こんにちは。サーバーサイドエンジニアの青山です。
先日、弊社のAmazon Aurora MySQLのCPU負荷が急に上昇してDBが再起動するという事象が発生しました。その原因を調査した時の話をRollbackSegmentHistoryListLengthを中心に紹介します。
当時の状況
Amazon RDSのコンソールやDatadogのメトリクスから確認できたCPU負荷が上昇した時の状況は以下の通りです。
- ライターインスタンスのRollbackSegmentHistoryListLengthが増加
- ライターインスタンスのDMLThroughputが増加
- リーダーインスタンスのCPUが上昇
- AuroraReplicaLagが増加
- 大幅なレプリケーション遅延のためリーダーインスタンスが再起動
この時点で、RollbackSegmentHistoryListLengthの増加がトリガーになってレプリケーション遅延を引き起こし、インスタンスが再起動したと仮説を立てて調査を開始しました。
レプリケーション遅延による再起動
似たような事例はないか探していると「Amazon Auroraリードレプリカが遅れ、再起動されたのはなぜですか。」という記事を見つけました。
RollbackSegmentHistoryListLength（HLL）が増加している状況と照らし合わせると、以下が可能性としてありそうです。
増大化が進む History List Length (HLL) を調べる (Aurora MySQL - 互換)
MySQL InnoDB エンジンには、デフォルトで MVCC (multi-version concurrency control) が組み込まれています。これは、トランザクションの全体を通じて、影響を受けるすべての行で発生したすべての変更を追跡する必要があることを意味します。長時間実行されるトランザクションが完了すると、パージスレッドアクティビティの急増が始まります。長時間実行されるトランザクションによって作成されるバックログの量が原因で、この突然のパージが Aurora レプリカの遅延を引き起こす場合があります。
しかし、長時間実行されるトランザクションがないか調べたところ、そのような痕跡を見つけることはできませんでした。
RollbackSegmentHistoryListLengthが増加する原因
さらに公式ドキュメントを見ていると「InnoDB履歴リストの長さが大幅に増加しました」を見つけました。
こちらには長時間実行されるトランザクション以外にも書き込み負荷が高いことも原因の1つとして挙げられています。
履歴リストが長くなる一般的な原因には次のものがあります。
・実行時間の長いトランザクション (読み取りまたは書き込み)
・書き込み負荷が高い
確かに、DMLThroughputが増加していたので書き込み負荷が高かったことも可能性としてはありそうです。
また、「Amazon Aurora MySQL DB クラスターで SELECT クエリの実行が遅いのはなぜですか?」には以下のような記載もあります。
注: HLL の急増の原因は、長時間実行されるトランザクションだけではありません。消去スレッドが DB の変更に追い付かない場合でも、HLL は高いままになることがあります。
非同期処理による書き込み
DMLThroughputについて調べていると該当の時間帯に非同期処理のジョブが大量に実行され、同時に大量のINSERTが発行されていることが分かりました。
弊社では非同期処理のジョブが実行された時にその履歴を残すため、RDBにジョブの情報を書き込むような仕組みが用意されています。そのため、非同期処理のジョブ1件につきINSERTが追加で実行されることになります。
ただし、頻度の高いジョブについてはRDBへの負荷対策のため履歴を残さないようにしているのですが、今回のジョブはその対象になっていませんでした。
そこで、このジョブの履歴を残さないような修正を入れることで様子を見ることにしました。
おわりに
RollbackSegmentHistoryListLengthについては馴染みのない指標だったため、今回の件で発生しうる原因について知ることができて良かったです。
今のところ同じ事象は再発していませんが、Datadogのアラートを設定してRollbackSegmentHistoryListLengthが増加したら気付けるようにしたので、今後も注視していきます。
