ある日、以下の 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_gamecampaign 列を 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)
gamelist32376 行それぞれに対して、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_gamecampaign = 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 を追加することで対応完了とします。