[pgsql-jp: 41927] 【返信：質問】サブクエリを使った検索文の実行時間短縮について
toshio_uchiyama ＠ mirror.ocn.ne.jp
toshio_uchiyama ＠ mirror.ocn.ne.jp
2017年 3月 29日 (水) 13:53:21 JST
高塚様
お世話になります。返信、ありがとうございます。
大変、勉強になります。独学なので、explain analyze に
表示されている個々の数値の見方を高塚様のメールで
勉強しています ^^;。
プランの変更に該当するかどうかわかりませんが、
in 句を exists 句に変更してみました。結果は、
moovle=# explain analyze select distinct p.content from manual as p where
lower( p.content ) like lower( '%ありがとう%') and exists ( select distinct
c.video from manual as c where lower( c.content ) like lower( '%感謝%' ) and
p.video = c.video );
QUERY PLAN
----------------------------------------------------------------------------
----------------------------------------------------------------------------
----------
HashAggregate (cost=8954.30..8955.66 rows=136 width=48) (actual
time=11820.399..11820.972 rows=2656 loops=1)
Group Key: p.content
-> Nested Loop (cost=8748.89..8952.81 rows=596 width=48) (actual
time=79.851..11817.556 rows=4321 loops=1)
-> HashAggregate (cost=8650.73..8650.76 rows=3 width=12) (actual
time=29.522..30.353 rows=1904 loops=1)
Group Key: c.video
-> Bitmap Heap Scan on manual c (cost=42.50..8641.86
rows=3549 width=12) (actual time=5.470..24.826 rows=4541 loops=1)
Recheck Cond: (lower(content) ~~ '%感謝%'::text)
Heap Blocks: exact=3647
-> Bitmap Index Scan on manual_lower_gin_content_idx
(cost=0.00..41.62 rows=3549 width=0) (actual time=3.567..3.567 rows=4541
loops=1)
Index Cond: (lower(content) ~~ '%感謝%'::text)
-> Bitmap Heap Scan on manual p (cost=98.16..100.67 rows=1
width=60) (actual time=6.185..6.188 rows=2 loops=1904)
Recheck Cond: ((video = c.video) AND (lower(content) ~~ '%あ
りが とう%'::text))
Rows Removed by Index Recheck: 0
Heap Blocks: exact=2986
-> BitmapAnd (cost=98.16..98.16 rows=1 width=0) (actual
time=6.176..6.176 rows=0 loops=1904)
-> Bitmap Index Scan on manual_video_idx (cost=0.00..
25.40 rows=1454 width=0) (actual time=0.121..0.121 rows=797 loops=1904)
Index Cond: (video = c.video)
-> Bitmap Index Scan on manual_lower_gin_content_idx
(cost=0.00..71.62 rows=3549 width=0) (actual time=6.007..6.007 rows=16570
loops=1904)
Index Cond: (lower(content) ~~ '%ありがと
う%'::text)
Planning time: 1.979 ms
Execution time: 11821.506 ms
(21 行)
とあまり変わりません。この場合も 6.108 ms かかるループを 1904 回実行している
ところがネックのようですね。6 ms x 2000 は、12秒、実行時間の大半をしめている
ことになります。
比較のために、スポーツ、テニスもやってみました。
moovle=# explain analyze select distinct p.content from manual as p where
lower( p.content ) like lower( '%スポーツ%') and exists ( select distinct c.
video from
manual as c where lower( c.content ) like lower( '%テニス%' ) and p.video =
c.v
ideo );
QUERY PLAN
----------------------------------------------------------------------------
----------------------------------------------------------------------------
--------
HashAggregate (cost=8934.30..8935.66 rows=136 width=48) (actual
time=497.705..497.727 rows=152 loops=1)
Group Key: p.content
-> Nested Loop (cost=8748.89..8932.81 rows=596 width=48) (actual
time=21.344..497.525 rows=177 loops=1)
-> HashAggregate (cost=8660.73..8660.76 rows=3 width=12) (actual
time=4.614..4.729 rows=193 loops=1)
Group Key: c.video
-> Bitmap Heap Scan on manual c (cost=52.50..8651.86
rows=3549 width=12) (actual time=0.533..4.272 rows=327 loops=1)
Recheck Cond: (lower(content) ~~ '%テニス%'::text)
Heap Blocks: exact=233
-> Bitmap Index Scan on manual_lower_gin_content_idx
(cost=0.00..51.62 rows=3549 width=0) (actual time=0.428..0.428 rows=327
loops=1)
Index Cond: (lower(content) ~~ '%テニス%'::text)
-> Bitmap Heap Scan on manual p (cost=88.16..90.67 rows=1
width=60) (actual time=2.546..2.549 rows=1 loops=193)
Recheck Cond: ((video = c.video) AND (lower(content) ~~ '%ス
ポー ツ%'::text))
Heap Blocks: exact=113
-> BitmapAnd (cost=88.16..88.16 rows=1 width=0) (actual
time=2.539..2.539 rows=0 loops=193)
-> Bitmap Index Scan on manual_video_idx (cost=0.00..
25.40 rows=1454 width=0) (actual time=0.282..0.282 rows=846 loops=193)
Index Cond: (video = c.video)
-> Bitmap Index Scan on manual_lower_gin_content_idx
(cost=0.00..61.62 rows=3549 width=0) (actual time=2.243..2.243 rows=1606
loops=193)
Index Cond: (lower(content) ~~ '%スポー
ツ%'::text)
Planning time: 1.674 ms
Execution time: 497.912 ms
(20 行)
moovle=#
こちらは In 句に比べて、実行時間が、若干、遅くなりました。In 句のスポーツ、
テニスは
およそ 200ms でした。しかし、検索語による検索実行時間の傾向は同じです。
実行時間の差は、検索結果数によるものではないか。という推測を捨てられません。
ところで、「In句のスポーツ、テニス」で、「In 句のありがとう、感謝」にプラ
ンとして
対応する個所は
Bitmap Heap Scan on manual p (cost=88.16..90.67 rows=1 width=60) (actual
time=2.546..2.549 rows=1 loops=193)
になるかと思います。2.549 ms を 193 回おこなっています。2.5ms x 200 は
500ms です。
「In句のスポーツ、テニス」の実行時間とほぼ、一致します。
PostgreSQL 初心者なもので、explain analyze
の味方がよくわからないので、何をやっている Heap Scanなのかわかりません。
ここで疑問なのですが、なぜ、ここが、Bitmap Heap Scan なのでしょうか。
検索で使っている video も content もインデックスがついています。
なぜ、Index Scan でないのでしょうか。
どなたかご指導いただけますでしょうか。これ以上、プラン変更の名案が浮かびま
せん。
よろしくお願いします。
-----Original Message-----
From: pgsql-jp-bounces ＠ ml.postgresql.jp
[mailto:pgsql-jp-bounces ＠ ml.postgresql.jp] On Behalf Of TAKATSUKA Haruka
Sent: Wednesday, March 29, 2017 11:02 AM
To: PostgreSQL Japanese Mailing List
Subject: [pgsql-jp: 41926] Re: 【質問】サブクエリを使った検索文の実行時間短
縮について
こんにちは。JPUG の高塚です。
ヒット件数が 1. は 177件、 2. は 4321件なのですよね。
検索時間の差異はヒット件数に由来するように見えます。
2. では、1回平均 6.168ms を要する検索を 1904回ループ繰り返しする処理に
なっていることで時間を要しています。
SQLやプランを改善するアイデアは何かありそうですが、少なくとも
pgbigmによるインデックスキーワード検索自体の問題ということでは
なさそうです。
On Wed, 29 Mar 2017 02:51:08 +0900
<toshio_uchiyama ＠ mirror.ocn.ne.jp> wrote:
> PostgreSQL 9.4.4 とpg-bigm 1.1 を用いた
> 全文検索エンジンで、条件語
>
> 1. スポーツ と テニス の両方を含む
> 2. ありがとう と 感謝 の両方を含む
>
> を変更しただけの同一検索文
> （サブクエリを用いている）で実行時間に差が
> でています。1 の条件語での検索が 1 秒程度で
> 2 の検索語での検索が11秒程度です。
> どちらも 1 秒程度だと助かります。
> テーブルは、変な名前ですが manual という名前で
> ビデオの字幕を登録したものです。
>
> カラム データ型
> id bigint
> theme text
> video text
> starttime numeric(10,3)
> endtime numeric(10,3)
> content text
> track bigint
> userid text
> eng_conv integer
> time timestamp without time zone
>
> の10列です。theme がビデオ名です。video が
> ビデオの id です。starttimeとendtime が字幕の
> 開始時間と終了時間です。content が字幕です。
> track は字幕番号です。userid が登録者の
> ユーザーID です。eng_conv は英会話動画の
> フラグです。time が登録時刻です。複数の字幕に
> 同じ video ID とトラック番号がついています。
> インデックスは、
>
> manual_pkey
> CREATE UNIQUE INDEX manual_pkey ON manual USING btree (id)
> manual_eng_conv_idx CREATE INDEX manual_eng_conv_idx ON manual USING
> btree (eng_conv) manual_lower_gin_content_idx CREATE INDEX
> manual_lower_gin_content_idx ON manual USING gin
> (lower(content) gin_bigm_ops)
> manual_lower_gin_theme_idx
> CREATE INDEX manual_lower_gin_theme_idx ON manual USING gin
> (lower(theme)
> gin_bigm_ops)
> manual_track_idx
> CREATE INDEX manual_track_idx ON manual USING btree (track)
> manual_video_idx CREATE INDEX manual_video_idx ON manual USING btree
> (video)
>
> の6つを付けています。
>
> 1 の検索語の場合の explain analyze が
> moovle=# explain analyze select * from manual where lower( content )
> like lower( '%スポーツ%') and video in ( select distinct video from manual
> where lower( content ) like lower( '%テニス%' ));
>
> QUERY PLAN
> ----------------------------------------------------------------------
> ------
> ----------------------------------------------------------------------
> ------
> --
> Nested Loop (cost=8749.96..8936.05 rows=1 width=185) (actual
> time=4.825..202.034 rows=177 loops=1)
> -> HashAggregate (cost=8660.73..8660.76 rows=3 width=12) (actual
> time=0.712..0.764 rows=193 loops=1)
> Group Key: manual_1.video
> -> Bitmap Heap Scan on manual manual_1 (cost=52.50..8651.86
> rows=3549 width=12) (actual time=0.131..0.615 rows=327 loops=1)
> Recheck Cond: (lower(content) ~~ '%テニス%'::text)
> Heap Blocks: exact=233
> -> Bitmap Index Scan on manual_lower_gin_content_idx
> (cost=0.00..51.62 rows=3549 width=0) (actual time=0.104..0.104
> rows=327
> loops=1)
> Index Cond: (lower(content) ~~ '%テニス%'::text)
> -> Bitmap Heap Scan on manual (cost=89.23..91.74 rows=1
> width=185) (actual time=1.040..1.041 rows=1 loops=193)
> Recheck Cond: ((video = manual_1.video) AND (lower(content)
> ~~ '%ス
> ポーツ%'::text))
> Heap Blocks: exact=113
> -> BitmapAnd (cost=89.23..89.23 rows=1 width=0) (actual
> time=1.038..1.038 rows=0 loops=193)
> -> Bitmap Index Scan on manual_video_idx
> (cost=0.00..26.47
> rows=1454 width=0) (actual time=0.119..0.119 rows=846 loops=193)
> Index Cond: (video = manual_1.video)
> -> Bitmap Index Scan on manual_lower_gin_content_idx
> (cost=0.00..61.62 rows=3549 width=0) (actual time=0.913..0.913
> rows=1606
> loops=193)
> Index Cond: (lower(content) ~~ '%スポーツ%'::text)
> Planning time: 0.305 ms
> Execution time: 202.111 ms
> (18 行)
>
> 2 の検索語の explain analyze が
> moovle=# explain analyze select content from manual where lower(
> content ) like lower( '%ありがとう%' ) and video in ( select video from
> manual where lower( content ) like lower( '%感謝%' ));
>
> QUERY PLAN
> ----------------------------------------------------------------------
> ------
> ----------------------------------------------------------------------
> ------
> ----
> Nested Loop (cost=8748.89..8952.81 rows=596 width=48) (actual
time=69.371..
> 11769.517 rows=4321 loops=1)
> -> HashAggregate (cost=8650.73..8650.76 rows=3 width=12) (actual
> time=20.822..21.578 rows=1904 loops=1)
> Group Key: manual_1.video
> -> Bitmap Heap Scan on manual manual_1 (cost=42.50..8641.86
> rows=3549 width=12) (actual time=4.855..16.387 rows=4541 loops=1)
> Recheck Cond: (lower(content) ~~ '%感謝%'::text)
> Heap Blocks: exact=3647
> -> Bitmap Index Scan on manual_lower_gin_content_idx
> (cost=0.00..41.62 rows=3549 width=0) (actual time=3.041..3.041
> rows=4541
> loops=1)
> Index Cond: (lower(content) ~~ '%感謝%'::text)
> -> Bitmap Heap Scan on manual (cost=98.16..100.67 rows=1
> width=60) (actual time=6.165..6.168 rows=2 loops=1904)
> Recheck Cond: ((video = manual_1.video) AND (lower(content)
> ~~ '%あ
> りがとう%'::text))
> Rows Removed by Index Recheck: 0
> Heap Blocks: exact=2986
> -> BitmapAnd (cost=98.16..98.16 rows=1 width=0) (actual
> time=6.158..6.158 rows=0 loops=1904)
> -> Bitmap Index Scan on manual_video_idx
> (cost=0.00..25.40
> rows=1454 width=0) (actual time=0.115..0.115 rows=797 loops=1904)
> Index Cond: (video = manual_1.video)
> -> Bitmap Index Scan on manual_lower_gin_content_idx
> (cost=0.00..71.62 rows=3549 width=0) (actual time=6.005..6.005
> rows=16570
> loops=1904)
> Index Cond: (lower(content) ~~ '%ありがとう%'::text)
> Planning time: 1.660 ms
> Execution time: 11769.988 ms
> (19 行)
>
> です。explain analyze で見たときの両者の違いは、
> Rows Removed by Index Recheck: 0
> です。これによって、実行時間にこんなに差が出るでしょうか。
pgsql-jp メーリングリストの案内