Message-ID: <51656E03.7000701@ca.afilias.info>
Date: Wed, 10 Apr 2013 09:49:55 -0400
From: Steve Singer <ssinger@ca.afilias.info>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:17.0) Gecko/20130308 Thunderbird/17.0.4
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: slow bitmap heap scans on pg 9.2
Content-Type: multipart/mixed; boundary="------------020400070001070906080900"
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

This is a multi-part message in MIME format.
--------------020400070001070906080900
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

I'm encountering an issue where PG 9.2.4 (we also see this with 9.2.3) 
is picking a plan involving a bitmap heap scan that turns out to be much 
slower than a nested-loop plan using indexes.

The planner picks the hashjoin plan by default (see attached files)

Bitmap Heap Scan on public.table_b_2 b  (cost=172635.99..9800225.75 
rows=8435754 width=10) (actual t
ime=9132.194..1785196.352 rows=9749680 loops=1)
                            Recheck Cond: ((b.organization_id = 3) AND 
(b.year = 2013) AND (b.month = 3))
                            Rows Removed by Index Recheck: 313195667
                            Filter: (b.product_id = 2)

Is the part that seems be causing the problem (or at least taking most 
of the time, other than the final aggregation)

If I set enable_hashjoin=false and enable_mergejoin=false I get the 
nestedloop join plan.

table_b is 137 GB plus indexes each on is around 43 GB
table_a is 20 GB

random_page_cost = 2.0
effective_cache_size = 3500MB
cpu_tuple_cost = 0.01
cpu_index_tuple_cost = 0.005
cpu_operator_cost = 0.0025
work_mem = 64MB
shared_buffers = 300MB  (for this output, I've also had it at 2GB)

If I bump cpu_tuple_cost to the 10-20 range it will pick the nested loop 
join for some date ranges but not all. cpu_tuple_cost of 20 doesn't 
sound like an sane value.

This database used to run 8.3 where it picked the nested-loop join.   We 
used pg_upgrade to migrate to 9.2

Any ideas why the bitmap heap scan is much slower than the planner expects?

Steve

--------------020400070001070906080900
Content-Type: text/plain; charset=UTF-8;
 name="hashjoin.txt"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="hashjoin.txt"

HashAggregate  (cost=11972282.27..11972448.32 rows=11070 width=51) (actual time=3523526.572..3523526.646 rows=30 loops=1) 
   ->  Hash Join  (cost=1287232.78..11220656.06 rows=724459 width=51) (actual time=1702760.590..1898522.706 rows=662583 loops=1)     
         Hash Cond: (a.product_operation = o.id)
         ->  Hash Right Join  (cost=1287230.86..11210692.83 rows=724459 width=40) (actual time=1702760.538..1897144.746 rows=662583 loop
s=1)               
               Hash Cond: (b.a_id = a.id)
               ->  Append  (cost=0.00..9800225.75 rows=8435755 width=10) (actual time=9132.198..1788027.626 rows=9749680 loops=1)
                     ->  Seq Scan on public.table_b b  (cost=0.00..0.00 rows=1 width=22) (actual time=0.002..0.002 rows=0 loo
ps=1)
                           Filter: ((b.product_id = 2) AND (b.organization_id = 3) AND (b.year = 2013) AND (b.month = 3))
                     ->  Bitmap Heap Scan on public.table_b_2 b  (cost=172635.99..9800225.75 rows=8435754 width=10) (actual t
ime=9132.194..1785196.352 rows=9749680 loops=1)
                           Recheck Cond: ((b.organization_id = 3) AND (b.year = 2013) AND (b.month = 3))
                           Rows Removed by Index Recheck: 313195667
                           Filter: (b.product_id = 2)
                           ->  Bitmap Index Scan on table_b_2_orgid_ym_unq  (cost=0.00..170527.05 rows=8435754 width=0) (actual time=849
1.007..8491.007 rows=9749680 loops=1)
                                 Index Cond: ((b.organization_id = 3) AND (b.year = 2013) AND (b.month = 3))
               ->  Hash  (cost=1285387.42..1285387.42 rows=147475 width=34) (actual time=7291.015..7291.015 rows=662583 loops=1)
                     Buckets: 16384  Batches: 1  Memory Usage: 44000kB
                     ->  Append  (cost=0.00..1285387.42 rows=147475 width=34) (actual time=521.262..6780.112 rows=662583 loops=1)
                           ->  Seq Scan on public.table_a a  (cost=0.00..0.00 rows=1 width=60) (actual time=0.001..0.001 row
s=0 loops=1)
                                 Filter: ((a.twin_id IS NULL) AND (a.transaction_date >= '2012-11-01 00:00:00+00'::timestamp with time z
one) AND (a.transaction_date < '2012-12-01 00:00:00+00'::timestamp with time zone) AND (a.product_id = 2) AND ((a.trans_type_id = ANY ('
{2,3,4}'::integer[])) OR (a.trans_type_id IS NULL)))
                            ->  Bitmap Heap Scan on public.table_a_2 a  (cost=16549.24..1285387.42 rows=147474 width=34) (act
ual time=521.260..6677.788 rows=662583 loops=1)
                                 Recheck Cond: ((a.transaction_date >= '2012-11-01 00:00:00+00'::timestamp with time zone) AND (a.transa
ction_date < '2012-12-01 00:00:00+00'::timestamp with time zone))
                                 Filter: ((a.twin_id IS NULL) AND (a.product_id = 2) AND ((a.trans_type_id = ANY ('{2,3,4}'::integer[]))
 OR (a.trans_type_id IS NULL)))
                                 Rows Removed by Filter: 411920
                                 ->  Bitmap Index Scan on table_a_2_trans_date_idx  (cost=0.00..16512.37 rows=1065722 width=0) (act
ual time=376.848..376.848 rows=1074503 loops=1)
                                       Index Cond: ((a.transaction_date >= '2012-11-01 00:00:00+00'::timestamp with time zone) AND (a.tr
ansaction_date < '2012-12-01 00:00:00+00'::timestamp with time zone))
         ->  Hash  (cost=1.41..1.41 rows=41 width=19) (actual time=0.034..0.034 rows=41 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 3kB
               ->  Seq Scan on public.product_operations o  (cost=0.00..1.41 rows=41 width=19) (actual time=0.006..0.016 rows=41 loops=1
)
 Total runtime: 3523602.967 ms
(39 rows)

--------------020400070001070906080900
Content-Type: text/plain; charset=UTF-8;
 name="nestedloop.txt"
Content-Transfer-Encoding: base64
Content-Disposition: attachment;
 filename="nestedloop.txt"

SGFzaEFnZ3JlZ2F0ZSAgKGNvc3Q9MjE1Mjc2MzUuMjcuLjIxNTI3ODAxLjMy
IHJvd3M9MTEwNzAgd2lkdGg9NTEpIChhY3R1YWwgdGltZT0xNTc4MTc0LjY0
OS4uMTU3ODE3NC43NDQgcm93cz0zMCBsb29wcz0xKQogICAtPiAgTmVzdGVk
IExvb3AgTGVmdCBKb2luICAoY29zdD0wLjAwLi4yMDc3NjAwOS4wNiByb3dz
PTcyNDQ1OSB3aWR0aD01MSkgKGFjdHVhbCB0aW1lPTU5OC4zMzIuLjU0ODE1
LjAzOSByb3dzPTY2MjU4MyBsb29wcz0xKQogICAgICAgICAtPiAgTmVzdGVk
IExvb3AgIChjb3N0PTAuMDAuLjEzNzYwODYuMDYgcm93cz0xNDc0NzUgd2lk
dGg9NDUpIChhY3R1YWwgdGltZT01NTguMDIyLi4xMzkxNy44NzMgcm93cz02
NjI1ODMgbG9vcHM9MSkKICAgICAgICAgICAgICAgSm9pbiBGaWx0ZXI6IChh
LnByb2R1Y3Rfb3BlcmF0aW9uID0gby5pZCkKICAgICAgICAgICAgICAgUm93
cyBSZW1vdmVkIGJ5IEpvaW4gRmlsdGVyOiAyNjUwMzMyMAogICAgICAgICAg
ICAgICAtPiAgQXBwZW5kICAoY29zdD0wLjAwLi4xMjg1Mzg3LjQyIHJvd3M9
MTQ3NDc1IHdpZHRoPTM0KSAoYWN0dWFsIHRpbWU9NTUwLjc3OS4uNTcwOS43
Nzkgcm93cz02NjI1ODMgbG9vcHM9MSkKICAgICAgICAgICAgICAgICAgICAg
LT4gIFNlcSBTY2FuIG9uIHB1YmxpYy50YWJsZV9hIGEgIChjb3N0PTAuMDAu
LjAuMDAgcm93cz0xIHdpZHRoPTYwKSAoYWN0dWFsIHRpbWU9MC4wMDIuLjAu
MDAyIHJvd3M9MCBsbwpvcHM9MSkKICAgICAgICAgICAgICAgICAgICAgICAg
ICAgRmlsdGVyOiAoKGEudHdpbl9pZCBJUyBOVUxMKSBBTkQgKGEudHJhbnNh
Y3Rpb25fZGF0ZSA+PSAnMjAxMi0xMS0wMSAwMDowMDowMCswMCc6OnRpbWVz
dGFtcCB3aXRoIHRpbWUgem9uZSkgQQpORCAoYS50cmFuc2FjdGlvbl9kYXRl
IDwgJzIwMTItMTItMDEgMDA6MDA6MDArMDAnOjp0aW1lc3RhbXAgd2l0aCB0
aW1lIHpvbmUpIEFORCAoYS5wcm9kdWN0X2lkID0gMikgQU5EICgoYS50cmFu
c190eXBlX2lkID0gQU5ZICgnezIsMyw0Cn0nOjppbnRlZ2VyW10pKSBPUiAo
YS50cmFuc190eXBlX2lkIElTIE5VTEwpKSkKICAgICAgICAgICAgICAgICAg
ICAgLT4gIEJpdG1hcCBIZWFwIFNjYW4gb24gcHVibGljLnRhYmxlX2FfMiBh
ICAoY29zdD0xNjU0OS4yNC4uMTI4NTM4Ny40MiByb3dzPTE0NzQ3NCB3aWR0
aD0zNCkgKGFjdHVhbCB0aQptZT01NTAuNzc1Li41NTUxLjE5MCByb3dzPTY2
MjU4MyBsb29wcz0xKQp0X29wZXJhdGlvbgogICAgICAgICAgICAgICAgICAg
ICAgICAgICBSZWNoZWNrIENvbmQ6ICgoYS50cmFuc2FjdGlvbl9kYXRlID49
ICcyMDEyLTExLTAxIDAwOjAwOjAwKzAwJzo6dGltZXN0YW1wIHdpdGggdGlt
ZSB6b25lKSBBTkQgKGEudHJhbnNhY3Rpb25fCmRhdGUgPCAnMjAxMi0xMi0w
MSAwMDowMDowMCswMCc6OnRpbWVzdGFtcCB3aXRoIHRpbWUgem9uZSkpCiAg
ICAgICAgICAgICAgICAgICAgICAgICAgIEZpbHRlcjogKChhLnR3aW5faWQg
SVMgTlVMTCkgQU5EIChhLnByb2R1Y3RfaWQgPSAyKSBBTkQgKChhLnRyYW5z
X3R5cGVfaWQgPSBBTlkgKCd7MiwzLDR9Jzo6aW50ZWdlcltdKSkgT1IgKGEK
LnRyYW5zX3R5cGVfaWQgSVMgTlVMTCkpKQogICAgICAgICAgICAgICAgICAg
ICAgICAgICBSb3dzIFJlbW92ZWQgYnkgRmlsdGVyOiA0MTE5MjAKICAgICAg
ICAgICAgICAgICAgICAgICAgICAgLT4gIEJpdG1hcCBJbmRleCBTY2FuIG9u
IHRhYmxlX2FfMl90cmFuc19kYXRlX2lkeCAgKGNvc3Q9MC4wMC4uMTY1MTIu
Mzcgcm93cz0xMDY1NzIyIHdpZHRoPTApIChhY3R1YWwgdGkKbWU9Mzg2LjQ1
NS4uMzg2LjQ1NSByb3dzPTEwNzQ1MDMgbG9vcHM9MSkKICAgICAgICAgICAg
ICAgICAgICAgICAgICAgICAgICAgSW5kZXggQ29uZDogKChhLnRyYW5zYWN0
aW9uX2RhdGUgPj0gJzIwMTItMTEtMDEgMDA6MDA6MDArMDAnOjp0aW1lc3Rh
bXAgd2l0aCB0aW1lIHpvbmUpIEFORCAoYS50cmFuc2FjdAppb25fZGF0ZSA8
ICcyMDEyLTEyLTAxIDAwOjAwOjAwKzAwJzo6dGltZXN0YW1wIHdpdGggdGlt
ZSB6b25lKSkKICAgICAgICAgICAgICAgLT4gIE1hdGVyaWFsaXplICAoY29z
dD0wLjAwLi4xLjYyIHJvd3M9NDEgd2lkdGg9MTkpIChhY3R1YWwgdGltZT0w
LjAwMC4uMC4wMDUgcm93cz00MSBsb29wcz02NjI1ODMpCiAgICAgICAgICAg
ICAgICAgICAgIC0+ICBTZXEgU2NhbiBvbiBwdWJsaWMucHJvZHVjdF9vcGVy
YXRpb25zIG8gIChjb3N0PTAuMDAuLjEuNDEgcm93cz00MSB3aWR0aD0xOSkg
KGFjdHVhbCB0aW1lPTcuMjA3Li43LjIxNCByb3dzPTQxIGwKb29wcz0xKQog
ICAgICAgICAtPiAgQXBwZW5kICAoY29zdD0wLjAwLi4xMzEuNDggcm93cz03
IHdpZHRoPTEyKSAoYWN0dWFsIHRpbWU9MC4wNTguLjAuMDYwIHJvd3M9MSBs
b29wcz02NjI1ODMpCiAgICAgICAgICAgICAgIC0+ICBTZXEgU2NhbiBvbiBw
dWJsaWMudGFibGVfYiBiICAoY29zdD0wLjAwLi4wLjAwIHJvd3M9MSB3aWR0
aD0yMikgKGFjdHVhbCB0aW1lPTAuMDAwLi4wLjAwMCByb3dzPTAgbG9vcHM9
NjYyCjU4MykKICAgICAgICAgICAgICAgICAgICAgRmlsdGVyOiAoKGIucHJv
ZHVjdF9pZCA9IDIpIEFORCAoYi5vcmdhbml6YXRpb25faWQgPSAzKSBBTkQg
KGIueWVhciA9IDIwMTMpIEFORCAoYi5tb250aCA9IDMpIEFORCAoYS5pZCA9
IGIuYV9pZCkpCiAgICAgICAgICAgICAgIC0+ICBJbmRleCBTY2FuIHVzaW5n
IHRhYmxlX2JfcHRpZF9vcmdpZF95bV91bnEgb24gcHVibGljLnRhYmxlX2Jf
MiBiICAoY29zdD0wLjAwLi4xMzEuNDggcm93cz02IHdpZHRoPTEwKSAoYQpj
dHVhbCB0aW1lPTAuMDU1Li4wLjA1NiByb3dzPTEgbG9vcHM9NjYyNTgzKQog
ICAgICAgICAgICAgICAgICAgICBJbmRleCBDb25kOiAoKGEuaWQgPSBiLmFf
aWQpIEFORCAoYi5vcmdhbml6YXRpb25faWQgPSAzKSBBTkQgKGIueWVhciA9
IDIwMTMpIEFORCAoYi5tb250aCA9IDMpKQogICAgICAgICAgICAgICAgICAg
ICBGaWx0ZXI6IChiLnByb2R1Y3RfaWQgPSAyKQogVG90YWwgcnVudGltZTog
MTU3ODE5NC41MzIgbXMKKDMyIHJvd3MpDQo=

--------------020400070001070906080900
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

--------------020400070001070906080900--