Postgres Pro
Downloads
Home   >   mailing lists

query execution time faster with geqo on than off: bug? - Mailing list pgsql-hackers

From David Kamholz
Subject query execution time faster with geqo on than off: bug?
Date
Msg-id CAKuxgJ49ga=vptCir83JH=mW1Qu1DBfmYjfWNGgV8zJTP=uMzQ@mail.gmail.com
Whole thread Raw
Responses Re: query execution time faster with geqo on than off: bug?  (Merlin Moncure <mmoncure@gmail.com>)
List pgsql-hackers
Tree view
I've encountered a query with 11 joins whose execution time (i.e., the time not taken up by planning) is significantly faster with geqo on rather than off. This is surprising to me and seems like it might be a bug in the planner, so I am posting it here rather than to -performance.

The query is below, along with EXPLAIN ANALYZE results with geqo on and off. The server version is 9.4.4. The various geqo options are all set to the default. join_collapse_limit is set to 12 (the query is much slower with it set to the default of 8). Let me know what other information might be helpful in debugging this further. Thanks!

QUERY:

SELECT ex.ex, ex.lv, ex.tt, ex.td, dnsrc.ex AS trex, ((uiuq_score(array_agg(ap.ui), array_agg(ap.uq)) + uiuq_score(array_agg(apsrc.ui), array_agg(apsrc.uq))) / 2) AS trq 
FROM ex 
INNER JOIN lv ON (lv.lv = ex.lv) 
INNER JOIN dn ON (dn.ex = ex.ex) 
INNER JOIN mn ON (mn.mn = dn.mn) 
INNER JOIN ap ON (ap.ap = mn.ap) 
INNER JOIN dn AS dn2 ON (dn2.mn = dn.mn) 
INNER JOIN dn AS dn3 ON (dn3.ex = dn2.ex) 
INNER JOIN dn AS dnsrc ON (dnsrc.mn = dn3.mn) 
INNER JOIN mn AS mnsrc ON (mnsrc.mn = dnsrc.mn) 
INNER JOIN ap AS apsrc ON (apsrc.ap = mnsrc.ap) 
INNER JOIN ex AS exsrc ON (exsrc.ex = dnsrc.ex) 
INNER JOIN lv AS lvsrc ON (lvsrc.lv = exsrc.lv) 
WHERE 
dn.ex != dn2.ex AND 
dn3.ex != dnsrc.ex AND 
mn.ap != mnsrc.ap AND 
dn.ex != dnsrc.ex AND 
lcvc(lv.lc, lv.vc) IN ('zul-000') AND 
lcvc(lvsrc.lc, lvsrc.vc) IN ('gle-000') AND 
exsrc.tt IN ('doras') 
GROUP BY ex.ex, dnsrc.ex 
ORDER BY trq desc LIMIT 2000;

EXPLAIN ANALYZE with geqo on:

                                                                                             QUERY PLAN                                                                                              
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=3603.82..3603.82 rows=2 width=57) (actual time=623.322..623.326 rows=31 loops=1)
   ->  Sort  (cost=3603.82..3603.82 rows=2 width=57) (actual time=623.321..623.321 rows=31 loops=1)
         Sort Key: (((uiuq_score(array_agg(ap.ui), array_agg(ap.uq)) + uiuq_score(array_agg(apsrc.ui), array_agg(apsrc.uq))) / 2))
         Sort Method: quicksort  Memory: 27kB
         ->  HashAggregate  (cost=3603.60..3603.82 rows=2 width=57) (actual time=622.074..623.283 rows=31 loops=1)
               Group Key: ex.ex, dnsrc.ex
               ->  Nested Loop  (cost=3075.23..3603.59 rows=2 width=57) (actual time=8.023..620.761 rows=766 loops=1)
                     ->  Nested Loop  (cost=3075.17..3603.43 rows=2 width=55) (actual time=8.009..619.417 rows=766 loops=1)
                           Join Filter: (mn.ap <> mnsrc.ap)
                           Rows Removed by Join Filter: 3793
                           ->  Hash Join  (cost=3075.08..3603.21 rows=2 width=63) (actual time=7.984..610.206 rows=4559 loops=1)
                                 Hash Cond: (dn.ex = ex.ex)
                                 ->  Nested Loop  (cost=3.04..510.58 rows=20564 width=26) (actual time=0.918..509.574 rows=1047967 loops=1)
                                       Join Filter: (dn.ex <> dnsrc.ex)
                                       Rows Removed by Join Filter: 5396
                                       ->  Nested Loop  (cost=2.92..277.03 rows=118 width=22) (actual time=0.913..113.830 rows=40525 loops=1)
                                             ->  Nested Loop  (cost=2.87..267.76 rows=118 width=16) (actual time=0.899..60.170 rows=40525 loops=1)
                                                   ->  Hash Join  (cost=2.76..266.08 rows=1 width=12) (actual time=0.878..5.057 rows=1254 loops=1)
                                                         Hash Cond: (exsrc.lv = lvsrc.lv)
                                                         ->  Nested Loop  (cost=0.43..263.08 rows=871 width=16) (actual time=0.169..4.626 rows=1516 loops=1)
                                                               ->  Nested Loop  (cost=0.34..164.79 rows=871 width=20) (actual time=0.138..1.180 rows=1516 loops=1)
                                                                     ->  Nested Loop  (cost=0.23..155.09 rows=5 width=12) (actual time=0.097..0.306 rows=43 loops=1)
                                                                           ->  Index Scan using ex_tt_idx on ex exsrc  (cost=0.11..2.57 rows=2 width=8) (actual time=0.056..0.061 rows=5 loops=1)
                                                                                 Index Cond: (tt = 'doras'::text)
                                                                           ->  Index Scan using dn_ex_idx on dn dnsrc  (cost=0.11..75.55 rows=71 width=8) (actual time=0.027..0.046 rows=9 loops=5)
                                                                                 Index Cond: (ex = exsrc.ex)
                                                                     ->  Index Only Scan using dn_mn_ex_key on dn dn3  (cost=0.11..1.13 rows=81 width=8) (actual time=0.008..0.015 rows=35 loops=43)
                                                                           Index Cond: (mn = dnsrc.mn)
                                                                           Filter: (ex <> dnsrc.ex)
                                                                           Rows Removed by Filter: 1
                                                                           Heap Fetches: 0
                                                               ->  Index Scan using mn_pkey on mn mnsrc  (cost=0.09..0.10 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=1516)
                                                                     Index Cond: (mn = dnsrc.mn)
                                                         ->  Hash  (cost=2.32..2.32 rows=1 width=4) (actual time=0.026..0.026 rows=1 loops=1)
                                                               Buckets: 1024  Batches: 1  Memory Usage: 1kB
                                                               ->  Index Scan using lv_lcvc_idx on lv lvsrc  (cost=0.11..2.32 rows=1 width=4) (actual time=0.024..0.025 rows=1 loops=1)
                                                                     Index Cond: (lcvc(lc, vc) = 'gle-000'::bpchar)
                                                   ->  Index Scan using dn_ex_idx on dn dn2  (cost=0.11..0.98 rows=71 width=8) (actual time=0.005..0.040 rows=32 loops=1254)
                                                         Index Cond: (ex = dn3.ex)
                                             ->  Index Scan using ap_pkey on ap apsrc  (cost=0.06..0.07 rows=1 width=10) (actual time=0.001..0.001 rows=1 loops=40525)
                                                   Index Cond: (ap = mnsrc.ap)
                                       ->  Index Only Scan using dn_mn_ex_key on dn  (cost=0.11..1.13 rows=81 width=8) (actual time=0.003..0.006 rows=26 loops=40525)
                                             Index Cond: (mn = dn2.mn)
                                             Filter: (ex <> dn2.ex)
                                             Rows Removed by Filter: 1
                                             Heap Fetches: 728
                                 ->  Hash  (cost=3049.48..3049.48 rows=2149 width=41) (actual time=5.575..5.575 rows=2105 loops=1)
                                       Buckets: 1024  Batches: 1  Memory Usage: 121kB
                                       ->  Nested Loop  (cost=0.19..3049.48 rows=2149 width=41) (actual time=0.044..5.191 rows=2105 loops=1)
                                             ->  Index Scan using lv_lcvc_idx on lv  (cost=0.11..2.32 rows=1 width=4) (actual time=0.013..0.013 rows=1 loops=1)
                                                   Index Cond: (lcvc(lc, vc) = 'zul-000'::bpchar)
                                             ->  Index Scan using ex_lv_idx on ex  (cost=0.09..3017.95 rows=2921 width=41) (actual time=0.031..4.834 rows=2105 loops=1)
                                                   Index Cond: (lv = lv.lv)
                           ->  Index Scan using mn_pkey on mn  (cost=0.09..0.10 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=4559)
                                 Index Cond: (mn = dn.mn)
                     ->  Index Scan using ap_pkey on ap  (cost=0.06..0.07 rows=1 width=10) (actual time=0.001..0.001 rows=1 loops=766)
                           Index Cond: (ap = mn.ap)
 Planning time: 103.653 ms
 Execution time: 623.546 ms

EXPLAIN ANALYZE with geqo off:

                                                                                                QUERY PLAN                                                                                                 
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=114.58..114.58 rows=1 width=57) (actual time=11128.861..11128.865 rows=31 loops=1)
   ->  Sort  (cost=114.58..114.58 rows=1 width=57) (actual time=11128.861..11128.865 rows=31 loops=1)
         Sort Key: (((uiuq_score(array_agg(ap.ui), array_agg(ap.uq)) + uiuq_score(array_agg(apsrc.ui), array_agg(apsrc.uq))) / 2))
         Sort Method: quicksort  Memory: 27kB
         ->  HashAggregate  (cost=114.47..114.58 rows=1 width=57) (actual time=11127.638..11128.840 rows=31 loops=1)
               Group Key: ex.ex, dnsrc.ex
               ->  Nested Loop  (cost=1.10..114.46 rows=1 width=57) (actual time=6.716..11126.183 rows=766 loops=1)
                     ->  Nested Loop  (cost=1.05..114.38 rows=1 width=55) (actual time=6.712..11124.683 rows=766 loops=1)
                           Join Filter: (mn.ap <> mnsrc.ap)
                           Rows Removed by Join Filter: 3793
                           ->  Nested Loop  (cost=0.96..114.27 rows=1 width=63) (actual time=6.709..11111.769 rows=4559 loops=1)
                                 ->  Nested Loop  (cost=0.90..114.19 rows=1 width=57) (actual time=6.703..11098.471 rows=4559 loops=1)
                                       ->  Nested Loop  (cost=0.85..110.70 rows=27 width=57) (actual time=0.135..3765.710 rows=1047967 loops=1)
                                             ->  Nested Loop  (cost=0.76..107.61 rows=27 width=20) (actual time=0.116..797.027 rows=1047967 loops=1)
                                                   Join Filter: ((dn.ex <> dn2.ex) AND (dn.ex <> dnsrc.ex))
                                                   Rows Removed by Join Filter: 45921
                                                   ->  Nested Loop  (cost=0.65..85.78 rows=11 width=28) (actual time=0.110..226.986 rows=40525 loops=1)
                                                         ->  Nested Loop  (cost=0.56..84.54 rows=11 width=20) (actual time=0.103..53.716 rows=40525 loops=1)
                                                               ->  Nested Loop  (cost=0.45..82.85 rows=1 width=16) (actual time=0.094..1.009 rows=1254 loops=1)
                                                                     ->  Nested Loop  (cost=0.33..80.91 rows=1 width=8) (actual time=0.082..0.123 rows=26 loops=1)
                                                                           ->  Nested Loop  (cost=0.22..4.65 rows=1 width=4) (actual time=0.072..0.075 rows=1 loops=1)
                                                                                 ->  Index Scan using lv_lcvc_idx on lv lvsrc  (cost=0.11..2.32 rows=1 width=4) (actual time=0.022..0.023 rows=1 loops=1)
                                                                                       Index Cond: (lcvc(lc, vc) = 'gle-000'::bpchar)
                                                                                 ->  Index Scan using ex_lv_tt_key on ex exsrc  (cost=0.11..2.32 rows=1 width=8) (actual time=0.048..0.049 rows=1 loops=1)
                                                                                       Index Cond: ((lv = lvsrc.lv) AND (tt = 'doras'::text))
                                                                           ->  Index Scan using dn_ex_idx on dn dnsrc  (cost=0.11..75.55 rows=71 width=8) (actual time=0.009..0.040 rows=26 loops=1)
                                                                                 Index Cond: (ex = exsrc.ex)
                                                                     ->  Index Only Scan using dn_mn_ex_key on dn dn3  (cost=0.11..1.13 rows=81 width=8) (actual time=0.004..0.023 rows=48 loops=26)
                                                                           Index Cond: (mn = dnsrc.mn)
                                                                           Filter: (ex <> dnsrc.ex)
                                                                           Rows Removed by Filter: 1
                                                                           Heap Fetches: 0
                                                               ->  Index Scan using dn_ex_idx on dn dn2  (cost=0.11..0.98 rows=71 width=8) (actual time=0.005..0.036 rows=32 loops=1254)
                                                                     Index Cond: (ex = dn3.ex)
                                                         ->  Index Scan using mn_pkey on mn  (cost=0.09..0.10 rows=1 width=8) (actual time=0.003..0.004 rows=1 loops=40525)
                                                               Index Cond: (mn = dn2.mn)
                                                   ->  Index Only Scan using dn_mn_ex_key on dn  (cost=0.11..1.09 rows=81 width=8) (actual time=0.003..0.008 rows=27 loops=40525)
                                                         Index Cond: (mn = mn.mn)
                                                         Heap Fetches: 728
                                             ->  Index Scan using ex_pkey on ex  (cost=0.09..0.10 rows=1 width=41) (actual time=0.002..0.002 rows=1 loops=1047967)
                                                   Index Cond: (ex = dn.ex)
                                       ->  Index Scan using lv_pkey on lv  (cost=0.06..0.12 rows=1 width=4) (actual time=0.007..0.007 rows=0 loops=1047967)
                                             Index Cond: (lv = ex.lv)
                                             Filter: (lcvc(lc, vc) = 'zul-000'::bpchar)
                                             Rows Removed by Filter: 1
                                 ->  Index Scan using ap_pkey on ap  (cost=0.06..0.07 rows=1 width=10) (actual time=0.002..0.002 rows=1 loops=4559)
                                       Index Cond: (ap = mn.ap)
                           ->  Index Scan using mn_pkey on mn mnsrc  (cost=0.09..0.10 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=4559)
                                 Index Cond: (mn = dnsrc.mn)
                     ->  Index Scan using ap_pkey on ap apsrc  (cost=0.06..0.07 rows=1 width=10) (actual time=0.001..0.001 rows=1 loops=766)
                           Index Cond: (ap = mnsrc.ap)
 Planning time: 163.302 ms
 Execution time: 11129.050 ms

pgsql-hackers by date:

Previous
From: Michael Paquier
Date:
Subject: Re: The real reason why TAP testing isn't ready for prime time
Next
From: David Rowley
Date:
Subject: Sharing aggregate states between different aggregate functions