マルチAZ配置のAmazon RDS for SQL Serverのエンジンメジャーバージョンアップに3時間以上かかった時に取得できたRDSイベントを公開します

エンジンメジャーバージョンアップを実施した

こんにちは！AWS事業本部のおつまみです。

みなさん、マルチAZ配置のAmazon RDS for SQL Serverのエンジンメジャーバージョンアップを実施したことはありますか？私はあります。
先日こちらの作業を立ち会った際、事前検証の倍以上時間がかかるといった事態が発生していました。

今回その時にどのくらい時間がかかったのか、およびその時のRDSイベントログを公開したいと思います。
また、なぜそれほど時間がかかったのかRDSイベントログから考察してみました。

いきなり結論

• メジャーバージョンアップ時に、3時間以上の時間を要した。
• RDSイベントログをみる限り、以下の処理に時間を要した。
  • アップグレード前のスナップショットを取得(79分)
  • RDSのリカバリ処理（49分）
• スナップショットの取得時間はワークロードの実行有無に依存する。
• RDSのリカバリ処理はRDSの基盤となるハードウェアに障害が発生した場合に届く通知である。

前提

エンジンバージョンアップ時の挙動

RDSがエンジンバージョンアップ時にどのような挙動をするかおさらいしましょう。

RDSの自動バックアップが有効な場合、バージョンアップグレード処理は以下のようなステップとなります。

1. アップグレード前のスナップショットを取得
2. DBインスタンスをアップグレード
3. アップグレード後のスナップショットを取得

シングルAZ/マルチAZ構成に関わらず同じ挙動となりますが、マルチAZ構成の場合はスタンバイのRDSからスナップショットが取得されます。
図にするとこのようなイメージです。

RDSイベントログ

通常時

同じインスタンスクラスのRDSでエンジンバージョンアップを実行した際、下記のログが出力されていました。
最初の実行時間を00:00:00として、時系列に変換しています。

時間	イベントID	メッセージ	備考
00:00:00	RDS-EVENT-0001	Backing up DB instance
00:03:00	RDS-EVENT-0002	Finished DB Instance backup
00:03:00	RDS-EVENT-0026	Applying off-line patches to DB instance	DB インスタンスのオフライン メンテナンス実行中。DB インスタンスは現在利用できません。
00:11:00	RDS-EVENT-0004	DB instance shutdown
00:21:00	RDS-EVENT-0004	DB instance shutdown
00:21:00	RDS-EVENT-0006	DB instance restarted
00:41:00	RDS-EVENT-0004	DB instance shutdown
00:41:00	RDS-EVENT-0006	DB instance restarted
00:47:00	RDS-EVENT-0013	Multi-AZ instance failover started.
00:47:00	RDS-EVENT-0049	Multi-AZ instance failover completed
00:54:00	RDS-EVENT-0004	DB instance shutdown
00:55:00	RDS-EVENT-0023	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
01:00:00	RDS-EVENT-0023	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
01:00:00	RDS-EVENT-0004	DB instance shutdown
01:00:00	RDS-EVENT-0006	DB instance restarted
01:05:00	RDS-EVENT-0023	Emergent Snapshot Request: Databases found to still be awaiting snapshot.	手動バックアップがリクエストされましたが、現在、Amazon RDS は DB スナップショットの作成中です。Amazon RDS で DB スナップショットの作成が完了した後で、リクエストをもう一度送信してください。
01:06:00	RDS-EVENT-0027	Finished applying off-line patches to DB instance	DB インスタンスのオフラインメンテナンスが完了しました。現在、DB インスタンスは利用できます。
01:07:00	RDS-EVENT-0078	Monitoring Interval changed to 60	拡張モニタリングの設定が変更されました。
01:07:00	N/A	Performance Insights has been enabled
01:07:00	RDS-EVENT-0001	Backing up DB instance
01:11:00	RDS-EVENT-0002	Finished DB Instance backup
01:14:00	RDS-EVENT-0092	Finished updating DB parameter group

結果、約1時間14分でバージョンアップが完了しました。

なお今回本番変更するRDSのスナップショットを取得することができなかったため、上記は同じインスタンスクラスのRDSを使用し、検証しています。

本番変更時のRDSイベントログ

本番変更時では、下記のログが出力されていました。
想定より時間がかかった処理には備考欄に△、事前検証時に確認できなかったイベントログには備考欄に☆をつけています。

時間	イベントID	イベント説明	備考
00:00:00	RDS-EVENT-0001	Backing up DB instance
01:19:00	RDS-EVENT-0002	Finished DB Instance backup	△
01:19:00	RDS-EVENT-0026	Applying off-line patches to DB instance
01:28:00	RDS-EVENT-0004	DB instance shutdown
01:41:00	RDS-EVENT-0020	Recovery of the DB instance has started. Recovery time will vary with the amount of data to recover.	☆
01:55:00	RDS-EVENT-0020	Recovery of the DB instance has started. Recovery time will vary with the amount of data to recover.	☆
02:05:00	RDS-EVENT-0020	Recovery of the DB instance is complete.	☆
02:30:00	RDS-EVENT-0004	DB instance shutdown
02:31:00	RDS-EVENT-0006	DB instance restarted
02:34:00	RDS-EVENT-0065	Recovered from partial failover
02:34:00	RDS-EVENT-0013	Multi-AZ instance failover started.
02:34:00	RDS-EVENT-0049	Multi-AZ instance failover completed
02:41:00	RDS-EVENT-0004	DB instance shutdown
02:42:00	N/A	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
02:47:00	N/A	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
02:52:00	N/A	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
02:53:00	RDS-EVENT-0004	DB instance shutdown
02:53:00	RDS-EVENT-0006	DB instance restarted
02:56:00	RDS-EVENT-0027	Finished applying off-line patches to DB instance
02:57:00	N/A	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
02:57:00	RDS-EVENT-0006	DB instance restarted
02:58:00	RDS-EVENT-0006	DB instance restarted
03:02:00	N/A	Emergent Snapshot Request: Databases found to still be awaiting snapshot.
03:02:00	RDS-EVENT-0092	Finished updating DB parameter group
03:04:00	RDS-EVENT-0001	Backing up DB instance
03:09:00	RDS-EVENT-0002	Finished DB Instance backup

結果、約3時間9分でバージョンアップが完了しました。

想定より時間がかかった処理および、事前検証時に確認できなかったイベントログはこちらです。

• アップグレード前のスナップショットを取得(79分)
• RDSのリカバリ処理（49分）

ここから、なぜ時間を要したのか考察してみます。

考察

アップグレード前のスナップショットを取得

まず、アップグレード前のスナップショットを取得に79分の時間を要していました。

こちら調査したところ、スナップショットの取得時間はワークロードの実行有無に依存するとのことでした。

バックアップ時間を長くするその他の要因には、次のようなものがあります。 - CPU とメモリの可用性 - ディスク I/O - データベースアクティビティ - データベースのサイズ （引用：RDS for SQL Server のバックアップにかかる時間を確認する | AWS re:Post）

つまり、本番環境のスナップショット取得には、上記の要因が絡み、大幅に時間が延長された可能性が考えられます。

一方、事前検証は本番環境のスナップショットから復元した環境で実施していました。
そのため、実際にワークロードが実行されておらず、本番環境と比較し、短時間で完了したということが考えられます。

RDSのリカバリ処理

つづいて、RDSのリカバリ処理に49分の時間を要していました。

出力されていたRecovery of the DB instance has started. Recovery time will vary with the amount of data to recover.は、RDSの基盤となるハードウェアに障害が発生した場合に届く通知のようです。

イベント「Recovery of the DB instance has started. Recovery time will vary with the amount of data to be recovered. (DB インスタンスの復旧がスタートされました。復旧時間は、復旧するデータの量に応じて変わります。) 」これは、インスタンスのハードウェアが復旧中であることを意味します。Amazon RDS の復旧は、新しい Amazon Elastic Compute Cloud (Amazon EC2) ホストに移行して、ハードウェアを交換することによって行われます。 （引用：Amazon RDS と Amazon Aurora のパフォーマンスとイベントの可視性を高める）

今回該当時間帯に、 AWS Health Dashboard でRDSの基盤となるハードウェアへの障害報告は出ていませんでした。
そのため、運悪くハードウェア障害が発生したことが考えられます。

考察は以上となります。

さいごに

今回は、マルチAZ配置Amazon RDS for SQL Serverのエンジンメジャーバージョンアップに3時間以上かかった時に取得できたRDSイベントを公開してみました。

本番環境のスナップショットから復元した環境と本番環境では、実際のワークロード状況に応じて、変更時間に差異が発生することがわかりました。
どのくらい時間がかかるは実際にワークロードを実行し、全く同じ条件にしないと予測できないということですね。

今後変更を予定されている方は注意してください！

最後までお読みいただきありがとうございました！
どなたかのお役に立てれば幸いです。

以上、おつまみ（＠AWS11077）でした！

参考

Amazon RDS のイベントカテゴリとイベントメッセージ - Amazon Relational Database Service

RDS for SQL Server のバックアップにかかる時間を確認する | AWS re:Post

Amazon RDS と Amazon Aurora のパフォーマンスとイベントの可視性を高める

RDS went into Recovery itself