[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