こんにちは。SmartHRでプロダクトエンジニアをしているdelhi09です。私が所属するチームは「人給基幹プロダクト」と呼ばれるSmartHR最大のRailsアプリケーションに携わっています。
私たちのチームはとある画面の特定の条件でレスポンスタイムが約600秒（10分）かかっていた処理を、チューニングにより1.5秒まで短縮しました。本記事では、ボトルネックの特定から解決に至るまでのプロセスを詳しく解説します。
性能問題の検知〜私たちのチームに改善タスクが割り当てられるまで
検知のきっかけはGoogle CloudのMonitoringによるスロークエリのアラートでした。インフラ担当が詳細を調査したところ繰り返し発生していることが分かり、チューニングが必要な旨を該当機能のプロダクトマネージャーにエスカレーションしました。その結果、私たちのチームが性能改善タスクを担当することになりました。
性能問題の存在の裏付け
New RelicのTransactionsを見る
まずは発生しているURLの特定を行いました。スロークエリのSQLで参照しているテーブルなどの情報から、発生している可能性の高い画面はすぐにあたりをつけることができました。
私たちのチームではオブザーバビリティツールとしてNew Relicを利用しています。そこで次にNew Relicで性能に問題があることの裏付けを行いました。New Relicにはアプリケーションのパフォーマンスを管理する仕組み（APM）としてTransactionsという機能があります。TransactionsではURL単位でレスポンスタイムの平均や99パーセンタイル（後述）などの数値を確認することができます。URLの部分一致検索もできるため、対象のURLを検索して数値を確認しました。
99パーセンタイルを確認する
性能問題の存在を裏付けるため、今回は99パーセンタイルという数値に着目しました。
「Nパーセンタイル」とは、計測値を小さい順（レスポンスタイムであれば速い順）に並べた際、下位から数えて全体のN%がその値以下に収まる境界値のことです。例えば「99パーセンタイルが10秒」であれば、「全リクエストの少なくとも99%は10秒以下に収まっており、10秒を超えるリクエストは多くても1%であること」を意味します。
99パーセンタイルが、平均値や95パーセンタイルに比べて極端に遅い場合、以下のような可能性が考えられます。
- 一部のテナントでレスポンスタイムが極端に遅い
- 特定の検索条件でレスポンスタイムが極端に遅い
特に前者は、SmartHRのようなマルチテナント型サービス特有の課題です。特定のデータ量の多いテナントのリクエストが1%に偏在している場合、該当のテナントのお客様にとっては常に体験が悪い状態が続いていることになります。レスポンスタイムの平均だけを追っていると、こうした特定条件下で発生する深刻な遅延を見落としてしまいます。すべてのお客様に快適な体験を提供できているかを測る指標として、99パーセンタイルは非常に有効です。実際に該当URLの画面について99パーセンタイルを確認したところ、平均値とは乖離した、明らかに改善が必要な数値が検出されました。
遅いリクエストの傾向を分析する
URLの特定ができたので、次に「レスポンスタイムが遅いリクエスト」に絞り込み、テナントや検索条件にどのような傾向があるかを分析しました。
New RelicではTransactionsの一覧から対象のURLを選択すると、Transaction tracesという機能で該当のURLのサンプリングされたリクエストの一覧を確認できます。これらをレスポンスタイムの遅い順にソートします。
さらに特定のリクエストを押すと、AttributesやDatabase queriesで該当リクエストのテナントや検索条件などの詳細な情報を確認できます。
これらのNew Relicの機能を利用してレスポンスタイムの遅延が上位のリクエストを一つずつ掘り下げていきました。なお、検索条件を分析する際は、Google CloudのCloud Loggingも併用しました。
数十件ほどリクエストを確認した結果、以下の傾向があることが分かりました。
- テナントの偏り：特定のデータ量が非常に多いテナントに集中している
- 検索条件の偏り：すべて特定の検索条件を含む
時間がかかっている処理の特定
次にレスポンスタイムの遅延が大きいリクエストに関して、処理のどの部分に時間がかかっているのかを特定します。
New RelicではTransactionsのリクエスト詳細画面のTrace detailsでドリルダウンしながら処理単位でかかった時間を調べることができます。処理の粒度はSQL発行やキャッシュ取得などの非常に細かいレベルです。
実際に詳細を確認したところ、他の処理と比べて明らかに実行時間が長く、リクエスト時間の大部分を占有しているSELECT文がありました。このSQLはアラートが上がったスロークエリとも一致しており、このクエリの発行が遅延の直接的な要因であると特定できました。
New RelicではSELECT文をクリックするとDatabasesという機能に遷移して、該当のSQLの以下のような詳細情報を確認することができます。
- 発行されたSQL文
- SQLの発行元のコードのStack Trace
- 該当のSQLの実行計画（explain結果）
これで「どこで時間がかかっているか」の特定が完了しました。加えて、次に取り組むSQLのチューニングに必要な情報もNew Relicから取得することができました。
「仮説を立てる→検証する」のサイクルを回す
今回のボトルネックはSQLだと判明したので、高速化するためには該当のSQL自体を高速化する必要があります。前述したように、New RelicのDatabases機能の画面では該当のSQLの詳細を確認できます。これによりスロークエリの実行計画が次のようなツリーとして表示されます。
この実行計画を読み解くには、使用しているRDBプロダクトに関する知識が必要です。SmartHRはPostgreSQL （AlloyDB）を使っているので、PostgreSQLの実行計画を読み込む必要があります（参考: PostgreSQL公式ドキュメント - Using EXPLAIN）。
今回は、施策を導入するまでの初動も考えて、まずは実行計画を詳細に読み解かなくても可能なチューニングを試しつつ、並行して実行計画を読み込んでのチューニングも進めることにしました。
以降では、それぞれについて仮説と検証のサイクルをどう回したかを説明します。
チューニングその1 〜実行計画の構造的な差分に着目する
仮説：データ量によって「最適ではない実行計画」が選ばれているのではないか？
今回の性能問題はデータ量の多い一部のテナントに偏在して発生していました。従って、まずは実行時間が正常なSQLの実行計画を採取して両者の実行計画を比較してみました。具体的には、同じSQLをデータ量が標準的な検証環境のテナントに対して発行して、New Relicで採取したスロークエリの実行計画と比較しました。両者を比較したところ、正常なSQLとスロークエリではそもそもジョインの順序などの実行計画の構造が大きく異なることが分かりました。従って、データ量が多いテナントではオプティマイザが最適ではない実行計画を選んでしまっているのでは？という仮説を立てました。
施策：実行計画を固定する
仮説を検証するためには、スロークエリの実行計画を正常なSQLの実行計画と同じ構造にしてリリースする必要があります。実行計画を制御したい場合、MySQLなどのRDBプロダクトではヒント句という機能がサポートされています。
しかし、PostgreSQLでは標準機能としてヒント句は使えません。ここで行き詰まりかけたのですが、チューニング対象のSQLを確認したところ、複数の条件をサブクエリーのIN句でネストして絞り込む構造になっていました。具体的には、従業員に紐づく従業員情報A・従業員情報Bの入力状態をそれぞれ別テーブルで管理しており、両方の条件を満たす従業員を1つのクエリで取得していました。イメージとしては以下のようなSQLです。
SELECT * FROM employees WHERE id IN (SELECT employee_id FROM employee_info_a WHERE completed = true) AND id IN (SELECT employee_id FROM employee_info_b WHERE detail_id IN (SELECT id FROM employee_info_b_details WHERE completed = true));
Railsのコードでは、これらの条件をまとめた1つのスコープとして定義されていました。
修正前
# 従業員情報A・Bの入力完了を1つのスコープで絞り込む scope :required_attributes_completed, -> { where(id: EmployeeInfoA.input_completed.select(:employee_id)) .where(id: EmployeeInfoB.where( detail_id: EmployeeInfoBDetail.input_completed.select(:id) ).select(:employee_id)) } employees = Employee.required_attributes_completed
このスコープが生成するSQLでは、複数のサブクエリーがネストされた状態でオプティマイザに渡されます。データ量が少ないテナントでは問題ありませんが、データ量が多いテナントではオプティマイザが最適ではないジョイン順序を選んでしまっていました。そこで、スコープを条件ごとに分割し、片方の条件を先にpluckで実行してIDの配列として取得することで、サブクエリーのネストを解消しました。
修正後
scope :required_info_a_completed, -> { where(id: EmployeeInfoA.input_completed.select(:employee_id)) } scope :required_info_b_completed, -> { where(id: EmployeeInfoB.where( detail_id: EmployeeInfoBDetail.input_completed.select(:id) ).select(:employee_id)) } # 従業員情報Aの条件を先に別クエリとして実行し、IDの配列を取得する ids = Employee.required_info_a_completed.pluck(:id) employees = Employee.where(id: ids).required_info_b_completed
こうすることで、2本のSQLがそれぞれ独立した実行計画で処理されるようになり、オプティマイザが各クエリに対して適切な実行計画を選べるようになります。
このアイデアはあくまで仮説であり、むしろ性能が劣化する可能性もあります。従って、影響範囲を限定するため、Flipperによるフィーチャーフラグを導入して、初回は最も遅延が深刻な1テナントのみに限定して適用しました。
employees = if Flipper.enabled?(:optimize_employee_search, Tenant.current) ids = employees.required_info_a_completed.pluck(:id) employees.where(id: ids).required_info_b_completed else employees.required_attributes_completed end
仮に性能が悪化していたらすぐに切り戻せるように、リリース直後はNew Relicで重点的に監視しました。
効果検証：テナントによって効果にばらつきが出る
チューニングを導入した1テナントでは、レスポンスタイムが600秒 → 6秒と大幅な改善がみられました。
しかし、他のレスポンスタイムが遅い上位約10テナントに追加でフィーチャーフラグを有効にしたところ、本チューニングでは効果が出ないテナントも多いということも分かりました。99パーセンタイルの観点でも大きな改善はみられませんでした。加えて、効果が出たテナントに関しても600秒 → 6秒自体は大幅な改善ですが、SELECT文単体で6秒近くかかっているというのは、一般的な感覚ではまだかなり遅いといえます。
以上より、真のボトルネックは他にありそうということで、チューニングを継続することにしました。
チューニングその2 〜実行計画そのものを分析する
仮説：特定のジョインでインデックスが使われていないのではないか？
真のボトルネックを探すためにはやはり実行計画を正面から読み解くしかないということで、実行計画の解読にチャレンジしました。前述したように、PostgreSQLの実行計画はNew Relicではツリー状に表示されます。ツリーのノードには以下のようなコストが表示されます。
Merge Left Join (cost=1731909.37..1731927.82 rows=1 width=16)
..の前は最初の行が返されるまでのスタートアップコスト、後ろはすべての行が返されるまでの合計コストを意味します。「合計コスト - スタートアップコスト」がその処理にかかるコストになります。コストはあくまで相対的な値であるため、処理コストが大きい枝を追跡していくことで怪しい箇所にたどり着く目印にするという使い方をしました。加えて、AIにも実行計画を渡して壁打ちしながらボトルネックを探しました。
すると、ジョインにインデックスが使われていなさそうな箇所を発見しました。
Parallel Seq Scanはインデックスを使わないテーブルフルスキャンを意味します。レコード数が少ないテーブルであれば問題ありませんが、employeesのような巨大なテーブルへの検索でインデックスが使われていないということは、インデックスが不足しておりチューニングの余地があることを意味します。
-> Parallel Seq Scan on employees (cost=0.00..1715305.37 rows=146887 width=48)
施策：適切なインデックスの追加
該当テーブルに貼られているインデックスを確認したところ、該当のジョインの条件で使用されるカラムと対象カラムがおおむね一致する複合インデックスが存在しました。しかし一部のカラムが足りておらず、意図した場面で使われていなさそうであることが分かりました。
以上の分析結果に基づき、ジョインの条件となっているカラムに対して適切なインデックスを追加するRailsのマイグレーションを作成・適用しました。
結果：性能問題の完全な解消
仮説通り、インデックスの追加は劇的な効果がありました。
New Relicで確認したところ、最も問題が大きかったテナントでは、約600秒（10分）かかっていたレスポンスタイムを約1.5秒まで短縮することができました。また、該当URLの99パーセンタイルも1.0秒未満に収まるようになり、一部のデータ量が多いテナントで発生していた「著しくユーザー体験を損なっている状態」を完全に解消できました。
実行計画も確認したところ、ボトルネックを疑っていた箇所がフルスキャンであるParallel Seq Scanから、インデックスを使用するIndex Scanに変わっており、コストも激減したことを確認できました。
Index Scan using idx_xxx on employees (cost=0.56..57.40 rows=11 width=48)
システムの外部観点（New Relic）と内部観点（SQLの実行計画）の両方で施策の効果を確認できました。
| 指標 | チューニング前 | チューニング後 |
|---|---|---|
| 特定の条件下での最大レスポンスタイム | 約600秒（10分） | 約1.5秒 |
| 全体リクエストの99パーセンタイル | 数十秒 〜 数百秒（不安定） | 1.0秒未満 |
| 実行計画（ボトルネック箇所） | Parallel Seq Scan | Index Scan |
チューニング前後で数百倍の改善が得られ、すべてのテナントで快適なレスポンスタイムを実現できました。
進め方の工夫
ここからは、今回の性能改善を進めるにあたって意識したことを紹介します。
計測→仮説→施策→検証のサイクルをスプリント内で回す
「推測するな、計測せよ」の格言に従い、以下のサイクルを回すことを徹底しました。
- まずはNew Relicを使って数値や実行計画などの客観的なデータを確認する
- 原因の仮説を立てる
- 施策を投入する
- 施策投入後の結果を計測する
最終的な結論はインデックスが足りなかったというよくある話ですが、原理原則に従ったプロセスで効率的にボトルネックを特定できたことに価値があると考えています。
今回の性能改善タスクはメインフィーチャー開発の傍らでスプリントの約10%の作業時間を使って行いました。1スプリントで1サイクルを実施することで、フィーチャー開発の時間を圧迫することなく実施できました。
フィーチャーフラグによる段階的なリリース
前述の通り、チューニングの施策投入時にはFlipperによるフィーチャーフラグを活用しました。フィーチャーフラグでテナント単位に適用対象を限定することで、万が一性能が悪化した場合もコードのリバートなしに即座に切り戻せる状態を作りました。効果を確認してから段階的に対象テナントを広げていくことで、影響範囲を最小限に抑えながら安全にチューニングを進めることができました。
課題
今回の性能改善は成功した一方で、問題の検知がインフラチームからのエスカレーション頼みになってしまい、対応が後手に回ったという課題がありました。今後は「人給基幹プロダクト」の開発チームで自律的にパフォーマンス低下を検知・改善できる仕組みを目指し、以下の取り組みを進めています。
- CUJ（Critical User Journey：ユーザーにとって重要な操作フロー）のワークショップを開催することで、SLO （Service Level Objective：サービスレベル目標）への意識を高める
- SmartHRのSREチームによるオブザーバビリティ・SLO導入の取り組みは、以下の発表資料で詳しく紹介されています
- 定期的にチームでNew Relicをみて確認する時間を作る
- 改善タスク枠（1スプリントの開発時間の約20%）に性能改善タスクも含め、定常的に改善していく
We Are Hiring!
SmartHRでは今回の事例のようにまだまだ性能面の課題がたくさんあります。今回のようなパフォーマンスチューニングの事例に少しでも興味を持っていただけたら、ぜひカジュアル面談でざっくばらんにお話ししましょう！
