TOPメッセージ, エンジニア, 実用

「INDEXによる高速化」は本当なのか!?PostgreSQLでパフォーマンスチューニングしてみた

お久しぶりですね。
みんなの恋人(ラバー)、リモートワーカーの仲井です。

カタリストで作っている「とある魔術系のサイト」では、それなりに魔力(規模)が大きいためにどうしても詠唱(検索処理)が遅くなってしまうことがありました。
テーブルによっては1000万超のスペル(レコード)もあり、高名なハイウィザードでもないかぎり、ここの詠唱(検索処理)がボトルネックになることも多いです。

ちょっとひねって面白くしようと思ったけど、上司のウケも悪いし、続けるのもめんどくさいからこの魔術設定はやめますね。

(大規模サイト担当してる人から見ればたった1000万でしょ? となるかもですが、カタリストでは大きい方なのです。というかビッグデータを扱うサービスと比較するのは用途もスペックも違うんだしナンセンスですね。)

ここまで大きくなくても、数千、数万レベルのレコード数であっても設計を間違えるとそれがボトルネックになることもあり、必ずしも大容量データだと遅くなるというわけではありません。大容量でも適切なチューニングがされていれば問題はないのです。

DBのパフォーマンスチューニングについてはたくさんのサイトやブログで紹介があり、皆さま既に知識としてはご存知とは思いますので、細かい内容は無視して「チューニングすると、実際これくらい差が出る」ということを、私がこれまで経験した内容を紹介したいと思います。

実際INDEX貼り忘れるとどれくらい遅いの?

よく言われるINDEXですが、これもむやみに貼ればいいものではありません。
しかし、必要なのに貼っていない場合の影響はとても大きいです。

カタリストで実際にあった例を紹介したいと思います。

  • BtoCサイトの管理画面
  • ユーザからの問い合わせ対応のためにスタッフが使用する
  • 過去の問い合わせ履歴や過去にユーザがサイトで利用したマイレージの履歴も参照できる

この画面で、
「ユーザからのある特定の問い合わせにID:227のスタッフが対応していて、最後にマイレージを使用した日付が指定した範囲内のユーザを検索する」
という検索処理がありました。

しかし、この検索処理がなかなか終わらず、結果として1回の検索処理に20分もかかってしまうというとてもひどい状態となっていました。
そこでボトルネックを調査し、原因を解消したときに対応した内容を紹介します。
SQLのボトルネックを調べるためにおなじみの「EXPLAIN ANALYZE」を使用して、実行速度を計測しました。その時の結果がこれです。

1.最初の検索処理

最初のSQLがこちら


EXPLAIN ANALYZE 
SELECT 
   * 
FROM  ( 
   SELECT 
      DISTINCT ON (b.ID) a.ID as staffID , b.ID , a.dd AS mdd
   FROM   
      support AS a  , usrData AS b 
   WHERE 
      a.motoID = b.ID AND a.staffID = 227  
      AND EXISTS (
         SELECT 1 FROM (
            SELECT  
               ID , max(dd) AS dd 
            FROM 
               mileageRiyou 
            WHERE 
               type >= 1 AND type <= 8 
            GROUP BY ID 
         ) SAISYUU_PT_RIYOU 
         WHERE 
            to_char(dd, 'YYYYMMDDHH24') <= '2016071923' 
            AND 
            SAISYUU_PT_RIYOU.ID = b.ID
      ) 
      AND EXISTS (
         SELECT 1 FROM (
            SELECT * FROM (
               SELECT 
                  max(toiID) AS toiID 
               FROM 
                  toiawase 
               WHERE 
                  staffID = 227 
                  AND 
                  toiType = 'T' 
               GROUP BY ID
            ) TMP
            , toiawase t 
            WHERE 
               TMP.toiID = t.toiID  AND toiType = 'T'  
               AND substr(toiNo, 1, 10) >= '2007000001'
         ) AS toiMatome 
         WHERE 
            toiMatome.ID = b.ID
      )  
   ORDER BY 
      b.ID , a.dd DESC  
) AS z  
WHERE 
   z.joutai = 1 
ORDER BY 
   z.mdd DESC;

supportテーブルがユーザからの問い合わせデータ

 ID  INTEGER  宛先のスタッフID
 motoID  INTEGER  問い合わせ元のユーザID
 honbun  TEXT  問い合わせ本文
 dd  TIMESTAMP  問い合わせ日時

usrDataテーブルがユーザデータ

 ID  INTEGER  ユーザID
 name  TEXT  ユーザ名
 joutai  SMALLINT  登録状態

mileageRiyouテーブルがユーザのマイレージ利用データ

 ID  INTEGER  ユーザID
 type  SMALLINT  利用種別
 dd  TIMESTAMP  利用日

toiawaseテーブルがユーザからの問い合わせ種別を持つデータ

 toiID  INTEGER  問い合わせ毎のID
 ID  INTEGER  ユーザID
 staffID  INTEGER  問い合わせ先のスタッフID
 toiType  TEXT  問い合わせ種別
 toiNo  TEXT  問い合わせ番号

かなり長いので不要部分は省略します。


Sort  (cost=478905.76..478905.77 rows=1 width=215) (actual time=1213518.262..1213518.264 rows=22 loops=1)
   Sort Key: z.mdd
   Sort Method: quicksort  Memory: 31kB
   ->  Subquery Scan on z  (cost=478905.73..478905.75 rows=1 width=215) (actual time=1213518.163..1213518.245 rows=22 loops=1)
         Filter: (z.joutai = 1)
         ->  Unique  (cost=478905.73..478905.74 rows=1 width=215) (actual time=1213518.158..1213518.234 rows=22 loops=1)
               ->  Sort  (cost=478905.73..478905.74 rows=1 width=215) (actual time=1213518.157..1213518.185 rows=497 loops=1)
                     Sort Key: b.id, a.dd
                     Sort Method: quicksort  Memory: 182kB
                     ->  Nested Loop Anti Join  (cost=477256.40..478905.72 rows=1 width=215) (actual time=115788.578..1213514.712 rows=497 loops=1)
                           ->  Nested Loop  (cost=477256.40..478076.65 rows=1 width=219) (actual time=115788.263..1213362.470 rows=497 loops=1)
                                 Join Filter: (a.motoid = b.id)
                                 ->  Nested Loop  (cost=477256.40..478066.03 rows=1 width=118) (actual time=115788.197..1213347.667 rows=497 loops=1)
                                       Join Filter: (a.motoid = mileageRiyou.id)
                                       Rows Removed by Join Filter: 1142286572
                                       ->  Merge Join  (cost=242716.31..242763.76 rows=1 width=114) (actual time=1083.661..1103.677 rows=3773 loops=1)
                                             Merge Cond: (a.motoid = t.id)
                                             ->  Sort  (cost=1555.86..1579.57 rows=9487 width=110) (actual time=9.129..11.360 rows=9423 loops=1)
                                                   Sort Key: a.motoid
                                                   Sort Method: quicksort  Memory: 2205kB
                                                   ->  Append  (cost=0.00..929.16 rows=9487 width=110) (actual time=0.129..5.300 rows=9426 loops=1)
                                                         ->  Seq Scan on support a  (cost=0.00..0.00 rows=1 width=86) (actual time=0.000..0.000 rows=0 loops=1)
                                                               Filter: (staffid = 227)
                                                         ->  Index Scan using support_00_id_idx on support_00 a  (cost=0.00..5.30 rows=1 width=144) (actual time=0.007..0.007 rows=0 loops=1)
~~~~~~~~~~~~~~~~~~~~~省略~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                               Index Cond: (staffid = 227)
                                             ->  Sort  (cost=241160.45..241160.46 rows=1 width=4) (actual time=1074.522..1078.057 rows=3772 loops=1)
                                                   Sort Key: t.id
                                                   Sort Method: quicksort  Memory: 28kB
                                                   ->  HashAggregate  (cost=241160.43..241160.44 rows=1 width=4) (actual time=1074.495..1074.505 rows=79 loops=1)
                                                         ->  Nested Loop  (cost=241083.87..241160.43 rows=1 width=4) (actual time=1072.015..1074.467 rows=79 loops=1)
                                                               ->  HashAggregate  (cost=241083.87..241083.91 rows=4 width=8) (actual time=1071.947..1072.007 rows=242 loops=1)
                                                                     ->  Seq Scan on toiawase  (cost=0.00..241076.70 rows=1434 width=8) (actual time=1.321..1070.918 rows=2368 loops=1)
                                                                           Filter: ((staffid = 227) AND (toitype = 'T'::text))
                                                                           Rows Removed by Filter: 9580209
                                                               ->  Index Scan using toiawase_pkey on toiawase t  (cost=0.00..19.11 rows=1 width=8) (actual time=0.010..0.010 rows=0 loops=242)
                                                                     Index Cond: (toiid = (max(toiawase.toiid)))
                                                                     Filter: ((toitype = 'T'::text) AND (substr(toino, 1, 10) >= '2007000001'::text))
                                                                     Rows Removed by Filter: 1
                                       ->  HashAggregate  (cost=234540.09..234844.96 rows=20325 width=12) (actual time=0.576..292.349 rows=302753 loops=3773)
                                             Filter: (to_char(max(mileageriyou.dd), 'YYYYMMDDHH24'::text) <= '2016071923'::text)
                                             Rows Removed by Filter: 535
                                             ->  Seq Scan on mileageriyou  (cost=0.00..202608.83 rows=4257501 width=12) (actual time=0.025..1221.489 rows=4291349 loops=1)
                                                   Filter: ((type >= 1) AND (type <= 8))
                                                   Rows Removed by Filter: 2283909
                                 ->  Index Scan using usrdata_pkey on usrdata b  (cost=0.00..10.61 rows=1 width=109) (actual time=0.020..0.021 rows=1 loops=497)
                                       Index Cond: (id = mileageriyou.id)
                           ->  Append  (cost=0.00..414.28 rows=51 width=4) (actual time=0.294..0.294 rows=0 loops=497)
                                 ->  Seq Scan on support tmp  (cost=0.00..0.00 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=497)
~~~~~~~~~~~~~~~~~~~~~省略~~~~~~~~~~~~~~~~~~~~~~~~
Total runtime: 1213519.185 ms

全体で1200秒つまり20分もかかっています。もう異常です。

20分あったら新宿から山手線内回りで品川まで行けますよ。
函館本線で野幌から札幌まで行けますよ。

女子5000メートル競歩の世界記録が「ジリアン・オサリバン」の

「20分02秒60」
だそうです。

5000メートルを競歩すること自体が驚異ですが。

ここで赤字にした部分がボトルネックとなっている部分です。

1.Seq Scan on toiawase (cost=0.00..241076.70 rows=1434 width=8) (actual time=1.321..1070.918 rows=2368 loops=1)
actual timeを見るとユーザからの問い合わせ種別の検索に1,070 msかかっていることになります。

次にユーザのマイレージ利用履歴の検索では
2.Seq Scan on mileageriyou (cost=0.00..202608.83 rows=4257501 width=12) (actual time=0.025..1221.489 rows=4291349 loops=1)
1,221 msかかっています。

どこを見るかというと、actual timeの開始時間と終了時間の差を見ます。
参考:http://www.atmarkit.co.jp/ait/articles/0806/09/news125_3.html

2.INDEXを貼った処理

では、ここからどうすればいいでしょうか。
両テーブルの対象レコード数(rows)を見てみましょう。
1のtoiawaseテーブルでは2,368行
2のmileageRiyouテーブルでは4,291,349行
となっています。

mileageRiyouテーブルは1000万超から400万の絞り込みで、toiawaseテーブルは数万(当時のデータがないので自分の記憶ですが)から2000の絞り込みとなっており、toiawaseテーブルの絞り込みに異常な時間がかかっていることがわかります。

次にtoiawaseテーブルのどこにそれほど時間がかかっているのか調べます。
既にお気づきの人もいると思いますが、ヒントは出ています。

1.Seq Scan on toiawase (cost=0.00..241076.70 rows=1434 width=8) (actual time=1.321..1070.918 rows=2368 loops=1)

toiawaseテーブルに対してシーケンシャルスキャンになってますね。
何を検索しているのでしょう。
すぐ下に
Filter: ((staffid = 227) AND (toitype = ‘T’::text))
とあります。
SQLでいうと

SELECT max(toiID) AS toiID FROM toiawase WHERE staffID = 227 AND toiType = 'T'

の部分のようです。

ここでまさかと思い、toiawaseテーブルのDDLを確認したところ、staffIDにINDEXが貼られていませんでした。
さっそくインデックス名(toiawase__staffid__idx)として追加しました。

追加のSQL

CREATE INDEX toiawase__staffID__idx ON toiawase(staffID);

もう一つの
2.Seq Scan on mileageriyou (cost=0.00..202608.83 rows=4257501 width=12) (actual time=0.025..1221.489 rows=4291349 loops=1)
については、レコード数がもともと大きいテーブルということと、検索対象のtypeカラム自体に種類が少ないなど諸々の要因からINDEXを貼る意味がないと判断したため、こちらは対応なしとしました。

さらにto_char関数が速度低下を招くため、特にこだわる必要もないのでやめることにしました。

改善版のSQL


EXPLAIN ANALYZE 
SELECT * FROM  ( 
   SELECT 
      DISTINCT ON (b.ID) a.ID as staffID , b.ID 
   FROM 
      support AS a  , usrData AS b 
   WHERE 
      a.motoID = b.ID AND a.staffID = 227  
      AND EXISTS (
         SELECT 1 FROM (
            SELECT  
               ID , max(dd) AS dd 
            FROM 
               mileageRiyou 
            WHERE 
               type >= 1 AND type <= 8 GROUP BY ID 
         ) SAISYUU_PT_RIYOU 
         WHERE 
            dd <= '2016-07-19 23:59:59' 
            AND SAISYUU_PT_RIYOU.ID = b.ID
      ) AND EXISTS (
         SELECT 1 FROM (
            SELECT * FROM (
               SELECT 
                  max(toiID) AS toiID 
               FROM 
                  toiawase 
               WHERE 
                  staffID = 227 AND toiType = 'T' 
               GROUP BY ID
            ) TMP
            , toiawase t 
            WHERE 
               TMP.toiID = t.toiID  
               AND toiType = 'T'  
               AND substr(toiNo, 1, 10) >= '2007000001'
      ) AS toiMatome 
      WHERE 
         toiMatome.ID = b.ID
   )  
   ORDER BY 
      b.ID , a.dd DESC  
) AS z  
WHERE 
   z.joutai = 1 
ORDER BY 
   z.mdd DESC;

測定結果は以下です。(重要部分だけ抜粋します。)


Sort  (cost=352869.39..352869.39 rows=1 width=215) (actual time=201064.609..201064.611 rows=18 loops=1)
   Sort Key: z.mdd
   Sort Method: quicksort  Memory: 29kB
   ->  Subquery Scan on z  (cost=352869.36..352869.38 rows=1 width=215) (actual time=201064.515..201064.582 rows=18 loops=1)
         Filter: (z.joutai = 1)
         ->  Unique  (cost=352869.36..352869.36 rows=1 width=215) (actual time=201064.509..201064.569 rows=18 loops=1)
               ->  Sort  (cost=352869.36..352869.36 rows=1 width=215) (actual time=201064.508..201064.530 rows=410 loops=1)
                     Sort Key: b.id, a.dd
                     Sort Method: quicksort  Memory: 153kB
                     ->  Nested Loop  (cost=351816.11..352869.35 rows=1 width=215) (actual time=2847.967..201063.277 rows=410 loops=1)
                           Join Filter: (b.id = mileageriyou.id)
                           Rows Removed by Join Filter: 1142080540
                           ->  HashAggregate  (cost=234438.52..234689.22 rows=20056 width=12) (actual time=2169.157..2330.241 rows=302538 loops=1)
                                 Filter: (max(mileageriyou.dd) <= '2016-07-19 23:59:59'::timestamp without time zone)
                                 Rows Removed by Filter: 1015
                                 ->  Seq Scan on mileageriyou  (cost=0.00..202481.29 rows=4260964 width=12) (actual time=0.017..1223.725 rows=4292637 loops=1)
                                       Filter: ((type >= 1) AND (type <= 8))
                                       Rows Removed by Filter: 2284096
~~~~~~~~~~~~~~~省略~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                               ->  Sort  (cost=115517.13..115517.14 rows=2 width=4) (actual time=123.484..123.512 rows=79 loops=1)
                                                                     Sort Key: t.id
                                                                     Sort Method: quicksort  Memory: 28kB
                                                                     ->  Nested Loop  (cost=115383.17..115517.12 rows=2 width=4) (actual time=121.673..123.443 rows=79 loops=1)
                                                                           ->  HashAggregate  (cost=115383.17..115383.24 rows=7 width=8) (actual time=121.610..121.667 rows=241 loops=1)
                                                                                 ->  Bitmap Heap Scan on toiawase  (cost=7826.01..115368.02 rows=3030 width=8) (actual time=33.996..120.929 rows=2354 loops=1)
                                                                                       Recheck Cond: (staffid = 227)
                                                                                       Filter: (toitype = 'T'::text)
                                                                                       Rows Removed by Filter: 422970
                                                                                       ->  Bitmap Index Scan on toiawase__staffid__idx  (cost=0.00..7825.25 rows=422734 width=0) (actual time=27.870..27.870 rows=425324 loops=1)
                                                                                             Index Cond: (staffid = 227)
                                                                           ->  Index Scan using toiawase_pkey on toiawase t  (cost=0.00..19.11 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=241)
                                                                                 Index Cond: (toiid = (max(toiawase.toiid)))
                                                                                 Filter: (substr(toino, 1, 10) >= '2007000001'::text)
                                                                                 Rows Removed by Filter: 1
~~~~~~~~~~~~~~~省略~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total runtime: 201068.282 ms

1,213,519 msから201,068 msまで短縮されました。
およそ6倍のスピードになっています。たった1箇所のINDEXをつけただけです。
通常ザクと比べたシャア専用ザクより速いのです。

Bitmap Index Scan on toiawase__staffid__idx (cost=0.00..7825.25 rows=422734 width=0) (actual time=27.870..27.870 rows=425324 loops=1)
Index Cond: (staffid = 227)

実行時間もほとんどかかっておらず、INDEXも効いています。

ただ、これでも3分以上かかることになり、まだまだ遅いです。

3.検索順序の変更

これ以上INDEXは貼れないし、どこを修正すればいいのかわかりません。
改めて上から実行結果を眺めていて、私は気になる箇所を見つけました。

Seq Scan on mileageriyou (cost=0.00..202481.29 rows=4260964 width=12) (actual time=0.017..1223.725 rows=4292637 loops=1)

mileageRiyouテーブル自体がINDEXも貼れず、これ以上対応しないというのは上述の通りなのですが、問題はそこではなく、これが表示されている位置です。

上から順に読んでいくと、SQLの記載通りなのですが

  1. mileageRiyouのIDとusrDataのIDを紐付けて、指定範囲にマイレージ利用があったユーザを絞り込む
  2. toiawaseテーブルのstaffIDとtoiTypeの絞込
  3. toiawaseテーブルのtoiNoとtoiIDの絞込
  4. 絞り込んだtoiawaseテーブルのIDとusrDataのIDの紐付けて、指定種別の問い合わせがあったユーザを絞り込む

となっています。
何が問題なのか?

検索の順序です。
mileageRiyouテーブルはレコード数がとても多く、INDEXも貼れないテーブルです。(理由は後述します)
最初に「膨大な量のmileageRiyouテーブル」と「絞り込む前のユーザ情報テーブル」を紐付けようとするため、ここでかなりの時間がかかっています。

さらに改善が必要です。
条件を絞り込む順番を間違えるとこのような悲劇が生まれます。
どうするべきなのか?
とても簡単です。

  1. toiawaseテーブルのstaffIDとtoiTypeの絞込
  2. toiawaseテーブルのtoiNoとtoiIDの絞込
  3. 絞り込んだtoiawaseテーブルのIDとusrDataのIDの紐付けて、指定種別の問い合わせがあったユーザを絞り込む
  4. mileageRiyouのIDと絞り込まれたusrDataのIDを紐付けて、指定範囲にマイレージ利用があったユーザを絞り込む

要するに最後にmileageRiyouテーブルの絞込みをするように順序を変えただけです。

SQLはこうなります。


EXPLAIN ANALYZE 
SELECT * FROM  ( 
   SELECT 
      DISTINCT ON (b.ID) a.ID as staffID , b.ID 
   FROM 
      support AS a  , usrData AS b 
   WHERE 
      a.motoID = b.ID AND a.staffID = 227  
      AND EXISTS (
         SELECT 1 FROM (
            SELECT * FROM (
               SELECT 
                  max(toiID) AS toiID 
               FROM 
                  toiawase 
               WHERE 
                  staffID = 227 AND toiType = 'T' 
               GROUP BY ID
            ) TMP
            , toiawase t 
            WHERE 
               TMP.toiID = t.toiID  
               AND toiType = 'T'  
               AND substr(toiNo, 1, 10) >= '2007000001'
         ) AS toiMatome 
         WHERE 
            toiMatome.ID = b.ID
      ) AND EXISTS (
         SELECT 1 FROM (
            SELECT  
               ID , max(dd) AS dd 
            FROM 
               mileageRiyou 
            WHERE 
               type >= 1 AND type <= 8 
            GROUP BY ID 
         ) SAISYUU_PT_RIYOU 
         WHERE 
            dd <= '2016-07-19 23:59:59' 
            AND SAISYUU_PT_RIYOU.ID = b.ID
      )  
   ORDER BY 
      b.ID , a.dd DESC  
) AS z  
WHERE 
   z.joutai = 1 
ORDER BY 
   z.mdd DESC;

本当にEXISTSの順序を変えただけですね。
さて、これがどうなったでしょうか。


 Sort  (cost=352518.48..352518.49 rows=1 width=215) (actual time=2388.115..2388.117 rows=18 loops=1)
   Sort Key: z.mdd
   Sort Method: quicksort  Memory: 29kB
   ->  Subquery Scan on z  (cost=352518.45..352518.47 rows=1 width=215) (actual time=2388.038..2388.106 rows=18 loops=1)
         Filter: (z.joutai = 1)
         ->  Unique  (cost=352518.45..352518.46 rows=1 width=215) (actual time=2388.035..2388.097 rows=18 loops=1)
               ->  Sort  (cost=352518.45..352518.46 rows=1 width=215) (actual time=2388.034..2388.053 rows=410 loops=1)
                     Sort Key: b.id, a.dd
                     Sort Method: quicksort  Memory: 153kB
                     ->  Hash Join  (cost=350657.61..352518.44 rows=1 width=215) (actual time=2371.387..2387.626 rows=410 loops=1)
                           Hash Cond: (b.id = mileageriyou.id)
                           ->  Nested Loop Anti Join  (cost=115517.14..117377.93 rows=2 width=223) (actual time=127.077..142.519 rows=3775 loops=1)
                                 Join Filter: (tmp.id = a.motoid)
                                 ->  Nested Loop  (cost=115517.14..116402.46 rows=2 width=223) (actual time=123.611..137.847 rows=3775 loops=1)
                                       ->  Nested Loop  (cost=115517.14..115538.36 rows=2 width=113) (actual time=123.430..124.906 rows=79 loops=1)
                                             ->  Unique  (cost=115517.14..115517.15 rows=2 width=4) (actual time=123.405..123.463 rows=79 loops=1)
                                                   ->  Sort  (cost=115517.14..115517.14 rows=2 width=4) (actual time=123.404..123.427 rows=79 loops=1)
                                                         Sort Key: t.id
                                                         Sort Method: quicksort  Memory: 28kB
                                                         ->  Nested Loop  (cost=115383.18..115517.13 rows=2 width=4) (actual time=121.648..123.384 rows=79 loops=1)
                                                               ->  HashAggregate  (cost=115383.18..115383.25 rows=7 width=8) (actual time=121.604..121.652 rows=241 loops=1)
                                                                     ->  Bitmap Heap Scan on toiawase  (cost=7826.02..115368.03 rows=3030 width=8) (actual time=33.272..120.882 rows=2354 loops=1)
                                                                           Recheck Cond: (staffid = 227)
                                                                           Filter: (toitype = 'T'::text)
                                                                           Rows Removed by Filter: 422972
                                                                           ->  Bitmap Index Scan on toiawase__staffid__idx  (cost=0.00..7825.26 rows=422734 width=0) (actual time=27.344..27.344 rows=425326 loops=1)
                                                                                 Index Cond: (staffid = 227)
                                                               ->  Index Scan using toiawase_pkey on toiawase t  (cost=0.00..19.11 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=241)
                                                                     Index Cond: (id = (max(toiawase.id)))
                                                                     Filter: (substr(toino, 1, 10) >= '2007000001'::text)
                                                                     Rows Removed by Filter: 1
~~~~~~~~~~~~~~~省略~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                           ->  Hash  (cost=234889.78..234889.78 rows=20056 width=4) (actual time=2242.321..2242.321 rows=302538 loops=1)
                                 Buckets: 2048  Batches: 1  Memory Usage: 14182kB
                                 ->  HashAggregate  (cost=234438.52..234689.22 rows=20056 width=12) (actual time=2108.580..2198.481 rows=302538 loops=1)
                                       Filter: (max(mileageriyou.dd) <= '2016-07-19 23:59:59'::timestamp without time zone)
                                       Rows Removed by Filter: 1018
                                       ->  Seq Scan on mileageriyou  (cost=0.00..202481.29 rows=4260964 width=12) (actual time=0.018..1203.682 rows=4292660 loops=1)
                                             Filter: ((type >= 1) AND (type <= 8))
                                             Rows Removed by Filter: 2284097

 Total runtime: 2388.961 ms

なんと、201,068.282 msが2,388.961 msになるという驚異的な進化を遂げました。
100倍くらい速くなっています。
最初が1,213,519.185 msだから最終的に500倍以上速くなったことになります。

絞り込む順番を変えただけなのに、どういうことなのか?

最初の検索

  1. ユーザ情報とマイレージ利用を紐付けるために絞り込み前のユーザ情報×膨大なマイレージ利用データを検索します。
  2. 1で絞ったユーザ情報と問い合せ種別データを紐付けて検索し、さらにユーザを絞ります

改善後の検索

  1. 絞り込み前のユーザ情報と比較的量の少ない問い合せ種別データを先に紐付けて検索し、ユーザを絞り込む
  2. 1で絞り込んだユーザ情報とマイレージ利用データを紐付けて、さらにユーザを絞り込む
図:簡略化した検索イメージ。改善前は絞り込まれる前のユーザ情報4×マイレージ利用データ5との検索で計20回の検索が行われる。改善後は絞り込まれたあとのユーザ情報2×マイレージ利用データ5との検索で10回の検索で済むので改善前より速くなる。

結果的に2秒程度になりました。
まだ遅いですが、最初に比べるとはるかに速くなっており、とりあえずこれでよしとしました。

まとめると

  1. シーケンシャルスキャンになっている箇所を探す
  2. シーケンシャルスキャンの箇所にINDEXを貼れば速くなるが、貼れない場合もある
  3. AND条件の絞り込み順序を気にしてみる

当たり前ですが、対象テーブルのレコード数が多ければそれだけ検索に時間がかかります。
それを解消するためにINDEXが存在しますが、INDEXが意味をなさない構造のテーブルもあります。
INDEXを貼れない大量レコードテーブルがあれば、できる限り絞り込み順序を後にすれば、絞り込みで減っているはずのレコードと大量レコードの紐付けとなるため、絞り込まれた分だけ検索処理が速くなることになります。

この時は、大量レコードとのAND検索を行なう前提で検索しているためこのような対処となりましたが、できれば大量レコードの検索は避けたいし、INDEXは貼りたいですよね。

最初に設計する際には、

  • そのテーブルのどのカラムに対する検索が今後増えそうか
  • そこにINDEXは貼れるか(何種類くらいのデータが見込まれるか)
  • 部分INDEXでも対応可能か
  • INDEXを貼れないなら別のカラムで代用できるのか
  • そもそもテーブル設計がこれでいいのか

をじっくり考えた方いいでしょう。
※時には最初に想定された使い方とは違う使い方になったりするので臨機応変にできるといいですね。

今回のmileageRiyouテーブルのtypeカラムは入るデータが10種類程度だったため、INDEXを貼っても意味がなさそうと判断したことと、レコード数自体が1000万件を超えるため、INDEXを貼るだけでサービスを停止する必要があったために断念しました。
(もしかするとINDEXを貼れば解消できた可能性はあります)
INDEXを貼るとテーブルへの書き込みがロックされるため、サービスを停止しないと対応できません。
PostgreSQLではVer8.2からCONCURRENTLYというオプションを使うことで、ロックせずにINDEXが貼れるためサービス停止は回避できますが、通常よりも処理に時間がかかる上に、その間の負荷も上がってしまうため、稼働中のサービスへの影響を考慮してこれも断念しました。

「PostgreSQLは書き込みをロックしないインデックス作成もサポートしています。 CREATE INDEXにCONCURRENTLYオプションをつけることでこの方式が行われます。 このオプションを使うと、PostgreSQLはテーブルを2回スキャンしなければなりません。 さらに、潜在的にそのインデックスを更新または使用する可能性がある、実行中のすべてのトランザクションが終わるまで待機しなければなりません。 したがって、この方式は通常の方式よりも総作業時間がかかり、また、完了するまでの時間が非常に長くなります。 しかし、インデックス作成中に通常の操作を行い続けることができますので、この方式は運用環境での新規インデックス作成に有用です。 もちろん、インデックス作成によりCPUや入出力に余分に負荷がかかりますので、他の操作が低速になる可能性があります。」
参考:https://www.postgresql.jp/document/9.6/html/sql-createindex.htmlより

さらに言い訳すれば、ここまでレコード数が増えることを考慮してなかったことと、削除契機がないためにどんどん増え続けてしまうというのも原因です。
今後このテーブルについてはまだまだ検討の余地があります。
こんなテーブルにならないように気をつけましょう。

おまけ

大容量テーブルの検索を回避した話

前述のmileageRiyouテーブルの話で、同じようにこれを検索する必要がある別の処理のお話です。

この時は「最初にマイレージを使用した日付の検索」のために、このテーブルを検索する必要がありました。

検索内容としては

  1. ユーザの登録日を絞る
  2. ユーザの登録コードを絞る(この時はLIKEで全検索)
  3. さらに最初にマイレージを使用した日付で絞る

となります。

SQLがこちら


EXPLAIN ANALYZE 
SELECT 
   ID 
FROM 
   usrData 
WHERE 
   joutai = 1 
   AND tourokudd >= '2017-09-12 00:00:00.000000' 
   AND tourokudd <= '2017-09-21 23:59:59.999999' 
   AND ( code LIKE '______' )  
   AND EXISTS ( 
      SELECT 1 FROM ( 
         SELECT 
            ID 
         FROM 
            mileageRiyou 
         WHERE 
            type >= 1 AND type <= 18 
         GROUP BY 
            ID 
         HAVING 
            min(dd) >= '2017-09-12 00:00:00.000000' 
            AND min(dd) <= '2017-09-12 23:59:59.999999' 
      ) USE_FST 
      WHERE 
         USE_FST.ID = usrData.ID 
   ) ; 

その実行予測がこちら


Hash Semi Join  (cost=680337.86..1216589.25 rows=3894 width=4) (actual time=7407.028..10541.237 rows=41 loops=1)
   Hash Cond: (usrdata.id = mileageriyou.id)
   ->  Append  (cost=0.00..536092.71 rows=7789 width=4) (actual time=20.471..3348.901 rows=9048 loops=1)
         ->  Seq Scan on usrdata  (cost=0.00..362560.72 rows=6925 width=4) (actual time=20.471..2385.254 rows=8067 loops=1)
               Filter: ((tourokudd >= '2017-09-12 00:00:00'::timestamp without time zone) AND (tourokudd <= '2017-09-21 23:59:59.999999'::timestamp without time zone) AND (code ~~ '______'::text) AND (joutai = 1))
   ->  Hash  (cost=680031.23..680031.23 rows=24530 width=4) (actual time=7190.765..7190.765 rows=99 loops=1)
         Buckets: 4096  Batches: 1  Memory Usage: 4kB
         ->  HashAggregate  (cost=679417.98..679785.93 rows=24530 width=12) (actual time=7031.698..7190.685 rows=99 loops=1)
               Filter: ((min(mileageriyou.dd) >= '2017-09-12 00:00:00'::timestamp without time zone) AND (min(mileageriyou.dd) <= '2017-09-12 23:59:59.999999'::timestamp without time zone))
               ->  Seq Scan on mileageriyou  (cost=0.00..580139.38 rows=13237147 width=12) (actual time=0.013..3808.120 rows=13676227 loops=1)
                     Filter: ((type >= 1) AND (type <= 18))
 Total runtime: 10543.266 ms

10秒程度かかってますね。
実際には、この検索を日付範囲分行なっていて、例えば9/1~9/30までほしい、という場合は日付を1日ずつズラしながら30回この検索を行ないます。

ではこの実行結果を確認します。
シーケンシャルスキャンが2箇所あります。

1.Seq Scan on usrdata (cost=0.00..362560.72 rows=6925 width=4) (actual time=20.471..2385.254 rows=8067 loops=1)

2.Seq Scan on mileageriyou (cost=0.00..580139.38 rows=13237147 width=12) (actual time=0.013..3808.120 rows=13676227 loops=1)

1で2,000 ms、2で3,800 msほどかかっていることになります。遅いですね。
1をなんとかできればいいのですが、かなり昔に設計されたテーブルなのと容量が大きいことと、アクセスがとても多いテーブルなので、前述にあるようにパフォーマンスやサービスへの影響を考えると登録日にINDEX貼ることもできず、手が出せません・・・・。

では2にINDEX貼り直せばいいのか?というとこちらも前述の通りサービスが・・・・となるので、手を出せません。
これは困ります。サービス開始当初にここまでデータが増えることと、日付検索が多いことがわかっていれば対応していたのでしょうが、今となってはとき既にお寿司。

発想を転換する

そこで私は、神の啓示を受け取るためひと月ほど山に籠もり、外界との接触を断つことで宇宙の真理と結びつくことに成功しました。

預言者となった私にもたらされた神の言葉はこうでした。

「最初にマイレージを使った日が分かればよいのだから、最初の利用日だけを別で取ればいいのではないか。おお、なんと小さき者よ

私は雷に打たれたかのような衝撃を受けました。神は人間のことを「小さき者」と呼ぶのです。

そこで「ユーザが最初にマイレージを利用した日 saisyoMileageRiyou」テーブルを追加しました。ここに1ユーザ毎に初回マイレージ利用時に1レコード入ります。

これを利用したSQLが


EXPLAIN ANALYZE 
SELECT 
   ID 
FROM 
   usrData 
WHERE 
   joutai = 1 
   AND tourokudd >= '2017-09-12 00:00:00.000000' 
   AND tourokudd <= '2017-09-21 23:59:59.999999' 
   AND ( code LIKE '______' )  
   AND EXISTS ( 
      SELECT 1 FROM ( 
         SELECT 
            ID 
         FROM 
            saisyoMileageRiyou 
         WHERE 
            dd >= '2017-09-12 00:00:00.000000' 
            AND dd <= '2017-09-12 23:59:59.999999' 
      ) USE_FST 
      WHERE 
         USE_FST.ID = usrData.ID 
   ) ; 

これを利用した実行結果がこちら


Nested Loop Semi Join  (cost=0.00..538346.07 rows=3894 width=4) (actual time=206.802..2703.723 rows=41 loops=1)
   ->  Append  (cost=0.00..536092.71 rows=7789 width=4) (actual time=18.726..2689.839 rows=9048 loops=1)
         ->  Seq Scan on usrdata  (cost=0.00..362560.72 rows=6925 width=4) (actual time=18.726..1770.301 rows=8067 loops=1)
               Filter: ((tourokudd >= '2017-09-12 00:00:00'::timestamp without time zone) AND (tourokudd <= '2017-09-21 23:59:59.999999'::timestamp without time zone) AND (code ~~ '______'::text) AND (joutai = 1))
   ->  Index Scan using saisyomileageriyou__id__idx on saisyomileageriyou  (cost=0.00..0.28 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=9048)
         Index Cond: (id = usrdata.id)
         Filter: ((dd >= '2017-09-12 00:00:00'::timestamp without time zone) AND (dd <= '2017-09-12 23:59:59.999999'::timestamp without time zone))
 Total runtime: 2703.762 ms

1.Seq Scan on usrdata (cost=0.00..362560.72 rows=6925 width=4) (actual time=18.726..1770.301 rows=8067 loops=1)

2.Index Scan using saisyomileageriyou__id__idx on saisyomileageriyou (cost=0.00..0.28 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=9048)

当然ですが2の処理が格段に速くなっています。INDEXも効いてます。
1ユーザ1レコードなのでそもそものレコード数も違います。

これでも3秒近くかかっているのでもう少し改善の余地がありますが、とりあえずここまでとしています。

何が必要なのか考える

ここで大事なことは、「必要なこと」が分かっていれば対策はあるということです。
INDEXが貼れないから諦めよう、ではなくて今回のように「そのテーブルのすべてが必要なのか」、「別のデータに置き換えられないか」という検討です。

いま、できることは何かを考え、そこから対応していくことが大切だと思います。

本当であれば、サービスを停止してINDEXを貼るか、アクセスの少ない時間にCONCURRENTLYオプションでINDEXを貼ることが最善とは思いますが、今回は諸事情で実施できなかったので、仕方なく上記対応としましたが、これでもいままでと比べると劇的にスピードアップしています。

しかし、上記対応で完璧なわけではなく、まだまだ改善の余地があります。(登録日にINDEX貼ったり、絞り込み条件を変えたり、PostgreSQLのバージョンが上がればできることが広がったり・・・・)
試行錯誤を繰り返し、今後のテーブル設計の際の糧としていければと思います。

私自身まだまだググりながら改善方法を検討している勉強中の身ですので、ほとんど先人の知恵なわけですが、少しでも同じような状況の人の参考になれればとても幸いです。

また新しい情報があれば発信していきたいと思います。

さて、ながながと書いてしまいましたが今回はここで終わります。
次はいつになるかわかりませんが、また会う日までお元気で~~。

次回は、オガティーの性能テスト、パフォーマンス改善系のお話をお届けします。

引用元・出典
5000メートル競歩 – Wikipedia
Linuxトラブルシューティング探偵団(3):PostgreSQLを遅くしている犯人はどこだ? (3/3) – @IT
PostgreSQL 9.3.2文書

LINEで送る
Pocket

この記事を書いた人・プロフィール
コウダインテ
ニックネーム: コウダインテ

北海道で一人リモートワーク。
主にPHP、PostgreSQLを使用。
ピアノはあるけど10年くらい弾いてない。
最近ゴルフを始めましたが、パターがダメで諦めそう。
車は5MTの軽自動車。無駄に変速できる。