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

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

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


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

- ### [Performance Insights](https://aws.amazon.com/jp/rds/performance-insights/)
データベース負荷をSQLなどの単位で時系列で可視化したり、トップSQLやDBのヘルスメトリクスを見れるRDSの機能です。アプリのパフォーマンスに影響を与えずに7日分の記録を無料で出力できるのでミニマルにやるなら最適と言えると思います。[手順](https://docs.aws.amazon.com/ja_jp/AmazonRDS/latest/UserGuide/USER_PerfInsights.Enabling.html)はめちゃくちゃ簡単で、<b>RDSの設定を変えるだけでダウンタイム、再起動なしで適用できます</b>。ちょっと古いUIですが画面イメージは公式が上げてますのでご興味あれば見てみてください。


https://youtu.be/4462hcfkApM

<br />

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

設定した実行時間の閾値を超えた以下のようなログの一覧を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;
```

:::note warn
※パラメータ変更について補足です。
カスタムのパラメータグループを使っている場合は再起動不要ですが、デフォルトのパラメータグループを使っている場合にはカスタムのパラメータグループに変更する必要があるためその際にはRDS再起動が必要になります。
参考：[デフォルトおよびカスタムパラメータグループ](https://docs.aws.amazon.com/ja_jp/AmazonRDS/latest/UserGuide/parameter-groups-overview.html#parameter-groups-overview.custom)
:::

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

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

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


## インデックスの追加

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

```ruby:結果はフェイク
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しただけです。

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

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

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


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

```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](https://docs.ruby-lang.org/ja/latest/class/Benchmark.html)を使い、`find_by`と`where&min_by`の速度を比較したところ開発環境で0.003秒程度速くなることを確認できました。
※誤差の可能性もあったので数回実行させた平均をとりました。

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


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

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

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

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

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