はじめに
こんにちは、スタメンにてにてエンジニアインターンをしております中村です。
「TUNAGチャット」では、データベースとしてGoogle Cloud（旧GCP）のAlloyDB for PostgreSQLを利用しています。以前から平日昼間のCPU使用率は55~65％の水準でしたが、ある時期からデプロイのタイミングでDBのCPU負荷が100%に達し、一時的に障害となる事態が問題となりました。
調査の結果、今回のDB負荷の原因は「オプティマイザの行数推定」というRDBMSの基礎的な仕組みに関わるものでした。
本記事では、以下のアプローチで行ったパフォーマンスチューニングの詳細を書きました。
- DB負荷の原因を探る：Google Cloudの機能を利用した原因調査
- クエリの改善： 統計情報を阻害していたSQLアンチパターンの解消
- 実行回数の削減： アプリケーションロジックの見直し
特にクエリ改善に関しては15~20倍高速化され、PostgreSQLに限らずリレーショナルデータベースに一般的な内容となっていますので、ご笑覧いただけますと幸いです。
1. DB負荷の原因を探る
改善のために、「なにが」「いつどこで」「なぜ」起きているのかを特定する必要があります。以下のステップで調査を進めました。
スロークエリの特定
「なにが」負荷原因であるかを確認するため、AlloyDBの標準機能であるQuery Insightsを使用しました。 Query Insightsは高負荷なクエリを可視化し、実行計画までWeb上で確認できる分析ツールです*1。
順位表を確認すると、Top 5のクエリだけでDB負荷の大半を占めていることが判明しました（下図）。
また通常時・スパイク時それぞれで負荷割合の時系列グラフを見ると、以下のことがわかりました。
- これらのクエリは、特定の時間だけでなく昼夜問わず恒常的に実行されている
- スパイクが発生したリリースで「新しい高負荷クエリ」が追加されたわけではなく、既存のクエリ構成のまま負荷が急増していた
呼び出し元の特定
次に、Top5のクエリを発行するAPIが「いつどこで」叩かれているかを調査しました。 アプリケーションの実装から「どこ」の当たりをつけつつ、Google CloudのLog Analyticsを使用して「いつ」叩かれているか確認します。
Log Analyticsでは、Google Cloudのプロジェクト単位で保存されているログに対してSQLを実行できます。TUNAGチャットではL7のHTTPロードバランサー（LB）を使用しているので、LBのログから特定のエンドポイントのアクセス傾向を分析できます。
以下のSQLを実行し、APIごとのリクエスト数を時系列で集計しました。
SELECT TIMESTAMP_TRUNC(timestamp, HOUR) as log_hour, count(*) as request_count FROM `{PROJECT_ID}.{LOCATION}._Default._Default` WHERE resource.type = "http_load_balancer" AND log_name LIKE "%/logs/requests" AND http_request.request_url LIKE "%{任意のAPIエンドポイントの部分文字列}%" GROUP BY log_hour ORDER BY log_hour DESC
調べたAPIからは、深夜帯にも一定のリクエストがあり、クエリ負荷が深夜帯にもあることと一致しています。API発行元は、スパイクに関連していそうな場所として「リロード時の初期情報取得」・「WebSocket再接続時の情報取得」がありました。
スパイクを引き起こした原因の予想
ここまでの調査から「なぜ」起こったかを予想すると、
- DB負荷の高いクエリがプロダクトに存在し、普段は分散して実行されることで耐えていた。
- デプロイによるサーバー再起動がトリガーとなり、既存のWebSocket接続が一斉に切断されてクライアントが一斉に再接続を試みた。
- 「リロード時」「再接続時」に含まれていた高負荷クエリが瞬間的に集中し、CPU使用率のスパイクを引き起こした。
つまり、「重いクエリを放置したまま、アクセスが一点集中する状況を作ってしまったこと」がスパイクの直接的な原因のようでした。 再発防止のためには、この「重いクエリ」自体を軽量化する必要があります。
2. クエリの改善
スパイクの原因はデプロイ時のコード変更ではなく、既存実装の「重いクエリ」にあることがわかりました。
なぜか選択されるNested loop
Query Insightsで高負荷な５つのうち１つのクエリの実行計画を確認したところ、Nested Loopがボトルネックとなっていました。
SeqScanが重いことも注目すべきですが、SeqScanで40000行返されているのにも関わらず、オプティマイザ（クエリプランナー）がNestedLoopを選択していることがわかります。
なぜNested loopが選択されたのかを確認するため、実際のDBに対して再度実行計画を取得しました。
QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------- Finalize GroupAggregate (cost=1000.42..6444.51 rows=3 width=56) Group Key: threads.threadteamid -> Gather (cost=1000.42..6444.45 rows=3 width=56) // 計２プロセスで並列処理（リーダー＋ワーカー1人） Workers Planned: 1 -> Partial GroupAggregate (cost=0.42..5444.15 rows=3 width=56) Group Key: threads.threadteamid -> Nested Loop (cost=0.42..5444.08 rows=5 width=32) // ⬇️threadsに対して、１プロセスあたり238行と見積もられている -> Parallel Seq Scan on threads (cost=0.00..3496.03 rows=238 width=51) Filter: (((threadteamid)::text = 'XXXXXXXXXXXX'::text) AND (COALESCE(threaddeleteat, '0'::bigint) = 0)) -> Index Scan using threadmemberships_pkey on threadmemberships (cost=0.42..8.19 rows=1 width=35) Index Cond: (((postid)::text = (threads.postid)::text) AND ((userid)::text = 'XXXXXXXXXXXX'::text)) Filter: following
オプティマイザは統計情報をもとに行数推定を行い、その値をみて実行計画を最適化します *2。rowsが各プロセスでの行数推定の値であり、値は『テーブルにWhere句を適用したときに残っている見積もり行数』を意味します。
Query Insightsの実行計画に、SeqScanで返された行数が40767とあるので、実態としては40000*2(プロセス数)= 80000行程度がthreadsテーブルから返されています*3 *4。 しかし実行計画上の推定行数（rows）はたったの238行と、極端に過小評価されていることがわかりました。
WHERE句で関数を使うと、行数推定に統計情報が使えない
行数推定が狂った原因は、以下のようにWHERE句で関数を使用していたことでした。
WHERE (~~ AND COALESCE(Threads.ThreadDeleteAt, 0) = 0 ~~)
行数推定の概要については、こちらのスライド *5が私のような初心者にもわかりやすくまとまっていました。 推定行数は以下の式で計算されます *6
推定行数＝『濃度（テーブルの総行数）』×『選択度（WHERE句にマッチする割合）』
『濃度』『選択度』は、それぞれPostgreSQLが統計情報として持っています。 今回のテーブルの濃度を取得してみます *7 。
SELECT relpages, reltuples FROM pg_class WHERE relname = 'threads'; relpages | reltuples ----------+----------- 2701 | 90908
また『選択度』はオプティマイザーがWHERE句の条件文を見て、統計情報を使える場合は使い、使えない場合は以下のようなデフォルト値 *8 を使用します。
/* default selectivity estimate for equalities such as "A = b" */ #define DEFAULT_EQ_SEL 0.005 /* default selectivity estimate for inequalities such as "A < b" */ #define DEFAULT_INEQ_SEL 0.3333333333333333 /* default selectivity estimate for range inequalities "A > b AND A < c" */ #define DEFAULT_RANGE_INEQ_SEL 0.005 /* default selectivity estimate for multirange inequalities "A > b AND A < c" */ #define DEFAULT_MULTIRANGE_INEQ_SEL 0.005 /* default selectivity estimate for pattern-match operators such as LIKE */ #define DEFAULT_MATCH_SEL 0.005 /* default selectivity estimate for other matching operators */ #define DEFAULT_MATCHING_SEL 0.010 ...
値を比較する際、COALESCE(Threads.ThreadDeleteAt, 0) = 0のように関数を通すとオプティマイザが出力を予想できず、『選択度』に最頻値などの統計情報が使えなくなります。その結果、今回はイコール式が条件文のため、オプティマイザは『選択度』として最初の行にある0.005を使用します。
今回の並列処理（2プロセス）に当てはめてざっくりと行数推定してみると、『濃度』*『選択度』=90908*0.005=454.54、１プロセスあたり454.54÷2(プロセス数)=227.27と、オプティマイザが計算した238に近い値になりました。
つまり、データの実態を無視して、Where句を適用した後の行は「全体の0.5%しかない」と見積もられた結果、4万行のループ処理が走っていたようです。
実行計画が実態を反映するようになった
負荷Top5のクエリ全てで、WHERE句にCOALESCEが使用されていたため、統計情報が正しく機能するシンプルな比較式に書き換えました。
WHERE (~~ AND (Threads.ThreadDeleteAt = 0 OR Threads.ThreadDeleteAt IS NULL)) ~~)
この修正により、オプティマイザは行数を約8万件と正しく認識するようになり、Nested Loopから Hash Join を選択するようになりました。
QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------- GroupAggregate (cost=4047.87..8320.14 rows=3 width=56) Group Key: threads.threadteamid -> Hash Join (cost=4047.87..8312.34 rows=1554 width=32) Hash Cond: ((threads.postid)::text = (threadmemberships.postid)::text) // ⬇️実態が反映されている -> Seq Scan on threads (cost=0.00..4052.55 rows=80727 width=51) Filter: (((threaddeleteat = 0) OR (threaddeleteat IS NULL)) AND ((threadteamid)::text = 'XXXXXXXXXXXX'::text)) -> Hash (cost=4026.18..4026.18 rows=1735 width=35) -> Bitmap Heap Scan on threadmemberships (cost=34.63..4026.18 rows=1735 width=35) Recheck Cond: ((userid)::text = 'XXXXXXXXXXXX'::text) Filter: following -> Bitmap Index Scan on idx_thread_memberships_user_id (cost=0.00..34.19 rows=1836 width=0) Index Cond: ((userid)::text = 'XXXXXXXXXXXX'::text)
3. 実行回数の削減
クエリ単体の軽量化に加え、アプリケーション層でも「そもそもそのクエリを投げる必要があるか」を見直しました。
調査の結果、5つの高負荷クエリのうち一部は、特定の画面状態によっては実行が不要なものであることが判明しました。特にデプロイ後に負荷が集中する「リロード時」や「WebSocket再接続時」において、ロジック上不要なクエリの発行をフラグ制御でスキップするように修正しました。
改善結果
CPU使用率
赤棒は左から、応急措置として行なったスケールアップ（左の赤線）、元スペックへのスケールダウン（右の赤線）を示しています。対策適用を行なった以降は、インスタンススペックを元に戻した後も、CPU使用率20〜30%程度で安定して推移しています。
クエリ実行速度
実行計画が適正化されたことで、レイテンシが劇的に改善しました。 平均実行時間は 約400msから20ms台 へと短縮され、15~20倍高速化されました。
| 番号 | 修正前 | 修正後 | 改善倍率 |
|---|---|---|---|
| ① | 436.71 ms | 20.87 ms | 約 20.9倍 |
| ② | 435.86 ms | 20.75 ms | 約 21.0倍 |
| ③ | 440.62 ms | 29.06 ms | 約 15.2倍 |
| ④ | 369.46 ms | 25.20 ms | 約 14.7倍 |
| ⑤ | 369.16 ms | 24.99 ms | 約 14.8倍 |
まとめ
Where句で安易に関数を使うと、オプティマイザが行数推定を誤り、データ量に見合わない非効率な実行計画が選択される原因になります。 またスロークエリの原因を探る際は、単に「インデックスがあるか」だけでなく、オプティマイザの実行計画が正しいかどうかに注意する必要があることが、今回の調査で身にしみてわかりました。
最後に
今回、Google Cloudを触るのもDBチューニングも初めてでしたが、DB負荷改善という明確な目標に取り組みながら学ぶことで、自分にとって良い経験になりました。
本記事は、会社で契約しているGeminiに校正をしてもらいました。
スタメンには、新人のうちから色々なことを経験させてもらえる文化があります。またエンジニアだけでなく全部署でAI活用を推進しています。少しでも興味を持たれましたら、以下フォームからぜひご応募ください！ herp.careers
