RDS の CPU 使用率がほぼ 100％ どう調査する？ 実例から学ぶ原因と解決策 〜オペ部だより〜

こんにちは、札幌在住 AWS 事業本部 オペレーション部（通称オペ部）の池田です。オペ部ではクラスメソッドメンバーズにご加入いただいているお客様が直面されたお困りごとや疑問など、様々なお問い合わせに対して各種ドキュメントや技術検証結果のご案内をしたり、場合によっては AWS と連携してお客様が直面している問題解決の支援を行なっています。 本記事では、タイトルにある通り実際にいただいた「RDS の CPU 使用率が（ほぼ）100％ 何が原因なの？」というお問い合わせの中から、代表的な事例とその調査方法をご紹介したいと思います（今回も全ての事例を網羅できているわけではありませんが、調査方法の参考にしていただけると嬉しいです）。

はじめに

RDS の CPU 使用率が 100% あるいは ほぼ 100% となる原因は実に様々です。そもそも選択したインスタンスのスペックが低すぎる場合、設計上想定していなかったクエリによる場合、メディア露出やキャンペーン等による急なリクエスト増である場合、例を挙げればきりがありません。 実は、私たちオペ部に寄せられた「RDS の CPU 使用率が（ほぼ）100％ 何が原因なの？」というお問い合わせの中には「拡張モニタリング」が有効になっていなかったため、CPU を多く使用しているプロセスの特定に至る前に（インスタンスの再起動やスケールアップなどによって）収束してしまい、根本原因の特定が困難となってしまったケースもあります。本番環境では、原因究明よりも復旧を最優先事項として選択するケースが多いので仕方のないことと思います。

CPU 使用率が急上昇したら

では、突然このような状況になった場合に何をするのが良いでしょうか。異常に気が付いたタイミングから「拡張モニタリング」を有効にしましょう。この機能は、有効化 / 無効化の際にインスタンスを再起動する必要がありません。60 秒間隔程度のモニタリングであれば性能への影響も顕著に現れることはありませんし、原因となるプロセスの情報などを得ることができるため事象の早期解消に繋げられるほか、再発防止策を講じやすくなります。 また、Performance Insights を有効にしている場合には、リソースの消費状況などを確認することが可能です。その情報から関連する処理の流れを追うことで原因にたどり着きやすくなるはずです。また、スロークエリログを設定していれば、どのクエリ処理に時間がかかっていたかを確認することができます。 Oracle なら、事象発生時の Statspack や systemstate も有益な情報源となり得ます。 RDS で CPU 使用率が上昇する事象については、利用方法や実行していたクエリなどによって状況が異なり、一概に判断することができません。そのため、原因を特定するためには拡張モニタリングや Performance Insights 、スロークエリログなどを利用して CPU 使用率が上昇した時の状況を調査する必要があります。

参考

MySQL のスロークエリと一般ログにアクセスする Oracle Statspack Oracle Database のログファイル - トレースファイルとトレースセッションを生成する Amazon RDSパフォーマンスインサイトの使用

事例

小さめのインスタンスを利用しているケース

db.t2.small を利用していると突然 CPU 使用率が高くなった。という事例です。 CloudWatch に記録されていた情報から、対象の時間帯にメンテナンスウィンドウ内でパッチ適用が行われていたことが判明しました。このパッチ適用処理によって、平常時の同時間帯に比べて 2% ほど CPU 使用率が高くなりほぼ 100% という状況になっていたのでした。 お客様へは、必要に応じてメンテナンスウィンドウの調整（アクセスの少ない夜間帯に設定いただくなど）をご検討いただけるようご案内を差し上げました。

Amazon Relational Database Service ユーザーガイド: Amazon RDS メンテナンスウィンドウ

すべての DB インスタンスや DB クラスターには週次のメンテナンスウィンドウがあり、その期間内にシステムの変更が適用されます。メンテナンスウィンドウは、変更やソフトウェアのパッチ適用がリスエストされた場合や必要となった場合に、いつ実行するかを制御できる機会と考えることができます。

また、このケースでは平常時の CPU 使用率がほぼ 98% で推移しており、2％ 程度の上昇がシステム応答に影響を与えてしまっていました。パッチ適用処理以外にも様々な理由によって CPU 使用率が一時的に上昇することは十分にあり得ますから、消費リソースを観察して余裕あるインスタンスタイプへの移行検討も提案させていただきました。

スロークエリが原因だったケース

平常時は負荷も少なく、アクセスも少ないサービスで、ある時 DB コネクション数が急増し、DB への接続ができず WEB サイトの閲覧に支障が出た。という事例です。 WEB サイトの閲覧ができない状況が発生し、調べたところ DB コネクション数が非常に多かった。アクセス数を確認したが、平常時の倍程度でしかなく、アクセス数の増加に対して DB コネクション数が異常に増えているように思われる。というお問い合わせがありました。 このケースでも、先にご紹介した「拡張モニタリング」などは無効であったので事象発生時にはあまり有力な情報は入手できませんでした。しかし、類似した事例でスロークエリによって DB コネクション数が急増したケースが複数あったことから、スロークエリログの取得と確認をお客様へ依頼しました。 結果、特定のクエリの処理に時間がかかっていることで DB コネクション数が増えてしまっている状況であることが判明しました。

スロークエリが原因でインスタンスのもつ DB コネクション数の上限値と思われるような値まで増加したケースもあり、アクセス数の上昇に比べて DB コネクション数の増え方が極端に多い場合には、スロークエリログの確認も有効な調査方法のひとつだと言える事例でした。 本記事を書き進めるにあたって過去のお問い合わせ事例を調べたところ、このケースが非常に多いことに気がつきました。

スロークエリログを設定することによって、どのクエリ処理に時間がかかっていたか確認することができます。具体的には、閾値(long_query_time) の秒数以上に時間がかかったクエリがログに入ります。

参考： MySQL 5.6 リファレンスマニュアル スロークエリーログ

上記ドキュメントにあるように MySQL 5.6 の場合、デフォルトは 10秒となっています。スロークエリを見つけ出したいときの一般的な方法として次の 2つが挙げられます。

• ステージング環境では小さな値(1秒やそれ以下)にして遅いクエリを洗い出す
• 本番環境では大きめな値にして特に遅いクエリを捕捉する（小さな値にすると想定以上にログが記録されるケースもあります）

ステージング環境と本番環境でスロークエリログの閾値を変える場合、両環境用に別々の DB パラメータグループを作成しておいた方が良いかもしれません。DB パラメータグループを差し替えるには RDS の再起動が必要となりますので注意が必要です。

スロークエリログの出力先は、MySQL 5.5 以降デフォルトの設定で TABLE となっており、mysql.slow_log というテーブルに格納されます。ただし、マネジメントコンソール上で閲覧できる状態ではないので MySQL クライアント側からテーブル内のログを参照する必要があります。これを RDS コンソール上で確認できるようにするためには、slow_log の出力先を FILE に変更する必要があります。変更後は RDS コンソールの「ログとイベント」のタブで表示されるログのうち slowquery/mysql-slowquery.log* というログで確認が可能となります。 なお、この設定変更は RDS の再起動を必要としないので、いつでも変更が可能です。 ただし、エラーログは 24時間でローテートされる仕様ですから、それ以上の期間ログを保存するためには CloudWatch Logs に転送して保存する必要があります。

参考： Amazon Relational Database Service ユーザーガイド MySQL ログを CloudWatch Logs に発行する

毎日同じ時間などに CPU 使用率が上昇するケース

定期的に発生する、特に発生する時間まで同じである場合には、バッチやバックアップなど、RDS に対して定期実行している処理による負荷が原因という可能性が非常に高いと思われます。CloudWatch で 1日の負荷状況を確認し、処理内容や定期実行処理タイミングの見直し、インスタンスのスペックが適切であるのかについても検討した方が良いかもしれません。

おわりに

ここでご紹介した他にも様々な原因で CPU 使用率が上昇する場合があり、本記事の内容はそのまま参考にならない場面も多くあるかと思います。AWS が管理する仮想ホスト側や連携している EC2 など他のサービスに問題が生じている可能性もあります。しかし、原因を特定して早期復旧に繋げるには「何が起きているのか」を正しく把握する必要があります。そのためにもまずは落ち着いて、CPU が上昇し始めたタイミングとその時間帯に行なっている定期処理や実行したクエリに問題がないがないか確認しましょう。可能ならチーム内の別のメンバーにダブルチェックをしてもらうのも有効かもしれません。現時点でアクセス可能なログファイルや CloudWatch の内容を確認してみてください。メッセージやログに記録されている内容をよく読めば、きっと原因につながるメッセージが見つかるはずです。 それでも解消されない、原因が見つからない場合にはそれまで調べた情報と共にサポートへ問い合わせましょう。ユーザー側ではアクセスできない領域も含めて調査してもらえます。また、他のユーザー事例から解決策が素早く提示されるかもしれません。この記事がいつか誰かのお役に立てば幸いです。