原因不明だったRDS負荷のスパイクを改善できた話

概要

当時数ヶ月間誰も原因がわからなかった一時的にRDSの負荷（CPU使用率）がスパイクする現象の原因を調査できる環境を整えて、原因分析〜改善まで実施したときの話です。

1つ1つの取り組み自体は大きなことはやっていませんが、一連の動きで得られたものも多かったのでアウトプットしようと思い記事にまとめました。

取り組んだ課題

原因を特定するためのツールがない

そもそも何が原因でRDSのCPU負荷が高まっているのかを調べるための情報がCPU使用率以外に全くない状況でした。
そこでRDSの負荷原因を探る方法を調べると、Performance InsightsやCloudWatch Logsへのスロークエリログ出力を使う記事をいくつか見つけたのでこの2つについて調べることにしました。

• Performance Insights

データベース負荷をSQLなどの単位で時系列で可視化したり、トップSQLやDBのヘルスメトリクスを見れるRDSの機能です。アプリのパフォーマンスに影響を与えずに7日分の記録を無料で出力できるのでミニマルにやるなら最適と言えると思います。手順はめちゃくちゃ簡単で、RDSの設定を変えるだけでダウンタイム、再起動なしで適用できます。ちょっと古いUIですが画面イメージは公式が上げてますのでご興味あれば見てみてください。

• CloudWatch Logsへのスロークエリログ出力

CloudWatch LogsはRDSを含むAWSリソースのログファイルをモニタリングする機能です。今回はRDSのスロークエリログを出力する目的で使うことにしました。収集と保存の利用料がかかるため、ログの量によってはコスト増に繋がるので保存期間などのチューニングは必要そう。パラメータ（出力形式, 出力切り替え, 閾値）の設定とRDSの設定（ログのエクスポート）を変えるだけで設定でき、RDSのダウンタイム、再起動などサービスへの影響はありません※でした。

設定した実行時間の閾値を超えた以下のようなログの一覧をAWSのマネコン上で見ることができます。
フィルターを使って検索することも可能です。

例

2023-12-06T18:07:52.764+09:00

# Time: 2023-12-06T09:07:52.764008Z
# User@Host: XXXXXXXXXXXXX  Id: IIIIIIIII
# Query_time: 99.999999  Lock_time: 0.000099 Rows_sent: 1  Rows_examined: 11111111
SET timestamp=1701853672;
SELECT `models`.* FROM `models` WHERE `models`.`column1` = hogehoge AND (`models`.`column2` = 'fugafuga') ORDER BY `models`.`id` ASC LIMIT 1;

※パラメータ変更について補足です。
カスタムのパラメータグループを使っている場合は再起動不要ですが、デフォルトのパラメータグループを使っている場合にはカスタムのパラメータグループに変更する必要があるためその際にはRDS再起動が必要になります。
参考：デフォルトおよびカスタムパラメータグループ

導入コスト（工数・金額）が低く、Opsの効率化につながると判断し、Performance Insightsとスロークエリログの出力設定をチームに提案し設定しました。

設定後に同じ事象が発生した際に上記2つに出力されたクエリからスパイクの原因となった機能および条件を把握することができ、SQLの実行時間は幅はありますが311秒もかかっていることがわかりました。

詳しいソースの言及は避けますが、データ検索時に対象データ件数が大きかったことが負荷の原因となっていたようです。

インデックスの追加

データ検索に2つのカラムが使われていたので、出力されたスロークエリをEXPLAINしてインデックスが貼ってあるか確認しました。possible_keysを見て、column1とcolumn2のインデックスがないことが確認できたのでまずはインデックスの追加を試しました。

結果はフェイク

mysql> EXPLAIN SELECT `models`.* FROM `models` WHERE `models`.`column1` = hogehoge AND (`models`.`column2` = 'fugafuga') ORDER BY `models`.`id` ASC LIMIT 1;
+----+-------------+-----------+------------+------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------+-------+----------+----------+------------------------------------+
| id | select_type | table     | partitions | type | possible_keys                                                                                                                             | key                        | key_len | ref   | rows     | filtered | Extra                              |
+----+-------------+-----------+------------+------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------+-------+----------+----------+------------------------------------+
|  1 | SIMPLE      | models | NULL       | ref  | index_models_on_column1_and_column3,fk_models_services1_idx,index_models_on_column2 | fk_models_services1_idx | 4       | const | NNNNNNNN |    19.00 | Using index condition; Using where |
+----+-------------+-----------+------------+------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------+-------+----------+----------+------------------------------------+

参考：https://dev.mysql.com/doc/refman/5.7/en/mysql-indexes.html
実際の作業はRailsを使っていたので以下のようなadd_indexのマイグレーションファイルを作りmigrateしただけです。

class AddIndexToTables < ActiveRecord::Migration
  def change
    add_index :tables, [:column1, :column2]
  end
end

結果として、311秒を83秒に短縮することに成功！！(インデックスすごい)...したのですが、RDS負荷が一時的にスパイクする事象自体の解消には繋がらなかったため、次のクエリ改善を試みることにしました。

検索クエリを流して実行時間を検証する時、全く同じものを検索するとキャッシュされた以前の検索情報がヒットしてしまい検索の実行時間や負荷が再現できなくなるので検索対象を変えて再現。
参考：MySQL クエリーキャッシュ 【チューニング方法とかも】

クエリの改善

検索機能にはActive Recordのfind_byが使われていて、発行されたSQLは以下のような形でした。

SELECT `models`.* FROM `models` WHERE `models`.`column1` = hogehoge AND (`models`.`column2` = 'fugafuga') ORDER BY `models`.`id` ASC LIMIT 1;

正直めちゃくちゃシンプルだし、これ以上改善しても意味あんのかという気はしたのですが、ORDER BY models.id ASC LIMIT 1の箇所が処理時間を長くしていると仮説を立てました。

SQLから検索の要件（やっていること）は以下だと仮定。

1. column1, column2の条件にヒットするデータ群を取得
2. その中からidで昇順に並び替えて最初の1件を取得

DBへの問い合わせはwhereを使い「1. column1, column2の条件にヒットするデータ群を取得」までとし、「2. その中からidで昇順に並び替えて最初の1件を取得」の処理についてmin_byを使いRubyにやらせることでDBへの負荷軽減を目論みました。

Benchmarkを使い、find_byとwhere&min_byの速度を比較したところ開発環境で0.003秒程度速くなることを確認できました。
※誤差の可能性もあったので数回実行させた平均をとりました。

リリース後は83秒を20~34秒程度に軽減することに成功し、一時的にRDSの負荷がスパイクする事象も発生しないようにできました。
原因としては、データ数が肥大化していたことと、データ数に適さないクエリを発行していたことが原因と言えそうです。
また同じような事象が発生した場合はDBの設計や運用方法を見直すタイミングかもな〜...などとふんわり考えてます。

取り組みの成果

• Performance InsightsやCloudWatch Logsの導入でアプリのパフォーマンス異常の原因を調査しやすい環境を整備
• 検索機能の実行時間を311秒→34秒(約90%)程度に改善🎉
• SQL改善までの過程でDBの機能、ツール理解に繋がった

反省点

• 実行時間の改善率やCPU使用率スパイク改善という一定の成果は出せているといえるが、改善後も一般的に速いとは言えない実行時間な気がする...
• DB周りの知識をつけて設計や運用を改善できるようにしたい

感想

今回の取り組み前にKaigi on Rails2023でActive Recordとの奮闘の話をいくつか聞いてきたことで今回のようなパフォーマンス改善へのモチベーションがかなり高くなっていたので、実際に自分の力で原因究明から解消までできたときの達成感は最高によかったです。

実際にやったことは大したことではないですし、自分以外の人も本気出したら余裕で特定・改善までできていたと思うのですが、問題に対する原因分析環境の構築、原因の分析、継続的な改善を一人称で経験できたのは大きいと思ってます。

自分にとってパフォーマンス改善はやりがいを感じたのでそれにつながる知識は積極的に身につけていきたいです。