Re: Extremely slow when query uses GIST exclusion index
Am 29.08.2018 um 05:31 schrieb David: For now, I can bypass the GIST index by avoiding range operators in my queries. But why is the GIST index so slow? your GiST-Index contains (member_id,group_id,valid_period), but your query is only on the latter 2 fields. test=*# create index test_index on member_span using gist (group_id,valid_period); CREATE INDEX test=*# commit; COMMIT test=# explain analyse SELECT * FROM app JOIN group_span ON app.group_id = group_span.group_id AND app.app_time <@ group_span.valid_period JOIN member_span ON group_span.group_id = member_span.group_id AND group_span.valid_period && member_span.valid_period; QUERY PLAN --- Nested Loop (cost=319.27..776.18 rows=1 width=196) (actual time=3.156..334.963 rows=1 loops=1) Join Filter: (app.group_id = member_span.group_id) -> Hash Join (cost=319.00..771.00 rows=12 width=104) (actual time=3.100..14.040 rows=1 loops=1) Hash Cond: (group_span.group_id = app.group_id) Join Filter: (app.app_time <@ group_span.valid_period) Rows Removed by Join Filter: 2000 -> Seq Scan on group_span (cost=0.00..257.00 rows=12000 width=59) (actual time=0.013..1.865 rows=12000 loops=1) -> Hash (cost=194.00..194.00 rows=1 width=45) (actual time=3.037..3.037 rows=1 loops=1) Buckets: 16384 Batches: 1 Memory Usage: 910kB -> Seq Scan on app (cost=0.00..194.00 rows=1 width=45) (actual time=0.010..1.201 rows=1 loops=1) -> Index Scan using test_index on member_span (cost=0.28..0.42 rows=1 width=92) (actual time=0.027..0.031 rows=1 loops=1) Index Cond: ((group_id = group_span.group_id) AND (group_span.valid_period && valid_period)) Planning time: 2.160 ms Execution time: 335.820 ms (14 rows) test=*# better? Okay, other solution. The problem is the nested loop, we can disable that: test=*# set enable_nestloop to false; SET test=*# explain analyse SELECT * FROM app JOIN group_span ON app.group_id = group_span.group_id AND app.app_time <@ group_span.valid_period JOIN member_span ON group_span.group_id = member_span.group_id AND group_span.valid_period && member_span.valid_period; QUERY PLAN - Hash Join (cost=771.15..1121.33 rows=1 width=196) (actual time=23.291..32.028 rows=1 loops=1) Hash Cond: (member_span.group_id = app.group_id) Join Filter: (group_span.valid_period && member_span.valid_period) Rows Removed by Join Filter: 2000 -> Seq Scan on member_span (cost=0.00..305.00 rows=12000 width=92) (actual time=0.019..1.577 rows=12000 loops=1) -> Hash (cost=771.00..771.00 rows=12 width=104) (actual time=23.254..23.254 rows=1 loops=1) Buckets: 16384 (originally 1024) Batches: 1 (originally 1) Memory Usage: 1486kB -> Hash Join (cost=319.00..771.00 rows=12 width=104) (actual time=7.968..18.951 rows=1 loops=1) Hash Cond: (group_span.group_id = app.group_id) Join Filter: (app.app_time <@ group_span.valid_period) Rows Removed by Join Filter: 2000 -> Seq Scan on group_span (cost=0.00..257.00 rows=12000 width=59) (actual time=0.010..2.068 rows=12000 loops=1) -> Hash (cost=194.00..194.00 rows=1 width=45) (actual time=7.900..7.900 rows=1 loops=1) Buckets: 16384 Batches: 1 Memory Usage: 910kB -> Seq Scan on app (cost=0.00..194.00 rows=1 width=45) (actual time=0.011..3.165 rows=1 loops=1) Planning time: 1.241 ms Execution time: 32.676 ms (17 rows) test=*# Regards, Andreas -- 2ndQuadrant - The PostgreSQL Support Company. www.2ndQuadrant.com
Re: Extremely slow when query uses GIST exclusion index
Am 29.08.2018 um 12:50 schrieb Andreas Kretschmer: Okay, other solution. The problem is the nested loop, we can disable that: oh, i used PG 10, this time 9.5: test=# explain analyse SELECT * FROM app JOIN group_span ON app.group_id = group_span.group_id AND app.app_time <@ group_span.valid_period JOIN member_span ON group_span.group_id = member_span.group_id AND group_span.valid_period && member_span.valid_period; QUERY PLAN -- Nested Loop (cost=0.55..4740.90 rows=180 width=212) (actual time=2.915..17624.676 rows=1 loops=1) Join Filter: (app.group_id = member_span.group_id) -> Nested Loop (cost=0.28..4472.00 rows=600 width=112) (actual time=0.292..347.838 rows=1 loops=1) -> Seq Scan on app (cost=0.00..194.00 rows=1 width=44) (actual time=0.012..2.689 rows=1 loops=1) -> Index Scan using group_span_group_id_valid_period_excl on group_span (cost=0.28..0.42 rows=1 width=68) (actual time=0.029..0.033 rows=1 loops=1) Index Cond: ((group_id = app.group_id) AND (app.app_time <@ valid_period)) -> Index Scan using member_span_member_id_group_id_valid_period_excl on member_span (cost=0.28..0.44 rows=1 width=100) (actual time=0.912..1.726 rows=1 loops=1) Index Cond: ((group_id = group_span.group_id) AND (group_span.valid_period && valid_period)) Planning time: 1.554 ms Execution time: 17627.266 ms (10 rows) test=*# set enable_nestloop to false; SET test=*# explain analyse SELECT * FROM app JOIN group_span ON app.group_id = group_span.group_id AND app.app_time <@ group_span.valid_period JOIN member_span ON group_span.group_id = member_span.group_id AND group_span.valid_period && member_span.valid_period; QUERY PLAN - Hash Join (cost=2383.43..14284.93 rows=180 width=212) (actual time=42.440..63.834 rows=1 loops=1) Hash Cond: (app.group_id = member_span.group_id) Join Filter: (group_span.valid_period && member_span.valid_period) Rows Removed by Join Filter: 2000 -> Merge Join (cost=1928.43..12478.43 rows=600 width=112) (actual time=34.068..47.954 rows=1 loops=1) Merge Cond: (app.group_id = group_span.group_id) Join Filter: (app.app_time <@ group_span.valid_period) Rows Removed by Join Filter: 2000 -> Sort (cost=858.39..883.39 rows=1 width=44) (actual time=15.331..17.104 rows=1 loops=1) Sort Key: app.group_id Sort Method: quicksort Memory: 1166kB -> Seq Scan on app (cost=0.00..194.00 rows=1 width=44) (actual time=0.004..1.070 rows=1 loops=1) -> Sort (cost=1070.04..1100.04 rows=12000 width=68) (actual time=18.720..20.712 rows=12000 loops=1) Sort Key: group_span.group_id Sort Method: quicksort Memory: 2072kB -> Seq Scan on group_span (cost=0.00..257.00 rows=12000 width=68) (actual time=0.007..1.396 rows=12000 loops=1) -> Hash (cost=305.00..305.00 rows=12000 width=100) (actual time=8.198..8.198 rows=12000 loops=1) Buckets: 16384 Batches: 1 Memory Usage: 1582kB -> Seq Scan on member_span (cost=0.00..305.00 rows=12000 width=100) (actual time=0.011..2.783 rows=12000 loops=1) Planning time: 0.468 ms Execution time: 64.694 ms (21 rows) test=*# Regards, Andreas -- 2ndQuadrant - The PostgreSQL Support Company. www.2ndQuadrant.com
Re: Extremely slow when query uses GIST exclusion index
Thanks for your help investigating this! Follow-up below: On Wed, Aug 29, 2018 at 7:25 AM, Andreas Kretschmer wrote: > > Okay, other solution. The problem is the nested loop, we can disable that: >> > test=*# set enable_nestloop to false; Is it OK to keep this off permanently in production? I thought these settings were just for debugging, and once we've identified the culprit, we're supposed to take other steps (?) to avoid the suboptimal execution plan. your GiST-Index contains (member_id,group_id,valid_period), but your query > is only on the latter 2 fields. Yeah, I didn't really want GIST index in the first place -- PostgreSQL created it automatically as a side effect of the exclusion constraint that I need. Your suggestion to create *another* GIST index is an interesting workaround. But we've seen that the query runs even faster if we didn't have the GIST index(es) at all. So is there any way to tell the planner to avoid the GIST index altogether? (Alternatively, could there be a bug that's causing PostgreSQL to underestimate the cost of using the GIST index?) > Nested Loop (cost=319.27..776.18 rows=1 width=196) (actual > time=3.156..334.963 rows=1 loops=1) >Join Filter: (app.group_id = member_span.group_id) >-> Hash Join (cost=319.00..771.00 rows=12 width=104) (actual > time=3.100..14.040 rows=1 loops=1) Hm, also, it looks like one of the oddities of this query is that PostgreSQL is severely underestimating the cardinality of the join. It seems to think that the join will result in only 1 row, when the join actually produces 10,000 rows. Maybe that's why the planner thinks that using the GIST index is cheap? (I.e., the planner thought that it would only need to do 1 GIST index lookup, which is cheaper than a sequential scan; but in reality it has to do 10,000 GIST index lookups, which is much more expensive than a scan.) Is there any way to help the planner better estimate how big the join output going to be?
Re: Extremely slow when query uses GIST exclusion index
Am 29.08.2018 um 20:10 schrieb David: On Wed, Aug 29, 2018 at 7:25 AM, Andreas Kretschmer mailto:andr...@a-kretschmer.de>> wrote: Okay, other solution. The problem is the nested loop, we can disable that: test=*# set enable_nestloop to false; Is it OK to keep this off permanently in production? no, but you can switch off/on per session, for instance. and you can it set to on after that query. Nested Loop (cost=319.27..776.18 rows=1 width=196) (actual time=3.156..334.963 rows=1 loops=1) Join Filter: (app.group_id = member_span.group_id) -> Hash Join (cost=319.00..771.00 rows=12 width=104) (actual time=3.100..14.040 rows=1 loops=1) Hm, also, it looks like one of the oddities of this query is that PostgreSQL is severely underestimating the cardinality of the join. ack, that's the main problem here, i think. It leads to the expensive nested loop. Tbh, i don't have a better suggestion now besides the workaround with setting nestloop to off. Regards, Andreas -- 2ndQuadrant - The PostgreSQL Support Company. www.2ndQuadrant.com
