Query planner making bad decisions

From: Cory Coager <ccoager(at)davisvision(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: Query planner making bad decisions
Date: 2009-05-11 21:03:15
Message-ID: 24433_1242075795_4A089293_24433_141_1_4A089293.8070806@handel.davisvision.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

I'm running version 8.1.11 on SLES 10 SP2. I'm trying to improve this
query and unfortunately I cannot change the application. For some
reason the planner is making a bad decision sometimes after an analyze
of table objectcustomfieldvalues.

The query is:
SELECT DISTINCT main.* FROM Tickets main JOIN CustomFields
CustomFields_1 ON ( CustomFields_1.Name = 'QA Origin' ) JOIN
CustomFields CustomFields_3 ON (CustomFields_3.Name = 'QA Group Code' )
JOIN ObjectCustomFieldValues ObjectCustomFieldValues_4 ON
(ObjectCustomFieldValues_4.ObjectId = main.id ) AND (
ObjectCustomFieldValues_4.Disabled = '0' ) AND
(ObjectCustomFieldValues_4.ObjectType = 'RT::Ticket' ) AND (
ObjectCustomFieldValues_4.CustomField = CustomFields_3.id ) JOIN
ObjectCustomFieldValues ObjectCustomFieldValues_2 ON (
ObjectCustomFieldValues_2.Disabled = '0' ) AND
(ObjectCustomFieldValues_2.ObjectId = main.id ) AND (
ObjectCustomFieldValues_2.CustomField = CustomFields_1.id ) AND
(ObjectCustomFieldValues_2.ObjectType = 'RT::Ticket' ) WHERE
(main.Status != 'deleted') AND (main.Queue = '60' AND
ObjectCustomFieldValues_2.Content LIKE '%Patient Sat Survey%' AND
ObjectCustomFieldValues_4.Content LIKE'%MOT%') AND (main.EffectiveId =
main.id) AND (main.Type = 'ticket') ORDER BY main.id ASC;

Here is the query run in 12379.816 ms:

Unique (cost=1560.06..1560.12 rows=1 width=181) (actual
time=12379.573..12379.642 rows=13 loops=1)
-> Sort (cost=1560.06..1560.06 rows=1 width=181) (actual
time=12379.568..12379.586 rows=13 loops=1)
Sort Key: main.id, main.effectiveid, main.queue, main."type",
main.issuestatement, main.resolution, main."owner", main.subject,
main.initialpriority, main.finalpriority, main.priority,
main.timeestimated, main.timeworked, main.status, main.timeleft,
main.told, main.starts, main.started, main.due, main.resolved,
main.lastupdatedby, main.lastupdated, main.creator, main.created,
main.disabled
-> Nested Loop (cost=0.00..1560.05 rows=1 width=181) (actual
time=9081.782..12379.303 rows=13 loops=1)
Join Filter: ("outer".objectid = "inner".id)
-> Nested Loop (cost=0.00..849.90 rows=1 width=8)
(actual time=9059.881..12052.548 rows=13 loops=1)
Join Filter: ("outer".objectid = "inner".objectid)
-> Nested Loop (cost=0.00..424.19 rows=1 width=4)
(actual time=0.274..26.660 rows=1575 loops=1)
-> Index Scan using customfields_pkey on
customfields customfields_1 (cost=0.00..16.41 rows=1 width=4) (actual
time=0.228..0.371 rows=1 loops=1)
Filter: ((name)::text = 'QA Origin'::text)
-> Index Scan using ticketcustomfieldvalues2
on objectcustomfieldvalues objectcustomfieldvalues_2 (cost=0.00..407.76
rows=1 width=8) (actual time=0.039..21.243 rows=1575 loops=1)
Index Cond:
(objectcustomfieldvalues_2.customfield = "outer".id)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%Patient Sat Survey%'::text))
-> Nested Loop (cost=0.00..424.99 rows=58
width=4) (actual time=5.188..7.605 rows=18 loops=1575)
-> Index Scan using customfields_pkey on
customfields customfields_3 (cost=0.00..16.41 rows=1 width=4) (actual
time=0.235..0.419 rows=1 loops=1575)
Filter: ((name)::text = 'QA Group
Code'::text)
-> Index Scan using ticketcustomfieldvalues2
on objectcustomfieldvalues objectcustomfieldvalues_4 (cost=0.00..407.76
rows=65 width=8) (actual time=4.947..7.130 rows=18 loops=1575)
Index Cond:
(objectcustomfieldvalues_4.customfield = "outer".id)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%MOT%'::text))
-> Index Scan using tickets1 on tickets main
(cost=0.00..709.77 rows=30 width=181) (actual time=0.020..17.104
rows=5743 loops=13)
Index Cond: (queue = 60)
Filter: (((status)::text <> 'deleted'::text) AND
(effectiveid = id) AND (("type")::text = 'ticket'::text))
Total runtime: 12379.816 ms
(23 rows)

select attname,n_distinct from pg_stats where tablename='tickets';
attname | n_distinct
-----------------+------------
id | -1
effectiveid | -0.968462
queue | 37
type | 1
issuestatement | 1
resolution | 1
owner | 123
subject | -0.885148
initialpriority | 12
finalpriority | 9
priority | 43
timeestimated | 5
timeworked | 5
status | 6
timeleft | 3
told | -0.128088
starts | 60
started | -0.862352
due | 1270
resolved | -0.94381
lastupdatedby | 366
lastupdated | -0.98511
creator | 1054
created | -0.965858
disabled | 1
(25 rows)

select attname,n_distinct from pg_stats where tablename='customfields';
attname | n_distinct
---------------+------------
id | -1
name | -0.83855
type | 3
description | -0.202636
sortorder | -0.110379
creator | 4
created | -0.739703
lastupdatedby | 4
lastupdated | -0.78089
disabled | 2
lookuptype | 1
repeated | 1
pattern | 1
maxvalues | 2
(14 rows)

select attname,n_distinct from pg_stats where
tablename='objectcustomfieldvalues';
attname | n_distinct
-----------------+------------
id | -1
objectid | 95048
customfield | 543
content | 30209
creator | 115
created | -0.268605
lastupdatedby | 115
lastupdated | -0.26863
objecttype | 1
largecontent | -1
contenttype | 1
contentencoding | 2
sortorder | 1
disabled | 2
(14 rows)

If I now analyze objectcustomfieldvalues the query now takes 51747.341 ms:

Unique (cost=1564.95..1565.02 rows=1 width=181) (actual
time=51747.087..51747.152 rows=13 loops=1)
-> Sort (cost=1564.95..1564.95 rows=1 width=181) (actual
time=51747.083..51747.097 rows=13 loops=1)
Sort Key: main.id, main.effectiveid, main.queue, main."type",
main.issuestatement, main.resolution, main."owner", main.subject,
main.initialpriority, main.finalpriority, main.priority,
main.timeestimated, main.timeworked, main.status, main.timeleft,
main.told, main.starts, main.started, main.due, main.resolved,
main.lastupdatedby, main.lastupdated, main.creator, main.created,
main.disabled
-> Nested Loop (cost=0.00..1564.94 rows=1 width=181) (actual
time=38871.343..51746.920 rows=13 loops=1)
Join Filter: ("inner".objectid = "outer".id)
-> Nested Loop (cost=0.00..1136.77 rows=1 width=185)
(actual time=7.772..39862.238 rows=1548 loops=1)
Join Filter: ("outer".objectid = "inner".id)
-> Nested Loop (cost=0.00..426.63 rows=1 width=4)
(actual time=0.266..27.745 rows=1575 loops=1)
-> Index Scan using customfields_pkey on
customfields customfields_1 (cost=0.00..16.41 rows=1 width=4) (actual
time=0.219..0.404 rows=1 loops=1)
Filter: ((name)::text = 'QA Origin'::text)
-> Index Scan using ticketcustomfieldvalues2
on objectcustomfieldvalues objectcustomfieldvalues_2 (cost=0.00..410.20
rows=1 width=8) (actual time=0.040..22.006 rows=1575 loops=1)
Index Cond:
(objectcustomfieldvalues_2.customfield = "outer".id)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%Patient Sat Survey%'::text))
-> Index Scan using tickets1 on tickets main
(cost=0.00..709.77 rows=30 width=181) (actual time=0.015..17.164
rows=5743 loops=1575)
Index Cond: (queue = 60)
Filter: (((status)::text <> 'deleted'::text)
AND (effectiveid = id) AND (("type")::text = 'ticket'::text))
-> Nested Loop (cost=0.00..427.44 rows=58 width=4)
(actual time=5.207..7.646 rows=18 loops=1548)
-> Index Scan using customfields_pkey on
customfields customfields_3 (cost=0.00..16.41 rows=1 width=4) (actual
time=0.242..0.434 rows=1 loops=1548)
Filter: ((name)::text = 'QA Group Code'::text)
-> Index Scan using ticketcustomfieldvalues2 on
objectcustomfieldvalues objectcustomfieldvalues_4 (cost=0.00..410.20
rows=66 width=8) (actual time=4.958..7.154 rows=18 loops=1548)
Index Cond:
(objectcustomfieldvalues_4.customfield = "outer".id)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%MOT%'::text))
Total runtime: 51747.341 ms
(23 rows)

select attname,n_distinct from pg_stats where
tablename='objectcustomfieldvalues';
attname | n_distinct
-----------------+------------
id | -1
objectid | 95017
customfield | 539
content | 30287
creator | 114
created | -0.268403
lastupdatedby | 114
lastupdated | -0.268809
objecttype | 1
largecontent | -1
contenttype | 1
contentencoding | 2
sortorder | 1
disabled | 2
(14 rows)

Even better yet, if I turn off enable_nestloop the query runs in
3499.970 ms:

Unique (cost=53860.11..53860.18 rows=1 width=181) (actual
time=3499.614..3499.684 rows=13 loops=1)
-> Sort (cost=53860.11..53860.11 rows=1 width=181) (actual
time=3499.608..3499.627 rows=13 loops=1)
Sort Key: main.id, main.effectiveid, main.queue, main."type",
main.issuestatement, main.resolution, main."owner", main.subject,
main.initialpriority, main.finalpriority, main.priority,
main.timeestimated, main.timeworked, main.status, main.timeleft,
main.told, main.starts, main.started, main.due, main.resolved,
main.lastupdatedby, main.lastupdated, main.creator, main.created,
main.disabled
-> Hash Join (cost=27240.41..53860.10 rows=1 width=181)
(actual time=3429.166..3499.538 rows=13 loops=1)
Hash Cond: ("outer".objectid = "inner".id)
-> Merge Join (cost=0.00..26619.39 rows=58 width=4)
(actual time=1666.503..1736.814 rows=18 loops=1)
Merge Cond: ("outer".id = "inner".customfield)
-> Index Scan using customfields_pkey on
customfields customfields_3 (cost=0.00..16.41 rows=1 width=4) (actual
time=0.221..0.410 rows=1 loops=1)
Filter: ((name)::text = 'QA Group Code'::text)
-> Index Scan using ticketcustomfieldvalues2 on
objectcustomfieldvalues objectcustomfieldvalues_4 (cost=0.00..26514.04
rows=35342 width=8) (actual time=98.035..1736.277 rows=44 loops=1)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%MOT%'::text))
-> Hash (cost=27240.40..27240.40 rows=1 width=185)
(actual time=1762.572..1762.572 rows=1548 loops=1)
-> Hash Join (cost=26530.47..27240.40 rows=1
width=185) (actual time=1728.887..1758.147 rows=1548 loops=1)
Hash Cond: ("outer".id = "inner".objectid)
-> Index Scan using tickets1 on tickets
main (cost=0.00..709.77 rows=30 width=181) (actual time=0.024..17.550
rows=5743 loops=1)
Index Cond: (queue = 60)
Filter: (((status)::text <>
'deleted'::text) AND (effectiveid = id) AND (("type")::text =
'ticket'::text))
-> Hash (cost=26530.47..26530.47 rows=1
width=4) (actual time=1728.787..1728.787 rows=1575 loops=1)
-> Merge Join (cost=0.00..26530.47
rows=1 width=4) (actual time=1493.343..1726.020 rows=1575 loops=1)
Merge Cond: ("outer".id =
"inner".customfield)
-> Index Scan using
customfields_pkey on customfields customfields_1 (cost=0.00..16.41
rows=1 width=4) (actual time=0.237..0.429 rows=1 loops=1)
Filter: ((name)::text = 'QA
Origin'::text)
-> Index Scan using
ticketcustomfieldvalues2 on objectcustomfieldvalues
objectcustomfieldvalues_2 (cost=0.00..26514.04 rows=1 width=8) (actual
time=1493.091..1721.155 rows=1575 loops=1)
Filter: ((disabled = 0) AND
((objecttype)::text = 'RT::Ticket'::text) AND ((content)::text ~~
'%Patient Sat Survey%'::text))
Total runtime: 3499.970 ms
(25 rows)

Is there anything I can do to improve this?

~Cory Coager

------------------------------------------------------------------------
The information contained in this communication is intended
only for the use of the recipient(s) named above. It may
contain information that is privileged or confidential, and
may be protected by State and/or Federal Regulations. If
the reader of this message is not the intended recipient,
you are hereby notified that any dissemination,
distribution, or copying of this communication, or any of
its contents, is strictly prohibited. If you have received
this communication in error, please return it to the sender
immediately and delete the original message and any copy
of it from your computer system. If you have any questions
concerning this message, please contact the sender.
------------------------------------------------------------------------

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Dimitri 2009-05-11 22:30:43 Re: Any better plan for this query?..
Previous Message Aidan Van Dyk 2009-05-11 19:46:15 Re: Any better plan for this query?..