Обсуждение: Strange workaround for slow query
Hi group,
We have two related tables with event types and events. We query for a join between these two tables and experience that, when there is an to-be-expected very small result set, this query performs particularly poor. Understanding in this matter would be appreciated.
SELECT * from events_event_types WHERE id IN (71,999);
id | name | severity
----+------------------------+----------
71 | Xenteo Payment handled | 20
(1 row)
Following original query returns zero rows (as to be expected on what I showed above) and takes (relatively) a lot of time doing so:
SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON eventType_id=events_event_types.id WHERE severity=70 AND (eventType_id IN (71)) ORDER BY datetime DESC LIMIT 50;
id | carparkid | cleared | datetime | identity | generatedbystationid | eventtype_id | relatedstationid | processingstatus | id | name | severity
----+-----------+---------+----------+----------+----------------------+--------------+------------------+------------------+----+------+----------
(0 rows)
Time: 397.564 ms
Following query is much alike the original query, but I changed the "WHERE severity". It returns the number of rows are requested in LIMIT and takes only little time doing so:
SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON eventType_id=events_event_types.id WHERE severity=20 AND (eventType_id IN (71)) ORDER BY datetime DESC limit 50;
...
(50 rows)
Time: 1.604 ms
The latter much to prove that this is a problem related to small result sets.
Following query is much alike the original query, although I've added a dummy value (non-existent in event types table; "999") to the WHERE IN clause. It returns the same zero rows and takes only little time doing so:
SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON eventType_id=events_event_types.id WHERE severity=70 AND (eventType_id IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
id | carparkid | cleared | datetime | identity | generatedbystationid | eventtype_id | relatedstationid | processingstatus | id | name | severity
----+-----------+---------+----------+----------+----------------------+--------------+------------------+------------------+----+------+----------
(0 rows)
Time: 1.340 ms
Now I have at least two possibilities:
- Implementing the dummy value as shown above in my source code to improve query performance (dirty but effective)
- Further investigating what is going on, which at this point is something I need help with
Thanks for your assistance in this matter!
Following are a number of details to describe the environment that this is seen in.
SELECT version();
PostgreSQL 8.3.7 on i486-pc-linux-gnu, compiled by GCC cc (GCC) 4.2.4 (Ubuntu 4.2.4-1ubuntu3)
Postgres was installed as Debian package in Ubuntu 8.04 LTS.
SELECT count(*) FROM events_events;
7619991
SELECT count(*) FROM events_events WHERE eventtype_id=71;
50348
SELECT count(*) FROM events_event_types;
82
\d events_event_types
Table "public.events_event_types"
Column | Type | Modifiers
----------+------------------------+-----------------------------------------------------------------
id | bigint | not null default nextval('events_event_types_id_seq'::regclass)
name | character varying(255) | not null
severity | bigint | not null
Indexes:
"events_event_types_pkey" PRIMARY KEY, btree (id)
"events_event_types_name_key" UNIQUE, btree (name)
"events_event_types_severity_ind" btree (severity)
"test_events_eventtypes_id_severity_ind" btree (id, severity)
"test_events_eventtypes_severity_id_ind" btree (severity, id)
\d events_events
Table "public.events_events"
Column | Type | Modifiers
----------------------+--------------------------+------------------------------------------------------------
id | bigint | not null default nextval('events_events_id_seq'::regclass)
carparkid | bigint |
cleared | boolean | not null
datetime | timestamp with time zone |
identity | character varying(255) |
generatedbystationid | bigint |
eventtype_id | bigint | not null
relatedstationid | bigint |
processingstatus | character varying(255) | not null
Indexes:
"events_events_pkey" PRIMARY KEY, btree (id)
"events_events_cleared_ind" btree (cleared)
"events_events_datetime_eventtype_id_ind" btree (datetime, eventtype_id)
"events_events_datetime_ind" btree (datetime)
"events_events_eventtype_id_datetime_ind" btree (eventtype_id, datetime)
"events_events_eventtype_id_ind" btree (eventtype_id)
"events_events_identity_ind" btree (identity)
"events_events_not_cleared_ind" btree (cleared) WHERE NOT cleared
"events_events_processingstatus_new" btree (processingstatus) WHERE processingstatus::text = 'NEW'::text
"test2_events_events_eventtype_id_severity_ind" btree (datetime, eventtype_id, cleared)
"test3_events_events_eventtype_id_severity_ind" btree (cleared, datetime, eventtype_id)
"test4_events_events_eventtype_id_severity_ind" btree (datetime, cleared, eventtype_id)
"test5_events_events_eventtype_id_severity_ind" btree (datetime, cleared)
"test_events_events_eventtype_id_severity_ind" btree (eventtype_id, cleared)
Foreign-key constraints:
"fk88fe3effa0559276" FOREIGN KEY (eventtype_id) REFERENCES events_event_types(id)
Groeten, best regards,
Sander Verhagen
Hello Sander, Can you post the explain plan output of these queries? > SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON > eventType_id=events_event_types.id WHERE severity=20 AND (eventType_id > IN (71)) ORDER BY datetime DESC limit 50; > > SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON > eventType_id=events_event_types.id WHERE severity=70 AND (eventType_id > IN (71, 999)) ORDER BY datetime DESC LIMIT 50; > regards Yeb Havinga
Hi,
EXPLAIN SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON
eventType_id=events_event_types.id WHERE severity=20 AND (eventType_id
IN (71)) ORDER BY datetime DESC limit 50;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=3.23..200.31 rows=50 width=131)
-> Nested Loop (cost=3.23..49139.16 rows=12466 width=131)
-> Index Scan Backward using events_events_eventtype_id_datetime_ind on events_events (cost=0.00..48886.61 rows=12466 width=93)
Index Cond: (eventtype_id = 71)
-> Materialize (cost=3.23..3.24 rows=1 width=38)
-> Seq Scan on events_event_types (cost=0.00..3.23 rows=1 width=38)
Filter: ((id = 71) AND (severity = 20))
EXPLAIN SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON
eventType_id=events_event_types.id WHERE severity=70 AND (eventType_id
IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=27290.24..27290.37 rows=50 width=131)
-> Sort (cost=27290.24..27303.15 rows=5164 width=131)
Sort Key: events_events.datetime
-> Nested Loop (cost=22.95..27118.70 rows=5164 width=131)
-> Seq Scan on events_event_types (cost=0.00..3.02 rows=17 width=38)
Filter: (severity = 70)
-> Bitmap Heap Scan on events_events (cost=22.95..1589.94 rows=408 width=93)
Recheck Cond: ((events_events.eventtype_id = ANY ('{71,999}'::bigint[])) AND (events_events.eventtype_id = events_event_types.id))
-> Bitmap Index Scan on test_events_events_eventtype_id_severity_ind (cost=0.00..22.85 rows=408 width=0)
Index Cond: ((events_events.eventtype_id = ANY ('{71,999}'::bigint[])) AND (events_events.eventtype_id = events_event_types.id))
By the way, sorry for my colleague Kees re-posting my message, but I was under the assumption that my post did not make it into the group (as we experienced in the past as well).
Groeten, best regards,
Sander Verhagen
sverhagen@wps-nl.com wrote:
>
> Hi,
>
>
> EXPLAIN SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON
> eventType_id=events_event_types.id WHERE severity=20 AND (eventType_id
> IN (71)) ORDER BY datetime DESC limit 50;
> QUERY PLAN
>
-------------------------------------------------------------------------------------------------------------------------------------------
> Limit (cost=3.23..200.31 rows=50 width=131)
> -> Nested Loop (cost=3.23..49139.16 rows=12466 width=131)
> -> Index Scan Backward using events_events_eventtype_id_datetime_ind
> on events_events (cost=0.00..48886.61 rows=12466 width=93)
> Index Cond: (eventtype_id = 71)
> -> Materialize (cost=3.23..3.24 rows=1 width=38)
> -> Seq Scan on events_event_types (cost=0.00..3.23 rows=1 width=38)
> Filter: ((id = 71) AND (severity = 20))
>
>
> EXPLAIN SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON
> eventType_id=events_event_types.id WHERE severity=70 AND (eventType_id
> IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
> QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------------------------------
> Limit (cost=27290.24..27290.37 rows=50 width=131)
> -> Sort (cost=27290.24..27303.15 rows=5164 width=131)
> Sort Key: events_events.datetime
> -> Nested Loop (cost=22.95..27118.70 rows=5164 width=131)
> -> Seq Scan on events_event_types (cost=0.00..3.02 rows=17 width=38)
> Filter: (severity = 70)
> -> Bitmap Heap Scan on events_events (cost=22.95..1589.94 rows=408
> width=93)
> Recheck Cond: ((events_events.eventtype_id = ANY
> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =
> events_event_types.id))
> -> Bitmap Index Scan on test_events_events_eventtype_id_severity_ind
> (cost=0.00..22.85 rows=408 width=0)
> Index Cond: ((events_events.eventtype_id = ANY ('{71,999}'::bigint[]))
> AND (events_events.eventtype_id = events_event_types.id))
>
Thanks - I'm sorry that I was not more specific earlier, but what would
be *really* helpful is the output of explain analyze, since that also
shows actual time, # rows and # loops of the inner nestloop. I'm
wondering though why you do a left outer join. From the \d output in the
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.
regards
Yeb Havinga
> Thanks - I'm sorry that I was not more specific earlier, but what would
> 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=events_event_types.id WHERE severity=20 AND (eventType_id
IN (71)) ORDER BY datetime DESC limit 50;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=3.23..200.31 rows=50 width=131) (actual time=0.070..0.341 rows=50 loops=1)
-> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual time=0.069..0.309 rows=50 loops=1)
-> Index Scan Backward using events_events_eventtype_id_datetime_ind on events_events (cost=0.00..48886.61 rows=12466 width=93) (actual time=0.037..0.144 rows=50 loops=1)
Index Cond: (eventtype_id = 71)
-> Materialize (cost=3.23..3.24 rows=1 width=38) (actual time=0.001..0.001 rows=1 loops=50)
-> Seq Scan on events_event_types (cost=0.00..3.23 rows=1 width=38) (actual time=0.024..0.029 rows=1 loops=1)
Filter: ((id = 71) AND (severity = 20))
Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
IN (71)) ORDER BY datetime DESC limit 50;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=3.23..200.31 rows=50 width=131) (actual time=11641.775..11641.775 rows=0 loops=1)
-> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual time=11641.773..11641.773 rows=0 loops=1)
-> Index Scan Backward using events_events_eventtype_id_datetime_ind on events_events (cost=0.00..48886.61 rows=12466 width=93) (actual time=0.035..11573.320 rows=50389 loops=1)
Index Cond: (eventtype_id = 71)
-> Materialize (cost=3.23..3.24 rows=1 width=38) (actual time=0.000..0.000 rows=0 loops=50389)
-> Seq Scan on events_event_types (cost=0.00..3.23 rows=1 width=38) (actual time=0.028..0.028 rows=0 loops=1)
Filter: ((id = 71) AND (severity = 70))
Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=27290.26..27290.38 rows=50 width=131) (actual time=0.118..0.118 rows=0 loops=1)
-> Sort (cost=27290.26..27303.17 rows=5164 width=131) (actual time=0.117..0.117 rows=0 loops=1)
Sort Key: events_events.datetime
Sort Method: quicksort Memory: 17kB
-> Nested Loop (cost=22.95..27118.71 rows=5164 width=131) (actual time=0.112..0.112 rows=0 loops=1)
-> Seq Scan on events_event_types (cost=0.00..3.02 rows=17 width=38) (actual time=0.016..0.041 rows=16 loops=1)
Filter: (severity = 70)
-> Bitmap Heap Scan on events_events (cost=22.95..1589.94 rows=408 width=93) (actual time=0.002..0.002 rows=0 loops=16)
Recheck Cond: ((events_events.eventtype_id = ANY ('{71,999}'::bigint[])) AND (events_events.eventtype_id = events_event_types.id))
-> Bitmap Index Scan on test_events_events_eventtype_id_severity_ind (cost=0.00..22.85 rows=408 width=0) (actual time=0.001..0.001 rows=0 loops=16)
Index Cond: ((events_events.eventtype_id = ANY ('{71,999}'::bigint[])) AND (events_events.eventtype_id = events_event_types.id))
Total 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 the
> 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 of an existing implementation of ours, for which I'm not aware why they chose 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 existing implementation. But it's on my mind as well ;-)
sverhagen@wps-nl.com wrote:
>
> > Thanks - I'm sorry that I was not more specific earlier, but what would
> > 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=events_event_types.id WHERE severity=20 AND (eventType_id
> IN (71)) ORDER BY datetime DESC limit 50;
>
> QUERY PLAN
>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Limit (cost=3.23..200.31 rows=50 width=131) (actual
> time=0.070..0.341 rows=50 loops=1)
> -> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual
> time=0.069..0.309 rows=50 loops=1)
> -> Index Scan Backward using
> events_events_eventtype_id_datetime_ind on events_events
> (cost=0.00..48886.61 rows=12466 width=93) (actual time=0.037..0.144
> rows=50 loops=1)
> Index Cond: (eventtype_id = 71)
> -> Materialize (cost=3.23..3.24 rows=1 width=38) (actual
> time=0.001..0.001 rows=1 loops=50)
> -> Seq Scan on events_event_types (cost=0.00..3.23
> rows=1 width=38) (actual time=0.024..0.029 rows=1 loops=1)
> Filter: ((id = 71) AND (severity = 20))
> Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
> IN (71)) ORDER BY datetime DESC limit 50;
>
> QUERY PLAN
>
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Limit (cost=3.23..200.31 rows=50 width=131) (actual
> time=11641.775..11641.775 rows=0 loops=1)
> -> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual
> time=11641.773..11641.773 rows=0 loops=1)
> -> Index Scan Backward using
> events_events_eventtype_id_datetime_ind on events_events
> (cost=0.00..48886.61 rows=12466 width=93) (actual
> time=0.035..11573.320 rows=50389 loops=1)
> Index Cond: (eventtype_id = 71)
> -> Materialize (cost=3.23..3.24 rows=1 width=38) (actual
> time=0.000..0.000 rows=0 loops=50389)
> -> Seq Scan on events_event_types (cost=0.00..3.23
> rows=1 width=38) (actual time=0.028..0.028 rows=0 loops=1)
> Filter: ((id = 71) AND (severity = 70))
> Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
> IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
>
> QUERY PLAN
>
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Limit (cost=27290.26..27290.38 rows=50 width=131) (actual
> time=0.118..0.118 rows=0 loops=1)
> -> Sort (cost=27290.26..27303.17 rows=5164 width=131) (actual
> time=0.117..0.117 rows=0 loops=1)
> Sort Key: events_events.datetime
> Sort Method: quicksort Memory: 17kB
> -> Nested Loop (cost=22.95..27118.71 rows=5164 width=131)
> (actual time=0.112..0.112 rows=0 loops=1)
> -> Seq Scan on events_event_types (cost=0.00..3.02
> rows=17 width=38) (actual time=0.016..0.041 rows=16 loops=1)
> Filter: (severity = 70)
> -> Bitmap Heap Scan on events_events
> (cost=22.95..1589.94 rows=408 width=93) (actual time=0.002..0.002
> rows=0 loops=16)
> Recheck Cond: ((events_events.eventtype_id = ANY
> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =
> events_event_types.id))
> -> Bitmap Index Scan on
> test_events_events_eventtype_id_severity_ind (cost=0.00..22.85
> rows=408 width=0) (actual time=0.001..0.001 rows=0 loops=16)
> Index Cond: ((events_events.eventtype_id =
> ANY ('{71,999}'::bigint[])) AND (events_events.eventtype_id =
> events_event_types.id))
> Total 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
> the
> > 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
> of an existing implementation of ours, for which I'm not aware why
> they chose 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 existing 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
expression is only eventtype_id = 71, and the second has the extra
knowledge from the scan of events_event_type in the nestloops outer
loop, which returns 0 rows in all cases and is hence a lot faster, even
though that scan is called 16 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 increase 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.
regards,
Yeb Havinga
In article <OF6136AD9B.D40F3AF5-ONC12576E2.002D5763-C12576E2.002FBD70@imtechrelay.nl>, sverhagen@wps-nl.com writes: > SELECT * FROM events_events LEFT OUTER JOIN events_event_types ON eventType_id= > events_event_types.id WHERE severity=70 AND (eventType_id IN (71)) ORDER BY > datetime DESC LIMIT 50; > Now I have at least two possibilities: > - Implementing the dummy value as shown above in my source code to improve > query performance (dirty but effective) > - Further investigating what is going on, which at this point is something I > need help with First I'd change the query. You build an OUTER JOIN and immediately convert it to an INNER JOIN by referencing the "severity" column. Then show us what EXPLAIN ANALYZE says to the problem.
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 would
>> > 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=events_event_types.id WHERE severity=20 AND (eventType_id
>> IN (71)) ORDER BY datetime DESC limit 50;
>>
>> QUERY PLAN
>>
>>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> Limit (cost=3.23..200.31 rows=50 width=131) (actual time=0.070..0.341
>> rows=50 loops=1)
>> -> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual
>> time=0.069..0.309 rows=50 loops=1)
>> -> Index Scan Backward using
>> events_events_eventtype_id_datetime_ind on events_events
>> (cost=0.00..48886.61 rows=12466 width=93) (actual time=0.037..0.144 rows=50
>> loops=1)
>> Index Cond: (eventtype_id = 71)
>> -> Materialize (cost=3.23..3.24 rows=1 width=38) (actual
>> time=0.001..0.001 rows=1 loops=50)
>> -> Seq Scan on events_event_types (cost=0.00..3.23 rows=1
>> width=38) (actual time=0.024..0.029 rows=1 loops=1)
>> Filter: ((id = 71) AND (severity = 20))
>> Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
>> IN (71)) ORDER BY datetime DESC limit 50;
>>
>> QUERY PLAN
>>
>>
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> Limit (cost=3.23..200.31 rows=50 width=131) (actual
>> time=11641.775..11641.775 rows=0 loops=1)
>> -> Nested Loop (cost=3.23..49139.16 rows=12466 width=131) (actual
>> time=11641.773..11641.773 rows=0 loops=1)
>> -> Index Scan Backward using
>> events_events_eventtype_id_datetime_ind on events_events
>> (cost=0.00..48886.61 rows=12466 width=93) (actual time=0.035..11573.320
>> rows=50389 loops=1)
>> Index Cond: (eventtype_id = 71)
>> -> Materialize (cost=3.23..3.24 rows=1 width=38) (actual
>> time=0.000..0.000 rows=0 loops=50389)
>> -> Seq Scan on events_event_types (cost=0.00..3.23 rows=1
>> width=38) (actual time=0.028..0.028 rows=0 loops=1)
>> Filter: ((id = 71) AND (severity = 70))
>> Total 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=events_event_types.id WHERE severity=70 AND (eventType_id
>> IN (71, 999)) ORDER BY datetime DESC LIMIT 50;
>>
>> QUERY PLAN
>>
>>
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> Limit (cost=27290.26..27290.38 rows=50 width=131) (actual
>> time=0.118..0.118 rows=0 loops=1)
>> -> Sort (cost=27290.26..27303.17 rows=5164 width=131) (actual
>> time=0.117..0.117 rows=0 loops=1)
>> Sort Key: events_events.datetime
>> Sort Method: quicksort Memory: 17kB
>> -> Nested Loop (cost=22.95..27118.71 rows=5164 width=131)
>> (actual time=0.112..0.112 rows=0 loops=1)
>> -> Seq Scan on events_event_types (cost=0.00..3.02 rows=17
>> width=38) (actual time=0.016..0.041 rows=16 loops=1)
>> Filter: (severity = 70)
>> -> Bitmap Heap Scan on events_events (cost=22.95..1589.94
>> rows=408 width=93) (actual time=0.002..0.002 rows=0 loops=16)
>> Recheck Cond: ((events_events.eventtype_id = ANY
>> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =
>> events_event_types.id))
>> -> Bitmap Index Scan on
>> test_events_events_eventtype_id_severity_ind (cost=0.00..22.85 rows=408
>> width=0) (actual time=0.001..0.001 rows=0 loops=16)
>> Index Cond: ((events_events.eventtype_id = ANY
>> ('{71,999}'::bigint[])) AND (events_events.eventtype_id =
>> events_event_types.id))
>> Total 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 the
>> > 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 of
>> an existing implementation of ours, for which I'm not aware why they chose
>> 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 existing
>> 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 expression
> is only eventtype_id = 71, and the second has the extra knowledge from the
> scan of events_event_type in the nestloops outer loop, which returns 0 rows
> in all cases and is hence a lot faster, even though that scan is called 16
> 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 increase
> 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
Robert Haas <robertmhaas@gmail.com> writes:
> 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.
Yeah, the same thing occurred to me while looking at this example.
Right now, nodeNestloop is not really aware of whether the inner scan
depends on any parameters from the outer scan, so it's a bit hard to
determine whether the join can be abandoned. However, I have 9.1
plans to change that --- I'd like to get rid of the current
pass-the-outer-tuple-to-ReScan hack entirely, in favor of having
nodeNestloop explicitly set PARAM_EXEC parameters for the inner scan.
Once that's in, it would be pretty easy to apply this optimization.
(I've added a note to my private TODO file about it.)
Another possible objection is that if the inner scan has any volatile
functions in its quals, it might yield a different result upon rescan
even without parameters. However, since we are already willing to stick
a Materialize node on it at the whim of the planner, I don't see how
such a short-circuit in the executor would make things any worse.
regards, tom lane
On Wed, Mar 10, 2010 at 5:37 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Robert Haas <robertmhaas@gmail.com> writes: >> 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. > > Yeah, the same thing occurred to me while looking at this example. > > Right now, nodeNestloop is not really aware of whether the inner scan > depends on any parameters from the outer scan, so it's a bit hard to > determine whether the join can be abandoned. However, I have 9.1 > plans to change that --- I'd like to get rid of the current > pass-the-outer-tuple-to-ReScan hack entirely, in favor of having > nodeNestloop explicitly set PARAM_EXEC parameters for the inner scan. > Once that's in, it would be pretty easy to apply this optimization. > (I've added a note to my private TODO file about it.) Oh, cool. I was thinking about working on that exact project (getting rid of the outer tuple stuff) per some of our earlier conversations, but I don't understand the code well enough so it is likely to be exceedingly slow going if I have to do it. > Another possible objection is that if the inner scan has any volatile > functions in its quals, it might yield a different result upon rescan > even without parameters. However, since we are already willing to stick > a Materialize node on it at the whim of the planner, I don't see how > such a short-circuit in the executor would make things any worse. +1. ...Robert
Tom Lane <tgl@sss.pgh.pa.us> wrote on 10-03-2010 23:37:20:
> Tom Lane <tgl@sss.pgh.pa.us>
> 10-03-2010 23:37
>
> Right now, nodeNestloop is not really aware of whether the inner scan
> depends on any parameters from the outer scan, so it's a bit hard to
> determine whether the join can be abandoned. However, I have 9.1
> plans to change that --- I'd like to get rid of the current
> pass-the-outer-tuple-to-ReScan hack entirely, in favor of having
> nodeNestloop explicitly set PARAM_EXEC parameters for the inner scan.
> Once that's in, it would be pretty easy to apply this optimization.
I've made it my personal standard to sit mailing list discussions out to the end, report back on results, etc. This one has been sitting in my Inbox for a couple of months now, waiting for me to respond. But the truth is: you're going way over my head. And that is fine, you seem to know of the inner workings of PostgreSQL, and I'll be waiting for future versions that may well solve my problem -- or not, it being a great product either way.
Keep up the good work, Sander.