[rt-users] Slow PostgreSQL perf with 3.8.7
Kenneth Marshall
ktm at rice.edu
Wed Sep 22 16:16:38 EDT 2010
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.
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