ある日、以下の SQL を実行した際、
テーブルの定義は以下のとおりです。
campaign_game テーブルに campaign = '7588' に該当する行がない場合、約 300ms もの時間がかかる現象 が発生しました。SELECT
cg.game,
cg.content,
cg.url,
g.gamename,
g.median
FROM
campaign_game cg
INNER JOIN gamelist g
ON cg.game = g.id
WHERE
cg.campaign = '7588'
ORDER BY
g.median DESC,
g.count2 DESC,
g.id
LIMIT 1;
campaign_game テーブルは、あるキャンペーンにどのゲームが紐づいているかを格納する中間テーブルです。テーブルの定義は以下のとおりです。
# \d campaign_game
Table "public.campaign_game"
Column | Type | Collation | Nullable | Default
-------------------+---------+------------+------------+-------------------------------------------
id | integer | | not null | nextval('campaign_game_id_seq'::regclass)
campaign | integer | | not null |
game | integer | | not null |
content | text | | |
url | text | | |
Indexes:
"campaign_game_pkey" PRIMARY KEY, btree (id)
"campaign_game_campaign_index" btree (campaign)
"campaign_game_game_index" btree (game)
Foreign-key constraints:
"campaign_game_campaign_fkey" FOREIGN KEY (campaign) REFERENCES campaignlist(id) ON UPDATE CASCADE ON DELETE CASCADE
"campaign_game_game_fkey" FOREIGN KEY (game) REFERENCES gamelist(id) ON UPDATE CASCADE ON DELETE CASCADE
結論として、campaign_game テーブルに複数列インデックスCREATE INDEX campaign_game_campaign_game_index ON campaign_game (campaign, game);を作成していなかったことが原因でした。
事象の分析
gamelist テーブルはゲームの情報を格納するテーブルです。
今回のクエリは campaign = 7588 のキャンペーン対象のゲームを取得するものですが、campaign_game には campaign = 7588 のデータが存在しません。
したがって、campaign_game の campaign 列を campaign_game_campaign_index で検索すれば、すぐに 0 行であると判明し、速やかに応答が返るはずでした。
しかし、事象発生時の EXPLAIN ANALYZE の出力は以下のようになっていました。
Limit (cost=868.30..1355.74 rows=1 width=164) (actual time=327.409..327.409 rows=0 loops=1)
-> Incremental Sort (cost=868.30..87631.79 rows=178 width=164) (actual time=327.408..327.408 rows=0 loops=1)
Sort Key: g.median DESC, g.count2 DESC, cg.game
Presorted Key: g.median
Full-sort Groups: 1 Sort Method: quicksort Average Memory: 25kB Peak Memory: 25kB
-> Nested Loop (cost=0.71..87625.98 rows=178 width=164) (actual time=327.404..327.405 rows=0 loops=1)
-> Index Scan Backward using tokuten_index on gamelist g (cost=0.29..15344.82 rows=32376 width=107) (actual time=0.007..24.140 rows=32376 loops=1)
-> Index Scan using campaign_game_game_index on campaign_game cg (cost=0.42..2.22 rows=1 width=57) (actual time=0.009..0.009 rows=0 loops=32376)
Index Cond: (game = g.id)
Filter: (campaign = 7588)
Rows Removed by Filter: 19
Planning Time: 0.230 ms
Execution Time: 327.437 ms
この結果を分析したところ、以下の問題点が判明しました。campaign_game 側のフィルタが結合後に実行されているIndex Scan using campaign_game_game_index on campaign_game cg Index Cond: (game = g.id) Filter: (campaign = 7588)
gamelist の 32376 行それぞれに対して、campaign_game を結合した後に campaign = 7588 のフィルタを適用しているため、無駄なループ (loops=32376) が発生。このため、本来
campaign = 7588 の行がないとすぐに終了すべきクエリが、すべての gamelist のデータを走査してしまい、遅くなっていました。対応策
campaign_game テーブルに (campaign, game) の複合インデックスを作成。
CREATE INDEX idx_campaign_game ON campaign_game (campaign, game);この結果、
EXPLAIN ANALYZE は以下のように改善されました。 Limit (cost=562.42..879.79 rows=1 width=164) (actual time=52.224..52.225 rows=0 loops=1)
-> Incremental Sort (cost=562.42..56737.69 rows=177 width=164) (actual time=52.224..52.224 rows=0 loops=1)
Sort Key: g.median DESC, g.count2 DESC, cg.game
Presorted Key: g.median
Full-sort Groups: 1 Sort Method: quicksort Average Memory: 25kB Peak Memory: 25kB
-> Nested Loop (cost=0.71..56731.90 rows=177 width=164) (actual time=52.220..52.220 rows=0 loops=1)
-> Index Scan Backward using tokuten_index on gamelist g (cost=0.29..15344.82 rows=32376 width=107) (actual
time=0.006..19.325 rows=32381 loops=1)
-> Index Scan using campaign_game_campaign_game_index on campaign_game cg (cost=0.42..1.27 rows=1 width=57)
(actual time=0.001..0.001 rows=0 loops=32381)
Index Cond: ((campaign = 7588) AND (game = g.id))
Planning Time: 0.425 ms
Execution Time: 52.252 ms
campaign_game の campaign = 7588 で事前にフィルタリングされ、Nested Loop の無駄な繰り返しがなくなりました。教訓
サロゲートキーのある中間テーブルでは、複数列インデックスの作成を考慮する。
補足
今回のSQLは、ある日突然遅くなりました。つまり、それ以前は素早い応答を返していたはずです。
そこで、作成した campaign_game_campaign_game_index を削除し、SQL を実行してみました。
Limit (cost=27.87..107.02 rows=1 width=160) (actual time=0.010..0.011 rows=0 loops=1)
-> Merge Join (cost=27.87..14038.89 rows=177 width=160) (actual time=0.010..0.010 rows=0 loops=1)
Merge Cond: (g.id = cg.game)
-> Index Scan using gamelist_pkey on gamelist g (cost=0.29..14296.29 rows=32376 width=103) (actual time=0.004..0.004 rows=1 loops=1)
-> Sort (cost=26.25..26.69 rows=177 width=57) (actual time=0.005..0.005 rows=0 loops=1)
Sort Key: cg.game
Sort Method: quicksort Memory: 25kB
-> Index Scan using campaign_game_campaign_index on campaign_game cg (cost=0.42..19.64 rows=177 width=57) (actual time=0.004..0.004 rows=0 loops=1)
Index Cond: (campaign = 7588)
Planning Time: 0.194 ms
Execution Time: 0.027 ms
実行結果を見ると、campaign_game テーブルを campaign = 7588 で絞り込んでいるため、爆速で結果が返ってきています。
もともとこのクエリで動いていたのに、実行計画が変わったことでクエリの処理が遅くなったのではないかと考えられます。
その後、再び campaign_game_campaign_game_index を追加し、削除してみたところ、上記の実行計画にはならなくなりました。
今回の案件は campaign_game_campaign_game_index を追加することで対応完了とします。
