Received: from localhost (unknown [200.46.204.183]) by mail.postgresql.org (Postfix) with ESMTP id 4931C633240 for ; Thu, 5 Mar 2009 21:42:23 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 96227-03 for ; Thu, 5 Mar 2009 21:42:20 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from qw-out-2122.google.com (qw-out-2122.google.com [74.125.92.25]) by mail.postgresql.org (Postfix) with ESMTP id DEE246327B1 for ; Thu, 5 Mar 2009 21:42:20 -0400 (AST) Received: by qw-out-2122.google.com with SMTP id 5so194210qwd.61 for ; Thu, 05 Mar 2009 17:42:19 -0800 (PST) MIME-Version: 1.0 Received: by 10.229.94.149 with SMTP id z21mr1537033qcm.50.1236303739169; Thu, 05 Mar 2009 17:42:19 -0800 (PST) In-Reply-To: <8053.1236277851@sss.pgh.pa.us> References: <78a8986f0903050756i7b1f6c27teb4c67d4578f11ae@mail.gmail.com> <8053.1236277851@sss.pgh.pa.us> Date: Thu, 5 Mar 2009 19:42:19 -0600 Message-ID: <78a8986f0903051742i57247620x372a63d78ac4eae@mail.gmail.com> Subject: Re: Index scan plan estimates way off. From: Jonathan Hseu To: pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary=0016364ee8de352b7904646965a3 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.001 tagged_above=0 required=5 tests=HTML_MESSAGE=0.001 X-Spam-Level: X-Archive-Number: 200903/57 X-Sequence-Number: 32979 --0016364ee8de352b7904646965a3 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Oops, forgot to CC my reply to the list. Sorry if this gets messed up. On Thu, Mar 5, 2009 at 12:30 PM, Tom Lane wrote: > Jonathan Hseu writes: > > Sort (cost=11684028.44..11761274.94 rows=30898601 width=40) > > Sort Key: "time" > > -> Bitmap Heap Scan on ticks (cost=715657.57..6995196.08 > rows=30898601 > > width=40) > > Recheck Cond: (contract_id = 1) > > -> Bitmap Index Scan on contract_id_time_idx > > (cost=0.00..707932.92 rows=30898601 width=0) > > Index Cond: (contract_id = 1) > > (6 rows) > > > This plan doesn't complete in a reasonable amount of time. I end up > having > > to kill the query after it's been running for over an hour. > > The bitmap scan should be at least as efficient as the plain indexscan, > so I suppose the problem is that the sort is slow. What's the datatype > of "time"? It's a timestamp with time zone and not null. > Can this machine actually support 256MB+ work_mem, or is that > likely to be driving it into swapping? Yeah, the machine has 4 GB of RAM and isn't even close to swapping at all. > > You might learn more from enabling trace_sort and watching the > postmaster log entries it generates. I got this (I'm not sure how to interpret it, as there doesn't seem to be any documentation about it on the web): 2009-03-05 15:28:27 CST STATEMENT: select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 15:28:30 CST LOG: begin tuple sort: nkeys = 1, workMem = 262144, randomAccess = f 2009-03-05 15:28:30 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 16:50:31 CST LOG: switching to external sort with 937 tapes: CPU 26.57s/4835.39u sec elapsed 4921.38 sec 2009-03-05 16:50:31 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 17:00:46 CST LOG: performsort starting: CPU 92.51s/4955.58u sec elapsed 5536.57 sec 2009-03-05 17:00:46 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 17:00:50 CST LOG: finished writing run 1 to tape 0: CPU 92.86s/4958.30u sec elapsed 5539.78 sec 2009-03-05 17:00:50 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 17:00:50 CST LOG: finished writing final run 2 to tape 1: CPU 92.88s/4958.40u sec elapsed 5539.90 sec 2009-03-05 17:00:50 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 17:00:51 CST LOG: performsort done (except 2-way final merge): CPU 92.96s/4958.55u sec elapsed 5541.10 sec 2009-03-05 17:00:51 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; 2009-03-05 17:00:58 CST LOG: external sort ended, 204674 disk blocks used: CPU 93.36s/4960.04u sec elapsed 5548.33 sec 2009-03-05 17:00:58 CST STATEMENT: explain analyze select * from ticks where contract_id=1 order by time limit 2800000; > On the whole I think the planner > isn't making a stupid choice here: sorting a large number of rows > usually *is* preferable to making an indexscan over them, unless the > table is remarkably close to being in physical order for the index. > So it would be worth trying to figure out what the problem with the > sort is. I don't really understand this. It seems to me that fetching and sorting 30 million rows wouldn't be preferable to just fetching them in the correct order in the first place, even if it's in a random order. I tried another query with a much smaller result set, and the index scan takes 76 seconds, but the bitmap scan & sort takes 1.5 hours. That's quite a difference. I'm pretty sure the physical order of the index is very different from the physical order of the table. The elements of the table are inserted in strictly time order, if that's how it ends up being on disk, whereas the index, as far as I understand it, would be sorted by the first of the multiple columns, the contract_id, then the time. Here's both of the EXPLAIN ANALYZEs for the same query: => explain analyze select * from ticks where contract_id=1 order by time limit 2800000; QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------------ Limit (cost=10487812.41..10494812.41 rows=2800000 width=40) (actual time=5541109.704..5545345.598 rows=2800000 loops=1) -> Sort (cost=10487812.41..10565267.29 rows=30981949 width=40) (actual time=5541109.702..5544883.149 rows=2800000 loops=1) Sort Key: "time" Sort Method: external merge Disk: 1637392kB -> Bitmap Heap Scan on ticks (cost=718724.01..7015201.37 rows=30981949 width=40) (actual time=4874084.105..5465131.997 rows=27917481 loops=1) Recheck Cond: (contract_id = 1) -> Bitmap Index Scan on contract_id_time_idx (cost=0.00..710978.52 rows=30981949 width=0) (actual time=4871649.240..4871649.240 rows=27918305 loops=1) Index Cond: (contract_id = 1) Total runtime: 5548440.918 ms (9 rows) => explain analyze select * from ticks where contract_id=1 order by time limit 2800000; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.00..10629028.93 rows=2800000 width=40) (actual time=136.612..75717.675 rows=2800000 loops=1) -> Index Scan using contract_id_time_idx on ticks (cost=0.00..117628023.89 rows=30986694 width=40) (actual time=136.611..75033.090 rows=2800000 loops=1) Index Cond: (contract_id = 1) Total runtime: 76081.634 ms (4 rows) To me, it seems like postgresql thinks that it has to do a random page fetch for each row from the index scan and so its prediction is way off. The prediction for the other bitmap plan is much closer. Thanks, Jonathan Hseu --0016364ee8de352b7904646965a3 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable
Oops, forgot to CC my reply to the list.=A0 Sorry if this= gets messed up.

On Thu, Mar 5, 2009 at 12:30 PM, Tom Lane <tgl@sss= .pgh.pa.us> wrote:
Jonathan Hseu <vomjom@vomjom.net> writes:
> =A0Sort =A0(cost=3D11684028.44..11761274.94 rows=3D30898601 width=3D40= )
> =A0 =A0Sort Key: "time"
> =A0 =A0-> =A0Bitmap Heap Scan on ticks =A0(cost=3D715657.57..699519= 6.08 rows=3D30898601
> width=3D40)
> =A0 =A0 =A0 =A0 =A0Recheck Cond: (contract_id =3D 1)
> =A0 =A0 =A0 =A0 =A0-> =A0Bitmap Index Scan on contract_id_time_idx<= br> > (cost=3D0.00..707932.92 rows=3D30898601 width=3D0)
> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0Index Cond: (contract_id =3D 1)
> (6 rows)

> This plan doesn't complete in a reasonable amount of time. =A0I en= d up having
> to kill the query after it's been running for over an hour.

The bitmap scan should be at least as efficient as the plain indexsca= n,
so I suppose the problem is that the sort is slow. =A0What's the dataty= pe
of "time"?

It's a timestamp with t= ime zone and not null.
=A0
Can this machine actually support 256MB+ work_mem, or is that
likely to be driving it into swapping?

Yeah, the= machine has 4 GB of RAM and isn't even close to swapping at all.=A0

You might learn more from enabling trace_sort and watching the
postmaster log entries it generates.

I got this = (I'm not sure how to interpret it, as there doesn't seem to be any = documentation about it on the web):

2009-03-05 15:28:27 CST STATEMEN= T:=A0 select * from ticks where contract_id=3D1 order by time limit 2800000= ;
2009-03-05 15:28:30 CST LOG:=A0 begin tuple sort: nkeys =3D 1, workMem =3D = 262144, randomAccess =3D f
2009-03-05 15:28:30 CST STATEMENT:=A0 explain= analyze select * from ticks where contract_id=3D1 order by time limit 2800= 000;
2009-03-05 16:50:31 CST LOG:=A0 switching to external sort with 937 tapes: = CPU 26.57s/4835.39u sec elapsed 4921.38 sec
2009-03-05 16:50:31 CST STAT= EMENT:=A0 explain analyze select * from ticks where contract_id=3D1 order b= y time limit 2800000;
2009-03-05 17:00:46 CST LOG:=A0 performsort starting: CPU 92.51s/4955.58u s= ec elapsed 5536.57 sec
2009-03-05 17:00:46 CST STATEMENT:=A0 explain ana= lyze select * from ticks where contract_id=3D1 order by time limit 2800000;=
2009-03-05 17:00:50 CST LOG:=A0 finished writing run 1 to tape 0: CPU 92.86= s/4958.30u sec elapsed 5539.78 sec
2009-03-05 17:00:50 CST STATEMENT:=A0= explain analyze select * from ticks where contract_id=3D1 order by time li= mit 2800000;
2009-03-05 17:00:50 CST LOG:=A0 finished writing final run 2 to tape 1: CPU= 92.88s/4958.40u sec elapsed 5539.90 sec
2009-03-05 17:00:50 CST STATEME= NT:=A0 explain analyze select * from ticks where contract_id=3D1 order by t= ime limit 2800000;
2009-03-05 17:00:51 CST LOG:=A0 performsort done (except 2-way final merge)= : CPU 92.96s/4958.55u sec elapsed 5541.10 sec
2009-03-05 17:00:51 CST ST= ATEMENT:=A0 explain analyze select * from ticks where contract_id=3D1 order= by time limit 2800000;
2009-03-05 17:00:58 CST LOG:=A0 external sort ended, 204674 disk blocks use= d: CPU 93.36s/4960.04u sec elapsed 5548.33 sec
2009-03-05 17:00:58 CST S= TATEMENT:=A0 explain analyze select * from ticks where contract_id=3D1 orde= r by time limit 2800000;

=A0
On the whole I think the planner
isn't making a stupid choice here: sorting a large number of rows
usually *is* preferable to making an indexscan over them, unless the
table is remarkably close to being in physical order for the index.
So it would be worth trying to figure out what the problem with the
sort is.

I don't really understand this.=A0 It seems to me that fetching and sorti= ng 30 million rows wouldn't be preferable to just fetching them in the correct order in the first place, even if it's in a random order.

I tried another query with a much smaller result set, and the index scan takes 76 seconds, but the bitmap scan & sort takes 1.5 hours.=A0 That's quite a difference.=A0 I'm pretty sure the physical order of= the index is very different from the physical order of the table.=A0 The elements of the table are inserted in strictly time order, if that's how it ends up being on disk, whereas the index, as far as I understand it, would be sorted by the first of the multiple columns, the contract_id, then the time.

Here's both of the EXPLAIN ANALYZEs for the same query:

=3D&= gt; explain analyze select * from ticks where contract_id=3D1 order by time= limit 2800000;
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 QUERY PLAN=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0
---------------------------------------------------------------------------= ---------------------------------------------------------------------------= ------------------
=A0Limit=A0 (cost=3D10487812.41..10494812.41 rows=3D2= 800000 width=3D40) (actual time=3D5541109.704..5545345.598 rows=3D2800000 l= oops=3D1)
=A0=A0 ->=A0 Sort=A0 (cost=3D10487812.41..10565267.29 rows=3D30981949 wi= dth=3D40) (actual time=3D5541109.702..5544883.149 rows=3D2800000 loops=3D1)
=A0=A0= =A0=A0=A0=A0=A0=A0 Sort Key: "time"
=A0=A0=A0=A0=A0=A0=A0=A0 S= ort Method:=A0 external merge=A0 Disk: 1637392kB
=A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Bitmap Heap Scan on ticks=A0 (cost=3D7187= 24.01..7015201.37 rows=3D30981949 width=3D40) (actual time=3D4874084.105..5465131.997 rows=3D27917481 loops=3D1)

=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0 Recheck Cond: (contract_id =3D 1)
=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0 ->=A0 Bitmap Index Scan on contract_id_time_idx=A0 (cost=3D0.00..710978.= 52 rows=3D30981949 width=3D0) (actual time=3D4871649.240..4871649.240 rows=3D27918305 loops=3D1)

=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (c= ontract_id =3D 1)
=A0Total runtime: 5548440.918 ms
(9 rows)
=
=3D> explain analyze select * from ticks where contract_id=3D1 order= by time limit 2800000;
=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0 QUERY PLAN=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0
---------------------------------------------------------------------------= ---------------------------------------------------------------------------= --------
=A0Limit=A0 (cost=3D0.00..10629028.93 rows=3D2800000 width=3D40= ) (actual time=3D136.612..75717.675 rows=3D2800000 loops=3D1)
=A0=A0 ->=A0 Index Scan using contract_id_time_idx on ticks=A0 (cost=3D0.00..117628023.89 rows=3D30986694 width=3D40) (actual time=3D136.611..75033.090 rows=3D2800000 loops=3D1)

= =A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (contract_id =3D 1)
=A0Total = runtime: 76081.634 ms
(4 rows)


To me, it seems like postgresql thinks that it has to do a random page fetch for each row from the index scan and so its prediction is way off.=A0 The prediction for the other bitmap plan is much closer.

Thanks,
Jonathan Hseu
--0016364ee8de352b7904646965a3--