Thread: Query planner making bad decisions

Query planner making bad decisions

From
Cory Coager
Date:
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.
------------------------------------------------------------------------


Re: Query planner making bad decisions

From
Tom Lane
Date:
Cory Coager <ccoager@davisvision.com> writes:
> Even better yet, if I turn off enable_nestloop the query runs in
> 3499.970 ms:

The reason it prefers a nestloop inappropriately is a mistaken estimate
that some plan node is only going to yield a very small number of rows
(like one or two --- there's not a hard cutoff, but usually more than
a couple of estimated rows will lead it away from a nestloop).
In this case the worst problem seems to be here:

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

where we're off by a factor of 1500+ :-(

I think most likely the ~~ operator is the biggest problem.
Unfortunately 8.1's estimator for ~~ is not terribly bright.  You could
try increasing your statistics target but I don't think it will help
much.  Is there any chance of updating to 8.2 or later?  8.2 can do
significantly better on this type of estimate as long as it has enough
stats.

In any case I'd suggest raising default_statistics_target to 100 or so,
as you seem to be running queries complex enough to need good stats.
But I'm not sure that that will be enough to fix the problem in 8.1.

            regards, tom lane

Re: Query planner making bad decisions

From
Cory Coager
Date:
Tom Lane said the following on 05/11/2009 07:02 PM:
> where we're off by a factor of 1500+ :-(
>
> I think most likely the ~~ operator is the biggest problem.
> Unfortunately 8.1's estimator for ~~ is not terribly bright.  You could
> try increasing your statistics target but I don't think it will help
> much.  Is there any chance of updating to 8.2 or later?  8.2 can do
> significantly better on this type of estimate as long as it has enough
> stats.
>
> In any case I'd suggest raising default_statistics_target to 100 or so,
> as you seem to be running queries complex enough to need good stats.
> But I'm not sure that that will be enough to fix the problem in 8.1.
>
>             regards, tom lane
>
I should have mentioned the statistics for every column are already set
to 1000.  I guess we'll have to add an upgrade to the project list.
Thanks for the info.



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


Re: Query planner making bad decisions

From
Rafael Martinez
Date:
Cory Coager wrote:
> 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;
>
>

Hello

Just in case you want this information. Our RT installation running on
8.3.6 / RHEL4 and with default_statistics_target=100 gives us this query
plan:

Unique  (cost=1360.05..1360.12 rows=1 width=161) (actual
time=2141.834..2141.834 rows=0 loops=1)
   ->  Sort  (cost=1360.05..1360.06 rows=1 width=161) (actual
time=2141.831..2141.831 rows=0 loops=1)
         Sort Key: main.effectiveid, 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
         Sort Method:  quicksort  Memory: 25kB
         ->  Nested Loop  (cost=14.14..1360.04 rows=1 width=161) (actual
time=2141.724..2141.724 rows=0 loops=1)
               ->  Nested Loop  (cost=14.14..1358.09 rows=1 width=165)
(actual time=2141.717..2141.717 rows=0 loops=1)
                     ->  Nested Loop  (cost=14.14..1356.14 rows=1
width=169) (actual time=2141.715..2141.715 rows=0 loops=1)
                           ->  Nested Loop  (cost=14.14..1348.69 rows=1
width=169) (actual time=2141.711..2141.711 rows=0 loops=1)
                                 ->  Bitmap Heap Scan on tickets main
(cost=14.14..1333.78 rows=2 width=161) (actual time=0.906..26.413
rows=1046 loops=1)
                                       Recheck Cond: (queue = 60)
                                       Filter: (((status)::text <>
'deleted'::text) AND (effectiveid = id) AND ((type)::text = 'ticket'::text))
                                       ->  Bitmap Index Scan on tickets1
 (cost=0.00..14.14 rows=781 width=0) (actual time=0.662..0.662 rows=1188
loops=1)
                                             Index Cond: (queue = 60)
                                 ->  Index Scan using
objectcustomfieldvalues3 on objectcustomfieldvalues
objectcustomfieldvalues_2  (cost=0.00..7.44 rows=1 width=8) (actual
time=2.017..2.017 rows=0 loops=1046)
                                       Index Cond:
((objectcustomfieldvalues_2.disabled = 0) AND
(objectcustomfieldvalues_2.objectid = main.effectiveid) AND
((objectcustomfieldvalues_2.objecttype)::text = 'RT::Ticket'::text))
                                       Filter:
((objectcustomfieldvalues_2.content)::text ~~ '%Patient Sat Survey%'::text)
                           ->  Index Scan using objectcustomfieldvalues3
on objectcustomfieldvalues objectcustomfieldvalues_4  (cost=0.00..7.44
rows=1 width=8) (never executed)
                                 Index Cond:
((objectcustomfieldvalues_4.disabled = 0) AND
(objectcustomfieldvalues_4.objectid = main.effectiveid) AND
((objectcustomfieldvalues_4.objecttype)::text = 'RT::Ticket'::text))
                                 Filter:
((objectcustomfieldvalues_4.content)::text ~~ '%MOT%'::text)
                     ->  Index Scan using customfields_pkey on
customfields customfields_3  (cost=0.00..1.94 rows=1 width=4) (never
executed)
                           Index Cond: (customfields_3.id =
objectcustomfieldvalues_4.customfield)
                           Filter: ((customfields_3.name)::text = 'QA
Group Code'::text)
               ->  Index Scan using customfields_pkey on customfields
customfields_1  (cost=0.00..1.94 rows=1 width=4) (never executed)
                     Index Cond: (customfields_1.id =
objectcustomfieldvalues_2.customfield)
                     Filter: ((customfields_1.name)::text = 'QA
Origin'::text)
 Total runtime: 2142.347 ms
(26 rows)

--
 Rafael Martinez, <r.m.guerrero@usit.uio.no>
 Center for Information Technology Services
 University of Oslo, Norway

 PGP Public Key: http://folk.uio.no/rafael/