[rt-users] Custom field queries are very slow after 3.8.8 upgrade (from 3.6.10)
Georgi Georgiev
georgi-georgiev-bestpractical at japannext.co.jp
Wed Jan 5 23:50:19 EST 2011
Quoting Kenneth Marshall at 05/01/2011-08:14:10(-0600):
> On Wed, Jan 05, 2011 at 07:31:37PM +0900, Georgi Georgiev wrote:
> > I am looking for some advice on how to speed up some queries using
> > custom fields that got unusably slow after an upgrade from the RT 3.6 series
> > to 3.8.
> >
> > We are currently running RT 3.6.10 on CentOS 5.5 with a postgresql
> > back end (used to be PgSQL 8.1 but we upgraded to 8.4 when CentOS 5.5
> > came out). The RT package is from EPEL and everything is fine.
> >
> > When trying to upgrade to RT 3.8.8 some of our saved queries using
> > custom fields get very, *very* slow. I tried this twelve months ago with
> > RT 3.8.7 on CentOS 5.x and PgSQL 8.1 (whatever was "current" then), and
> > also again today, on RHEL6 with PgSQL 8.4.
> >
> > The problematic queries look something like this:
> >
> > Queue = 'somequeue' AND Status = 'stalled' AND (
> > 'CF.{MyCF}' = 'value1' OR
> > 'CF.{MyCF}' = 'value2' OR
> > 'CF.{MyCF}' = 'value3' OR
> > 'CF.{MyCF}' = 'value4' OR
> > 'CF.{MyCF}' = 'value5' OR
> > 'CF.{MyCF}' = 'value6' OR
> > 'CF.{MyCF}' = 'value7' )
> >
> > where the listed values are 3-4 characters long and their number varies.
> >
> > After the ugprade, and with logging of slow queries enabled, I saw these
> > numbers for queries with 5, 6, 7, and 8 OR statements for the custom
> > field in the postgresql logs:
> > - query for 5 possible CF values - 0.6 seconds
> > - query for 6 possible CF values - 6 seconds
> > - query for 7 possible CF values - 65 seconds
> > - query for 8 possible CF values - 681 seconds
> >
> > In comparison, the corresponding query in RT 3.6 executes in less than 2
> > milliseconds.
> >
> > One thing I noticed is that the SQL that is generated by RT 3.6 and 3.8
> > is substantially different.
> >
> > In 3.6 there is a single SELECT on the ObjectCustomFieldValues table, so
> > the generated SQL looks like this:
> >
> > SELECT DISTINCT main.*
> > FROM Tickets main
> > JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1
> > ON ( ObjectCustomFieldValues_1.CustomField = '1' )
> > AND ( ObjectCustomFieldValues_1.ObjectType = 'RT::Ticket' )
> > AND ( ObjectCustomFieldValues_1.Disabled = '0' )
> > AND ( ObjectCustomFieldValues_1.ObjectId = main.id )
> > WHERE (main.Status != 'deleted')
> > AND (main.Queue = '11' AND main.Status = 'stalled' AND
> > (
> > ( ( ObjectCustomFieldValues_1.Content = 'value1' ) )
> > OR ( ( ObjectCustomFieldValues_1.Content = 'value2' ) )
> > ...
> > )
> > )
> > AND (main.Type = 'ticket')
> > AND (main.EffectiveId = main.id)
> > ORDER BY main.id ASC
> >
> > In RT 3.8.8 the generated SQL looks like this:
> >
> > SELECT DISTINCT main.*
> > FROM Tickets main
> > LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1
> > ON ( ObjectCustomFieldValues_1.CustomField = '1' )
> > AND ( ObjectCustomFieldValues_1.ObjectType = 'RT::Ticket' )
> > AND ( ObjectCustomFieldValues_1.Disabled = '0' )
> > AND ( ObjectCustomFieldValues_1.ObjectId = main.id )
> > LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_2
> > ON ( ObjectCustomFieldValues_2.CustomField = '1' )
> > AND ( ObjectCustomFieldValues_2.ObjectType = 'RT::Ticket' )
> > AND ( ObjectCustomFieldValues_2.Disabled = '0' )
> > AND ( ObjectCustomFieldValues_2.ObjectId = main.id )
> > ....
> > WHERE (main.Status != 'deleted')
> > AND (
> > main.Queue = '11' AND main.Status = 'stalled' AND
> > (
> > ( ( ( ObjectCustomFieldValues_1.Content = 'value1' ) ) )
> > OR ( ( ( ObjectCustomFieldValues_2.Content = 'value2' ) ) )
> > ....
> > )
> > )
> > AND (main.Type = 'ticket')
> > AND (main.EffectiveId = main.id)
> > ORDER BY main.id ASC
> >
> > I ran the queries through "explain analyze" and tried disabling nested
> > loops, then disabling hash joins (I tried disabling whatever the planner
> > was trying to use hoping it will try something else that is faster) but
> > the query speed did not change considerably.
> >
> > Our database is not that big and can easily fit in the memory of the
> > machine (400MB filesize), and we have less than 6000 tickets total. The
> > queries I tried out return only a total of 4 to 5 tickets in the end. The
> > custom field that I am referring to above is a mandatory field so it is
> > assigned for almost all tickets, and with multiple values most of the
> > time.
> >
> > Any advice?
> >
>
> Hi Georgi,
>
> What are your postgresql.conf parameters?
>
> What are the EXPLAIN ANALYZE results for the fast query (3.6.x) and
> the slow (3.8.8) query? That should also point out where an index may
> help.
Thanks for the pointers, Kenneth.
We actually haven't touched postgresql.conf at all. The defaults have
worked fine for our small postgresql installation thus far and I just
didn't know where I should look next - in RT or postgres. Here is our
postgresql.conf (it's the default one on the distro) and it is identical
on RHEL6 and CentOS 5.5.
max_connections = 100
shared_buffers = 32MB
logging_collector = on
log_directory = 'pg_log'
log_filename = 'postgresql-%a.log'
log_truncate_on_rotation = on
log_rotation_age = 1d
log_rotation_size = 0
datestyle = 'iso, mdy'
lc_messages = 'en_US.UTF-8'
lc_monetary = 'en_US.UTF-8'
lc_numeric = 'en_US.UTF-8'
lc_time = 'en_US.UTF-8'
default_text_search_config = 'pg_catalog.english'
I am also attaching the results and the query that I ran. This time I
used bogus values (literally "value1", "value2") and the query ran much
faster, but still not fast enough - 7 seconds for 7 values (going up to
45 seconds for 8 bogus values). It seems that indexes are indeed being
used where appropriate.
Am I missing something obvious?
--
/ Georgi Georgiev / Never make anything simple and efficient /
\ Sysadmin Head \ when a way can be found to make it complex \
/ -SBI Japannext- / and wonderful. /
-------------- next part --------------
explain analyze
SELECT DISTINCT main.* FROM Tickets main
JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1
ON ( ObjectCustomFieldValues_1.CustomField = '1' )
AND ( ObjectCustomFieldValues_1.ObjectType = 'RT::Ticket' )
AND ( ObjectCustomFieldValues_1.Disabled = '0' )
AND ( ObjectCustomFieldValues_1.ObjectId = main.id )
WHERE (main.Status != 'deleted') AND (
main.Queue = '11' AND main.Status = 'stalled' AND
(
( ( ObjectCustomFieldValues_1.Content = 'value1' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value2' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value3' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value4' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value5' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value6' ) )
OR ( ( ObjectCustomFieldValues_1.Content = 'value7' ) )
)
) AND (main.Type = 'ticket') AND (main.EffectiveId = main.id)
ORDER BY main.id ASC;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=131.42..131.48 rows=1 width=176) (actual time=3.708..3.708 rows=0 loops=1)
-> Sort (cost=131.42..131.42 rows=1 width=176) (actual time=3.707..3.707 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.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=4.84..131.41 rows=1 width=176) (actual time=3.565..3.565 rows=0 loops=1)
-> Bitmap Heap Scan on tickets main (cost=4.84..123.09 rows=1 width=176) (actual time=0.399..0.997 rows=45 loops=1)
Recheck Cond: ((queue = 11) AND ((status)::text = 'stalled'::text))
Filter: ((effectiveid = id) AND ((type)::text = 'ticket'::text))
-> Bitmap Index Scan on tickets1 (cost=0.00..4.84 rows=59 width=0) (actual time=0.233..0.233 rows=45 loops=1)
Index Cond: ((queue = 11) AND ((status)::text = 'stalled'::text))
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.00..8.30 rows=1 width=4) (actual time=0.055..0.055 rows=0 loops=45)
Index Cond: ((objectcustomfieldvalues_1.customfield = 1) AND ((objectcustomfieldvalues_1.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_1.objectid = main.effectiveid))
Filter: ((objectcustomfieldvalues_1.disabled = 0) AND (((objectcustomfieldvalues_1.content)::text = 'value1'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value2'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value3'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value4'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value5'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value6'::text) OR ((objectcustomfieldvalues_1.content)::text = 'value7'::text)))
Total runtime: 4.472 ms
(14 rows)
-------------- next part --------------
explain analyze SELECT DISTINCT main.*
FROM Tickets main
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1 ON ( ObjectCustomFieldValues_1.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_1.Disabled = '0' ) AND ( ObjectCustomFieldValues_1.CustomField = '1' ) AND ( ObjectCustomFieldValues_1.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_2 ON ( ObjectCustomFieldValues_2.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_2.Disabled = '0' ) AND ( ObjectCustomFieldValues_2.CustomField = '1' ) AND ( ObjectCustomFieldValues_2.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_3 ON ( ObjectCustomFieldValues_3.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_3.Disabled = '0' ) AND ( ObjectCustomFieldValues_3.CustomField = '1' ) AND ( ObjectCustomFieldValues_3.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_4 ON ( ObjectCustomFieldValues_4.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_4.Disabled = '0' ) AND ( ObjectCustomFieldValues_4.CustomField = '1' ) AND ( ObjectCustomFieldValues_4.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_5 ON ( ObjectCustomFieldValues_5.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_5.Disabled = '0' ) AND ( ObjectCustomFieldValues_5.CustomField = '1' ) AND ( ObjectCustomFieldValues_5.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_6 ON ( ObjectCustomFieldValues_6.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_6.Disabled = '0' ) AND ( ObjectCustomFieldValues_6.CustomField = '1' ) AND ( ObjectCustomFieldValues_6.ObjectId = main.id )
LEFT JOIN ObjectCustomFieldValues ObjectCustomFieldValues_7 ON ( ObjectCustomFieldValues_7.ObjectType = 'RT::Ticket' ) AND ( ObjectCustomFieldValues_7.Disabled = '0' ) AND ( ObjectCustomFieldValues_7.CustomField = '1' ) AND ( ObjectCustomFieldValues_7.ObjectId = main.id )
WHERE (main.Status != 'deleted')
AND (
main.Queue = '11' AND main.Status = 'stalled' AND
(
( ( ( ObjectCustomFieldValues_1.Content = 'value1' ) ) )
OR ( ( ( ObjectCustomFieldValues_2.Content = 'value2' ) ) )
OR ( ( ( ObjectCustomFieldValues_3.Content = 'value3' ) ) )
OR ( ( ( ObjectCustomFieldValues_4.Content = 'value4' ) ) )
OR ( ( ( ObjectCustomFieldValues_5.Content = 'value5' ) ) )
OR ( ( ( ObjectCustomFieldValues_6.Content = 'value6' ) ) )
OR ( ( ( ObjectCustomFieldValues_7.Content = 'value7' ) ) )
)
)
AND (main.Type = 'ticket')
AND (main.EffectiveId = main.id)
ORDER BY main.id ASC
;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=181.19..181.26 rows=1 width=176) (actual time=7064.367..7064.367 rows=0 loops=1)
-> Sort (cost=181.19..181.20 rows=1 width=176) (actual time=7064.365..7064.365 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.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 Left Join (cost=4.84..181.18 rows=1 width=176) (actual time=7064.225..7064.225 rows=0 loops=1)
Filter: (((objectcustomfieldvalues_1.content)::text = 'value1'::text) OR ((objectcustomfieldvalues_2.content)::text = 'value2'::text) OR ((objectcustomfieldvalues_3.content)::text = 'value3'::text) OR ((objectcustomfieldvalues_4.content)::text = 'value4'::text) OR ((objectcustomfieldvalues_5.content)::text = 'value5'::text) OR ((objectcustomfieldvalues_6.content)::text = 'value6'::text) OR ((objectcustomfieldvalues_7.content)::text = 'value7'::text))
-> Nested Loop Left Join (cost=4.84..172.87 rows=1 width=218) (actual time=0.731..1190.894 rows=278182 loops=1)
-> Nested Loop Left Join (cost=4.84..164.57 rows=1 width=211) (actual time=0.692..212.242 rows=45726 loops=1)
-> Nested Loop Left Join (cost=4.84..156.28 rows=1 width=204) (actual time=0.652..42.895 rows=7870 loops=1)
-> Nested Loop Left Join (cost=4.84..147.98 rows=1 width=197) (actual time=0.614..11.384 rows=1470 loops=1)
-> Nested Loop Left Join (cost=4.84..139.68 rows=1 width=190) (actual time=0.572..4.673 rows=322 loops=1)
-> Nested Loop Left Join (cost=4.84..131.39 rows=1 width=183) (actual time=0.533..2.707 rows=96 loops=1)
-> Bitmap Heap Scan on tickets main (cost=4.84..123.09 rows=1 width=176) (actual time=0.410..0.891 rows=45 loops=1)
Recheck Cond: ((queue = 11) AND ((status)::text = 'stalled'::text))
Filter: ((effectiveid = id) AND ((type)::text = 'ticket'::text))
-> Bitmap Index Scan on tickets1 (cost=0.00..4.84 rows=59 width=0) (actual time=0.371..0.371 rows=45 loops=1)
Index Cond: ((queue = 11) AND ((status)::text = 'stalled'::text))
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_7 (cost=0.00..8.28 rows=1 width=11) (actual time=0.036..0.037 rows=2 loops=45)
Index Cond: ((objectcustomfieldvalues_7.customfield = 1) AND ((objectcustomfieldvalues_7.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_7.objectid = main.id))
Filter: (objectcustomfieldvalues_7.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_6 (cost=0.00..8.28 rows=1 width=11) (actual time=0.016..0.018 rows=3 loops=96)
Index Cond: ((objectcustomfieldvalues_6.customfield = 1) AND ((objectcustomfieldvalues_6.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_6.objectid = main.id))
Filter: (objectcustomfieldvalues_6.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_5 (cost=0.00..8.28 rows=1 width=11) (actual time=0.015..0.017 rows=5 loops=322)
Index Cond: ((objectcustomfieldvalues_5.customfield = 1) AND ((objectcustomfieldvalues_5.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_5.objectid = main.id))
Filter: (objectcustomfieldvalues_5.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_4 (cost=0.00..8.28 rows=1 width=11) (actual time=0.014..0.018 rows=5 loops=1470)
Index Cond: ((objectcustomfieldvalues_4.customfield = 1) AND ((objectcustomfieldvalues_4.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_4.objectid = main.id))
Filter: (objectcustomfieldvalues_4.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_3 (cost=0.00..8.28 rows=1 width=11) (actual time=0.014..0.017 rows=6 loops=7870)
Index Cond: ((objectcustomfieldvalues_3.customfield = 1) AND ((objectcustomfieldvalues_3.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_3.objectid = main.id))
Filter: (objectcustomfieldvalues_3.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_2 (cost=0.00..8.28 rows=1 width=11) (actual time=0.014..0.017 rows=6 loops=45726)
Index Cond: ((objectcustomfieldvalues_2.customfield = 1) AND ((objectcustomfieldvalues_2.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_2.objectid = main.id))
Filter: (objectcustomfieldvalues_2.disabled = 0)
-> Index Scan using objectcustomfieldvalues2 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.00..8.28 rows=1 width=11) (actual time=0.014..0.017 rows=6 loops=278182)
Index Cond: ((objectcustomfieldvalues_1.customfield = 1) AND ((objectcustomfieldvalues_1.objecttype)::text = 'RT::Ticket'::text) AND (objectcustomfieldvalues_1.objectid = main.id))
Filter: (objectcustomfieldvalues_1.disabled = 0)
Total runtime: 7065.859 ms
(39 rows)
More information about the rt-users
mailing list