Slow PostgreSQL perf with 3.8.7

RT Users
1

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

2

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.
KenOn 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 [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 [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 [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 [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 [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!

3

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 [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 [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 [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 [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 [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!

4

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,
KenOn 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 [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 [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 [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 [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 [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!

5

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 crossedOn 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 [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 [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 [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 [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 [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!

6

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,
KenOn 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 [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 [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 [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 [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 [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!

7

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

8

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.

KenOn 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
[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
[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
[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
[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
[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!