Message-ID: <5165FBA1.90704@ca.afilias.info>
Date: Wed, 10 Apr 2013 19:54:09 -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: Jeff Janes <jeff.janes@gmail.com>
CC: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Re: slow bitmap heap scans on pg 9.2
References: <51656E03.7000701@ca.afilias.info>
	<CAMkU=1xQXQWBw8AngvhM70K9GOGby_WAGTR3YTDZ26apv9k9pw@mail.gmail.com>
In-Reply-To: 
 <CAMkU=1xQXQWBw8AngvhM70K9GOGby_WAGTR3YTDZ26apv9k9pw@mail.gmail.com>
Content-Type: multipart/mixed; boundary="------------050401010409070804040707"
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

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

On 13-04-10 02:06 PM, Jeff Janes wrote:
> On Wed, Apr 10, 2013 at 6:49 AM, Steve Singer <ssinger@ca.afilias.info
> <mailto:ssinger@ca.afilias.info>> wrote:
>

> I think the index recheck means your bitmap is overflowing (i.e. needing
> more space than work_mem) and so keeping only the pages which have at
> least one match, which means all rows in those pages need to be
> rechecked.  How many rows does the table have?  You might be essentially
> doing a seq scan, but with the additional overhead of the bitmap
> machinery.  Could you do "explain (analyze,buffers)", preferably with
> track_io_timing set to on?
>

table_b has 1,530,710,469 rows

Attached is the output with track_io_timings and buffers.


>   Cheers,
>
> Jeff


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

HashAggregate  (cost=11768301.08..11770515.08 rows=147600 width=51) (actual time=3518538.111..3518539.201 rows=36 loops=1)
   Buffers: shared hit=8892878 read=4997334
   I/O Timings: read=1935289.861
   ->  Hash Join  (cost=1282646.06..11041507.43 rows=700524 width=51) (actual time=94631.716..2065378.607 rows=543671 loops=1)
         Hash Cond: (a.product_operation = o.id)
         Buffers: shared hit=3419 read=4626531
         I/O Timings: read=1738580.922
         ->  Hash Right Join  (cost=1282644.14..11031873.30 rows=700524 width=40) (actual time=94631.646..2064079.068 rows=543671 l
oops=1)
               Hash Cond: (b.a_id = a.id)
               Buffers: shared hit=3418 read=4626531
               I/O Timings: read=1738580.922
               ->  Bitmap Heap Scan on public.table_b_2 b  (cost=173185.49..9820205.86 rows=8462538 width=10) (actual ti
me=10044.901..1970005.160 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)
                     Buffers: shared hit=232 read=4606751
                     I/O Timings: read=1726380.478
                     ->  Bitmap Index Scan on rec_rev_2_orgid_ym_unq  (cost=0.00..171069.85 rows=8462538 width=0) (actual time=9410
.598..9410.598 rows=9749680 loops=1)
                           Index Cond: ((b.organization_id = 3) AND (b.year = 2013) AND (b.month = 3))
                           Buffers: shared read=37360
                           I/O Timings: read=3460.299
               ->  Hash  (cost=1107975.15..1107975.15 rows=118680 width=34) (actual time=13732.784..13732.784 rows=543671 loops=1)
                     Buckets: 16384  Batches: 1  Memory Usage: 37388kB
                     Buffers: shared hit=3186 read=19780
                     I/O Timings: read=12200.444
                     ->  Append  (cost=0.00..1107975.15 rows=118680 width=34) (actual time=935.605..13395.517 rows=543671 loops=1)
                           Buffers: shared hit=3186 read=19780
                           I/O Timings: read=12200.444
                           ->  Seq Scan on public.table_a a  (cost=0.00..0.00 rows=1 width=60) (actual time=0.001..0.00
1 rows=0 loops=1)
                                 Filter: ((a.twin_id IS NULL) AND (a.transaction_date >= '2009-09-01 00:00:00+00'::timestamp with t
ime zone) AND (a.transaction_date < '2009-10-01 00:00:00+00'::timestamp with time zone) AND (a.product_id = 2) AND ((a.trans_type_i
d = ANY ('{2,3,4}'::integer[])) OR (a.trans_type_id IS NULL)))
                           ->  Bitmap Heap Scan on public.table_a_2 a  (cost=13335.33..1107975.15 rows=118679 width=34)
 (actual time=935.603..13301.854 rows=543671 loops=1)
                                 Recheck Cond: ((a.transaction_date >= '2009-09-01 00:00:00+00'::timestamp with time zone) AND (a.t
ransaction_date < '2009-10-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}'::intege
r[])) OR (a.trans_type_id IS NULL)))
                                 Rows Removed by Filter: 302939
                                 Buffers: shared hit=3186 read=19780
                                 I/O Timings: read=12200.444
                                 ->  Bitmap Index Scan on table_a_2_trans_date_idx  (cost=0.00..13305.66 rows=858651 width=0) 
(actual time=303.756..303.756 rows=846610 loops=1)
                                       Index Cond: ((a.transaction_date >= '2009-09-01 00:00:00+00'::timestamp with time zone) AND 
(a.transaction_date < '2009-10-01 00:00:00+00'::timestamp with time zone))
                                       Buffers: shared read=2317
                                       I/O Timings: read=170.564
         ->  Hash  (cost=1.41..1.41 rows=41 width=19) (actual time=0.036..0.036 rows=41 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 3kB
               Buffers: shared hit=1
               ->  Seq Scan on public.product_operations o  (cost=0.00..1.41 rows=41 width=19) (actual time=0.009..0.018 rows=41 lo
ops=1)
                     Buffers: shared hit=1
 Total runtime: 3518541.146 ms
(55 rows)

steve_test=# 

--------------050401010409070804040707
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

--------------050401010409070804040707--