[rt-users] Slow PostgreSQL perf with 3.8.7

Kenneth Marshall ktm at rice.edu
Wed Sep 22 16:34:20 EDT 2010


Did you performance problem go away? You may want to run a
REINDEX on your tables to clear out any bloat which will
degrade lookup performance, though.

Ken

On Wed, Sep 22, 2010 at 04:29:40PM -0400, Jeff Blaine wrote:
> On 9/22/2010 4:16 PM, Kenneth Marshall wrote:
>> It should be called "default_statistics_target" according to
>> the PostgreSQL 8.1 documentation. I would set it to 100 like
>> the current 8.4 default and re-analyze the database:
>>
>> vacuumdb -a -z
>>
>> You could add a '-v' for more information while it is running.
>> You may not have heeded the VACUUM documentation, but you should
>> almost never use "VACUUM FULL" but just a simple "VACUUM". The
>> FULL variant can cause serious index bloating which can only
>> be fixed by running REINDEX. Good luck.
>
> Hm, I don't see such a warning here:
>
>     http://www.postgresql.org/docs/8.1/static/sql-vacuum.html
>
> Maybe it's officially-undocumented knowledge of yours from
> experience?
>
> The Notes do say the following, but from what I can tell the
> only hangup on FULL is that it takes longer and exclusively
> locks.
>
>     "The FULL option is not recommended for routine use, but
>     may be useful in special cases. An example is when you
>     have deleted most of the rows in a table and would like
>     the table to physically shrink to occupy less disk space.
>     VACUUM FULL will usually shrink the table more than a
>     plain VACUUM would."
>
> We *did* in fact RT-Shredder-ify 50% of the tickets 4
> weeks ago (bogus tickets from the user's misconfigured code).
>
> At any rate, VACUUM FULL ANALYZE solved the problem, which
> should be addressed going forward by auto-vacuum.
>
> Thanks again
>
>> Cheers,
>> Ken
>>
>> On Wed, Sep 22, 2010 at 04:08:08PM -0400, Jeff Blaine wrote:
>>> Ken,
>>>
>>> Thanks for the replies.
>>>
>>> I don't see any planner settings in postgresql.conf (so
>>> no I've not changed that).
>>>
>>> I've turned on autovacuum as well as log_planner_stats (on
>>> a whim that it might provide useful info based on your lead).
>>>
>>> Hmm... given how long 'VACUUM FULL;' is taking now,
>>> maybe I was connected to the default database when I
>>> ran it before starting this thread instead of 'rt3'
>>>
>>> *fingers crossed*
>>>
>>> On 9/22/2010 3:25 PM, Kenneth Marshall wrote:
>>>> Hi Jeff,
>>>>
>>>> Just a quick glance at your plan seems to indicate that there is
>>>> a fairly wide discrepency between how many results a query returns
>>>> and what the planner thinks the query should return. Have you already
>>>> bumped the planner statistics target to 100 or 200 and then re-analyzed
>>>> the database. I do not think that 8.1 had autovacuum enabled by default
>>>> so you should enable it to keep the statistics updated and run a full
>>>> database-wide re-analyze to update the stats. Then try your query again.
>>>>
>>>> Regards,
>>>> Ken
>>>>
>>>> On Wed, Sep 22, 2010 at 12:57:58PM -0400, Jeff Blaine wrote:
>>>>> We have this in place:
>>>>>
>>>>>       CREATE INDEX ObjectCustomFieldValues3 ON ObjectCustomFieldValues
>>>>> (ObjectId,ObjectType);
>>>>>
>>>>> And I don't see any other suggested indexes in the wiki.
>>>>> Maybe I am missing a certain page?  Should I add these:
>>>>>
>>>>>       http://wiki.bestpractical.com/view/DatabaseIndexes
>>>>>
>>>>> Here's the EXPLAIN for one of the slow statements:
>>>>>
>>>>> rt3=# EXPLAIN ANALYZE SELECT DISTINCT main.id AS id, main.Content AS
>>>>> content, main.ContentType AS contenttype, main.TransactionId AS
>>>>> transactionid, main.ContentEncoding AS contentencoding FROM Attachments
>>>>> main JOIN Transactions Transactions_1  ON ( Transactions_1.id =
>>>>> main.TransactionId ) JOIN Tickets Tickets_2  ON ( Tickets_2.id =
>>>>> Transactions_1.ObjectId )  WHERE (Tickets_2.EffectiveId = '35339') AND
>>>>> (Transactions_1.ObjectType = 'RT::Ticket') AND (main.ContentType =
>>>>> 'text/plain' OR main.ContentType LIKE 'message/%' OR main.ContentType =
>>>>> 'text') ORDER BY main.id ASC;
>>>>>
>>>>>        QUERY PLAN
>>>>> ------------------------------------------------------------------------------------------------------------------------------------------------------------------
>>>>>    Unique  (cost=1033.85..1033.86 rows=1 width=396) (actual
>>>>> time=3720.579..3720.579 rows=1 loops=1)
>>>>>      ->    Sort  (cost=1033.85..1033.85 rows=1 width=396) (actual
>>>>> time=3720.373..3720.373 rows=1 loops=1)
>>>>>            Sort Key: main.id, main.content, main.contenttype,
>>>>> main.transactionid, main.contentencoding
>>>>>            ->    Nested Loop  (cost=17.77..1033.84 rows=1 width=396)
>>>>> (actual
>>>>> time=3569.107..3719.649 rows=1 loops=1)
>>>>>                  ->    Nested Loop  (cost=14.13..383.55 rows=1 width=4)
>>>>> (actual
>>>>> time=3562.353..3717.041 rows=28 loops=1)
>>>>>                        ->    Bitmap Heap Scan on transactions
>>>>> transactions_1
>>>>> (cost=14.13..154.48 rows=38 width=8) (actual time=159.630..1185.953
>>>>> rows=75440 loops=1)
>>>>>                              Recheck Cond: ((objecttype)::text =
>>>>> 'RT::Ticket'::text)
>>>>>                              ->    Bitmap Index Scan on transactions1
>>>>> (cost=0.00..14.13 rows=38 width=0) (actual time=156.409..156.409
>>>>> rows=133079 loops=1)
>>>>>                                    Index Cond: ((objecttype)::text =
>>>>> 'RT::Ticket'::text)
>>>>>                        ->    Index Scan using tickets4 on tickets 
>>>>> tickets_2
>>>>> (cost=0.00..6.02 rows=1 width=4) (actual time=0.026..0.026 rows=0
>>>>> loops=75440)
>>>>>                              Index Cond: (tickets_2.id = 
>>>>> "outer".objectid)
>>>>>                              Filter: (effectiveid = 35339)
>>>>>                  ->    Bitmap Heap Scan on attachments main
>>>>> (cost=3.63..648.02
>>>>> rows=181 width=396) (actual time=0.078..0.082 rows=0 loops=28)
>>>>>                        Recheck Cond: ("outer".id = main.transactionid)
>>>>>                        Filter: (((contenttype)::text = 
>>>>> 'text/plain'::text)
>>>>> OR
>>>>> ((contenttype)::text ~~ 'message/%'::text) OR ((contenttype)::text =
>>>>> 'text'::text))
>>>>>                        ->    Bitmap Index Scan on attachments2
>>>>> (cost=0.00..3.63
>>>>> rows=181 width=0) (actual time=0.011..0.011 rows=1 loops=28)
>>>>>                              Index Cond: ("outer".id = 
>>>>> main.transactionid)
>>>>>    Total runtime: 3722.252 ms
>>>>> (18 rows)
>>>>>
>>>>> rt3=#
>>>>>
>>>>>
>>>>> On 9/22/2010 12:24 PM, Kenneth Marshall wrote:
>>>>>> Hi Jeff,
>>>>>>
>>>>>> Wow, is that version of PostgreSQL old. Certainly there have
>>>>>> been many, many performance improvements since v8.1.x. While
>>>>>> upgrading would help, you really need to run an EXPLAIN ANALYZE
>>>>>> for your slow queries to see if there is a problem area. Also,
>>>>>> you should check to wiki to see if you have all of the recommended
>>>>>> PostgreSQL indexes.
>>>>>>
>>>>>> Some things to check.
>>>>>> Ken
>>>>>>
>>>>>> On Wed, Sep 22, 2010 at 12:12:59PM -0400, Jeff Blaine wrote:
>>>>>>> Please bear with my ignorance on this topic.  I realize
>>>>>>> this isn't a PostgreSQL tuning forum, but since it's RT-related
>>>>>>> I thought I'd ask here.
>>>>>>>
>>>>>>> RT 3.8.7 (and RTFM) with PostgreSQL 8.1.18 via RHELv5 running
>>>>>>> as a VM.
>>>>>>>
>>>>>>> We're experiencing significant delays today with various
>>>>>>> PostgreSQL statements taking longer than 1000ms to complete.
>>>>>>>
>>>>>>> We have 10,000 tickets, 1300 of which are 'open'
>>>>>>>
>>>>>>> Can anyone throw out any ideas, things to check, etc?
>>>>>>> Is this just
>>>>>>>
>>>>>>> Viewing a single ticket results in the following, showing
>>>>>>> only those longer than 1000ms:
>>>>>>>
>>>>>>> LOG:  duration: 1496.023 ms
>>>>>>> LOG:  duration: 1496.023 ms  statement: EXECUTE<unnamed>     
>>>>>>> [PREPARE:
>>>>>>> SELECT
>>>>>>> DISTINCT main.Id AS id, main.Filename AS filename, main.Headers AS
>>>>>>> headers,
>>>>>>> main.Subject AS subject, main.Parent AS parent, main.ContentEncoding 
>>>>>>> AS
>>>>>>> contentencoding, main.ContentType AS contenttype, main.TransactionId 
>>>>>>> AS
>>>>>>> transactionid, main.Created AS created FROM Attachments main JOIN
>>>>>>> Transactions Transactions_1  ON ( Transactions_1.id =
>>>>>>> main.TransactionId
>>>>>>> )
>>>>>>> JOIN Tickets Tickets_2  ON ( Tickets_2.id = Transactions_1.ObjectId )
>>>>>>> WHERE (Tickets_2.EffectiveId = '35803') AND 
>>>>>>> (Transactions_1.ObjectType
>>>>>>> =
>>>>>>> 'RT::Ticket')  ORDER BY main.id ASC ]
>>>>>>> LOG:  duration: 2207.968 ms
>>>>>>> LOG:  duration: 2207.968 ms  statement: EXECUTE<unnamed>     
>>>>>>> [PREPARE:
>>>>>>> SELECT
>>>>>>> DISTINCT main.* FROM Users main CROSS JOIN ACL ACL_4 JOIN Principals
>>>>>>> Principals_1  ON ( Principals_1.id = main.id ) JOIN 
>>>>>>> CachedGroupMembers
>>>>>>> CachedGroupMembers_2  ON ( CachedGroupMembers_2.MemberId =
>>>>>>> Principals_1.id
>>>>>>> ) JOIN Groups Groups_3 ON ( Groups_3.id = 
>>>>>>> CachedGroupMembers_2.GroupId
>>>>>>> )
>>>>>>> WHERE (Principals_1.Disabled = '0') AND (ACL_4.PrincipalType =
>>>>>>> Groups_3.Type) AND (Principals_1.id != '1') AND
>>>>>>> (Principals_1.PrincipalType
>>>>>>> = 'User') AND (ACL_4.RightName = 'OwnTicket' OR ACL_4.RightName =
>>>>>>> 'SuperUser') AND (Groups_3.Domain = 'RT::Queue-Role' AND
>>>>>>> Groups_3.Instance
>>>>>>> = '1') AND ((ACL_4.ObjectType = 'RT::Queue' AND ACL_4.ObjectId = 1) 
>>>>>>> OR
>>>>>>> (ACL_4.ObjectType = 'RT::System'))  ORDER BY main.Name ASC ]
>>>>>>> LOG:  duration: 3363.967 ms
>>>>>>> LOG:  duration: 3363.967 ms  statement: EXECUTE<unnamed>     
>>>>>>> [PREPARE:
>>>>>>> SELECT
>>>>>>> DISTINCT main.* FROM Users main CROSS JOIN ACL ACL_2 JOIN Principals
>>>>>>> Principals_1  ON ( Principals_1.id = main.id ) JOIN 
>>>>>>> CachedGroupMembers
>>>>>>> CachedGroupMembers_3  ON ( CachedGroupMembers_3.MemberId =
>>>>>>> Principals_1.id
>>>>>>> )  WHERE (Principals_1.Disabled = '0') AND (ACL_2.PrincipalId =
>>>>>>> CachedGroupMembers_3.GroupId) AND (Principals_1.id != '1') AND
>>>>>>> (ACL_2.PrincipalType = 'Group') AND (Principals_1.PrincipalType =
>>>>>>> 'User')
>>>>>>> AND (ACL_2.RightName = 'OwnTicket' OR ACL_2.RightName = 'SuperUser')
>>>>>>> AND
>>>>>>> ((ACL_2.ObjectType = 'RT::Queue' AND ACL_2.ObjectId   = 1) OR
>>>>>>> (ACL_2.ObjectType = 'RT::System'))  ORDER BY main.Name ASC ]
>>>>>>> LOG:  duration: 1482.014 ms
>>>>>>> LOG:  duration: 1482.014 ms  statement: EXECUTE<unnamed>     
>>>>>>> [PREPARE:
>>>>>>> SELECT
>>>>>>> DISTINCT main.id AS id, main.Content AS content, main.ContentType AS
>>>>>>> contenttype, main.TransactionId AS transactionid, 
>>>>>>> main.ContentEncoding
>>>>>>> AS
>>>>>>> contentencoding FROM Attachments main JOIN Transactions 
>>>>>>> Transactions_1
>>>>>>> ON
>>>>>>> ( Transactions_1.id = main.TransactionId ) JOIN Tickets Tickets_2  ON 
>>>>>>> (
>>>>>>> Tickets_2.id = Transactions_1.ObjectId )  WHERE 
>>>>>>> (Tickets_2.EffectiveId
>>>>>>> =
>>>>>>> '35803') AND (Transactions_1.ObjectType = 'RT::Ticket') AND
>>>>>>> (main.ContentType = 'text/plain' OR main.ContentType LIKE 'message/%'
>>>>>>> OR
>>>>>>> main.ContentType = 'text')  ORDER BY main.id ASC ]
>>>>>>> LOG:  duration: 1329.789 ms
>>>>>>> LOG:  duration: 1329.789 ms  statement: EXECUTE<unnamed>     
>>>>>>> [PREPARE:
>>>>>>> SELECT
>>>>>>> DISTINCT main.* FROM Transactions main JOIN Tickets Tickets_1  ON (
>>>>>>> Tickets_1.id = main.ObjectId )  WHERE (main.ObjectType = 
>>>>>>> 'RT::Ticket')
>>>>>>> AND
>>>>>>> (Tickets_1.EffectiveId = '35803')  ORDER BY main.Created ASC, main.id
>>>>>>> ASC
>>>>>>> ]
>>>>>>>
>>>>>>>
>>>>>>> # /sbin/sysctl kernel.shmmax kernel.shmall kernel.shmmni kernel.sem
>>>>>>> kernel.shmmax = 4294967296
>>>>>>> kernel.shmall = 2097152
>>>>>>> kernel.shmmni = 4096
>>>>>>> kernel.sem = 250        32000   100     128
>>>>>>> # cat /proc/cpuinfo
>>>>>>> processor       : 0
>>>>>>> vendor_id       : GenuineIntel
>>>>>>> cpu family      : 6
>>>>>>> model           : 15
>>>>>>> model name      : Intel(R) Xeon(R) CPU           X5365  @ 3.00GHz
>>>>>>> stepping        : 1
>>>>>>> cpu MHz         : 2992.499
>>>>>>> cache size      : 4096 KB
>>>>>>> fpu             : yes
>>>>>>> fpu_exception   : yes
>>>>>>> cpuid level     : 10
>>>>>>> wp              : yes
>>>>>>> flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr 
>>>>>>> pge
>>>>>>> mca
>>>>>>> cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss syscall nx lm
>>>>>>> constant_tsc up pni ssse3 cx16 lahf_lm
>>>>>>> bogomips        : 5984.99
>>>>>>> clflush size    : 64
>>>>>>> cache_alignment : 64
>>>>>>> address sizes   : 40 bits physical, 48 bits virtual
>>>>>>> power management:
>>>>>>>
>>>>>>> # cat /proc/meminfo
>>>>>>> MemTotal:      2059588 kB
>>>>>>> MemFree:        664456 kB
>>>>>>> Buffers:         21620 kB
>>>>>>> Cached:         612024 kB
>>>>>>> SwapCached:      25724 kB
>>>>>>> Active:        1164032 kB
>>>>>>> Inactive:       116264 kB
>>>>>>> HighTotal:           0 kB
>>>>>>> HighFree:            0 kB
>>>>>>> LowTotal:      2059588 kB
>>>>>>> LowFree:        664456 kB
>>>>>>> SwapTotal:     2064376 kB
>>>>>>> SwapFree:      1997364 kB
>>>>>>> Dirty:             400 kB
>>>>>>> Writeback:           0 kB
>>>>>>> AnonPages:      644712 kB
>>>>>>> Mapped:          75512 kB
>>>>>>> Slab:            78748 kB
>>>>>>> PageTables:      16492 kB
>>>>>>> NFS_Unstable:        0 kB
>>>>>>> Bounce:              0 kB
>>>>>>> CommitLimit:   3094168 kB
>>>>>>> Committed_AS:  1383072 kB
>>>>>>> VmallocTotal: 34359738367 kB
>>>>>>> VmallocUsed:    263920 kB
>>>>>>> VmallocChunk: 34359473927 kB
>>>>>>> HugePages_Total:     0
>>>>>>> HugePages_Free:      0
>>>>>>> HugePages_Rsvd:      0
>>>>>>> Hugepagesize:     2048 kB
>>>>>>> #
>>>>>>>
>>>>>>> RT Training in Washington DC, USA on Oct 25&    26 2010
>>>>>>> Last one this year -- Learn how to get the most out of RT!
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>



More information about the rt-users mailing list