DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma;
	h=mime-version:in-reply-to:references:date:message-id:subject:from:to
	:cc:content-type:content-transfer-encoding;
	b=CgJeJ/XW98rUBa0X1b52yuVYdDV2NzIZFPR6WtrLQ/MBSqUcseSXfw5oCYn9LLPfsx
	ectBJaulwkj3ov5BEHM1lSVGO5EkwC22wzyVsIw+17yM+ET08QIxQoSrbQh+VYgsgfFt
	MNg1Ars8Q5+/NYgumhi265jUoZgj45TXJ8Uk8=
MIME-Version: 1.0
In-Reply-To: <4B977CD3.5030402@gmail.com>
References: 
 <OF6136AD9B.D40F3AF5-ONC12576E2.002D5763-C12576E2.002FBD70@imtechrelay.nl>
	<4B976229.7030407@gmail.com>
	<OFAD6B66E9.A0DAC161-ONC12576E2.0033EEEB-C12576E2.0033F903@imtechrelay.nl>
	<4B977045.6040604@gmail.com>
	<OF4ACE0533.8EF639EC-ONC12576E2.0039BD09-C12576E2.003A2A20@imtechrelay.nl>
	<4B977CD3.5030402@gmail.com>
Date: Wed, 10 Mar 2010 16:55:32 -0500
Message-ID: <603c8f071003101355r155a3078p7962360d0167895d@mail.gmail.com>
Subject: Re: Strange workaround for slow query
From: Robert Haas <robertmhaas@gmail.com>
To: Yeb Havinga <yebhavinga@gmail.com>
Cc: sverhagen@wps-nl.com, pgsql-performance@postgresql.org
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

On Wed, Mar 10, 2010 at 6:04 AM, Yeb Havinga <yebhavinga@gmail.com> wrote:
> sverhagen@wps-nl.com wrote:
>>
>> > Thanks - I'm sorry that I was not more specific earlier, but what woul=
d
>> > be *really* helpful is the output of explain analyze, since that also
>> > shows actual time, # rows and # loops of the inner nestloop.
>>
>> No problem at all.
>>
>>
>> EXPLAIN ANALYZE SELECT * FROM events_events LEFT OUTER JOIN
>> events_event_types ON
>> eventType_id=3Devents_event_types.id WHERE severity=3D20 AND (eventType_=
id
>> IN (71)) ORDER BY datetime DESC limit 50;
>>
>> =A0 =A0 =A0 =A0 =A0 =A0QUERY PLAN
>>
>> ------------------------------------------------------------------------=
---------------------------------------------------------------------------=
-----------------------------------
>> =A0Limit =A0(cost=3D3.23..200.31 rows=3D50 width=3D131) (actual time=3D0=
.070..0.341
>> rows=3D50 loops=3D1)
>> =A0 -> =A0Nested Loop =A0(cost=3D3.23..49139.16 rows=3D12466 width=3D131=
) (actual
>> time=3D0.069..0.309 rows=3D50 loops=3D1)
>> =A0 =A0 =A0 =A0 -> =A0Index Scan Backward using
>> events_events_eventtype_id_datetime_ind on events_events
>> =A0(cost=3D0.00..48886.61 rows=3D12466 width=3D93) (actual time=3D0.037.=
.0.144 rows=3D50
>> loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 Index Cond: (eventtype_id =3D 71)
>> =A0 =A0 =A0 =A0 -> =A0Materialize =A0(cost=3D3.23..3.24 rows=3D1 width=
=3D38) (actual
>> time=3D0.001..0.001 rows=3D1 loops=3D50)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 -> =A0Seq Scan on events_event_types =A0(cos=
t=3D0.00..3.23 rows=3D1
>> width=3D38) (actual time=3D0.024..0.029 rows=3D1 loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 Filter: ((id =3D 71) AND (severi=
ty =3D 20))
>> =A0Total runtime: 0.415 ms
>> (8 rows)
>>
>> Time: 1.290 ms
>>
>>
>> EXPLAIN ANALYZE SELECT * FROM events_events LEFT OUTER JOIN
>> events_event_types ON
>> eventType_id=3Devents_event_types.id WHERE severity=3D70 AND (eventType_=
id
>> IN (71)) ORDER BY datetime DESC limit 50;
>>
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 QUERY PLAN
>>
>> ------------------------------------------------------------------------=
---------------------------------------------------------------------------=
------------------------------------------
>> =A0Limit =A0(cost=3D3.23..200.31 rows=3D50 width=3D131) (actual
>> time=3D11641.775..11641.775 rows=3D0 loops=3D1)
>> =A0 -> =A0Nested Loop =A0(cost=3D3.23..49139.16 rows=3D12466 width=3D131=
) (actual
>> time=3D11641.773..11641.773 rows=3D0 loops=3D1)
>> =A0 =A0 =A0 =A0 -> =A0Index Scan Backward using
>> events_events_eventtype_id_datetime_ind on events_events
>> =A0(cost=3D0.00..48886.61 rows=3D12466 width=3D93) (actual time=3D0.035.=
.11573.320
>> rows=3D50389 loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 Index Cond: (eventtype_id =3D 71)
>> =A0 =A0 =A0 =A0 -> =A0Materialize =A0(cost=3D3.23..3.24 rows=3D1 width=
=3D38) (actual
>> time=3D0.000..0.000 rows=3D0 loops=3D50389)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 -> =A0Seq Scan on events_event_types =A0(cos=
t=3D0.00..3.23 rows=3D1
>> width=3D38) (actual time=3D0.028..0.028 rows=3D0 loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 Filter: ((id =3D 71) AND (severi=
ty =3D 70))
>> =A0Total runtime: 11641.839 ms
>> (8 rows)
>>
>> Time: 11642.902 ms
>>
>>
>> EXPLAIN ANALYZE SELECT * FROM events_events LEFT OUTER JOIN
>> events_event_types ON
>> eventType_id=3Devents_event_types.id WHERE severity=3D70 AND (eventType_=
id
>> IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
>>
>> =A0 =A0 =A0QUERY PLAN
>>
>> ------------------------------------------------------------------------=
---------------------------------------------------------------------------=
------------------------
>> =A0Limit =A0(cost=3D27290.26..27290.38 rows=3D50 width=3D131) (actual
>> time=3D0.118..0.118 rows=3D0 loops=3D1)
>> =A0 -> =A0Sort =A0(cost=3D27290.26..27303.17 rows=3D5164 width=3D131) (a=
ctual
>> time=3D0.117..0.117 rows=3D0 loops=3D1)
>> =A0 =A0 =A0 =A0 Sort Key: events_events.datetime
>> =A0 =A0 =A0 =A0 Sort Method: =A0quicksort =A0Memory: 17kB
>> =A0 =A0 =A0 =A0 -> =A0Nested Loop =A0(cost=3D22.95..27118.71 rows=3D5164=
 width=3D131)
>> (actual time=3D0.112..0.112 rows=3D0 loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 -> =A0Seq Scan on events_event_types =A0(cos=
t=3D0.00..3.02 rows=3D17
>> width=3D38) (actual time=3D0.016..0.041 rows=3D16 loops=3D1)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 Filter: (severity =3D 70)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 -> =A0Bitmap Heap Scan on events_events =A0(=
cost=3D22.95..1589.94
>> rows=3D408 width=3D93) (actual time=3D0.002..0.002 rows=3D0 loops=3D16)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 Recheck Cond: ((events_events.ev=
enttype_id =3D ANY
>> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =3D
>> events_event_types.id))
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 -> =A0Bitmap Index Scan on
>> test_events_events_eventtype_id_severity_ind =A0(cost=3D0.00..22.85 rows=
=3D408
>> width=3D0) (actual time=3D0.001..0.001 rows=3D0 loops=3D16)
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 Index Cond: ((events=
_events.eventtype_id =3D ANY
>> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =3D
>> events_event_types.id))
>> =A0Total runtime: 0.179 ms
>> (12 rows)
>>
>> Time: 1.510 ms
>>
>>
>> > I'm
>> > wondering though why you do a left outer join. From the \d output in t=
he
>> > previous mail, events_event.eventtype_id has a not null constraint and=
 a
>> > fk to events_event_types.id, so an inner join would be appropriate.
>> > Outer joins limits the amount of join orders the planner considers, so=
 a
>> > better plan might arise when the join is changed to inner.
>>
>> I do agree with this assessment. I'm sort of improving the performance o=
f
>> an existing implementation of ours, for which I'm not aware why they cho=
se
>> for LEFT OUTER. I did, however, test things with INNER as well, with the
>> same results, so I decided to stick with what I encountered in the exist=
ing
>> implementation. But it's on my mind as well ;-)
>>
> Thanks for the formatted output. The difference in speed is caused by the
> first query that has to read 50k rows from an index, with filter expressi=
on
> is only eventtype_id =3D 71, and the second has the extra knowledge from =
the
> scan of events_event_type in the nestloops outer loop, which returns 0 ro=
ws
> in all cases and is hence a lot faster, even though that scan is called 1=
6
> times.
>
> But the big question is: why does the planner chooses plan 1 in the first
> case, or how to fix that? My $0,02 would be to 'help' the planner find a
> better plan. Ofcourse you did ANALYZE, but maybe another idea is to incre=
ase
> the default_statistics_target if it is still at the default value of 10.
> More info on
> http://www.postgresql.org/docs/8.3/static/runtime-config-query.html. And
> also to 'help' the planner: I'd just change the query to an inner join in
> this case, since there cannot be null tuples in the right hand side here.

I believe that the planner already figured that part out - it is
implemented a Nested Loop, rather than a Nested Loop Left Join.

I think that the planner thinks that the backward index scan plan will
be faster because it expects not to have to scan very many rows before
it finds enough rows that match the join condition to fulfill the
limit.  It actually ends up scanning the entire index range one tuple
at a time, which is slow, and backwards, which is slower.  But it's
also possible to have mistakes in the opposite direction, where the
planner thinks it will be faster to bitmap-index-scan the index but it
turns out that since only a small number of rows are needed a regular
index scan (forward or backward) would have been better.

It does seem like once the materialize step is done we could notice
that the tuplestore is empty and, given that uses no outer variables
or parameters and therefore will never be re-executed, we could skip
the rest of the index scan.  That doesn't really fix the problem in
general because you could have one row in the tuplestore and need to
iterate through the entire index to find out that nothing matches, but
it might still be worth doing.

...Robert