データ取得がなんか重い、、、複数のアプローチから原因の解明とパフォーマンス改善に取り組んだ話

こんにちは。メディアサプライチェーン技術部第1グループの大野です。

「システムの動きがなんとなく重い気がする、、、」

「データ取得に結構時間がかかっているな、、、」

そんな風に思ったことはありませんか？

私が担当している Node.js と PostgreSQL で構築されたプロダクトでも、そのように感じるタイミングが時々ありました。

そこで、ボトルネックになっている箇所をチームで特定していくと、ボトルネックとなっている原因が1箇所ではなく複数あることが分かりました。原因を特定し順番に対応したことで、以下のような改善をすることができました。

レスポンスタイムの短縮などによるUXの改善
インデックス追加などによるデータベース負荷・CPU使用率の削減

さらにパフォーマンス改善によりDBインスタンスのサイズダウンができ、コストダウンにも成功しました。

今回は、ボトルネックを特定した方法とパフォーマンス改善としてチームで実施したことを共有していきます。

【フェーズ1】アプリケーション側の時間がかかるAPIを改善: 0x
【フェーズ2】オブザーバビリティツールでボトルネックを探して改善: new relic
【フェーズ3】DB側の原因探しと改善: AWS Database Insights と PostgreSQL 標準の EXPLAIN ANALYZE
【フェーズ4】謎の現象: なぜか本番環境だけ特に重い
- 環境別インデックス一覧の比較
- 改善方法: 環境ごとの差異が生まれないようにする
改善の成果
3つの教訓
まとめ

【フェーズ1】アプリケーション側の時間がかかるAPIを改善: 0x

「サービスの一部が重い」という事象に対して、まず私たちはNode.jsプロセス自体の負荷調査をおこないました。

プロファイリングツールの 0x を使用して、データ取得に時間がかかっている1日分のデータ取得APIについて分析することにしました。

1日分のデータを取得してまとめてレスポンスするため、1つのデータ取得よりも多少重くなるのは仕方ないことですが、2.5秒ほどかかっており、改善できないかと考えました。

https://www.npmjs.com/package/0x

0x を使用したチューニング方法

0x をインストールする
node コマンドの代わりに 0x コマンドでアプリケーションを起動 (例：node app.js → 0x app.js)
起動した状態で、チューニングしたいAPIリクエストを実行する
Ctrl + C でアプリケーションを停止する
HTMLで出力された結果を開き、時間のかかっている箇所のコードを修正する

もし Cluster Mode を使用しているのであれば、無効にすることをおすすめします。

0x で応答時間の長い API をチェックする

1日分のデータ取得APIを 0x 起動状態で実行してフレームグラフを作成して確認したところ、スタックトレースの大部分を lodash の cloneDeep が占めていました。

lodash公式ドキュメント

分析結果のうち、水色になっている箇所がcloneDeepによる部分です。

cloneDeepは再帰的に動くため、大きなオブジェクトになるほどCPUリソースへの負荷が高くなってしまいます。該当の箇所をコードで確認すると、ほとんどが cloneDeep でのコピーは不必要な箇所であることがわかりました。

改善方法: シャローコピーへの移行

0x で確認して、スタックトレースが縦に積み重なっており、時間のかかっている箇所の _.cloneDeep(object) をスプレッド構文の {...object} でコピーするシャローコピーに変更しました。

結果的に2.5秒かかっていたこのAPIの応答時間が1.3秒となり、応答時間を約半分に削減することに成功しました。

【フェーズ2】オブザーバビリティツールでボトルネックを探して改善: new relic

new relicでボトルネックを見つける

次に改善すべき箇所の検討をつけることが難しかったため、昨年導入した new relic を使用して大まかなあたりをつけました。 new relic は、アプリケーションからインフラまで統合的に可視化するオブザーバビリティツールです。

newrelic.com

new relic の「Transactions」や「Databases」から時間がかかっている処理やスループットの多い処理を探ります。それぞれのサマリで上位20個のトランザクションやデータベース操作を表示してくれるため、比較的簡単に他と比べて怪しい箇所を見つけることができます。

レスポンス時間のワースト上位に紛れる1つのGETリクエスト

注目したのは、ある詳細データ取得の処理です。

トランザクション処理でレスポンス時間でワースト10を見たとき、この詳細データ取得以外は全てPOSTリクエストで、この詳細データ取得だけがGETリクエストでワーストに入っていました。この詳細取得は、結合させる子データも多い取得処理で、他のGETリクエストよりも時間がかかることは想像できますが、他のPOSTリクエストと並ぶほどのデータ取得はおこなっていないはずでした。

改善方法: Sequelizeの最適化

このAPIでは、毎回全ての子データ取得もおこなわれており、不要なクエリが多く叩かれている状態でした。そのため、リクエストのクエリで取得内容を絞ることができる設計に変更しました。

この改善は、レスポンスサイズを小さくすることやクエリ実行回数の減少につながりました。

【フェーズ3】DB側の原因探しと改善: AWS Database Insights と PostgreSQL 標準の EXPLAIN ANALYZE

次は、旧 Performance Insights を含む CloudWatch の Database Insights を使用し、データベース負荷の高いクエリを探します。

docs.aws.amazon.com

Database Insights を確認すると、データベース負荷の指標として AAS と言うものが出てきます。

AWSのドキュメントによると、AASとはAverage Active Session(平均アクティブセッション)のことで、メトリクスの単位になり、データベース上で同時にアクティブなセッション数が測定されます。

Database Insights のページを開いて下の方に少しスクロールしたところにあるトップSQLを見ると、多くのSQLがAASの数値が < 0.01 になっている中、 AAS が高い SQL がいくつかあることが分かりました。

Sequelize で logging オプションを設定してSQLを出力する

Database Insights でも、確認したいSQLをクリックして詳細を開くと実際の値を含めたクエリを確認することができますが、今回はsequelize の機能を使ってログとしてSQL文を出力します。

logging オプションを特に設定していない場合は、SQLがコンソールに出力される状態がデフォルトになっているようでしたが、対象のプロジェクトではlogging オプションはオフになっていたため、ログが出力されるように変更します。

プロジェクト全体のSQLをコンソールに出力する場合は、Sequelize のコンストラクタに指定します。

const sequelize = new Sequelize(database, username, password, {
  logging: console.log
});

特定のクエリ実行時のみ個別に設定したい場合は、各メソッドのオプションにlogging を追加することで出力できます。

const user = await User.findOne({
  where: { id: 1 },
  logging: console.log 
});

出力したSQLを EXPLAIN ANALYZE にかける

次に、出力したSQLを EXPLAIN ANALYZE にかけて、実際のクエリがどのように実行されているかを確認しました。

EXPLAIN ANALYZE [該当のクエリ(SELECT文など)]

EXPLAIN は実行計画のみ、 EXPLAIN ANALYZE はクエリ実行も実際におこない、実行結果の統計情報も表示してくれます。

ANALYZE 結果から怪しい部分を探す

主な確認ポイントは以下の通りです。

実行計画と実行結果に大きな乖離がないか
Seq Scan, Parallel Seq Scan となっている箇所で、スキャンの対象数が大きくなっていないか
Rows Removed by Filter (=スキャンで一度取得されたけど、フィルターによって除外された不要なデータ) が大きな数字になっていないか
ExecutionTime (=実行時間) が長くないか

今回確認したクエリでは2〜4が見られ、インデックスを追加することで解消されると考えられたため、インデックスを追加することにしました。また3の数字がそこまで大きくなくても、プロダクトの年数が経つにつれて増加していくものについてもインデックスを追加することにしました。

改善方法: インデックスの追加

インデックス、およびGINインデックスの追加は、最終的には Sequelize のマイグレーション用にファイルを作成しますが、検証段階ではクエリ実行で確認しました。

インデックスの作成

CREATE INDEX 設定したいインデックス名 
ON テーブル名 (インデックスを張るカラム名);

Sequelize のマイグレーションファイルとしては以下のように記述できます。

module.exports = {
  up: async (queryInterface, Sequelize) => {
    return queryInterface.addIndex('テーブル名', ['インデックスを張るカラム名'], {
      name: '設定したいインデックス名'
    });
  },
  down: async (queryInterface, Sequelize) => {
    return queryInterface.removeIndex('テーブル名', '削除したいインデックス名');
  },
};

GINインデックスは、Generalized Inverted Index(汎用逆インデックス) のことで、jsonbや配列のカラムに対して効率的にインデックスを張ることができるデータ構造です。

GINインデックスの作成

CREATE INDEX 設定したいインデックス名 
ON テーブル名 USING GIN (インデックスを張るカラム名);

GINインデックスのマイグレーションファイルの記述方法

module.exports = {
  up: async (queryInterface, Sequelize) => {
    return queryInterface.addIndex('テーブル名', ['インデックスを張るjsonbのカラム名'], {
      name: '設定したいインデックス名',
      using: 'GIN'
    }),
  },
  down: async (queryInterface, Sequelize) => {
    return queryInterface.removeIndex('テーブル名', '削除したいインデックス名'),
  },
};

認証まわりのインデックス追加は全体に関わるため、Database Insights のデータベース負荷においても、かなりの改善が見られました。インデックス追加を境に、以前は定期実行処理のタイミングで負荷が高まっていましたが、大きな負荷の上昇は起こりづらくなりました。

【フェーズ4】謎の現象: なぜか本番環境だけ特に重い

ここまで調査してきて、ある現象に気づきました。

それは、本番環境と検証環境で負荷とレスポンスタイムに差があることです。しかも本番環境の方が負荷が高く、レスポンスタイムが長い状態です。

同じデータで実行してみてもやはり差があり、これは変だと思い、検証環境と本番環境それぞれで EXPLAIN ANALYZE をかけたところ、同じクエリでも検証環境ではインデックス使用、本番環境ではフルスキャンになっている箇所があることが分かりました。

環境別インデックス一覧の比較

試しに全てのインデックスを出力して本番環境と検証環境とで比較すると、1つだけではなく複数差異がありました。この差異があったインデックスは、例の詳細データ取得に結合させる子データ取得に関するインデックスで、ローカル環境でテストする際は検証環境のDBを利用していたため気づくことができませんでした。

サービスローンチ当初に実装されたと思われる部分で、テストとして手動でインデックスを追加してそのままになっていたのかもしれません。

ちなみに、DBに存在するインデックスの一覧は以下のクエリで取得可能です。

SELECT
  tablename,
  indexname,
  indexdef
FROM
  pg_indexes
WHERE
  schemaname = 'public'
ORDER BY
  tablename,
  indexname;

改善方法: 環境ごとの差異が生まれないようにする

インデックスは、Sequelize のマイグレーション機能を活用することで作成できるため、手動で追加したと思われるインデックスについてマイグレーションファイルを新規で作成しました。ローカルDBで正常に作成されるかを確認した後、本番環境にも該当のインデックスを追加しました。

インデックスを追加したことにより本番環境のパフォーマンスが大幅に改善され、「本番環境の方が重い」という現象を解消することができました。レスポンスタイムも、平均7.75秒かかっていたクエリが平均2.7秒となり、約65%の短縮に成功しました。

改善の成果

フェーズ1からフェーズ4の取り組みを経て、レスポンスタイムやデータベース負荷など、様々な面での改善ができました。

レスポンスタイム: ある詳細取得APIで約 65% 短縮
CPU使用率: 約8割削減
コスト: DBインスタンスを 1/2 にサイズダウン

3つの教訓

今回複数のアプローチでパフォーマンス改善を進めて、3つの教訓を得ました。

1. 少しの対応でも、共通処理や高頻度で呼ばれる処理での改善は大きな効果となりうる

ほとんど全てのリクエストで呼ばれている権限まわりの改善では、インデックスを追加しただけで、大幅にデータベース負荷を下げることができました。 1リクエストあたりの改善がそこまで顕著ではなくても、高頻度で呼ばれているため、積み重なると大きな改善となってくれました。 1つの処理での大幅な改善も大切ですが、影響範囲の広い部分を気にしてみると良いかもしれないと感じました。

2. ORMは便利だが高負荷にならないよう注意

ORM は非常に便利な反面、無意識に実装すると高負荷な処理となってしまうことがあるとわかりました。スケーラブルな開発には、最小限に制御することが必要だと感じました。

3. マイグレーション機能など積極的に活用すべし

環境におけるインデックスの差異は、基本的にはないという前提にいるとなかなか気づくことが難しいと今回痛感しました。マイグレーション機能やテンプレート機能など、汎用化・共通化できる機能は積極的に活用し、日頃から差異が生まれにくい環境にしておくこと、初期に手動で用意したものも共通化・自動化していくことが大事だと思いました。

まとめ

ボトルネックを探す作業は地道な作業ではありましたが、原因を予想・特定し、検証して実際に効果が顕著に現れたときには、謎解きゲームをクリアしたような快感がありました。ユーザーにとってもデータ取得が軽くなると、サービスを使うストレスが低くなり、より活用してもらえるようになるかもしれないですよね。少しでもUXを向上できるよう、日頃からパフォーマンスを意識しながら引き続き開発していきたいと思います。

PLAY DEVELOPERS BLOG

HuluやTVerなどの日本最大級の動画配信を支える株式会社PLAYが運営するテックブログです。