Hi everyone --
I had an issue the other day where a relatively simple query went from
taking about 1 minute to execute to taking 19 hours. It seems that the
planner chooses to use a materialize sometimes [1] and not other times
[2]. I think the issue is that the row count estimate for the result
of the condition "type_id = 23 and ref.attributes ? 'reference'" is
about 10k rows, but the actual result is 4624280. It seems the
estimate varies slightly over time, and if it drops low enough then
the planner decides to materialize the result of the bitmap heap scan
and the query takes forever.
As an exercise, I tried removing the clause "ref.attributes ?
'reference'" and the estimates are very accurate [3].
It seems to me that improving the row estimates would be prudent, but
I can't figure out how postgres figures out the estimate for the
hstore ? operator. I suspect it is making a wild guess, since it has
no data on the contents of the hstore in its estimates.
[1] Query plan with materialize:
# explain (analyze, buffers) declare "foo_cursor" cursor for SELECT
ref.case_id, array_agg(ref.attributes -> 'reference') FROM
component ref JOIN document c ON c.id = ref.case_id WHERE ref.type_id
= 23 AND ref.attributes ? 'reference' AND NOT 0 = ANY(c.types) GROUP
BY ref.case_id;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
GroupAggregate (cost=390241.39..16973874.43 rows=10 width=35)
(actual time=81253.653..69928443.721 rows=90969 loops=1)
Buffers: shared hit=54539 read=1551654, temp read=11959529274 written=126377
-> Nested Loop (cost=390241.39..16973835.54 rows=5169 width=35)
(actual time=16157.261..69925063.268 rows=2488142 loops=1)
Join Filter: (ref.case_id = c.id)
Rows Removed by Join Filter: 437611625378
Buffers: shared hit=54539 read=1551654, temp read=11959529274
written=126377
-> Index Scan using document_pkey on document c
(cost=0.42..314999.89 rows=99659 width=4) (actual
time=0.016..59255.527 rows=94634 loops=1)
Filter: (0 <> ALL (types))
Rows Removed by Filter: 70829
Buffers: shared hit=54539 read=113549
-> Materialize (cost=390240.97..3189944.33 rows=9010
width=35) (actual time=0.088..450.898 rows=4624280 loops=94634)
Buffers: shared read=1438105, temp read=11959529274
written=126377
-> Bitmap Heap Scan on component ref
(cost=390240.97..3189899.28 rows=9010 width=35) (actual
time=8107.625..79508.136 rows=4624280 loops=1)
Recheck Cond: (type_id = 23)
Rows Removed by Index Recheck: 49237707
Filter: (attributes ? 'reference'::text)
Rows Removed by Filter: 4496624
Buffers: shared read=1438105
-> Bitmap Index Scan on component_type_id
(cost=0.00..390238.72 rows=9009887 width=0) (actual
time=8105.963..8105.963 rows=9666659 loops=1)
Index Cond: (type_id = 23)
Buffers: shared read=156948
Total runtime: 69928552.870 ms
[2] Query plan with simple bitmap heap scan:
# explain (analyze, buffers) declare "foo_cursor" cursor for SELECT
ref.case_id, array_agg(ref.attributes -> 'reference') FROM
component ref JOIN document c ON c.id = ref.case_id WHERE ref.type_id
= 23 AND ref.attributes ? 'reference' AND NOT 0 = ANY(c.types) GROUP
BY ref.case_id;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=3724614.33..3724614.46 rows=10 width=34) (actual
time=248900.627..249030.530 rows=90969 loops=1)
Buffers: shared hit=16962106 read=5551197 written=5806
-> Nested Loop (cost=488092.46..3724570.36 rows=5863 width=34)
(actual time=30839.635..246416.327 rows=2488142 loops=1)
Buffers: shared hit=16962106 read=5551197 written=5806
-> Bitmap Heap Scan on component ref
(cost=488088.03..3638070.85 rows=10220 width=34) (actual
time=30833.215..196239.109 rows=4624280 loops=1)
Recheck Cond: (type_id = 23)
Rows Removed by Index Recheck: 57730489
Filter: (attributes ? 'reference'::text)
Rows Removed by Filter: 4496624
Buffers: shared hit=6922 read=1901840 written=2252
-> Bitmap Index Scan on component_type_id
(cost=0.00..488085.48 rows=10220388 width=0) (actual
time=30811.185..30811.185 rows=13292968 loops=1)
Index Cond: (type_id = 23)
Buffers: shared hit=6922 read=162906 written=1529
-> Bitmap Heap Scan on document c (cost=4.43..8.45 rows=1
width=4) (actual time=0.010..0.010 rows=1 loops=4624280)
Recheck Cond: (id = ref.case_id)
Filter: (0 <> ALL (types))
Rows Removed by Filter: 0
Buffers: shared hit=16955184 read=3649357 written=3554
-> Bitmap Index Scan on document_pkey
(cost=0.00..4.43 rows=1 width=0) (actual time=0.004..0.004 rows=1
loops=4624280)
Index Cond: (id = ref.case_id)
Buffers: shared hit=14090230 read=1890031 written=1819
Total runtime: 249051.265 ms
[3] Query plan with hstore clause removed:
# explain (analyze, buffers) declare "foo_cursor" cursor for SELECT
ref.case_id, array_agg(ref.attributes -> 'reference') FROM
component ref JOIN document c ON c.id = ref.case_id WHERE ref.type_id
= 23 AND NOT 0 = ANY(c.types) GROUP BY ref.case_id;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
GroupAggregate (cost=5922838.29..12804427.63 rows=9817 width=34)
(actual time=168896.503..181202.278 rows=93580 loops=1)
Buffers: shared hit=13847 read=2104804 written=26, temp read=902336
written=902336
-> Merge Join (cost=5922838.29..12760329.44 rows=5863397
width=34) (actual time=168896.459..180103.335 rows=5115136 loops=1)
Merge Cond: (c.id = ref.case_id)
Buffers: shared hit=13847 read=2104804 written=26, temp
read=902336 written=902336
-> Index Scan using document_pkey on document c
(cost=0.43..6696889.20 rows=2128590 width=4) (actual
time=0.006..7684.681 rows=94634 loops=1)
Filter: (0 <> ALL (types))
Rows Removed by Filter: 70829
Buffers: shared hit=13847 read=196042
-> Materialize (cost=5922836.37..5973938.31 rows=10220388
width=34) (actual time=168896.449..171403.773 rows=9120904 loops=1)
Buffers: shared read=1908762 written=26, temp
read=902336 written=902336
-> Sort (cost=5922836.37..5948387.34 rows=10220388
width=34) (actual time=168896.447..170586.341 rows=9120904 loops=1)
Sort Key: ref.case_id
Sort Method: external merge Disk: 1392648kB
Buffers: shared read=1908762 written=26, temp
read=902336 written=902336
-> Bitmap Heap Scan on component ref
(cost=490640.57..3615072.42 rows=10220388 width=34) (actual
time=21652.779..148333.012 rows=9120904 loops=1)
Recheck Cond: (type_id = 23)
Rows Removed by Index Recheck: 57730489
Buffers: shared read=1908762 written=26
-> Bitmap Index Scan on component_type_id
(cost=0.00..488085.48 rows=10220388 width=0) (actual
time=21649.716..21649.716 rows=13292968 loops=1)
Index Cond: (type_id = 23)
Buffers: shared read=169828
Total runtime: 181378.101 ms
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
